Add logging

backend/authik/src/main/kotlin/ru/ifmo/se/dating/authik/api/HttpAuthApi.kt

@@ -9,13 +9,16 @@ import ru.ifmo.se.dating.authik.model.generated.TelegramInitDataMessage
 import ru.ifmo.se.dating.authik.external.telegram.TelegramInitDataParser
 import ru.ifmo.se.dating.exception.AuthenticationException
 import ru.ifmo.se.dating.exception.GenericException
+import ru.ifmo.se.dating.logging.Log.Companion.autoLog
 import ru.ifmo.se.dating.text.abbreviated
 
 @Controller
 class HttpAuthApi(
     private val telegramParser: TelegramInitDataParser,
     private val auth: AuthService,
 ) : AuthApiDelegate {
+    private val log = autoLog()
+
     override suspend fun authTelegramWebAppPut(
         telegramInitDataMessage: TelegramInitDataMessage,
     ): ResponseEntity<AuthGrantMessage> {
@@ -29,6 +32,7 @@ class HttpAuthApi(
         try {
             telegramParser.parse(telegramInitDataMessage)
         } catch (error: GenericException) {
+            log.warn("Telegram Init Data parsing failed: ${error.message}")
             throw AuthenticationException(
                 "Corrupted ${telegramInitDataMessage.string.abbreviated()}: ${error.message}",
                 error,

backend/authik/src/main/kotlin/ru/ifmo/se/dating/authik/logic/basic/BasicAuthService.kt

@@ -1,19 +1,17 @@
 package ru.ifmo.se.dating.authik.logic.basic
 
-import org.springframework.stereotype.Service
 import ru.ifmo.se.dating.authik.logic.AuthService
 import ru.ifmo.se.dating.authik.model.generated.TelegramWebAppInitDataMessage
-import ru.ifmo.se.dating.authik.security.auth.JwtTokenIssuer
+import ru.ifmo.se.dating.authik.security.auth.TokenIssuer
 import ru.ifmo.se.dating.authik.storage.TelegramAccountStorage
 import ru.ifmo.se.dating.logging.Log.Companion.autoLog
 import ru.ifmo.se.dating.security.auth.AccessToken
 import ru.ifmo.se.dating.security.auth.User
 import ru.ifmo.se.dating.storage.TxEnv
 
-@Service
 class BasicAuthService(
     private val telegramAccountStorage: TelegramAccountStorage,
-    private val issuer: JwtTokenIssuer,
+    private val issuer: TokenIssuer,
     private val txEnv: TxEnv,
 ) : AuthService {
     private val log = autoLog()

backend/authik/src/main/kotlin/ru/ifmo/se/dating/authik/logic/logging/LoggingAuthService.kt

@@ -0,0 +1,18 @@
+package ru.ifmo.se.dating.authik.logic.logging
+
+import ru.ifmo.se.dating.authik.logic.AuthService
+import ru.ifmo.se.dating.authik.model.generated.TelegramWebAppInitDataMessage
+import ru.ifmo.se.dating.logging.Log.Companion.autoLog
+import ru.ifmo.se.dating.security.auth.AccessToken
+
+class LoggingAuthService(val origin: AuthService) : AuthService {
+    private val log = autoLog()
+
+    override suspend fun authenticate(telegram: TelegramWebAppInitDataMessage): AccessToken =
+        runCatching { origin.authenticate(telegram) }
+            .onSuccess { log.debug("Authenticated telegram user with id ${telegram.user.id}") }
+            .onFailure { e ->
+                log.warn("Failed to authenticate telegram with id ${telegram.user.id}: ${e.message}")
+            }
+            .getOrThrow()
+}

backend/authik/src/main/kotlin/ru/ifmo/se/dating/authik/logic/spring/SpringAuthService.kt

@@ -0,0 +1,23 @@
+package ru.ifmo.se.dating.authik.logic.spring
+
+import org.springframework.stereotype.Service
+import ru.ifmo.se.dating.authik.logic.AuthService
+import ru.ifmo.se.dating.authik.logic.basic.BasicAuthService
+import ru.ifmo.se.dating.authik.logic.logging.LoggingAuthService
+import ru.ifmo.se.dating.authik.security.auth.TokenIssuer
+import ru.ifmo.se.dating.authik.storage.TelegramAccountStorage
+import ru.ifmo.se.dating.storage.TxEnv
+
+@Service
+class SpringAuthService(
+    telegramAccountStorage: TelegramAccountStorage,
+    issuer: TokenIssuer,
+    txEnv: TxEnv,
+) : AuthService by
+LoggingAuthService(
+    BasicAuthService(
+        telegramAccountStorage = telegramAccountStorage,
+        issuer = issuer,
+        txEnv = txEnv,
+    )
+)

backend/authik/src/main/kotlin/ru/ifmo/se/dating/authik/security/auth/JwtTokenIssuer.kt

@@ -15,24 +15,6 @@ import kotlin.time.toKotlinDuration
 import java.time.Duration as JavaDuration
 import kotlin.time.Duration as KotlinDuration
 
-@Configuration
-class JwtTokenIssuerConfiguration {
-    @Bean
-    fun jwtTokenIssuer(
-        clock: Clock,
-
-        @Value("\${security.auth.token.sign.private}")
-        privateSignKey: String,
-
-        @Value("\${security.auth.token.duration}")
-        duration: JavaDuration,
-    ) = JwtTokenIssuer(
-        clock = clock,
-        privateSignKey = Keys.deserializePrivate(privateSignKey),
-        duration = duration.toKotlinDuration(),
-    )
-}
-
 class JwtTokenIssuer(
     private val clock: Clock,
     private val privateSignKey: PrivateKey,

backend/authik/src/main/kotlin/ru/ifmo/se/dating/authik/security/auth/JwtTokenIssuerConfiguration.kt

@@ -0,0 +1,29 @@
+package ru.ifmo.se.dating.authik.security.auth
+
+import org.springframework.beans.factory.annotation.Value
+import org.springframework.context.annotation.Bean
+import org.springframework.context.annotation.Configuration
+import ru.ifmo.se.dating.security.key.Keys
+import java.time.Clock
+import java.time.Duration
+import kotlin.time.toKotlinDuration
+
+@Configuration
+class JwtTokenIssuerConfiguration {
+    @Bean
+    fun jwtTokenIssuer(
+        clock: Clock,
+
+        @Value("\${security.auth.token.sign.private}")
+        privateSignKey: String,
+
+        @Value("\${security.auth.token.duration}")
+        duration: Duration,
+    ) = LoggingTokenIssuer(
+        JwtTokenIssuer(
+            clock = clock,
+            privateSignKey = Keys.deserializePrivate(privateSignKey),
+            duration = duration.toKotlinDuration(),
+        )
+    )
+}

backend/authik/src/main/kotlin/ru/ifmo/se/dating/authik/security/auth/LoggingTokenIssuer.kt

@@ -0,0 +1,16 @@
+package ru.ifmo.se.dating.authik.security.auth
+
+import ru.ifmo.se.dating.logging.Log.Companion.autoLog
+import ru.ifmo.se.dating.security.auth.AccessToken
+
+class LoggingTokenIssuer(private val origin: TokenIssuer) : TokenIssuer {
+    private val log = autoLog()
+
+    override fun issue(payload: AccessToken.Payload): AccessToken =
+        runCatching { origin.issue(payload) }
+            .onSuccess { log.info("Issued access token for user with id ${payload.userId}") }
+            .onFailure { e ->
+                log.warn("Failed to issue access token for user with id ${payload.userId}: ${e.message}")
+            }
+            .getOrThrow()
+}

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/logging/Log.kt

@@ -3,6 +3,8 @@ package ru.ifmo.se.dating.logging
 interface Log {
     fun info(message: String)
     fun warn(message: String)
+    fun warn(message: String, e: Throwable)
+    fun error(message: String, e: Throwable)
     fun debug(message: String)
 
     companion object {

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/logging/Slf4jLog.kt

@@ -11,6 +11,12 @@ class Slf4jLog(name: String) : Log {
     override fun warn(message: String) =
         origin.warn(message)
 
+    override fun warn(message: String, e: Throwable) =
+        origin.warn("${message}: ${e.message}", e)
+
+    override fun error(message: String, e: Throwable) =
+        origin.error("${message}: ${e.message}", e)
+
     override fun debug(message: String) =
         origin.debug(message)
 }

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/logic/LoggingTransactionalOutbox.kt

@@ -0,0 +1,60 @@
+package ru.ifmo.se.dating.logic
+
+import kotlinx.coroutines.flow.Flow
+import ru.ifmo.se.dating.logging.Log
+
+class LoggingTransactionalOutbox<E, Id>(
+    private val origin: TransactionalOutbox<E, Id>
+) : TransactionalOutbox<E, Id> by origin {
+    private val log = Log.forClass(origin.javaClass)
+
+    override fun publishable(): Flow<Id> =
+        runCatching { origin.publishable() }
+            .onSuccess { log.info("Retrieved publishable events") }
+            .onFailure { log.warn("Failed to retrieve publishable events") }
+            .getOrThrow()
+
+    override suspend fun acquireById(id: Id): E =
+        runCatching { origin.acquireById(id) }
+            .onSuccess { event ->
+                val status = if (isPublished(event)) {
+                    "a published"
+                } else {
+                    "an unpublished"
+                }
+                log.info("Acquired $status event with id $id")
+            }
+            .onFailure { log.warn("Failed to acquire an event with id $id") }
+            .getOrThrow()
+
+    override suspend fun isPublished(event: E): Boolean =
+        origin.isPublished(event)
+
+    override suspend fun doProcess(event: E) =
+        runCatching { origin.doProcess(event) }
+            .onSuccess { log.info("Executed an event processing") }
+            .onFailure { e -> log.warn("Failed to process an event: ${e.message}") }
+            .getOrThrow()
+
+    override suspend fun markPublished(event: E) =
+        runCatching { origin.markPublished(event) }
+            .onSuccess { log.info("Marked an event as published") }
+            .onFailure { e -> log.warn("Failed to mark an event as published: ${e.message}") }
+            .getOrThrow()
+
+    override suspend fun process(id: Id) {
+        log.info("Processing an event with id $id...")
+        runCatching { super.process(id) }
+            .onSuccess { log.info("An event with id $id was processed") }
+            .onFailure { log.warn("Failed to process an event with id $id") }
+            .getOrThrow()
+    }
+
+    override suspend fun recover() {
+        log.info("Starting the recovery...")
+        runCatching { super.recover() }
+            .onSuccess { log.info("Recovery was completed.") }
+            .onFailure { e -> log.warn("Recovery was failed", e) }
+            .getOrThrow()
+    }
+}

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/logic/TransactionalOutbox.kt

@@ -4,13 +4,13 @@ import kotlinx.coroutines.flow.Flow
 import kotlinx.coroutines.flow.toCollection
 import ru.ifmo.se.dating.storage.TxEnv
 
-abstract class TransactionalOutbox<E, Id> {
-    protected abstract val tx: TxEnv
-    protected abstract fun publishable(): Flow<Id>
-    protected abstract suspend fun acquireById(id: Id): E
-    protected abstract suspend fun isPublished(event: E): Boolean
-    protected abstract suspend fun doProcess(event: E)
-    protected abstract suspend fun markPublished(event: E)
+interface TransactionalOutbox<E, Id> {
+    val tx: TxEnv
+    fun publishable(): Flow<Id>
+    suspend fun acquireById(id: Id): E
+    suspend fun isPublished(event: E): Boolean
+    suspend fun doProcess(event: E)
+    suspend fun markPublished(event: E)
 
     suspend fun process(id: Id) = tx.transactional {
         val event = acquireById(id)

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/security/auth/JwtTokenDecoder.kt

@@ -12,20 +12,6 @@ import java.security.PublicKey
 import java.time.Clock
 import java.util.*
 
-@Configuration
-class JwtTokenDecoderConfiguration {
-    @Bean
-    fun jwtTokenDecoder(
-        clock: Clock,
-
-        @Value("\${security.auth.token.sign.public}")
-        publicSignKey: String,
-    ) = JwtTokenDecoder(
-        clock = clock,
-        publicSignKey = Keys.deserializePublic(publicSignKey),
-    )
-}
-
 class JwtTokenDecoder(
     private val clock: Clock,
     private val publicSignKey: PublicKey,

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/security/auth/JwtTokenDecoderConfiguration.kt

@@ -0,0 +1,23 @@
+package ru.ifmo.se.dating.security.auth
+
+import org.springframework.beans.factory.annotation.Value
+import org.springframework.context.annotation.Bean
+import org.springframework.context.annotation.Configuration
+import ru.ifmo.se.dating.security.key.Keys
+import java.time.Clock
+
+@Configuration
+class JwtTokenDecoderConfiguration {
+    @Bean
+    fun jwtTokenDecoder(
+        clock: Clock,
+
+        @Value("\${security.auth.token.sign.public}")
+        publicSignKey: String,
+    ) = LoggingTokenDecoder(
+        JwtTokenDecoder(
+            clock = clock,
+            publicSignKey = Keys.deserializePublic(publicSignKey),
+        )
+    )
+}

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/security/auth/LoggingTokenDecoder.kt

@@ -0,0 +1,13 @@
+package ru.ifmo.se.dating.security.auth
+
+import ru.ifmo.se.dating.logging.Log.Companion.autoLog
+
+class LoggingTokenDecoder(private val origin: TokenDecoder) : TokenDecoder {
+    private val log = autoLog()
+
+    override fun decode(token: AccessToken): AccessToken.Payload =
+        runCatching { origin.decode(token) }
+            .onSuccess { log.debug("Decoded a token of user with id ${it.userId}") }
+            .onFailure { log.warn("Failed to decode an auth token") }
+            .getOrThrow()
+}

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/spring/security/auth/SpringJwtContextRepository.kt

@@ -14,6 +14,7 @@ import org.springframework.web.server.ServerWebExchange
 import reactor.core.publisher.Mono
 import ru.ifmo.se.dating.exception.AuthenticationException
 import ru.ifmo.se.dating.exception.GenericException
+import ru.ifmo.se.dating.logging.Log.Companion.autoLog
 import ru.ifmo.se.dating.spring.exception.SpringGenericExceptionHandler
 
 @Component
@@ -41,6 +42,8 @@ class SpringJwtContextRepository(
     private val headerName = HttpHeaders.AUTHORIZATION
     private val bearerPrefix = "Bearer "
 
+    private val log = autoLog()
+
     override fun save(
         exchange: ServerWebExchange,
         context: SecurityContext,
@@ -61,19 +64,24 @@ class SpringJwtContextRepository(
             null
         }
 
-    private fun extractBearer(exchange: ServerWebExchange): String {
+    private fun extractBearer(exchange: ServerWebExchange): String = runCatching {
         val count = exchange.request.headers.getOrEmpty(headerName).size
         if (count != 1) {
             throw AuthenticationException(
                 "expected only 1 header '$headerName', got $count",
             )
         }
+
         val bearer = exchange.request.headers[headerName]!![0]
         if (!bearer.startsWith(bearerPrefix)) {
             throw AuthenticationException(
                 "expected format 'Bearer <your jwt token>'",
             )
         }
-        return bearer.substringAfter(bearerPrefix)
+
+        bearer.substringAfter(bearerPrefix)
     }
+        .onSuccess { log.debug("Extracted a bearer token") }
+        .onFailure { e -> log.warn("Failed to extract a bearer token: ${e.message}") }
+        .getOrThrow()
 }

backend/foundation/src/main/kotlin/ru/ifmo/se/dating/spring/security/auth/SpringSecurityContext.kt

@@ -4,15 +4,21 @@ import kotlinx.coroutines.reactive.awaitSingle
 import org.springframework.security.authentication.UsernamePasswordAuthenticationToken
 import org.springframework.security.core.context.ReactiveSecurityContextHolder
 import org.springframework.security.core.context.SecurityContext
+import ru.ifmo.se.dating.logging.Log.Companion.autoLog
 import ru.ifmo.se.dating.security.auth.User
 
 object SpringSecurityContext {
-    suspend fun principal(): User.Id {
+    private val log = autoLog()
+
+    suspend fun principal(): User.Id = runCatching {
         val context = context()
         val auth = context.authentication as UsernamePasswordAuthenticationToken
         val user = auth.principal as User.Id
-        return user
+        user
     }
+        .onSuccess { user -> log.info("Authenticated a user with id $user") }
+        .onFailure { e -> log.error("Failed to load security context: ${e.message}", e) }
+        .getOrThrow()
 
     private suspend fun context(): SecurityContext =
         ReactiveSecurityContextHolder.getContext().awaitSingle()