feat: Add more logging on testservice and possibility to set developm…

…ent api on instance creation (#2225)

* feat: add better debug info and error messages to testservice

* No need to print class

* Log when sync fails

* Attach kalium log output from kermit logger to regular log

* Log level for kalium is lower than the default

* Send response on timeout

* Better handling of delete instance

* Put instance in collection befor sync to be able to delete more clients on failure

* Fix return value

* Make development api setting configurable

* Fix compilation issue with logwriter

* Fix SpacingAroundOperators

* Use clear variables for parameters

* Revert change in CoreLogger and use CoreLogger.init to attach own logger

logic/src/commonMain/kotlin/com/wire/kalium/logic/CoreLogger.kt

@@ -40,6 +40,7 @@ object CoreLogger {
         CryptographyLogger.init(config = config)
         PersistenceLogger.init(config = config)
     }
+
     fun setLoggingLevel(level: KaliumLogLevel) {
         kaliumLoggerConfig.setLogLevel(level)
     }

testservice/config.yml

@@ -23,20 +23,22 @@ logging:
 
     # The default level of all loggers. Can be OFF, ERROR, WARN, INFO, DEBUG, TRACE, or ALL.
     level: INFO
+    loggers:
+        com.wire.kalium: DEBUG
 
     appenders:
         - type: console
-          threshold: INFO
+          threshold: DEBUG
         - type: file
-          threshold: INFO
-          logFormat: "%-6level [%d{HH:mm:ss.SSS}] [%t] %logger{5} - %X{code} %msg %n"
+          threshold: DEBUG
+          logFormat: "%-6level [%d{HH:mm:ss.SSS}] %X{code} %msg %n"
           currentLogFilename: /var/log/kalium-testservice/application.log
           archivedLogFilenamePattern: /var/log/kalium-testservice/application-%d{yyyy-MM-dd}.log
           archivedFileCount: 7
           timeZone: GMT+1
         - type: file
           threshold: ALL
-          logFormat: "%-6level [%d{HH:mm:ss.SSS}] [%t] %logger{5} - %X{code} %msg %n"
+          logFormat: "%-6level [%d{HH:mm:ss.SSS}] %X{code} %msg %n"
           currentLogFilename: /var/log/kalium-testservice/application_debug.log
           archivedLogFilenamePattern: /var/log/kalium-testservice/application_debug-%d{yyyy-MM-dd}.log
           archivedFileCount: 7

testservice/src/main/kotlin/com/wire/kalium/testservice/KaliumLogWriter.kt

@@ -0,0 +1,39 @@
+/*
+ * Wire
+ * Copyright (C) 2023 Wire Swiss GmbH
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program. If not, see http://www.gnu.org/licenses/.
+ */
+package com.wire.kalium.testservice
+
+import co.touchlab.kermit.LogWriter
+import co.touchlab.kermit.Severity
+import com.wire.kalium.testservice.managed.InstanceService
+import org.slf4j.LoggerFactory
+
+class KaliumLogWriter(private val instanceId: String) : LogWriter() {
+
+    private val log = LoggerFactory.getLogger(InstanceService::class.java.name)
+
+    override fun log(severity: Severity, message: String, tag: String, throwable: Throwable?) {
+        when (severity) {
+            Severity.Verbose -> log.debug("Instance $instanceId: $message")
+            Severity.Debug -> log.debug("Instance $instanceId: $message")
+            Severity.Info -> log.info("Instance $instanceId: $message")
+            Severity.Warn -> log.warn("Instance $instanceId: $message")
+            Severity.Error -> log.error("Instance $instanceId: $message $throwable")
+            Severity.Assert -> log.info("Instance $instanceId: $message")
+        }
+    }
+}

testservice/src/main/kotlin/com/wire/kalium/testservice/api/v1/InstanceLifecycle.kt

@@ -40,6 +40,7 @@ import javax.ws.rs.container.AsyncResponse
 import javax.ws.rs.container.ConnectionCallback
 import javax.ws.rs.container.Suspended
 import javax.ws.rs.core.MediaType
+import javax.ws.rs.core.Response
 
 @Path("/api/v1")
 @Produces(MediaType.APPLICATION_JSON)
@@ -69,14 +70,23 @@ class InstanceLifecycle(
         // handles unresponsive instances
         ar.setTimeout(timeout, TimeUnit.SECONDS)
         ar.setTimeoutHandler { asyncResponse: AsyncResponse ->
-            log.error("Async create instance request timed out after $timeout seconds")
-            asyncResponse.cancel()
-            instanceService.deleteInstance(instanceId)
+            log.error("Instance $instanceId: Async create instance request timed out after $timeout seconds")
+            asyncResponse.resume(
+                Response
+                    .status(Response.Status.GATEWAY_TIMEOUT)
+                    .entity("Instance $instanceId: Async create instance request timed out after $timeout seconds")
+                    .build()
+            )
+            if (instanceService.getInstance(instanceId) != null) {
+                instanceService.deleteInstance(instanceId)
+            }
         }
         // handles client disconnect
         ar.register(ConnectionCallback { disconnected: AsyncResponse? ->
-            log.error("Client disconnected from async create instance request")
-            instanceService.deleteInstance(instanceId)
+            log.error("Instance $instanceId: Client disconnected from async create instance request")
+            if (instanceService.getInstance(instanceId) != null) {
+                instanceService.deleteInstance(instanceId)
+            }
         })
 
         val createdInstance = try {
@@ -86,7 +96,7 @@ class InstanceLifecycle(
         } catch (we: WebApplicationException) {
             throw we
         } catch (e: Exception) {
-            log.error("Could not create instance: " + e.message, e)
+            log.error("Instance $instanceId: Could not create instance: " + e.message, e)
             throw WebApplicationException("Could not create instance: " + e.message)
         }
 

testservice/src/main/kotlin/com/wire/kalium/testservice/managed/InstanceService.kt

@@ -21,6 +21,7 @@ package com.wire.kalium.testservice.managed
 import com.codahale.metrics.Gauge
 import com.codahale.metrics.MetricRegistry
 import com.wire.kalium.logger.KaliumLogLevel
+import com.wire.kalium.logger.KaliumLogger
 import com.wire.kalium.logic.CoreLogger
 import com.wire.kalium.logic.CoreLogic
 import com.wire.kalium.logic.configuration.server.ServerConfig
@@ -39,6 +40,7 @@ import com.wire.kalium.logic.feature.client.RegisterClientUseCase
 import com.wire.kalium.logic.feature.session.CurrentSessionResult
 import com.wire.kalium.logic.featureFlags.KaliumConfigs
 import com.wire.kalium.logic.functional.onFailure
+import com.wire.kalium.testservice.KaliumLogWriter
 import com.wire.kalium.testservice.TestserviceConfiguration
 import com.wire.kalium.testservice.models.FingerprintResponse
 import com.wire.kalium.testservice.models.Instance
@@ -134,18 +136,18 @@ class InstanceService(
         )
     }
 
-    @Suppress("LongMethod", "ThrowsCount")
-    suspend fun createInstance(instanceId: String, instanceRequest: InstanceRequest): Instance {
+    @Suppress("LongMethod", "ThrowsCount", "ComplexMethod")
+    suspend fun createInstance(instanceId: String, instanceRequest: InstanceRequest): Any {
         val userAgent = "KaliumTestService/${System.getProperty("http.agent")}"
         val before = System.currentTimeMillis()
         val instancePath = System.getProperty("user.home") +
                 File.separator + ".testservice" + File.separator + instanceId
         log.info("Instance $instanceId: Creating $instancePath")
         val kaliumConfigs = KaliumConfigs(
-            developmentApiEnabled = false
+            developmentApiEnabled = instanceRequest.developmentApiEnabled ?: false
         )
         val coreLogic = CoreLogic(instancePath, kaliumConfigs, userAgent)
-        CoreLogger.setLoggingLevel(KaliumLogLevel.VERBOSE)
+        CoreLogger.init(KaliumLogger.Config(KaliumLogLevel.VERBOSE, listOf(KaliumLogWriter(instanceId))))
 
         val serverConfig = if (instanceRequest.customBackend != null) {
             ServerConfig.Links(
@@ -208,10 +210,8 @@ class InstanceService(
             loginResult.authData.userId
         }
 
-        var clientId: String? = null
-
         log.info("Instance $instanceId: Register client device")
-        runBlocking {
+        val response = runBlocking {
             coreLogic.sessionScope(userId) {
                 if (client.needsToRegisterClient()) {
                     when (val result = client.getOrRegister(
@@ -222,33 +222,50 @@ class InstanceService(
                             model = instanceRequest.deviceName
                         )
                     )) {
-                        is RegisterClientResult.Failure ->
-                            throw WebApplicationException("Instance $instanceId: Client registration failed")
-
                         is RegisterClientResult.Success -> {
-                            clientId = result.client.id.value
+                            val clientId = result.client.id.value
                             log.info("Instance $instanceId: Device $clientId successfully registered")
-                            syncManager.waitUntilLive()
+
+                            val startTime = System.currentTimeMillis()
+                            val startupTime = startTime - before
+
+                            val instance = Instance(
+                                instanceRequest.backend,
+                                clientId,
+                                instanceId,
+                                instanceRequest.name,
+                                coreLogic,
+                                instancePath,
+                                instanceRequest.password,
+                                startupTime,
+                                startTime
+                            )
+                            instances.put(instanceId, instance)
+
+                            syncManager.waitUntilLiveOrFailure().onFailure {
+                                log.error("Instance $instanceId: Sync failed with $it")
+                            }
+
+                            return@runBlocking instance
                         }
+                        is RegisterClientResult.Failure.TooManyClients ->
+                            throw WebApplicationException("Instance $instanceId: Client registration failed, too many clients")
+                        is RegisterClientResult.Failure.InvalidCredentials.Invalid2FA ->
+                            throw WebApplicationException("Instance $instanceId: Client registration failed, invalid 2FA code")
+                        is RegisterClientResult.Failure.InvalidCredentials.InvalidPassword ->
+                            throw WebApplicationException("Instance $instanceId: Client registration failed, invalid password")
+                        is RegisterClientResult.Failure.InvalidCredentials.Missing2FA ->
+                            throw WebApplicationException("Instance $instanceId: Client registration failed, 2FA code needed for account")
+                        is RegisterClientResult.Failure.PasswordAuthRequired ->
+                            throw WebApplicationException("Instance $instanceId: Client registration failed, missing password")
+                        is RegisterClientResult.Failure.Generic ->
+                            throw WebApplicationException("Instance $instanceId: Client registration failed")
                     }
                 }
             }
         }
 
-        val instance = Instance(
-            instanceRequest.backend,
-            clientId,
-            instanceId,
-            instanceRequest.name,
-            coreLogic,
-            instancePath,
-            instanceRequest.password,
-            System.currentTimeMillis() - before,
-            System.currentTimeMillis()
-        )
-        instances.put(instanceId, instance)
-
-        return instance
+        return response
     }
 
     fun deleteInstance(id: String) {

testservice/src/main/kotlin/com/wire/kalium/testservice/models/InstanceRequest.kt

@@ -30,4 +30,5 @@ data class InstanceRequest(
     val name: String = "",
     val password: String = "",
     val verificationCode: String? = null,
+    val developmentApiEnabled: Boolean? = false,
 )