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 <noreply@anthropic.com>
2026-05-02 16:35:51 +02:00
parent 3c47d2b8c9
commit b3aab9efd5
8 changed files with 68 additions and 7 deletions
@@ -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) =>
@@ -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)
    ()

@@ -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()
@@ -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(())
@@ -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,6 +27,8 @@ class GameRedisPublisher(
 ) extends Observer:

  def onGameEvent(event: GameEvent): Unit =
+    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))
@@ -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)
@@ -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
@@ -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))
    }

@@ -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))
    }