From b3aab9efd596db1ecd93a02ce2b77821dd23626a Mon Sep 17 00:00:00 2001 From: Janis Date: Sat, 2 May 2026 16:35:51 +0200 Subject: [PATCH 1/2] feat(logging): add DEBUG/INFO/WARN logging across services (NCS-72) Add org.jboss.logging.Logger to AccountService, BotRegistry, BotEventResource, InstanceRegistry, GameRedisSubscriberManager, GameRedisPublisher, GameWebSocketResource, UserWebSocketResource. Replace System.err.println with structured log.warnf in GameRedisSubscriberManager. Silent exception swallow in InstanceRegistry now emits WARN. Co-Authored-By: Claude Haiku 4.5 --- .../account/service/AccountService.scala | 23 ++++++++++++++++--- .../botplatform/registry/BotRegistry.scala | 6 +++++ .../resource/BotEventResource.scala | 6 +++++ .../service/InstanceRegistry.scala | 6 ++++- .../chess/redis/GameRedisPublisher.scala | 9 +++++++- .../redis/GameRedisSubscriberManager.scala | 11 ++++++++- .../ws/resource/GameWebSocketResource.scala | 5 ++++ .../ws/resource/UserWebSocketResource.scala | 9 +++++++- 8 files changed, 68 insertions(+), 7 deletions(-) diff --git a/modules/account/src/main/scala/de/nowchess/account/service/AccountService.scala b/modules/account/src/main/scala/de/nowchess/account/service/AccountService.scala index 71d5bb7..83404dd 100644 --- a/modules/account/src/main/scala/de/nowchess/account/service/AccountService.scala +++ b/modules/account/src/main/scala/de/nowchess/account/service/AccountService.scala @@ -9,6 +9,7 @@ import io.smallrye.jwt.build.Jwt import jakarta.enterprise.context.ApplicationScoped import jakarta.inject.Inject import jakarta.transaction.Transactional +import org.jboss.logging.Logger import scala.compiletime.uninitialized import java.time.Instant @@ -17,6 +18,8 @@ import java.util.UUID @ApplicationScoped class AccountService: + private val log = Logger.getLogger(classOf[AccountService]) + // scalafix:off DisableSyntax.var @Inject var userAccountRepository: UserAccountRepository = uninitialized @@ -30,6 +33,7 @@ class AccountService: @Transactional def register(req: RegisterRequest): Either[AccountError, UserAccount] = + log.infof("Registering user %s", req.username) if userAccountRepository.findByUsername(req.username).isDefined then Left(AccountError.UsernameTaken(req.username)) else if userAccountRepository.findByEmail(req.email).isDefined then Left(AccountError.EmailAlreadyRegistered(req.email)) @@ -40,15 +44,23 @@ class AccountService: account.passwordHash = BcryptUtil.bcryptHash(req.password) account.createdAt = Instant.now() userAccountRepository.persist(account) + log.infof("User %s registered successfully", req.username) Right(account) def login(req: LoginRequest): Either[AccountError, String] = userAccountRepository.findByUsername(req.username) match - case None => Left(AccountError.InvalidCredentials) + case None => + log.warnf("Login failed for unknown user %s", req.username) + Left(AccountError.InvalidCredentials) case Some(account) => - if !BcryptUtil.matches(req.password, account.passwordHash) then Left(AccountError.InvalidCredentials) - else if account.banned then Left(AccountError.UserBanned) + if !BcryptUtil.matches(req.password, account.passwordHash) then + log.warnf("Login failed — invalid credentials for %s", req.username) + Left(AccountError.InvalidCredentials) + else if account.banned then + log.warnf("Login rejected — user %s is banned", req.username) + Left(AccountError.UserBanned) else + log.infof("User %s logged in successfully", req.username) Right( Jwt .issuer("nowchess") @@ -65,6 +77,7 @@ class AccountService: @Transactional def createBotAccount(ownerId: UUID, botName: String): Either[AccountError, BotAccount] = + log.infof("Creating bot account %s for owner %s", botName, ownerId.toString) userAccountRepository.findById(ownerId) match case None => Left(AccountError.UserNotFound) case Some(owner) => @@ -77,6 +90,7 @@ class AccountService: bot.token = generateBotToken(bot.id) bot.createdAt = Instant.now() botAccountRepository.persist(bot) + log.infof("Bot account %s created for owner %s", botName, ownerId.toString) Right(bot) def getBotAccounts(ownerId: UUID): List[BotAccount] = @@ -93,6 +107,7 @@ class AccountService: case None => Left(AccountError.BotNotFound) case Some(_) => botAccountRepository.delete(botId) + log.infof("Deleting bot account %s", botId.toString) Right(()) @Transactional @@ -146,6 +161,7 @@ class AccountService: @Transactional def banUser(userId: UUID): Either[AccountError, UserAccount] = + log.infof("Banning user %s", userId.toString) userAccountRepository.findById(userId) match case None => Left(AccountError.UserNotFound) case Some(user) => @@ -156,6 +172,7 @@ class AccountService: @Transactional def unbanUser(userId: UUID): Either[AccountError, UserAccount] = + log.infof("Unbanning user %s", userId.toString) userAccountRepository.findById(userId) match case None => Left(AccountError.UserNotFound) case Some(user) => diff --git a/modules/bot-platform/src/main/scala/de/nowchess/botplatform/registry/BotRegistry.scala b/modules/bot-platform/src/main/scala/de/nowchess/botplatform/registry/BotRegistry.scala index 909ee3f..195364c 100644 --- a/modules/bot-platform/src/main/scala/de/nowchess/botplatform/registry/BotRegistry.scala +++ b/modules/bot-platform/src/main/scala/de/nowchess/botplatform/registry/BotRegistry.scala @@ -6,6 +6,7 @@ import io.quarkus.redis.datasource.pubsub.PubSubCommands import io.smallrye.mutiny.subscription.MultiEmitter import jakarta.enterprise.context.ApplicationScoped import jakarta.inject.Inject +import org.jboss.logging.Logger import scala.compiletime.uninitialized import java.util.concurrent.ConcurrentHashMap import java.util.function.Consumer @@ -13,6 +14,8 @@ import java.util.function.Consumer @ApplicationScoped class BotRegistry: + private val log = Logger.getLogger(classOf[BotRegistry]) + // scalafix:off DisableSyntax.var @Inject var redis: RedisDataSource = uninitialized @Inject var redisConfig: RedisConfig = uninitialized @@ -25,14 +28,17 @@ class BotRegistry: val handler: Consumer[String] = msg => emitter.emit(msg) val subscriber = redis.pubsub(classOf[String]).subscribe(channel, handler) connections.put(botId, (emitter, subscriber)) + log.infof("Bot %s registered", botId) () def unregister(botId: String): Unit = Option(connections.remove(botId)).foreach { (_, subscriber) => subscriber.unsubscribe(s"${redisConfig.prefix}:bot:$botId:events") } + log.infof("Bot %s unregistered", botId) def dispatch(botId: String, event: String): Unit = + log.debugf("Dispatching event to bot %s", botId) redis.pubsub(classOf[String]).publish(s"${redisConfig.prefix}:bot:$botId:events", event) () diff --git a/modules/bot-platform/src/main/scala/de/nowchess/botplatform/resource/BotEventResource.scala b/modules/bot-platform/src/main/scala/de/nowchess/botplatform/resource/BotEventResource.scala index 0264832..52283dc 100644 --- a/modules/bot-platform/src/main/scala/de/nowchess/botplatform/resource/BotEventResource.scala +++ b/modules/bot-platform/src/main/scala/de/nowchess/botplatform/resource/BotEventResource.scala @@ -10,6 +10,7 @@ import jakarta.inject.Inject import jakarta.ws.rs.* import jakarta.ws.rs.core.{MediaType, Response} import org.eclipse.microprofile.jwt.JsonWebToken +import org.jboss.logging.Logger import scala.compiletime.uninitialized import java.util.function.Consumer @@ -18,6 +19,8 @@ import java.util.function.Consumer @RolesAllowed(Array("**")) class BotEventResource: + private val log = Logger.getLogger(classOf[BotEventResource]) + // scalafix:off DisableSyntax.var @Inject var registry: BotRegistry = uninitialized @Inject var jwt: JsonWebToken = uninitialized @@ -32,8 +35,10 @@ class BotEventResource: val tokenType = Option(jwt.getClaim[AnyRef]("type")).map(_.toString).getOrElse("") val subject = Option(jwt.getSubject).getOrElse("") if tokenType != "bot" || subject != botId then + log.warnf("Unauthorized bot stream access — tokenType=%s subject=%s botId=%s", tokenType, subject, botId) Multi.createFrom().failure(new ForbiddenException("Not authorized for this bot")) else + log.infof("Bot %s connected to event stream", botId) Multi.createFrom().emitter[String] { emitter => registry.register(botId, emitter) emitter.onTermination(() => registry.unregister(botId)) @@ -58,6 +63,7 @@ class BotEventResource: @PathParam("uci") uci: String, ): Response = val playerId = Option(jwt.getSubject).getOrElse("") + log.debugf("Bot move %s in game %s by player %s", uci, gameId, playerId) val moveMsg = s"""{"type":"MOVE","uci":"$uci","playerId":"$playerId"}""" redis.pubsub(classOf[String]).publish(s"${redisConfig.prefix}:game:$gameId:c2s", moveMsg) Response.ok().build() diff --git a/modules/coordinator/src/main/scala/de/nowchess/coordinator/service/InstanceRegistry.scala b/modules/coordinator/src/main/scala/de/nowchess/coordinator/service/InstanceRegistry.scala index 480fbc5..f1a3532 100644 --- a/modules/coordinator/src/main/scala/de/nowchess/coordinator/service/InstanceRegistry.scala +++ b/modules/coordinator/src/main/scala/de/nowchess/coordinator/service/InstanceRegistry.scala @@ -9,6 +9,7 @@ import com.fasterxml.jackson.databind.ObjectMapper import de.nowchess.coordinator.dto.InstanceMetadata import java.util.concurrent.ConcurrentHashMap import io.smallrye.mutiny.Uni +import org.jboss.logging.Logger @ApplicationScoped class InstanceRegistry: @@ -18,6 +19,7 @@ class InstanceRegistry: private var redisPrefix = "nowchess" // scalafix:on DisableSyntax.var + private val log = Logger.getLogger(classOf[InstanceRegistry]) private val mapper = ObjectMapper() private val instances = ConcurrentHashMap[String, InstanceMetadata]() @@ -41,7 +43,9 @@ class InstanceRegistry: val metadata = mapper.readValue(value, classOf[InstanceMetadata]) instances.put(instanceId, metadata) Uni.createFrom().item(()) - catch case _: Exception => Uni.createFrom().item(()) + catch case ex: Exception => + log.warnf(ex, "Failed to parse instance metadata for %s", instanceId) + Uni.createFrom().item(()) } .onFailure() .recoverWithItem(()) diff --git a/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisPublisher.scala b/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisPublisher.scala index f8bd90f..80c106f 100644 --- a/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisPublisher.scala +++ b/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisPublisher.scala @@ -10,6 +10,10 @@ import de.nowchess.chess.observer.{GameEvent, Observer} import de.nowchess.chess.registry.GameRegistry import de.nowchess.chess.resource.GameDtoMapper import io.quarkus.redis.datasource.RedisDataSource +import org.jboss.logging.Logger + +object GameRedisPublisher: + private val log = Logger.getLogger(classOf[GameRedisPublisher]) class GameRedisPublisher( gameId: String, @@ -23,7 +27,9 @@ class GameRedisPublisher( ) extends Observer: def onGameEvent(event: GameEvent): Unit = - registry.get(gameId).foreach { entry => + try + GameRedisPublisher.log.debugf("Publishing game event for game %s", gameId) + registry.get(gameId).foreach { entry => val dto = GameDtoMapper.toGameStateDto(entry, ioClient) val json = objectMapper.writeValueAsString(GameStateEventDto(dto)) redis.pubsub(classOf[String]).publish(s2cTopicName, json) @@ -77,3 +83,4 @@ class GameRedisPublisher( writebackEmit(objectMapper.writeValueAsString(wb)) if entry.engine.context.result.isDefined then onGameOver(gameId) } + catch case ex: Exception => GameRedisPublisher.log.warnf(ex, "Failed to publish game event for game %s", gameId) diff --git a/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisSubscriberManager.scala b/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisSubscriberManager.scala index 05888ea..f41fa26 100644 --- a/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisSubscriberManager.scala +++ b/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisSubscriberManager.scala @@ -16,6 +16,7 @@ import jakarta.annotation.PreDestroy import jakarta.enterprise.context.ApplicationScoped import jakarta.enterprise.inject.Instance import jakarta.inject.Inject +import org.jboss.logging.Logger import scala.compiletime.uninitialized import scala.util.Try import java.util.concurrent.ConcurrentHashMap @@ -24,6 +25,8 @@ import java.util.function.Consumer @ApplicationScoped class GameRedisSubscriberManager: + private val log = Logger.getLogger(classOf[GameRedisSubscriberManager]) + // scalafix:off DisableSyntax.var @Inject var redis: RedisDataSource = uninitialized @Inject var registry: GameRegistry = uninitialized @@ -65,11 +68,12 @@ class GameRedisSubscriberManager: ) s2cObservers.put(gameId, obs) registry.get(gameId).foreach(_.engine.subscribe(obs)) + log.debugf("Subscribed to game %s", gameId) heartbeatServiceOpt.foreach(_.addGameSubscription(gameId)) catch case e: Exception => - System.err.println(s"Warning: Redis subscription failed for game $gameId: ${e.getMessage}") + log.warnf(e, "Redis subscription failed for game %s", gameId) () def unsubscribeGame(gameId: String): Unit = @@ -81,6 +85,7 @@ class GameRedisSubscriberManager: } heartbeatServiceOpt.foreach(_.removeGameSubscription(gameId)) + log.debugf("Unsubscribed from game %s", gameId) private def handleC2sMessage(gameId: String, msg: String): Unit = parseC2sMessage(msg) match @@ -97,6 +102,7 @@ class GameRedisSubscriberManager: } private def handleMove(gameId: String, uci: String, playerId: Option[String]): Unit = + log.debugf("Processing move %s for game %s by player %s", uci, gameId, playerId.getOrElse("anonymous")) registry.get(gameId).foreach { entry => entry.mode match case GameMode.Open => entry.engine.processUserInput(uci) @@ -127,6 +133,7 @@ class GameRedisSubscriberManager: def batchResubscribeGames(gameIds: java.util.List[String]): Int = gameIds.forEach(subscribeGame) + log.infof("Batch resubscribed %d games", gameIds.size()) gameIds.size() def unsubscribeGames(gameIds: java.util.List[String]): Int = @@ -135,12 +142,14 @@ class GameRedisSubscriberManager: def evictGames(gameIds: java.util.List[String]): Int = gameIds.forEach(unsubscribeGame) + log.infof("Evicting %d games", gameIds.size()) gameIds.size() def drainInstance(): Int = val gameIds = new java.util.ArrayList(c2sListeners.keySet()) val count = gameIds.size() gameIds.forEach(unsubscribeGame) + log.infof("Draining instance, unsubscribing %d games", count) count @PreDestroy diff --git a/modules/ws/src/main/scala/de/nowchess/ws/resource/GameWebSocketResource.scala b/modules/ws/src/main/scala/de/nowchess/ws/resource/GameWebSocketResource.scala index 204502c..42dcace 100644 --- a/modules/ws/src/main/scala/de/nowchess/ws/resource/GameWebSocketResource.scala +++ b/modules/ws/src/main/scala/de/nowchess/ws/resource/GameWebSocketResource.scala @@ -6,6 +6,7 @@ import io.quarkus.redis.datasource.pubsub.PubSubCommands import io.quarkus.websockets.next.* import io.smallrye.jwt.auth.principal.JWTParser import jakarta.inject.Inject +import org.jboss.logging.Logger import scala.compiletime.uninitialized import scala.util.Try import java.util.concurrent.ConcurrentHashMap @@ -14,6 +15,8 @@ import java.util.function.Consumer @WebSocket(path = "/api/board/game/{gameId}/ws") class GameWebSocketResource: + private val log = Logger.getLogger(classOf[GameWebSocketResource]) + // scalafix:off DisableSyntax.var @Inject var redis: RedisDataSource = uninitialized @@ -40,6 +43,7 @@ class GameWebSocketResource: .filter(_.nonEmpty) .flatMap(token => Try(jwtParser.parse(token)).toOption) .map(_.getSubject) + log.infof("Game WebSocket opened — gameId=%s playerId=%s", gameId, playerId.getOrElse("anonymous")) val handler: Consumer[String] = msg => connection.sendText(msg).subscribe().`with`(_ => (), _ => ()) val subscriber = redis.pubsub(classOf[String]).subscribe(s2cTopic(gameId), handler) connections.put(connection.id(), ConnectionMeta(gameId, subscriber, playerId)) @@ -60,6 +64,7 @@ class GameWebSocketResource: @OnClose def onClose(connection: WebSocketConnection): Unit = Option(connections.remove(connection.id())).foreach { meta => + log.infof("Game WebSocket closed — gameId=%s", meta.gameId) meta.subscriber.unsubscribe(s2cTopic(meta.gameId)) } diff --git a/modules/ws/src/main/scala/de/nowchess/ws/resource/UserWebSocketResource.scala b/modules/ws/src/main/scala/de/nowchess/ws/resource/UserWebSocketResource.scala index 0c68a7a..89434f5 100644 --- a/modules/ws/src/main/scala/de/nowchess/ws/resource/UserWebSocketResource.scala +++ b/modules/ws/src/main/scala/de/nowchess/ws/resource/UserWebSocketResource.scala @@ -6,6 +6,7 @@ import io.quarkus.redis.datasource.pubsub.PubSubCommands import io.quarkus.websockets.next.* import io.smallrye.jwt.auth.principal.JWTParser import jakarta.inject.Inject +import org.jboss.logging.Logger import scala.compiletime.uninitialized import scala.util.Try import java.util.concurrent.ConcurrentHashMap @@ -14,6 +15,8 @@ import java.util.function.Consumer @WebSocket(path = "/api/user/ws") class UserWebSocketResource: + private val log = Logger.getLogger(classOf[UserWebSocketResource]) + // scalafix:off DisableSyntax.var @Inject var redis: RedisDataSource = uninitialized @@ -38,8 +41,11 @@ class UserWebSocketResource: .map(_.getSubject) userIdOpt match - case None => connection.close().subscribe().`with`(_ => (), _ => ()) + case None => + log.warn("WebSocket opened with no valid JWT — closing connection") + connection.close().subscribe().`with`(_ => (), _ => ()) case Some(userId) => + log.infof("User WebSocket opened — userId=%s", userId) val handler: Consumer[String] = msg => connection.sendText(msg).subscribe().`with`(_ => (), _ => ()) val subscriber = redis.pubsub(classOf[String]).subscribe(userTopic(userId), handler) connections.put(connection.id(), (userId, subscriber)) @@ -48,6 +54,7 @@ class UserWebSocketResource: @OnClose def onClose(connection: WebSocketConnection): Unit = + log.infof("User WebSocket closed — connectionId=%s", connection.id()) Option(connections.remove(connection.id())).foreach { (userId, subscriber) => subscriber.unsubscribe(userTopic(userId)) } -- 2.52.0 From 4850b23e1925309f2cf81b5845378267c815d7d2 Mon Sep 17 00:00:00 2001 From: Janis Date: Sat, 2 May 2026 17:25:51 +0200 Subject: [PATCH 2/2] feat(logging): deepen coordinator and core logging (NCS-72) Coordinator: InstanceRegistry logs instance join/update/dead/remove; CoordinatorGrpcServer logs new stream + first heartbeat per instance; CoreGrpcClient logs channel open/evict and RPC success counts. Core: GameResource replaces println with logger; RedisGameRegistry logs store/Redis-load/DB-load and surfaces silent failures; CoordinatorServiceHandler logs inbound gRPC commands; IoGrpcClientWrapper and RuleSetGrpcAdapter wrap gRPC calls with WARN on failure. Co-Authored-By: Claude Haiku 4.5 --- .../resource/BotEventResource.scala | 2 +- .../src/main/resources/application.yml | 1 - .../grpc/CoordinatorGrpcServer.scala | 11 ++ .../coordinator/grpc/CoreGrpcClient.scala | 24 +++- .../service/InstanceRegistry.scala | 21 +++- .../grpc/CoordinatorServiceHandler.scala | 8 ++ .../chess/grpc/IoGrpcClientWrapper.scala | 46 +++++++- .../chess/grpc/RuleSetGrpcAdapter.scala | 98 ++++++++++++----- .../chess/redis/GameRedisPublisher.scala | 104 +++++++++--------- .../chess/registry/RedisGameRegistry.scala | 27 ++++- .../chess/resource/GameResource.scala | 15 ++- test | 2 +- 12 files changed, 256 insertions(+), 103 deletions(-) diff --git a/modules/bot-platform/src/main/scala/de/nowchess/botplatform/resource/BotEventResource.scala b/modules/bot-platform/src/main/scala/de/nowchess/botplatform/resource/BotEventResource.scala index 52283dc..f79211e 100644 --- a/modules/bot-platform/src/main/scala/de/nowchess/botplatform/resource/BotEventResource.scala +++ b/modules/bot-platform/src/main/scala/de/nowchess/botplatform/resource/BotEventResource.scala @@ -64,6 +64,6 @@ class BotEventResource: ): Response = val playerId = Option(jwt.getSubject).getOrElse("") log.debugf("Bot move %s in game %s by player %s", uci, gameId, playerId) - val moveMsg = s"""{"type":"MOVE","uci":"$uci","playerId":"$playerId"}""" + val moveMsg = s"""{"type":"MOVE","uci":"$uci","playerId":"$playerId"}""" redis.pubsub(classOf[String]).publish(s"${redisConfig.prefix}:game:$gameId:c2s", moveMsg) Response.ok().build() diff --git a/modules/coordinator/src/main/resources/application.yml b/modules/coordinator/src/main/resources/application.yml index e113a3a..1445991 100644 --- a/modules/coordinator/src/main/resources/application.yml +++ b/modules/coordinator/src/main/resources/application.yml @@ -9,7 +9,6 @@ quarkus: server: port: 9086 rest-client: - connection-timeout: 5000 read-timeout: 10000 smallrye-openapi: info-title: NowChess Coordinator Service diff --git a/modules/coordinator/src/main/scala/de/nowchess/coordinator/grpc/CoordinatorGrpcServer.scala b/modules/coordinator/src/main/scala/de/nowchess/coordinator/grpc/CoordinatorGrpcServer.scala index 45b8ae7..832c52c 100644 --- a/modules/coordinator/src/main/scala/de/nowchess/coordinator/grpc/CoordinatorGrpcServer.scala +++ b/modules/coordinator/src/main/scala/de/nowchess/coordinator/grpc/CoordinatorGrpcServer.scala @@ -27,13 +27,24 @@ class CoordinatorGrpcServer extends CoordinatorServiceGrpc.CoordinatorServiceImp override def heartbeatStream( responseObserver: StreamObserver[CoordinatorCommand], ): StreamObserver[HeartbeatFrame] = + log.info("New heartbeat stream connection established") new StreamObserver[HeartbeatFrame]: // scalafix:off DisableSyntax.var private var lastInstanceId = "" + private var firstFrameSeen = false // scalafix:on DisableSyntax.var override def onNext(frame: HeartbeatFrame): Unit = lastInstanceId = frame.getInstanceId + if !firstFrameSeen then + firstFrameSeen = true + log.infof( + "First heartbeat from instance %s (host=%s http=%d grpc=%d)", + frame.getInstanceId, + frame.getHostname, + frame.getHttpPort, + frame.getGrpcPort, + ) instanceRegistry .updateInstanceFromRedis(frame.getInstanceId) .subscribe() diff --git a/modules/coordinator/src/main/scala/de/nowchess/coordinator/grpc/CoreGrpcClient.scala b/modules/coordinator/src/main/scala/de/nowchess/coordinator/grpc/CoreGrpcClient.scala index 1be6081..6e95265 100644 --- a/modules/coordinator/src/main/scala/de/nowchess/coordinator/grpc/CoreGrpcClient.scala +++ b/modules/coordinator/src/main/scala/de/nowchess/coordinator/grpc/CoreGrpcClient.scala @@ -16,10 +16,18 @@ class CoreGrpcClient: private val channels = ConcurrentHashMap[String, ManagedChannel]() private def getChannel(host: String, port: Int): ManagedChannel = - channels.computeIfAbsent(s"$host:$port", _ => ManagedChannelBuilder.forAddress(host, port).usePlaintext().build()) + channels.computeIfAbsent( + s"$host:$port", + _ => + log.infof("Opening gRPC channel to %s:%d", host, port) + ManagedChannelBuilder.forAddress(host, port).usePlaintext().build(), + ) private def evictStaleChannel(host: String, port: Int): Unit = - Option(channels.remove(s"$host:$port")).foreach(_.shutdownNow()) + Option(channels.remove(s"$host:$port")).foreach { ch => + log.infof("Evicting stale gRPC channel to %s:%d", host, port) + ch.shutdownNow() + } @PreDestroy def shutdown(): Unit = @@ -33,7 +41,9 @@ class CoreGrpcClient: try val stub = CoordinatorServiceGrpc.newBlockingStub(getChannel(host, port)) val request = BatchResubscribeRequest.newBuilder().addAllGameIds(gameIds.asJava).build() - stub.batchResubscribeGames(request).getSubscribedCount + val count = stub.batchResubscribeGames(request).getSubscribedCount + log.debugf("batchResubscribeGames %s:%d — subscribed %d games", host, port, count) + count catch case ex: Exception => log.warnf(ex, "batchResubscribeGames RPC failed for %s:%d", host, port) @@ -44,7 +54,9 @@ class CoreGrpcClient: try val stub = CoordinatorServiceGrpc.newBlockingStub(getChannel(host, port)) val request = UnsubscribeGamesRequest.newBuilder().addAllGameIds(gameIds.asJava).build() - stub.unsubscribeGames(request).getUnsubscribedCount + val count = stub.unsubscribeGames(request).getUnsubscribedCount + log.debugf("unsubscribeGames %s:%d — unsubscribed %d games", host, port, count) + count catch case ex: Exception => log.warnf(ex, "unsubscribeGames RPC failed for %s:%d", host, port) @@ -55,7 +67,9 @@ class CoreGrpcClient: try val stub = CoordinatorServiceGrpc.newBlockingStub(getChannel(host, port)) val request = EvictGamesRequest.newBuilder().addAllGameIds(gameIds.asJava).build() - stub.evictGames(request).getEvictedCount + val count = stub.evictGames(request).getEvictedCount + log.debugf("evictGames %s:%d — evicted %d games", host, port, count) + count catch case ex: Exception => log.warnf(ex, "evictGames RPC failed for %s:%d", host, port) diff --git a/modules/coordinator/src/main/scala/de/nowchess/coordinator/service/InstanceRegistry.scala b/modules/coordinator/src/main/scala/de/nowchess/coordinator/service/InstanceRegistry.scala index f1a3532..0e2db31 100644 --- a/modules/coordinator/src/main/scala/de/nowchess/coordinator/service/InstanceRegistry.scala +++ b/modules/coordinator/src/main/scala/de/nowchess/coordinator/service/InstanceRegistry.scala @@ -41,19 +41,30 @@ class InstanceRegistry: .transformToUni { value => try val metadata = mapper.readValue(value, classOf[InstanceMetadata]) + val isNew = !instances.containsKey(instanceId) instances.put(instanceId, metadata) + if isNew then + log.infof("Instance %s joined registry (subscriptions=%d)", instanceId, metadata.subscriptionCount) + else + log.debugf( + "Instance %s updated (subscriptions=%d state=%s)", + instanceId, + metadata.subscriptionCount, + metadata.state, + ) Uni.createFrom().item(()) - catch case ex: Exception => - log.warnf(ex, "Failed to parse instance metadata for %s", instanceId) - Uni.createFrom().item(()) + catch + case ex: Exception => + log.warnf(ex, "Failed to parse instance metadata for %s", instanceId) + Uni.createFrom().item(()) } .onFailure() .recoverWithItem(()) def markInstanceDead(instanceId: String): Unit = instances.computeIfPresent(instanceId, (_, inst) => inst.copy(state = "DEAD")) - () + log.infof("Instance %s marked dead", instanceId) def removeInstance(instanceId: String): Unit = instances.remove(instanceId) - () + log.infof("Instance %s removed from registry", instanceId) diff --git a/modules/core/src/main/scala/de/nowchess/chess/grpc/CoordinatorServiceHandler.scala b/modules/core/src/main/scala/de/nowchess/chess/grpc/CoordinatorServiceHandler.scala index 05e2e9c..c263191 100644 --- a/modules/core/src/main/scala/de/nowchess/chess/grpc/CoordinatorServiceHandler.scala +++ b/modules/core/src/main/scala/de/nowchess/chess/grpc/CoordinatorServiceHandler.scala @@ -7,11 +7,15 @@ import scala.compiletime.uninitialized import de.nowchess.coordinator.proto.{CoordinatorServiceGrpc, *} import de.nowchess.chess.redis.GameRedisSubscriberManager import io.grpc.stub.StreamObserver +import org.jboss.logging.Logger import scala.jdk.CollectionConverters.* @GrpcService @Singleton class CoordinatorServiceHandler extends CoordinatorServiceGrpc.CoordinatorServiceImplBase: + + private val log = Logger.getLogger(classOf[CoordinatorServiceHandler]) + // scalafix:off DisableSyntax.var @Inject private var gameSubscriberManager: GameRedisSubscriberManager = uninitialized @@ -22,6 +26,7 @@ class CoordinatorServiceHandler extends CoordinatorServiceGrpc.CoordinatorServic responseObserver: StreamObserver[BatchResubscribeResponse], ): Unit = val count = gameSubscriberManager.batchResubscribeGames(request.getGameIdsList) + log.infof("Coordinator: batch resubscribe %d games → subscribed %d", request.getGameIdsList.size(), count) val response = BatchResubscribeResponse .newBuilder() .setSubscribedCount(count) @@ -34,6 +39,7 @@ class CoordinatorServiceHandler extends CoordinatorServiceGrpc.CoordinatorServic responseObserver: StreamObserver[UnsubscribeGamesResponse], ): Unit = val count = gameSubscriberManager.unsubscribeGames(request.getGameIdsList) + log.infof("Coordinator: unsubscribe %d games → unsubscribed %d", request.getGameIdsList.size(), count) val response = UnsubscribeGamesResponse .newBuilder() .setUnsubscribedCount(count) @@ -46,6 +52,7 @@ class CoordinatorServiceHandler extends CoordinatorServiceGrpc.CoordinatorServic responseObserver: StreamObserver[EvictGamesResponse], ): Unit = val count = gameSubscriberManager.evictGames(request.getGameIdsList) + log.infof("Coordinator: evict %d games → evicted %d", request.getGameIdsList.size(), count) val response = EvictGamesResponse .newBuilder() .setEvictedCount(count) @@ -58,6 +65,7 @@ class CoordinatorServiceHandler extends CoordinatorServiceGrpc.CoordinatorServic responseObserver: StreamObserver[DrainInstanceResponse], ): Unit = val migrated = gameSubscriberManager.drainInstance() + log.infof("Coordinator: drain instance → migrated %d games", migrated) val response = DrainInstanceResponse .newBuilder() .setGamesMigrated(migrated) diff --git a/modules/core/src/main/scala/de/nowchess/chess/grpc/IoGrpcClientWrapper.scala b/modules/core/src/main/scala/de/nowchess/chess/grpc/IoGrpcClientWrapper.scala index 126baee..f2698c4 100644 --- a/modules/core/src/main/scala/de/nowchess/chess/grpc/IoGrpcClientWrapper.scala +++ b/modules/core/src/main/scala/de/nowchess/chess/grpc/IoGrpcClientWrapper.scala @@ -5,29 +5,63 @@ import de.nowchess.chess.client.CombinedExportResponse import de.nowchess.core.proto.* import io.quarkus.grpc.GrpcClient import jakarta.enterprise.context.ApplicationScoped +import org.jboss.logging.Logger import scala.compiletime.uninitialized @ApplicationScoped class IoGrpcClientWrapper: + private val log = Logger.getLogger(classOf[IoGrpcClientWrapper]) + // scalafix:off DisableSyntax.var @GrpcClient("io-grpc") var stub: IoServiceGrpc.IoServiceBlockingStub = uninitialized // scalafix:on DisableSyntax.var def exportCombined(ctx: GameContext): CombinedExportResponse = - val combined = stub.exportCombined(CoreProtoMapper.toProtoGameContext(ctx)) - CombinedExportResponse(combined.getFen, combined.getPgn) + try + val combined = stub.exportCombined(CoreProtoMapper.toProtoGameContext(ctx)) + CombinedExportResponse(combined.getFen, combined.getPgn) + catch + case ex: Exception => + log.warnf(ex, "IO gRPC exportCombined failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw def importFen(fen: String): GameContext = - CoreProtoMapper.fromProtoGameContext(stub.importFen(ProtoImportFenRequest.newBuilder().setFen(fen).build())) + try CoreProtoMapper.fromProtoGameContext(stub.importFen(ProtoImportFenRequest.newBuilder().setFen(fen).build())) + catch + case ex: Exception => + log.warnf(ex, "IO gRPC importFen failed for fen %s", fen) + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw def importPgn(pgn: String): GameContext = - CoreProtoMapper.fromProtoGameContext(stub.importPgn(ProtoImportPgnRequest.newBuilder().setPgn(pgn).build())) + try CoreProtoMapper.fromProtoGameContext(stub.importPgn(ProtoImportPgnRequest.newBuilder().setPgn(pgn).build())) + catch + case ex: Exception => + log.warnf(ex, "IO gRPC importPgn failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw def exportFen(ctx: GameContext): String = - stub.exportFen(CoreProtoMapper.toProtoGameContext(ctx)).getValue + try stub.exportFen(CoreProtoMapper.toProtoGameContext(ctx)).getValue + catch + case ex: Exception => + log.warnf(ex, "IO gRPC exportFen failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw def exportPgn(ctx: GameContext): String = - stub.exportPgn(CoreProtoMapper.toProtoGameContext(ctx)).getValue + try stub.exportPgn(CoreProtoMapper.toProtoGameContext(ctx)).getValue + catch + case ex: Exception => + log.warnf(ex, "IO gRPC exportPgn failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw diff --git a/modules/core/src/main/scala/de/nowchess/chess/grpc/RuleSetGrpcAdapter.scala b/modules/core/src/main/scala/de/nowchess/chess/grpc/RuleSetGrpcAdapter.scala index f121ff0..1ad73db 100644 --- a/modules/core/src/main/scala/de/nowchess/chess/grpc/RuleSetGrpcAdapter.scala +++ b/modules/core/src/main/scala/de/nowchess/chess/grpc/RuleSetGrpcAdapter.scala @@ -7,6 +7,7 @@ import de.nowchess.api.rules.{PostMoveStatus, RuleSet} import de.nowchess.core.proto.* import io.quarkus.grpc.GrpcClient import jakarta.enterprise.context.ApplicationScoped +import org.jboss.logging.Logger import scala.compiletime.uninitialized import scala.jdk.CollectionConverters.* @@ -14,28 +15,59 @@ import scala.jdk.CollectionConverters.* @ApplicationScoped class RuleSetGrpcAdapter extends RuleSet: + private val log = Logger.getLogger(classOf[RuleSetGrpcAdapter]) + // scalafix:off DisableSyntax.var @GrpcClient("rule-grpc") var stub: RuleServiceGrpc.RuleServiceBlockingStub = uninitialized // scalafix:on DisableSyntax.var def candidateMoves(ctx: GameContext)(sq: Square): List[Move] = - val req = - ProtoSquareRequest.newBuilder().setContext(CoreProtoMapper.toProtoGameContext(ctx)).setSquare(sq.toString).build() - stub.candidateMoves(req).getMovesList.asScala.flatMap(CoreProtoMapper.fromProtoMove).toList + try + val req = + ProtoSquareRequest + .newBuilder() + .setContext(CoreProtoMapper.toProtoGameContext(ctx)) + .setSquare(sq.toString) + .build() + stub.candidateMoves(req).getMovesList.asScala.flatMap(CoreProtoMapper.fromProtoMove).toList + catch + case ex: Exception => + log.warnf(ex, "Rule gRPC candidateMoves failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw def legalMoves(ctx: GameContext)(sq: Square): List[Move] = - val req = - ProtoSquareRequest.newBuilder().setContext(CoreProtoMapper.toProtoGameContext(ctx)).setSquare(sq.toString).build() - stub.legalMoves(req).getMovesList.asScala.flatMap(CoreProtoMapper.fromProtoMove).toList + try + val req = + ProtoSquareRequest + .newBuilder() + .setContext(CoreProtoMapper.toProtoGameContext(ctx)) + .setSquare(sq.toString) + .build() + stub.legalMoves(req).getMovesList.asScala.flatMap(CoreProtoMapper.fromProtoMove).toList + catch + case ex: Exception => + log.warnf(ex, "Rule gRPC legalMoves failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw def allLegalMoves(ctx: GameContext): List[Move] = - stub - .allLegalMoves(CoreProtoMapper.toProtoGameContext(ctx)) - .getMovesList - .asScala - .flatMap(CoreProtoMapper.fromProtoMove) - .toList + try + stub + .allLegalMoves(CoreProtoMapper.toProtoGameContext(ctx)) + .getMovesList + .asScala + .flatMap(CoreProtoMapper.fromProtoMove) + .toList + catch + case ex: Exception => + log.warnf(ex, "Rule gRPC allLegalMoves failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw def isCheck(ctx: GameContext): Boolean = stub.isCheck(CoreProtoMapper.toProtoGameContext(ctx)).getValue @@ -56,19 +88,33 @@ class RuleSetGrpcAdapter extends RuleSet: stub.isThreefoldRepetition(CoreProtoMapper.toProtoGameContext(ctx)).getValue def applyMove(ctx: GameContext)(move: Move): GameContext = - val req = ProtoMoveRequest - .newBuilder() - .setContext(CoreProtoMapper.toProtoGameContext(ctx)) - .setMove(CoreProtoMapper.toProtoMove(move)) - .build() - CoreProtoMapper.fromProtoGameContext(stub.applyMove(req)) + try + val req = ProtoMoveRequest + .newBuilder() + .setContext(CoreProtoMapper.toProtoGameContext(ctx)) + .setMove(CoreProtoMapper.toProtoMove(move)) + .build() + CoreProtoMapper.fromProtoGameContext(stub.applyMove(req)) + catch + case ex: Exception => + log.warnf(ex, "Rule gRPC applyMove failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw override def postMoveStatus(ctx: GameContext): PostMoveStatus = - val p = stub.postMoveStatus(CoreProtoMapper.toProtoGameContext(ctx)) - PostMoveStatus( - p.getIsCheckmate, - p.getIsStalemate, - p.getIsInsufficientMaterial, - p.getIsCheck, - p.getIsThreefoldRepetition, - ) + try + val p = stub.postMoveStatus(CoreProtoMapper.toProtoGameContext(ctx)) + PostMoveStatus( + p.getIsCheckmate, + p.getIsStalemate, + p.getIsInsufficientMaterial, + p.getIsCheck, + p.getIsThreefoldRepetition, + ) + catch + case ex: Exception => + log.warnf(ex, "Rule gRPC postMoveStatus failed") + // scalafix:off DisableSyntax.throw + throw ex + // scalafix:on DisableSyntax.throw diff --git a/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisPublisher.scala b/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisPublisher.scala index 80c106f..322d6e6 100644 --- a/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisPublisher.scala +++ b/modules/core/src/main/scala/de/nowchess/chess/redis/GameRedisPublisher.scala @@ -30,57 +30,57 @@ class GameRedisPublisher( try GameRedisPublisher.log.debugf("Publishing game event for game %s", gameId) registry.get(gameId).foreach { entry => - val dto = GameDtoMapper.toGameStateDto(entry, ioClient) - val json = objectMapper.writeValueAsString(GameStateEventDto(dto)) - redis.pubsub(classOf[String]).publish(s2cTopicName, json) + val dto = GameDtoMapper.toGameStateDto(entry, ioClient) + val json = objectMapper.writeValueAsString(GameStateEventDto(dto)) + redis.pubsub(classOf[String]).publish(s2cTopicName, json) - val clock = entry.engine.currentClockState - val wb = GameWritebackEventDto( - gameId = gameId, - fen = dto.fen, - pgn = dto.pgn, - moveCount = entry.engine.context.moves.size, - whiteId = entry.white.id.value, - whiteName = entry.white.displayName, - blackId = entry.black.id.value, - blackName = entry.black.displayName, - mode = entry.mode.toString, - resigned = entry.resigned, - limitSeconds = entry.engine.timeControl match { - case de.nowchess.api.game.TimeControl.Clock(l, _) => Some(l); case _ => None - }, - incrementSeconds = entry.engine.timeControl match { - case de.nowchess.api.game.TimeControl.Clock(_, i) => Some(i); case _ => None - }, - daysPerMove = entry.engine.timeControl match { - case de.nowchess.api.game.TimeControl.Correspondence(d) => Some(d); case _ => None - }, - whiteRemainingMs = clock.collect { case c: LiveClockState => c.whiteRemainingMs }, - blackRemainingMs = clock.collect { case c: LiveClockState => c.blackRemainingMs }, - incrementMs = clock.collect { case c: LiveClockState => c.incrementMs }, - clockLastTickAt = clock.collect { case c: LiveClockState => c.lastTickAt.toEpochMilli }, - clockMoveDeadline = clock.collect { case c: CorrespondenceClockState => c.moveDeadline.toEpochMilli }, - clockActiveColor = clock.map(_.activeColor.label.toLowerCase), - pendingDrawOffer = entry.engine.pendingDrawOfferBy.map(_.label.toLowerCase), - result = entry.engine.context.result.map { - case GameResult.Win(Color.White, _) => "white" - case GameResult.Win(Color.Black, _) => "black" - case GameResult.Draw(_) => "draw" - }, - terminationReason = entry.engine.context.result.map { - case GameResult.Win(_, WinReason.Checkmate) => "checkmate" - case GameResult.Win(_, WinReason.Resignation) => "resignation" - case GameResult.Win(_, WinReason.TimeControl) => "timeout" - case GameResult.Draw(DrawReason.Stalemate) => "stalemate" - case GameResult.Draw(DrawReason.InsufficientMaterial) => "insufficient_material" - case GameResult.Draw(DrawReason.FiftyMoveRule) => "fifty_move" - case GameResult.Draw(DrawReason.ThreefoldRepetition) => "repetition" - case GameResult.Draw(DrawReason.Agreement) => "agreement" - }, - redoStack = entry.engine.redoStackMoves.map(GameDtoMapper.moveToUci), - pendingTakebackRequest = entry.engine.pendingTakebackRequestBy.map(_.label.toLowerCase), - ) - writebackEmit(objectMapper.writeValueAsString(wb)) - if entry.engine.context.result.isDefined then onGameOver(gameId) - } + val clock = entry.engine.currentClockState + val wb = GameWritebackEventDto( + gameId = gameId, + fen = dto.fen, + pgn = dto.pgn, + moveCount = entry.engine.context.moves.size, + whiteId = entry.white.id.value, + whiteName = entry.white.displayName, + blackId = entry.black.id.value, + blackName = entry.black.displayName, + mode = entry.mode.toString, + resigned = entry.resigned, + limitSeconds = entry.engine.timeControl match { + case de.nowchess.api.game.TimeControl.Clock(l, _) => Some(l); case _ => None + }, + incrementSeconds = entry.engine.timeControl match { + case de.nowchess.api.game.TimeControl.Clock(_, i) => Some(i); case _ => None + }, + daysPerMove = entry.engine.timeControl match { + case de.nowchess.api.game.TimeControl.Correspondence(d) => Some(d); case _ => None + }, + whiteRemainingMs = clock.collect { case c: LiveClockState => c.whiteRemainingMs }, + blackRemainingMs = clock.collect { case c: LiveClockState => c.blackRemainingMs }, + incrementMs = clock.collect { case c: LiveClockState => c.incrementMs }, + clockLastTickAt = clock.collect { case c: LiveClockState => c.lastTickAt.toEpochMilli }, + clockMoveDeadline = clock.collect { case c: CorrespondenceClockState => c.moveDeadline.toEpochMilli }, + clockActiveColor = clock.map(_.activeColor.label.toLowerCase), + pendingDrawOffer = entry.engine.pendingDrawOfferBy.map(_.label.toLowerCase), + result = entry.engine.context.result.map { + case GameResult.Win(Color.White, _) => "white" + case GameResult.Win(Color.Black, _) => "black" + case GameResult.Draw(_) => "draw" + }, + terminationReason = entry.engine.context.result.map { + case GameResult.Win(_, WinReason.Checkmate) => "checkmate" + case GameResult.Win(_, WinReason.Resignation) => "resignation" + case GameResult.Win(_, WinReason.TimeControl) => "timeout" + case GameResult.Draw(DrawReason.Stalemate) => "stalemate" + case GameResult.Draw(DrawReason.InsufficientMaterial) => "insufficient_material" + case GameResult.Draw(DrawReason.FiftyMoveRule) => "fifty_move" + case GameResult.Draw(DrawReason.ThreefoldRepetition) => "repetition" + case GameResult.Draw(DrawReason.Agreement) => "agreement" + }, + redoStack = entry.engine.redoStackMoves.map(GameDtoMapper.moveToUci), + pendingTakebackRequest = entry.engine.pendingTakebackRequestBy.map(_.label.toLowerCase), + ) + writebackEmit(objectMapper.writeValueAsString(wb)) + if entry.engine.context.result.isDefined then onGameOver(gameId) + } catch case ex: Exception => GameRedisPublisher.log.warnf(ex, "Failed to publish game event for game %s", gameId) diff --git a/modules/core/src/main/scala/de/nowchess/chess/registry/RedisGameRegistry.scala b/modules/core/src/main/scala/de/nowchess/chess/registry/RedisGameRegistry.scala index 49152b2..cbb122c 100644 --- a/modules/core/src/main/scala/de/nowchess/chess/registry/RedisGameRegistry.scala +++ b/modules/core/src/main/scala/de/nowchess/chess/registry/RedisGameRegistry.scala @@ -17,6 +17,7 @@ import jakarta.enterprise.context.ApplicationScoped import jakarta.inject.Inject import org.eclipse.microprofile.rest.client.inject.RestClient import scala.compiletime.uninitialized +import org.jboss.logging.Logger import scala.util.Try import java.nio.charset.StandardCharsets import java.security.{MessageDigest, SecureRandom} @@ -35,6 +36,7 @@ class RedisGameRegistry extends GameRegistry: @Inject @RestClient var storeClient: StoreServiceClient = uninitialized // scalafix:on + private val log = Logger.getLogger(classOf[RedisGameRegistry]) private val localEngines = ConcurrentHashMap[String, GameEntry]() private val rng = new SecureRandom() @@ -48,6 +50,12 @@ class RedisGameRegistry extends GameRegistry: localEngines.put(entry.gameId, entry) val combined = ioClient.exportCombined(entry.engine.context) redis.value(classOf[String]).setex(cacheKey(entry.gameId), 1800L, toJson(entry, combined.fen, combined.pgn)) + log.infof( + "Stored game %s in registry (white=%s black=%s)", + entry.gameId, + entry.white.displayName, + entry.black.displayName, + ) def get(gameId: String): Option[GameEntry] = Option(localEngines.get(gameId)) match @@ -71,9 +79,15 @@ class RedisGameRegistry extends GameRegistry: private def fromRedis(gameId: String): Option[GameEntry] = readRedisDto(gameId) - .flatMap(dto => Try(reconstruct(dto)).toOption) + .flatMap { dto => + Try(reconstruct(dto)).toOption.orElse { + log.warnf("Failed to reconstruct game %s from Redis", gameId) + None + } + } .map { entry => localEngines.put(gameId, entry) + log.infof("Loaded game %s from Redis cache", gameId) entry } @@ -102,12 +116,15 @@ class RedisGameRegistry extends GameRegistry: pendingDrawOffer = Option(record.pendingDrawOffer), ) (dto, reconstruct(dto)) - }.toOption - .map { case (dto, entry) => + } match + case scala.util.Success((dto, entry)) => + log.infof("Loaded game %s from store service", gameId) localEngines.put(gameId, entry) redis.value(classOf[String]).setex(cacheKey(gameId), 1800L, objectMapper.writeValueAsString(dto)) - entry - } + Some(entry) + case scala.util.Failure(ex) => + log.warnf(ex, "Failed to load game %s from store service", gameId) + None private def reconstruct(dto: GameCacheDto): GameEntry = val ctx = if dto.pgn.nonEmpty then ioClient.importPgn(dto.pgn) else GameContext.initial diff --git a/modules/core/src/main/scala/de/nowchess/chess/resource/GameResource.scala b/modules/core/src/main/scala/de/nowchess/chess/resource/GameResource.scala index 2a83dd6..2fcb7a4 100644 --- a/modules/core/src/main/scala/de/nowchess/chess/resource/GameResource.scala +++ b/modules/core/src/main/scala/de/nowchess/chess/resource/GameResource.scala @@ -30,6 +30,7 @@ import jakarta.inject.Inject import jakarta.ws.rs.* import jakarta.ws.rs.core.{MediaType, Response} import org.eclipse.microprofile.jwt.JsonWebToken +import org.jboss.logging.Logger import java.util.concurrent.atomic.AtomicReference import scala.compiletime.uninitialized @@ -38,6 +39,8 @@ import scala.compiletime.uninitialized @ApplicationScoped class GameResource: + private val log = Logger.getLogger(classOf[GameResource]) + // scalafix:off DisableSyntax.var @Inject var registry: GameRegistry = uninitialized @@ -165,7 +168,13 @@ class GameResource: val entry = newEntry(GameContext.initial, white, black, tc, mode) registry.store(entry) subscriberManager.subscribeGame(entry.gameId) - println(s"Created game ${entry.gameId}") + log.infof( + "Game %s created — white=%s black=%s mode=%s", + entry.gameId, + white.displayName, + black.displayName, + mode.toString, + ) created(GameDtoMapper.toGameFullDto(entry, ioClient)) @GET @@ -182,6 +191,7 @@ class GameResource: val entry = registry.get(gameId).getOrElse(throw GameNotFoundException(gameId)) assertGameNotOver(entry) val color = colorOf(entry) + log.infof("Game %s — resign by %s", gameId, color.label) entry.engine.resign(color) registry.update(entry.copy(resigned = true)) ok(OkResponseDto()) @@ -194,6 +204,7 @@ class GameResource: val entry = registry.get(gameId).getOrElse(throw GameNotFoundException(gameId)) assertGameNotOver(entry) assertIsCurrentPlayer(entry) + log.debugf("Game %s — move %s by %s", gameId, uci, colorOf(entry).label) if Parser.parseMove(uci).isEmpty then throw BadRequestException("INVALID_UCI", s"Invalid UCI notation: $uci", Some("uci")) applyMoveInput(entry.engine, uci).foreach(err => throw BadRequestException("INVALID_MOVE", err, Some("uci"))) @@ -284,6 +295,7 @@ class GameResource: val entry = newEntry(ctx, white, black, tc) registry.store(entry) subscriberManager.subscribeGame(entry.gameId) + log.infof("Imported FEN game %s", entry.gameId) created(GameDtoMapper.toGameFullDto(entry, ioClient)) @POST @@ -295,6 +307,7 @@ class GameResource: val entry = newEntry(ctx, DefaultWhite, DefaultBlack) registry.store(entry) subscriberManager.subscribeGame(entry.gameId) + log.infof("Imported PGN game %s", entry.gameId) created(GameDtoMapper.toGameFullDto(entry, ioClient)) @GET diff --git a/test b/test index b09567d..638b5e5 100755 --- a/test +++ b/test @@ -1,7 +1,7 @@ #! /usr/bin/env bash set -euo pipefail -./gradlew test +./gradlew test -Dquarkus.profile=test if [ "$#" -eq 0 ]; then PYTHONUTF8=1 python3 jacoco-reporter/test_gaps.py -- 2.52.0