[+] Metrics (#95)

* Add actuator and micrometer

* update

* [-] Remove unused import

* [O] Make code less verbose

* format

* refactor

---------

Co-authored-by: Azalea <22280294+hykilpikonna@users.noreply.github.com>

build.gradle.kts

@@ -46,6 +46,10 @@ dependencies {
     testImplementation("org.springframework.security:spring-security-test")
     implementation("net.logstash.logback:logstash-logback-encoder:7.4")
 
+    // Metrics
+    implementation("org.springframework.boot:spring-boot-starter-actuator")
+    implementation("io.micrometer:micrometer-registry-prometheus")
+
     // Database
     runtimeOnly("org.mariadb.jdbc:mariadb-java-client:3.3.3")
     runtimeOnly("org.xerial:sqlite-jdbc:3.45.2.0")

src/main/java/ext/Ext.kt

@@ -163,6 +163,7 @@ val Any?.truthy get() = when (this) {
 
 // Collections
 fun <T> ls(vararg args: T) = args.toList()
+inline fun <reified T> arr(vararg args: T) = arrayOf(*args)
 operator fun <K, V> Map<K, V>.plus(map: Map<K, V>) =
     (if (this is MutableMap) this else toMutableMap()).apply { putAll(map) }
 operator fun <K, V> MutableMap<K, V>.plusAssign(map: Map<K, V>) { putAll(map) }

src/main/java/icu/samnyan/aqua/net/utils/ErrorResponse.kt

@@ -17,6 +17,8 @@ class ApiException(val code: Int, message: Str) : RuntimeException(message) {
     fun resp() = ResponseEntity.status(code).body(message.toString())
 }
 
+fun Exception.simpleDescribe(): String = if (this is ApiException) "E${code}" else javaClass.simpleName
+
 @ControllerAdvice(basePackages = ["icu.samnyan"])
 class GlobalExceptionHandler {
     @ExceptionHandler(ApiException::class)

src/main/java/icu/samnyan/aqua/sega/aimedb/AimeDB.kt

@@ -4,6 +4,7 @@ import ext.toHex
 import icu.samnyan.aqua.net.db.AquaUserServices
 import icu.samnyan.aqua.sega.general.model.Card
 import icu.samnyan.aqua.sega.general.service.CardService
+import icu.samnyan.aqua.sega.allnet.AllNetProps
 import io.netty.buffer.ByteBuf
 import io.netty.buffer.ByteBufUtil
 import io.netty.buffer.Unpooled
@@ -25,6 +26,7 @@ import kotlin.jvm.optionals.getOrNull
 class AimeDB(
     val cardService: CardService,
     val us: AquaUserServices,
+    val allNetProps: AllNetProps,
 ): ChannelInboundHandlerAdapter() {
     val logger: Logger = LoggerFactory.getLogger(AimeDB::class.java)
 
@@ -65,7 +67,14 @@ class AimeDB(
             logger.info("AimeDB /${handler.name} : (game ${base.gameId}, keychip ${base.keychipId})")
 
             // Check keychip
-            if (!us.validKeychip(base.keychipId)) return logger.warn("> Rejected: Keychip not found")
+            if (!us.validKeychip(base.keychipId)) {
+                if (allNetProps.keychipPermissiveForTesting) {
+                    logger.warn("> Accepted invalid keychip ${base.keychipId} in permissive mode")
+                } else {
+                    logger.warn("> Rejected: Keychip not found")
+                    return
+                }
+            }
 
             handler.fn(data)?.let { ctx.write(it) }
         } finally {

src/main/java/icu/samnyan/aqua/sega/allnet/AllNet.kt

@@ -25,6 +25,7 @@ class AllNetProps {
     var port: Int? = null
     val keychipSesExpire: Long = 172800000 // milliseconds
     var checkKeychip: Boolean = false
+    var keychipPermissiveForTesting: Boolean = false
     var redirect: String = "web"
 
     var placeName: String = ""
@@ -102,9 +103,11 @@ class AllNet(
         // game_id SDEZ, ver 1.35, serial A0000001234, ip, firm_ver 50000, boot_ver 0000,
         // encode UTF-8, format_ver 3, hops 1， token 2010451813
         val reqMap = decodeAllNet(dataStream.readAllBytes())
-        var serial = reqMap["serial"] ?: ""
+        val serial = reqMap["serial"] ?: ""
         logger.info("AllNet /PowerOn : $reqMap")
 
+        var session: String? = null
+
         // Proper keychip authentication
         if (props.checkKeychip) {
             // If it's a user keychip, it should be in user database
@@ -112,11 +115,20 @@ class AllNet(
             if (u != null) {
                 // Create a new session for the user
                 logger.info("> Keychip authenticated: ${u.auId} ${u.computedName}")
-                serial = keychipSessionService.new(u).token
+                session = keychipSessionService.new(u, reqMap["game_id"] ?: "").token
             }
 
             // Check if it's a whitelisted keychip
-            else if (serial.isEmpty() || !keychipRepo.existsByKeychipId(serial)) {
+            else if (!serial.isEmpty() && keychipRepo.existsByKeychipId(serial)) {
+                session = keychipSessionService.new(null, reqMap["game_id"] ?: "").token
+            }
+
+            else if (props.keychipPermissiveForTesting) {
+                logger.warn("> Accepted invalid keychip $serial in permissive mode")
+                session = keychipSessionService.new(null, reqMap["game_id"] ?: "").token
+            }
+
+            else {
                 // This will cause an allnet auth bad on client side
                 return "".also { logger.warn("> Rejected: Keychip not found") }
             }
@@ -127,7 +139,7 @@ class AllNet(
 
         val formatVer = reqMap["format_ver"] ?: ""
         val resp = props.map.toMutableMap() + mapOf(
-            "uri" to switchUri(localAddr, localPort, gameId, ver, serial),
+            "uri" to switchUri(localAddr, localPort, gameId, ver, session),
             "host" to props.host.ifBlank { localAddr },
         )
 
@@ -160,15 +172,15 @@ class AllNet(
         return resp.toUrl() + "\n"
     }
 
-    private fun switchUri(localAddr: Str, localPort: Str, gameId: Str, ver: Str, serial: Str): Str {
+    private fun switchUri(localAddr: Str, localPort: Str, gameId: Str, ver: Str, session: Str?): Str {
         val addr = props.host.ifBlank { localAddr }
         val port = props.port?.toString() ?: localPort
 
         // If keychip authentication is enabled, the game URLs will be set to /gs/{token}/{game}/...
-        val base = if (props.checkKeychip) "gs/$serial" else "g"
+        val base = if (session != null) "gs/$session" else "g"
 
         return "http://$addr:$port/$base/" + when (gameId) {
-            "SDBT" -> "chu2/$ver/$serial/"
+            "SDBT" -> "chu2/$ver/$session/"
             "SDHD" -> "chu3/$ver/"
             "SDGS" -> "chu3/$ver/" // International (c3exp)
             "SBZV" -> "diva/"

src/main/java/icu/samnyan/aqua/sega/allnet/AllNetSecure.kt

@@ -6,6 +6,7 @@ import jakarta.servlet.http.HttpServletRequest
 import jakarta.servlet.http.HttpServletRequestWrapper
 import jakarta.servlet.http.HttpServletResponse
 import org.slf4j.LoggerFactory
+import org.springframework.beans.factory.annotation.Value
 import org.springframework.boot.autoconfigure.condition.ConditionalOnBean
 import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty
 import org.springframework.context.annotation.Configuration
@@ -30,6 +31,13 @@ class TokenChecker(
 ) : HandlerInterceptor {
     val log = LoggerFactory.getLogger(TokenChecker::class.java)
 
+    companion object {
+        private val log = LoggerFactory.getLogger(TokenChecker::class.java)
+
+        private val currentSession = ThreadLocal<KeychipSession?>()
+        fun getCurrentSession() = currentSession.get()
+    }
+
     /**
      * Handle request before it's processed.
      */
@@ -48,6 +56,8 @@ class TokenChecker(
         if (token.isNotBlank() && (keyChipRepo.existsByKeychipId(token) || session != null
                 || (frontierProps.enabled && frontierProps.ftk == token)))
         {
+            currentSession.set(session)
+
             // Forward the request
             val w = RewriteWrapper(req, token).apply { setAttribute("token", token) }
             req.getRequestDispatcher(w.requestURI).forward(w, resp)

src/main/java/icu/samnyan/aqua/sega/allnet/KeychipSession.kt

@@ -21,7 +21,10 @@ import java.security.SecureRandom
 class KeychipSession(
     @ManyToOne
     @JoinColumn(name = "au_id")
-    var user: AquaNetUser = AquaNetUser(),
+    var user: AquaNetUser? = null,
+
+    @Column(length = 4)
+    val gameId: String,
 
     @Id
     @Column(length = 32)
@@ -69,8 +72,8 @@ class KeychipSessionService(
     /**
      * Create a new session.
      */
-    fun new(user: AquaNetUser): KeychipSession {
+    fun new(user: AquaNetUser?, gameId: String): KeychipSession {
-        val session = KeychipSession(user = user)
+        val session = KeychipSession(user = user, gameId = gameId)
         return keychipSessionRepo.save(session)
     }
 

src/main/java/icu/samnyan/aqua/sega/chusan/ChusanServletController.kt

@@ -1,14 +1,15 @@
 package icu.samnyan.aqua.sega.chusan
 
 import ext.*
+import icu.samnyan.aqua.net.utils.simpleDescribe
 import icu.samnyan.aqua.sega.chunithm.handler.impl.GetGameIdlistHandler
 import icu.samnyan.aqua.sega.chusan.handler.*
 import icu.samnyan.aqua.sega.general.BaseHandler
+import icu.samnyan.aqua.spring.Metrics
 import org.slf4j.LoggerFactory
 import org.springframework.web.bind.annotation.*
 import kotlin.reflect.full.declaredMemberProperties
 
-
 /**
  * @author samnyan (privateamusement@protonmail.com)
  */
@@ -119,14 +120,31 @@ class ChusanServletController(
         }
 
         logger.info("Chu3 $api : $request")
+        if (api !in noopEndpoint && !handlers.containsKey(api)) {
+            logger.warn("Chu3 $api not found")
+            return """{"returnCode":"1","apiName":"$api"}"""
+        }
+
+        // Only record the counter metrics if the API is known.
+        Metrics.counter("aquadx_chusan_api_call", "api" to api).increment()
 
         if (api in noopEndpoint) {
             return """{"returnCode":"1"}"""
         }
 
-        return handlers[api]?.handle(request) ?: {
+        return try {
+            Metrics.timer("aquadx_chusan_api_latency", "api" to api).recordCallable {
+                handlers[api]?.handle(request) ?: {
                     logger.warn("Chu3 $api not found")
                     """{"returnCode":"1","apiName":"$api"}"""
                 }
             }
+        } catch (e: Exception) {
+            Metrics.counter(
+                "aquadx_chusan_api_error",
+                "api" to api, "error" to e.simpleDescribe()
+            ).increment()
+            throw e
+        }
+    }
 }

src/main/java/icu/samnyan/aqua/sega/maimai2/Maimai2ServletController.kt

@@ -2,9 +2,11 @@ package icu.samnyan.aqua.sega.maimai2
 
 import ext.*
 import icu.samnyan.aqua.net.utils.ApiException
+import icu.samnyan.aqua.net.utils.simpleDescribe
 import icu.samnyan.aqua.sega.general.BaseHandler
 import icu.samnyan.aqua.sega.maimai2.handler.*
 import icu.samnyan.aqua.sega.maimai2.model.Mai2Repos
+import icu.samnyan.aqua.spring.Metrics
 import io.ktor.client.request.*
 import org.slf4j.LoggerFactory
 import org.springframework.http.ResponseEntity
@@ -339,8 +341,14 @@ class Maimai2ServletController(
 
     @API("/{api}")
     fun handle(@PathVariable api: String, @RequestBody request: Map<String, Any>): Any {
-        try {
         logger.info("Mai2 < $api : ${request.toJson()}") // TODO: Optimize logging
+        if (api !in noopEndpoint && api !in staticEndpoint && !handlers.containsKey(api)) {
+            logger.warn("Mai2 > $api not found")
+            return """{"returnCode":1,"apiName":"com.sega.maimai2servlet.api.$api"}"""
+        }
+
+        // Only record the counter metrics if the API is known.
+        Metrics.counter("aquadx_maimai2_api_call", "api" to api).increment()
 
         if (api in noopEndpoint) {
             logger.info("Mai2 > $api no-op")
@@ -352,16 +360,23 @@ class Maimai2ServletController(
             return staticEndpoint[api]!!
         }
 
-            return handlers[api]?.handle(request)?.let { if (it is String) it else it.toJson() }?.also {
+        return try {
+            Metrics.timer("aquadx_maimai2_api_latency", "api" to api).recordCallable {
+                handlers[api]!!.handle(request).let { if (it is String) it else it.toJson() }.also {
                     if (api !in setOf("GetUserItemApi", "GetGameEventApi"))
                         logger.info("Mai2 > $api : $it")
-            } ?: {
-                logger.warn("Mai2 > $api not found")
-                """{"returnCode":1,"apiName":"com.sega.maimai2servlet.api.$api"}"""
                 }
-        } catch (e: ApiException) {
+            }
+        } catch (e: Exception) {
+            Metrics.counter(
+                "aquadx_maimai2_api_error",
+                "api" to api, "error" to e.simpleDescribe()
+            ).increment()
+
+            if (e is ApiException) {
                 // It's a bad practice to return 200 ok on error, but this is what maimai does so we have to follow
                 return ResponseEntity.ok().body("""{"returnCode":0,"apiName":"com.sega.maimai2servlet.api.$api","message":"${e.message?.replace("\"", "\\\"")} - ${e.code}"}""")
+            } else throw e
         }
     }
 }

src/main/java/icu/samnyan/aqua/sega/maimai2/handler/UploadUserPlaylogHandler.kt

@@ -1,12 +1,14 @@
 package icu.samnyan.aqua.sega.maimai2.handler
 
 import ext.millis
+import icu.samnyan.aqua.sega.allnet.TokenChecker
+import icu.samnyan.aqua.sega.general.BaseHandler
 import icu.samnyan.aqua.sega.maimai2.model.Mai2UserDataRepo
 import icu.samnyan.aqua.sega.maimai2.model.Mai2UserPlaylogRepo
-import icu.samnyan.aqua.sega.general.BaseHandler
 import icu.samnyan.aqua.sega.maimai2.model.request.UploadUserPlaylog
 import icu.samnyan.aqua.sega.maimai2.model.userdata.Mai2UserPlaylog
 import icu.samnyan.aqua.sega.util.jackson.BasicMapper
+import icu.samnyan.aqua.spring.Metrics
 import org.springframework.scheduling.annotation.Scheduled
 import org.springframework.stereotype.Component
 import kotlin.jvm.optionals.getOrNull
@@ -24,11 +26,23 @@ class UploadUserPlaylogHandler(
     companion object {
         @JvmStatic
         val playBacklog = mutableMapOf<Long, MutableList<BacklogEntry>>()
+
+        val VALID_GAME_IDS = setOf("SDEZ", "SDGA", "SDGB")
     }
 
     override fun handle(request: Map<String, Any>): String {
         val req = mapper.convert(request, UploadUserPlaylog::class.java)
 
+        val version = tryParseGameVersion(req.userPlaylog.version)
+        if (version != null) {
+            val session = TokenChecker.getCurrentSession()
+            val gameId = if (session?.gameId in VALID_GAME_IDS) session!!.gameId else ""
+            Metrics.counter(
+                "aquadx_maimai2_playlog_game_version",
+                "game_id" to gameId, "version" to version
+            ).increment()
+        }
+
         // Save if the user is registered
         val u = userDataRepository.findByCardExtId(req.userId).getOrNull()
         if (u != null) playlogRepo.save(req.userPlaylog.apply { user = u })
@@ -52,4 +66,13 @@ class UploadUserPlaylogHandler(
         playBacklog.filter { (_, v) -> v.isEmpty() || v[0].time - now > 300_000 }.toList()
             .forEach { (k, _) -> playBacklog.remove(k) }
     }
+
+    private fun tryParseGameVersion(version: Int): String? {
+        val major = version / 1000000
+        val minor = version / 1000 % 1000
+        if (major != 1) return null
+        if (minor !in 0..99) return null
+        // e.g. "1.30", minor should have two digits
+        return "$major.${minor.toString().padStart(2, '0')}"
+    }
 }

src/main/java/icu/samnyan/aqua/sega/wacca/WaccaServer.kt

@@ -4,6 +4,7 @@ import ext.*
 import icu.samnyan.aqua.net.db.AquaGameOptions
 import icu.samnyan.aqua.net.games.wacca.Wacca
 import icu.samnyan.aqua.net.utils.ApiException
+import icu.samnyan.aqua.net.utils.simpleDescribe
 import icu.samnyan.aqua.sega.general.dao.CardRepository
 import icu.samnyan.aqua.sega.wacca.WaccaItemType.*
 import icu.samnyan.aqua.sega.wacca.WaccaItemType.NOTE_COLOR
@@ -12,6 +13,7 @@ import icu.samnyan.aqua.sega.wacca.WaccaItemType.TOUCH_EFFECT
 import icu.samnyan.aqua.sega.wacca.WaccaOptionType.*
 import icu.samnyan.aqua.sega.wacca.model.BaseRequest
 import icu.samnyan.aqua.sega.wacca.model.db.*
+import icu.samnyan.aqua.spring.Metrics
 import io.ktor.client.utils.*
 import jakarta.servlet.http.HttpServletRequest
 import org.springframework.beans.factory.annotation.Autowired
@@ -79,14 +81,23 @@ class WaccaServer {
     /** Handle all requests */
     @API("/api/**")
     fun handle(req: HttpServletRequest, @RB body: String): Any {
-        return try {
+        // Normalize path
         val path = req.requestURI.removePrefix("/g/wacca").removePrefix("/WaccaServlet")
             .removePrefix("/api").removePrefix("/").lowercase()
+
+        if (path !in cacheMap && path !in handlerMap) {
+            return resp("[]", 1, "Not Found")
+        }
+
+        // Only record the counter metrics if the API is known.
+        Metrics.counter("aquadx_wacca_api_call", "api" to path).increment()
+
         if (path in cacheMap) return resp(cacheMap[path]!!)
-            if (path !in handlerMap) return resp("[]", 1, "Not Found")
 
         log.info("Wacca < $path : $body")
 
+        return try {
+            Metrics.timer("aquadx_wacca_api_latency", "api" to path).recordCallable {
                 val br = JACKSON.parse<BaseRequest>(body)
                 handlerMap[path]!!(br, br.params).let { when (it) {
                     is String -> resp(it)
@@ -94,12 +105,20 @@ class WaccaServer {
                     else -> error("Invalid response type ${it.javaClass}")
                 } }.also { log.info("Wacca > $path : ${it.body}") }
             }
-        catch (e: ApiException) { resp("[]", e.code, e.message ?: "") }
+        } catch (e: Exception) {
-        catch (e: Exception) {
+            Metrics.counter(
+                "aquadx_wacca_api_error",
+                "api" to path, "error" to e.simpleDescribe()
+            ).increment()
+
+            if (e is ApiException) {
+                resp("[]", e.code, e.message ?: "")
+            } else {
                 log.error("Wacca > Error", e)
                 resp("[]", 500, e.message ?: "")
             }
         }
+    }
 }
 
 @Suppress("UNCHECKED_CAST")

src/main/java/icu/samnyan/aqua/spring/Metrics.kt

@@ -0,0 +1,45 @@
+package icu.samnyan.aqua.spring
+
+import io.micrometer.core.instrument.Counter
+import io.micrometer.core.instrument.Timer
+import java.util.concurrent.ConcurrentHashMap
+import io.micrometer.core.instrument.Metrics as MMetrics
+
+object Metrics {
+    fun counter(metricName: String, vararg pairs: Pair<String, Any>): Counter {
+        val expandedLabels = expandLabels(*pairs)
+        return cache.computeIfAbsent(MetricCacheKey(Counter::class.java, metricName, expandedLabels)) {
+            Counter
+                .builder(metricName)
+                .tags(*expandedLabels)
+                .register(MMetrics.globalRegistry)
+        } as Counter
+    }
+
+    fun timer(metricName: String, vararg pairs: Pair<String, Any>): Timer {
+        val expandedLabels = expandLabels(*pairs)
+        return cache.computeIfAbsent(MetricCacheKey(Timer::class.java, metricName, expandedLabels)) {
+            Timer
+                .builder(metricName)
+                .publishPercentiles(0.5, 0.75, 0.90, 0.95, 0.99)
+                .tags(*expandedLabels)
+                .register(MMetrics.globalRegistry)
+        } as Timer
+    }
+
+    private data class MetricCacheKey(
+        val type: Class<*>,
+        val metricName: String,
+        val expandedLabels: Array<String>,
+    )
+
+    private val cache = ConcurrentHashMap<MetricCacheKey, Any>()
+
+    private fun expandLabels(vararg pairs: Pair<String, Any>): Array<String> {
+        return pairs
+            .flatMap {
+                listOf(it.first, it.second.toString())
+            }
+            .toTypedArray()
+    }
+}

src/main/resources/application.properties

@@ -33,3 +33,11 @@ spring.jpa.hibernate.ddl-auto=none
 # https://github.com/termstandard/colors#truecolor-support-in-output-devices
 # If you want to read the logs using a script, read the json logs in `logs` folder instead.
 spring.output.ansi.enabled=always
+
+# Metrics
+management.server.port=8081
+management.endpoint.prometheus.enabled=true
+management.endpoints.web.exposure.include=prometheus
+management.metrics.distribution.percentiles.http.server.requests=0.5, 0.75, 0.9, 0.95, 0.99
+management.metrics.distribution.percentiles.tasks.scheduled.execution=0.5, 0.75, 0.9, 0.95, 0.99
+management.metrics.distribution.percentiles.spring.data.repository.invocations=0.5, 0.75, 0.9, 0.95, 0.99

src/main/resources/db/migration/mariadb/V1000_20__keychip_session_game_id.sql

@@ -0,0 +1,2 @@
+ALTER TABLE allnet_keychip_sessions
+    ADD game_id VARCHAR(4) NULL;