Save journals to file (#1874)

* Save journals to file

* Use kotlin coroutines

* Fix StackOverflowError

* Auto split log files && test units

* Implement ConsoleTerminalSettings.noLogging

* Improve logging

* High-Speed logging test

mirai-console/backend/integration-test/test/MiraiConsoleIntegrationTestBootstrap.kt

@@ -12,6 +12,7 @@ package net.mamoe.console.integrationtest
 import net.mamoe.console.integrationtest.testpoints.DoNothingPoint
 import net.mamoe.console.integrationtest.testpoints.MCITBSelfAssertions
 import net.mamoe.console.integrationtest.testpoints.plugin.PluginDataRenameToIdTest
+import net.mamoe.console.integrationtest.testpoints.terminal.TestTerminalLogging
 import org.junit.jupiter.api.Test
 import java.io.File
 import java.lang.management.ManagementFactory
@@ -34,6 +35,7 @@ class MiraiConsoleIntegrationTestBootstrap {
             DoNothingPoint,
             MCITBSelfAssertions,
             PluginDataRenameToIdTest,
+            TestTerminalLogging,
         ).asSequence().map { v ->
             when (v) {
                 is Class<*> -> v

mirai-console/backend/integration-test/test/testpoints/terminal/TestTerminalLogging.kt

@@ -0,0 +1,86 @@
+/*
+ * Copyright 2019-2022 Mamoe Technologies and contributors.
+ *
+ * 此源代码的使用受 GNU AFFERO GENERAL PUBLIC LICENSE version 3 许可证的约束, 可以在以下链接找到该许可证.
+ * Use of this source code is governed by the GNU AGPLv3 license that can be found through the following link.
+ *
+ * https://github.com/mamoe/mirai/blob/dev/LICENSE
+ */
+
+@file:Suppress("INVISIBLE_MEMBER", "INVISIBLE_REFERENCE")
+
+package net.mamoe.console.integrationtest.testpoints.terminal
+
+import net.mamoe.console.integrationtest.AbstractTestPoint
+import net.mamoe.mirai.console.MiraiConsole
+import net.mamoe.mirai.console.MiraiConsoleImplementation
+import net.mamoe.mirai.console.terminal.LoggingServiceI
+import net.mamoe.mirai.console.terminal.MiraiConsoleImplementationTerminal
+import net.mamoe.mirai.utils.cast
+import net.mamoe.mirai.utils.info
+import java.io.File
+import java.util.*
+import kotlin.math.min
+import kotlin.test.assertTrue
+import kotlin.test.fail
+
+internal object TestTerminalLogging : AbstractTestPoint() {
+    override fun beforeConsoleStartup() {
+        System.setProperty("mirai.console.terminal.log.buffer", "10")
+    }
+
+    override fun onConsoleStartSuccessfully() {
+        val logService = MiraiConsoleImplementation.getInstance()
+            .cast<MiraiConsoleImplementationTerminal>()
+            .logService.cast<LoggingServiceI>()
+
+        logService.autoSplitTask.cancel(true)
+        File("logs/log-0.log").delete()
+
+        val stub = "Terminal Test: STUB" + UUID.randomUUID()
+        MiraiConsole.mainLogger.info { stub }
+        Thread.sleep(200L)
+
+        assertTrue { File("logs/latest.log").isFile }
+        assertTrue { File("logs/latest.log").readText().contains(stub) }
+
+        logService.switchLogFileNow.invoke()
+
+        assertTrue { File("logs/latest.log").isFile }
+        assertTrue { !File("logs/latest.log").readText().contains(stub) }
+        assertTrue { File("logs/log-0.log").isFile }
+        assertTrue { File("logs/log-0.log").readText().contains(stub) }
+
+        MiraiConsole.mainLogger.info("Pipeline size: " + logService.pipelineSize)
+
+        val logs = mutableListOf<String>()
+        logs.add("1================================================================")
+        repeat(100) { logs.add("TEST LINE $it -") }
+        logs.add("2================================================================")
+
+        logs.forEach { MiraiConsole.mainLogger.info(it) }
+
+        Thread.sleep(200L)
+
+        val lns = File("logs/latest.log").readLines().mapNotNull { line ->
+            logs.forEach { lx ->
+                if (line.contains(lx)) {
+                    return@mapNotNull lx
+                }
+            }
+            return@mapNotNull null
+        }
+
+        logService.switchLogFileNow.invoke()
+        // lns.forEach { println(it) }
+        var matched = 0
+        for (i in 0 until min(lns.size, logs.size)) {
+            if (lns[i] == logs[i]) matched++
+        }
+        println("Matched line: $matched, logs: ${logs.size}")
+        if (matched < (logs.size * 80 / 100)) {
+            lns.forEach { System.err.println(it) }
+            fail()
+        }
+    }
+}

mirai-console/frontend/mirai-console-terminal/src/ConsoleTerminalSettings.kt

@@ -48,4 +48,7 @@ object ConsoleTerminalSettings {
 
     @JvmField
     var noConsoleReadingReplacement: String = ""
+
+    @JvmField
+    var noLogging = false
 }

mirai-console/frontend/mirai-console-terminal/src/LoggingService.kt

@@ -0,0 +1,151 @@
+/*
+ * Copyright 2019-2022 Mamoe Technologies and contributors.
+ *
+ * 此源代码的使用受 GNU AFFERO GENERAL PUBLIC LICENSE version 3 许可证的约束, 可以在以下链接找到该许可证.
+ * Use of this source code is governed by the GNU AGPLv3 license that can be found through the following link.
+ *
+ * https://github.com/mamoe/mirai/blob/dev/LICENSE
+ */
+
+package net.mamoe.mirai.console.terminal
+
+import kotlinx.coroutines.*
+import kotlinx.coroutines.channels.Channel
+import kotlinx.coroutines.channels.onFailure
+import net.mamoe.mirai.utils.TestOnly
+import net.mamoe.mirai.utils.systemProp
+import java.io.File
+import java.io.RandomAccessFile
+import java.nio.file.Files
+import java.time.Instant
+import java.time.ZoneId
+import java.time.temporal.ChronoUnit
+import java.util.concurrent.Executors
+import java.util.concurrent.Future
+import java.util.concurrent.ThreadFactory
+import java.util.concurrent.TimeUnit
+import java.util.concurrent.atomic.AtomicInteger
+import java.util.concurrent.atomic.AtomicReference
+
+internal sealed class LoggingService {
+    @TestOnly
+    internal lateinit var switchLogFileNow: () -> Unit
+
+    internal abstract fun pushLine(line: String)
+}
+
+internal class LoggingServiceNoop : LoggingService() {
+    override fun pushLine(line: String) {
+    }
+
+    init {
+        @OptIn(TestOnly::class)
+        switchLogFileNow = {}
+    }
+}
+
+@OptIn(ConsoleTerminalExperimentalApi::class)
+internal class LoggingServiceI(
+    private val scope: CoroutineScope,
+) : LoggingService() {
+
+    private val threadPool = Executors.newScheduledThreadPool(3, object : ThreadFactory {
+        private val group = ThreadGroup("mirai console terminal logging")
+        private val counter = AtomicInteger(0)
+        override fun newThread(r: Runnable): Thread {
+            return Thread(
+                group,
+                r,
+                "Mirai Console Terminal Logging Thread#" + counter.getAndIncrement()
+            ).also { thread ->
+                thread.isDaemon = true
+            }
+        }
+    })
+    private val threadDispatcher = threadPool.asCoroutineDispatcher()
+    internal val pipelineSize = systemProp("mirai.console.terminal.log.buffer", 2048).toInt()
+    private val pipeline = Channel<String>(capacity = pipelineSize)
+    internal lateinit var autoSplitTask: Future<*>
+
+    @Suppress("BlockingMethodInNonBlockingContext")
+    fun startup(logDir: File) {
+        logDir.mkdirs()
+
+        val outputLock = Any()
+        val output = AtomicReference<RandomAccessFile>()
+
+        fun switchLogFile() {
+            val latestLogFile = logDir.resolve("latest.log")
+            var targetFile: File
+            if (latestLogFile.isFile) {
+                var counter = 0
+                do {
+                    targetFile = logDir.resolve("log-$counter.log")
+                    counter++
+                } while (targetFile.exists())
+
+            } else {
+                targetFile = latestLogFile
+            }
+
+            synchronized(outputLock) {
+                output.get()?.close()
+                if (latestLogFile !== targetFile) {
+                    Files.move(latestLogFile.toPath(), targetFile.toPath())
+                }
+                output.set(RandomAccessFile(latestLogFile, "rw").also { it.seek(it.length()) })
+            }
+        }
+        switchLogFile()
+
+        @OptIn(TestOnly::class)
+        switchLogFileNow = ::switchLogFile
+
+        scope.launch(threadDispatcher) {
+            while (isActive) {
+                val nextLine = pipeline.receive()
+                synchronized(outputLock) {
+                    output.get().let { out ->
+                        out.write(nextLine.toByteArray())
+                        out.write('\n'.code)
+                    }
+                }
+            }
+        }
+
+        // Daily split log files
+        val nextDayTimeSec = Instant.now()
+            .atZone(ZoneId.systemDefault())
+            .plus(1, ChronoUnit.DAYS)
+            .withHour(0)
+            .withMinute(0)
+            .withSecond(0)
+            .toEpochSecond()
+
+        autoSplitTask = threadPool.scheduleAtFixedRate(
+            ::switchLogFile,
+            nextDayTimeSec * 1000 - System.currentTimeMillis(),
+            TimeUnit.DAYS.toMillis(1), TimeUnit.MILLISECONDS
+        )
+
+        scope.coroutineContext.job.invokeOnCompletion {
+            threadPool.shutdown()
+            synchronized(outputLock) {
+                output.get()?.close()
+            }
+        }
+    }
+
+    private fun pushInPool(line: String) {
+        scope.launch(threadDispatcher, start = CoroutineStart.UNDISPATCHED) {
+            pipeline.send(line)
+        }
+    }
+
+    override fun pushLine(line: String) {
+        pipeline.trySend(line).onFailure {
+            pushInPool(line)
+        }
+    }
+
+}

mirai-console/frontend/mirai-console-terminal/src/MiraiConsoleImplementationTerminal.kt

@@ -86,23 +86,42 @@ open class MiraiConsoleImplementationTerminal
             configStorageForBuiltIns
         )
     }
+    // used in test
+    internal val logService: LoggingService
 
     override fun createLoginSolver(requesterBot: Long, configuration: BotConfiguration): LoginSolver {
         LoginSolver.Default?.takeIf { it !is StandardCharImageLoginSolver }?.let { return it }
         return StandardCharImageLoginSolver(input = { requestInput("LOGIN> ") })
     }
 
-    override fun createLogger(identity: String?): MiraiLogger = LoggerCreator(identity)
+    override fun createLogger(identity: String?): MiraiLogger {
+        return PlatformLogger(identity = identity, output = { line ->
+            val text = line + ANSI_RESET
+            lineReader.printAbove(text)
+            logService.pushLine(text)
+        })
+    }
 
     init {
         with(rootPath.toFile()) {
             mkdir()
             require(isDirectory) { "rootDir $absolutePath is not a directory" }
+            logService = if (ConsoleTerminalSettings.noLogging) {
+                LoggingServiceNoop()
+            } else {
+                LoggingServiceI(childScope("Log Service")).also { service ->
+                    service.startup(resolve("logs"))
+                }
+            }
         }
     }
 
     override val consoleLaunchOptions: MiraiConsoleImplementation.ConsoleLaunchOptions
         get() = ConsoleTerminalSettings.launchOptions
+
+    override fun preStart() {
+        overrideSTD(this)
+    }
 }
 
 val lineReader: LineReader by lazy {
@@ -163,9 +182,3 @@ private object ConsoleFrontEndDescImpl : MiraiConsoleFrontEndDescription {
 }
 
 internal val ANSI_RESET = Ansi().reset().toString()
-
-internal val LoggerCreator: (identity: String?) -> MiraiLogger = {
-    PlatformLogger(identity = it, output = { line ->
-        lineReader.printAbove(line + ANSI_RESET)
-    })
-}

mirai-console/frontend/mirai-console-terminal/src/MiraiConsoleTerminalLoader.kt

@@ -30,7 +30,6 @@ import net.mamoe.mirai.console.terminal.noconsole.SystemOutputPrintStream
 import net.mamoe.mirai.console.util.ConsoleExperimentalApi
 import net.mamoe.mirai.console.util.ConsoleInternalApi
 import net.mamoe.mirai.message.data.Message
-import net.mamoe.mirai.utils.MiraiLogger
 import net.mamoe.mirai.utils.childScope
 import java.io.FileDescriptor
 import java.io.FileOutputStream
@@ -154,7 +153,6 @@ object MiraiConsoleTerminalLoader {
     @ConsoleExperimentalApi
     fun startAsDaemon(instance: MiraiConsoleImplementationTerminal = MiraiConsoleImplementationTerminal()) {
         instance.start()
-        overrideSTD()
         startupConsoleThread()
     }
 }
@@ -169,12 +167,14 @@ internal object ConsoleDataHolder : AutoSavePluginDataHolder,
         get() = "Terminal"
 }
 
-internal fun overrideSTD() {
+internal fun overrideSTD(terminal: MiraiConsoleImplementation) {
+    if (ConsoleTerminalSettings.noConsole) {
+        SystemOutputPrintStream // Avoid StackOverflowError when launch with no console mode
+    }
     System.setOut(
         PrintStream(
             BufferedOutputStream(
-                logger = MiraiLogger.Factory.create(MiraiConsoleTerminalLoader::class, "stdout")
-                    .run { ({ line: String? -> info(line) }) }
+                logger = terminal.createLogger("stdout")::info
             ),
             false,
             "UTF-8"
@@ -183,8 +183,7 @@ internal fun overrideSTD() {
     System.setErr(
         PrintStream(
             BufferedOutputStream(
-                logger = MiraiLogger.Factory.create(MiraiConsoleTerminalLoader::class, "stderr")
-                    .run { ({ line: String? -> warning(line) }) }
+                logger = terminal.createLogger("stderr")::warning
             ),
             false,
             "UTF-8"