Add trace logging for event listener, with system property mirai.event.trace

docs/DebuggingNetwork.md

@@ -25,6 +25,7 @@
 | `mirai.network.show.verbose.packets`                | `true`/`false`                   | 在日志记录数据包时包含冗长的数据包 (如 `MessageSvc.PbGetMsg`, `OnlinePush.ReqPush`, `StatSvc.SimpleGet`) |
 | `mirai.network.show.packet.details`                 | `true`/`false`                   | 在日志记录数据包时包含 mirai 解析结果                                                                 |
 | `mirai.event.show.verbose.events`                   | `true`/`false`                   | 在日志记录事件时包含冗长的事件 (如 `GroupMessagePreSendEvent`, `GroupMessagePostSendEvent`)            |
+| `mirai.event.trace`                                 | `true`/`false`                   | 在日志记录事件监听器创建及使用的信息                                                                     |
 | `mirai.message.allow.sending.file.message`          | `true`/`false`                   | 允许发送 `FileMessage`, 用于兼容旧代码 ([#1715])                                                  |
 | `mirai.jce.deserializer.debug`                      | `true`/`false`                   | 启用数据包解析错误的详细信息显示                                                                       |
 

mirai-core/src/commonMain/kotlin/event/EventListeners.kt

@@ -15,6 +15,10 @@ import kotlinx.coroutines.supervisorScope
 import kotlinx.coroutines.sync.withLock
 import net.mamoe.mirai.event.*
 import net.mamoe.mirai.internal.network.components.EVENT_LAUNCH_UNDISPATCHED
+import net.mamoe.mirai.utils.MiraiLogger
+import net.mamoe.mirai.utils.info
+import net.mamoe.mirai.utils.systemProp
+import net.mamoe.mirai.utils.withSwitch
 import java.util.*
 import java.util.concurrent.ConcurrentLinkedQueue
 import kotlin.reflect.KClass
@@ -27,6 +31,12 @@ internal class ListenerRegistry(
 
 
 internal class EventListeners {
+    companion object {
+        private val logger by lazy {
+            MiraiLogger.Factory.create(EventListeners::class).withSwitch(systemProp("mirai.event.trace", false))
+        }
+    }
+
     private val map: Map<EventPriority, ConcurrentLinkedQueue<ListenerRegistry>>
 
     init {
@@ -85,6 +95,7 @@ internal class EventListeners {
     }
 
     internal fun <E : Event> addListener(eventClass: KClass<E>, listener: Listener<E>) {
+        logger.info { "Add listener: $listener for $eventClass" }
         val listeners = get(listener.priority)
 
         @Suppress("UNCHECKED_CAST")
@@ -101,6 +112,7 @@ internal class EventListeners {
         listener: Listener<Event>,
         event: E,
     ) {
+        logger.info { "Invoke listener: $listener" }
         when (listener.concurrencyKind) {
             ConcurrencyKind.LOCKED -> {
                 (listener as SafeListener).lock!!.withLock {
@@ -115,5 +127,6 @@ internal class EventListeners {
                 }
             }
         }
+        logger.info { "Finished listener: $listener" }
     }
 }

mirai-core/src/commonMain/kotlin/event/SafeListener.kt

@@ -14,6 +14,7 @@ import kotlinx.coroutines.sync.Mutex
 import net.mamoe.mirai.event.*
 import net.mamoe.mirai.event.events.BotEvent
 import net.mamoe.mirai.utils.MiraiLogger
+import net.mamoe.mirai.utils.systemProp
 import kotlin.coroutines.CoroutineContext
 
 /**
@@ -25,6 +26,7 @@ internal class SafeListener<in E : Event> internal constructor(
     private val listenerBlock: suspend (E) -> ListeningStatus,
     override val concurrencyKind: ConcurrencyKind,
     override val priority: EventPriority,
+    private val creationStacktrace: Exception? = if (traceEnabled) Exception() else null
 ) : Listener<E>, CompletableJob by SupervisorJob(parentJob) { // avoid being cancelled on handling event
 
     private val subscriberContext: CoroutineContext = subscriberContext + this // override Job.
@@ -34,6 +36,19 @@ internal class SafeListener<in E : Event> internal constructor(
         else -> null
     }
 
+    override fun toString(): String {
+        return if (creationStacktrace != null) {
+            "SafeListener(concurrency=${concurrencyKind}" +
+                    ", priority=$priority" +
+                    ", subscriberContext=${subscriberContext.minusKey(Job)}" +
+                    ", trace=${creationStacktrace.stackTraceToString()})"
+        } else {
+            return "SafeListener(concurrency=${concurrencyKind}" +
+                    ", priority=$priority" +
+                    ", subscriberContext=${subscriberContext.minusKey(Job)})" // remove this
+        }
+    }
+
     @Suppress("unused")
     override suspend fun onEvent(event: E): ListeningStatus {
         if (isCompleted || isCancelled) return ListeningStatus.STOPPED
@@ -70,4 +85,6 @@ internal class SafeListener<in E : Event> internal constructor(
             MiraiLogger.Factory.create(SafeListener::class)
         }
     }
-}
+}
+
+private val traceEnabled by lazy { systemProp("mirai.event.trace", true) }

mirai-core/src/commonTest/kotlin/event/AbstractEventTest.kt

@@ -11,4 +11,8 @@ package net.mamoe.mirai.internal.event
 
 import net.mamoe.mirai.internal.test.AbstractTest
 
-internal abstract class AbstractEventTest : AbstractTest()
+internal abstract class AbstractEventTest : AbstractTest() {
+    init {
+        System.setProperty("mirai.event.trace", "true")
+    }
+}