Merge pull request #1089 from modelix/feature/improve-logging

MODELIX-865: Improve logging

Author: languitar

gradle/libs.versions.toml

@@ -70,6 +70,7 @@ ktor-server-status-pages = { group = "io.ktor", name = "ktor-server-status-pages
 ktor-server-test-host = { group = "io.ktor", name = "ktor-server-test-host", version.ref = "ktor" }
 ktor-server-websockets = { group = "io.ktor", name = "ktor-server-websockets", version.ref = "ktor" }
 ktor-server-resources = { group = "io.ktor", name = "ktor-server-resources", version.ref = "ktor" }
+ktor-server-call-logging = { group = "io.ktor", name = "ktor-server-call-logging", version.ref = "ktor" }
 ktor-server-swagger = { group = "io.ktor", name = "ktor-server-swagger", version.ref = "ktor" }
 ktor-server-metrics-micrometer = { group = "io.ktor", name = "ktor-server-metrics-micrometer", version.ref = "ktor" }
 

model-datastructure/src/jvmMain/kotlin/org/modelix/model/InMemoryModel.kt

@@ -133,7 +133,7 @@ class InMemoryModel private constructor(
         fun load(branchId: String, slowMapRef: KVEntryReference<CPHamtNode>, store: IKeyValueStore, useRoleIds: Boolean): InMemoryModel {
             val fastMap: TLongObjectMap<CPNode> = TLongObjectHashMap()
             val bulkQuery = NonCachingObjectStore(store).newBulkQuery()
-            LOG.info { "Start loading model into memory" }
+            LOG.info { "Start loading model for branch $branchId into memory" }
             val duration = measureTimeMillis {
                 bulkQuery.query(slowMapRef).onReceive { slowMap ->
                     slowMap!!.visitEntries(bulkQuery) { nodeId, nodeDataRef ->
@@ -146,7 +146,7 @@ class InMemoryModel private constructor(
                 }
                 bulkQuery.executeQuery()
             }.milliseconds
-            LOG.info { "Done loading model into memory after ${duration.toDouble(DurationUnit.SECONDS)} s" }
+            LOG.info { "Done loading model for branch $branchId into memory after ${duration.toDouble(DurationUnit.SECONDS)} s" }
             return InMemoryModel(branchId, slowMapRef, fastMap, useRoleIds)
         }
     }

model-server/build.gradle.kts

@@ -50,6 +50,7 @@ dependencies {
     implementation(libs.ktor.server.websockets)
     implementation(libs.ktor.server.content.negotiation)
     implementation(libs.ktor.server.resources)
+    implementation(libs.ktor.server.call.logging)
     implementation(libs.ktor.serialization.json)
     implementation(libs.ktor.server.swagger)
     implementation(libs.ktor.server.metrics.micrometer)

model-server/src/main/kotlin/org/modelix/model/server/Main.kt

@@ -28,11 +28,16 @@ import io.ktor.server.engine.embeddedServer
 import io.ktor.server.http.content.staticResources
 import io.ktor.server.netty.Netty
 import io.ktor.server.netty.NettyApplicationEngine
+import io.ktor.server.plugins.callloging.CallLogging
+import io.ktor.server.plugins.callloging.processingTimeMillis
 import io.ktor.server.plugins.contentnegotiation.ContentNegotiation
 import io.ktor.server.plugins.cors.routing.CORS
 import io.ktor.server.plugins.forwardedheaders.ForwardedHeaders
+import io.ktor.server.plugins.origin
 import io.ktor.server.plugins.statuspages.StatusPages
 import io.ktor.server.plugins.swagger.swaggerUI
+import io.ktor.server.request.httpMethod
+import io.ktor.server.request.path
 import io.ktor.server.resources.Resources
 import io.ktor.server.response.respondText
 import io.ktor.server.routing.IgnoreTrailingSlash
@@ -192,6 +197,19 @@ object Main {
                     permissionSchema = ModelServerPermissionSchema.SCHEMA
                 }
                 install(ForwardedHeaders)
+                install(CallLogging) {
+                    format { call ->
+                        // Resemble the default format but include remote host and user agent for easier tracing on who issued a certain request.
+                        // INFO  ktor.application - 200 OK: GET - /public/modelix-base.css in 60ms
+                        val status = call.response.status()
+                        val httpMethod = call.request.httpMethod.value
+                        val userAgent = call.request.headers["User-Agent"]
+                        val processingTimeMillis = call.processingTimeMillis()
+                        val path = call.request.path()
+                        val remoteHost = call.request.origin.remoteHost
+                        "$status: $httpMethod - $path in ${processingTimeMillis}ms [Remote host: '$remoteHost', User agent: '$userAgent']"
+                    }
+                }
                 install(Resources)
                 // https://opensource.zalando.com/restful-api-guidelines/#136
                 install(IgnoreTrailingSlash)