Fix and improve event logging

This commit is contained in:
Him188 2021-04-26 23:21:27 +08:00
parent d73f5a2692
commit 35884182af
16 changed files with 164 additions and 138 deletions

View File

@ -145,33 +145,37 @@ public interface CancellableEvent : Event {
*/
@JvmSynthetic
public suspend fun <E : Event> E.broadcast(): E {
check(this is AbstractEvent) {
val event = this
check(event is AbstractEvent) {
"Events must extend AbstractEvent"
}
if (this is BroadcastControllable && !this.shouldBroadcast) {
return this
if (event is BroadcastControllable && !event.shouldBroadcast) {
return event
}
this.broadCastLock.withLock {
this._intercepted = false
event.broadCastLock.withLock {
event._intercepted = false
if (EventDisabled) return@withLock
if (this is Packet.NoEventLog) return@withLock
if (this is Packet.NoLog) return@withLock
if (this is MessageEvent) return@withLock // specially handled in [LoggingPacketHandlerAdapter]
// if (this is Packet) return@withLock // all [Packet]s are logged in [LoggingPacketHandlerAdapter]
if (this is BotEvent) {
this.bot.logger.verbose { "Event: $this" }
} else {
MiraiLogger.TopLevel.verbose { "Event: $this" }
}
callAndRemoveIfRequired(this)
logEvent(event)
callAndRemoveIfRequired(event)
}
return this
}
private fun logEvent(event: Event) {
if (event is Packet.NoEventLog) return
if (event is Packet.NoLog) return
if (event is MessageEvent) return // specially handled in [LoggingPacketHandlerAdapter]
// if (this is Packet) return@withLock // all [Packet]s are logged in [LoggingPacketHandlerAdapter]
if (event is BotEvent) {
event.bot.logger.verbose { "Event: $event" }
} else {
MiraiLogger.TopLevel.verbose { "Event: $event" }
}
}
/**
* Java 广播一个事件的唯一途径.
*

View File

@ -89,8 +89,8 @@ public sealed class BotOfflineEvent : BotEvent, AbstractEvent() {
*/
@MiraiInternalApi
public data class RequireReconnect @MiraiInternalApi public constructor(
public override val bot: Bot
) : BotOfflineEvent(), Packet, BotPassiveEvent {
public override val bot: Bot, override val cause: Throwable?,
) : BotOfflineEvent(), Packet, BotPassiveEvent, CauseAware {
override var reconnect: Boolean = true
}

View File

@ -40,6 +40,7 @@ import net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandlerFactory
import net.mamoe.mirai.internal.network.impl.netty.asCoroutineExceptionHandler
import net.mamoe.mirai.internal.network.protocol.packet.OutgoingPacket
import net.mamoe.mirai.internal.network.protocol.packet.OutgoingPacketWithRespType
import net.mamoe.mirai.internal.utils.subLogger
import net.mamoe.mirai.utils.BotConfiguration
import net.mamoe.mirai.utils.MiraiLogger
import net.mamoe.mirai.utils.systemProp
@ -143,7 +144,7 @@ internal open class QQAndroidBot constructor(
}
},
debugConfiguration.stateObserver
).safe(logger)
).safe(logger.subLogger("StateObserver"))
}
@ -154,25 +155,31 @@ internal open class QQAndroidBot constructor(
set(SsoProcessorContext, SsoProcessorContextImpl(bot))
set(SsoProcessor, SsoProcessorImpl(get(SsoProcessorContext)))
set(HeartbeatProcessor, HeartbeatProcessorImpl())
set(KeyRefreshProcessor, KeyRefreshProcessorImpl(networkLogger))
set(ConfigPushProcessor, ConfigPushProcessorImpl(networkLogger))
set(KeyRefreshProcessor, KeyRefreshProcessorImpl(networkLogger.subLogger("KeyRefreshProcessor")))
set(ConfigPushProcessor, ConfigPushProcessorImpl(networkLogger.subLogger("ConfigPushProcessor")))
set(BotOfflineEventMonitor, BotOfflineEventMonitorImpl())
set(BotInitProcessor, BotInitProcessorImpl(bot, components, bot.logger))
set(BotInitProcessor, BotInitProcessorImpl(bot, components, networkLogger.subLogger("BotInitProcessor")))
set(ContactCacheService, ContactCacheServiceImpl(bot))
set(ContactUpdater, ContactUpdaterImpl(bot, components, networkLogger))
set(BdhSessionSyncer, BdhSessionSyncerImpl(configuration, networkLogger, components))
set(ContactUpdater, ContactUpdaterImpl(bot, components, networkLogger.subLogger("ContactUpdater")))
set(
BdhSessionSyncer,
BdhSessionSyncerImpl(configuration, components, networkLogger.subLogger("BotSessionSyncer"))
)
set(ServerList, ServerListImpl())
set(PacketLoggingStrategy, PacketLoggingStrategyImpl(bot))
set(
PacketHandler, PacketHandlerChain(
LoggingPacketHandlerAdapter(networkLogger, get(PacketLoggingStrategy)),
LoggingPacketHandlerAdapter(get(PacketLoggingStrategy), networkLogger),
EventBroadcasterPacketHandler(networkLogger),
CallPacketFactoryPacketHandler(bot)
)
)
set(PacketCodec, PacketCodecImpl())
set(OtherClientUpdater, OtherClientUpdaterImpl(bot, components, bot.logger))
set(
OtherClientUpdater,
OtherClientUpdaterImpl(bot, components, networkLogger.subLogger("BotSessionSyncer"))
)
set(ConfigPushSyncer, ConfigPushSyncerImpl())
set(StateObserver, stateObserverChain())

View File

@ -46,8 +46,8 @@ internal interface BdhSessionSyncer {
@OptIn(ExperimentalCoroutinesApi::class)
internal class BdhSessionSyncerImpl(
private val configuration: BotConfiguration,
private val logger: MiraiLogger,
private val context: ComponentStorage,
private val logger: MiraiLogger,
) : BdhSessionSyncer {
@Volatile
override var bdhSession: CompletableDeferred<BdhSession> = CompletableDeferred()

View File

@ -13,7 +13,6 @@ import kotlinx.atomicfu.atomic
import kotlinx.coroutines.*
import net.mamoe.mirai.event.nextEvent
import net.mamoe.mirai.internal.QQAndroidBot
import net.mamoe.mirai.internal.network.Packet
import net.mamoe.mirai.internal.network.component.ComponentKey
import net.mamoe.mirai.internal.network.component.ComponentStorage
import net.mamoe.mirai.internal.network.handler.NetworkHandler
@ -21,8 +20,6 @@ import net.mamoe.mirai.internal.network.handler.NetworkHandler.State
import net.mamoe.mirai.internal.network.handler.state.JobAttachStateObserver
import net.mamoe.mirai.internal.network.handler.state.StateObserver
import net.mamoe.mirai.internal.network.protocol.data.proto.MsgSvc
import net.mamoe.mirai.internal.network.protocol.packet.OutgoingPacket
import net.mamoe.mirai.internal.network.protocol.packet.OutgoingPacketWithRespType
import net.mamoe.mirai.internal.network.protocol.packet.chat.receive.MessageSvcPbGetMsg
import net.mamoe.mirai.internal.network.protocol.packet.sendAndExpect
import net.mamoe.mirai.utils.MiraiLogger
@ -64,10 +61,6 @@ internal class BotInitProcessorImpl(
val registerResp =
context[SsoProcessor].registerResp ?: error("Internal error: registerResp is not yet available.")
bot.launch(CoroutineName("Awaiting ConfigPushSvc.PushReq")) {
context[ConfigPushSyncer].awaitSync()
} // TODO: 2021/4/17 should we launch here?
// do them parallel.
supervisorScope {
launch { syncMessageSvc() }
@ -87,13 +80,9 @@ internal class BotInitProcessorImpl(
it.bot == this@BotInitProcessorImpl.bot
}
}
MessageSvcPbGetMsg(bot.client, MsgSvc.SyncFlag.START, null).sendAndExpect()
MessageSvcPbGetMsg(bot.client, MsgSvc.SyncFlag.START, null).sendAndExpect(bot)
} ?: error("timeout syncing friend message history.")
logger.info { "Syncing friend message history: Success." }
}
private suspend inline fun <T : Packet> OutgoingPacket.sendAndExpect() = this.sendAndExpect<T>(bot.network)
private suspend inline fun <T : Packet> OutgoingPacketWithRespType<T>.sendAndExpect() =
this.sendAndExpect(bot.network)
}

View File

@ -9,56 +9,40 @@
package net.mamoe.mirai.internal.network.components
import kotlinx.coroutines.CancellationException
import kotlinx.coroutines.launch
import net.mamoe.mirai.event.broadcast
import net.mamoe.mirai.event.events.BotOfflineEvent
import net.mamoe.mirai.event.nextEventOrNull
import net.mamoe.mirai.internal.network.component.ComponentKey
import net.mamoe.mirai.internal.network.handler.NetworkHandler
import net.mamoe.mirai.internal.network.protocol.packet.login.ConfigPushSvc
import net.mamoe.mirai.utils.MiraiLogger
import net.mamoe.mirai.utils.info
import net.mamoe.mirai.utils.warning
/**
* Job: Switch server if ConfigPush not received.
*/
internal interface ConfigPushProcessor {
@Throws(RequireReconnectException::class)
suspend fun syncConfigPush(network: NetworkHandler)
class RequireReconnectException : Exception("ConfigPushProcessor: server requires reconnection")
companion object : ComponentKey<ConfigPushProcessor>
}
internal class ConfigPushProcessorImpl(
private val logger: MiraiLogger,
) : ConfigPushProcessor {
@Throws(ConfigPushProcessor.RequireReconnectException::class)
override suspend fun syncConfigPush(network: NetworkHandler) {
network.ConfigPushSyncer()
}
@Suppress("FunctionName", "UNUSED_VARIABLE")
private suspend fun NetworkHandler.ConfigPushSyncer() {
logger.info { "Awaiting ConfigPushSvc.PushReq." }
when (val resp: ConfigPushSvc.PushReq.PushReqResponse? = nextEventOrNull(30_000)) {
null -> {
val bdhSyncer = context[BdhSessionSyncer]
val hasSession = bdhSyncer.hasSession
kotlin.runCatching { bdhSyncer.bdhSession.completeExceptionally(CancellationException("Timeout waiting for ConfigPushSvc.PushReq")) }
if (!hasSession) {
logger.warning { "Missing ConfigPushSvc.PushReq. Switching server..." }
// bot.launch { BotOfflineEvent.RequireReconnect(bot).broadcast() }
throw ConfigPushProcessor.RequireReconnectException()
} else {
logger.warning { "Missing ConfigPushSvc.PushReq. Using the latest response. File uploading may be affected." }
if (nextEventOrNull<ConfigPushSvc.PushReq.PushReqResponse>(60_000) == null) {
val bdhSyncer = network.context[BdhSessionSyncer]
if (!bdhSyncer.hasSession) {
val e = IllegalStateException("Timeout waiting for ConfigPush.")
bdhSyncer.bdhSession.completeExceptionally(e)
logger.warning { "Missing ConfigPush. Switching server..." }
network.context.bot.launch {
BotOfflineEvent.RequireReconnect(network.context.bot, e).broadcast()
}
}
is ConfigPushSvc.PushReq.PushReqResponse.ConfigPush -> {
logger.info { "ConfigPushSvc.PushReq: Config updated." }
}
is ConfigPushSvc.PushReq.PushReqResponse.ServerListPush -> {
logger.info { "ConfigPushSvc.PushReq: Server updated." }
// handled in ConfigPushSvc
return
}
}
}
}

View File

@ -33,7 +33,6 @@ import net.mamoe.mirai.internal.contact.toMiraiFriendInfo
import net.mamoe.mirai.internal.network.Packet
import net.mamoe.mirai.internal.network.component.ComponentKey
import net.mamoe.mirai.internal.network.component.ComponentStorage
import net.mamoe.mirai.internal.network.handler.logger
import net.mamoe.mirai.internal.network.isValid
import net.mamoe.mirai.internal.network.protocol.data.jce.StTroopNum
import net.mamoe.mirai.internal.network.protocol.data.jce.SvcRespRegister
@ -160,7 +159,7 @@ internal class ContactUpdaterImpl(
val list = if (friendListCache?.isValid(registerResp) == true) {
val list = friendListCache.list
bot.network.logger.info { "Loaded ${list.size} friends from local cache." }
logger.info { "Loaded ${list.size} friends from local cache." }
// For sync bot nick
FriendList.GetFriendGroupList(
@ -199,7 +198,7 @@ internal class ContactUpdaterImpl(
val members = if (cache != null) {
if (cache.isValid(stTroopNum)) {
cache.list.asSequence().also {
bot.network.logger.info { "Loaded ${cache.list.size} members from local cache for group $groupName (${groupCode})" }
logger.info { "Loaded ${cache.list.size} members from local cache for group $groupName (${groupCode})" }
}
} else refreshGroupMemberList().also { sequence ->
cache.troopMemberNumSeq = dwMemberNumSeq ?: 0

View File

@ -50,8 +50,8 @@ internal data class ExceptionInPacketHandlerException(
) : IllegalStateException("Exception in PacketHandler '$packetHandler'.")
internal class LoggingPacketHandlerAdapter(
private val logger: MiraiLogger,
private val strategy: PacketLoggingStrategy,
private val logger: MiraiLogger,
) : PacketHandler {
override suspend fun handlePacket(incomingPacket: IncomingPacket) {
strategy.logReceived(logger, incomingPacket)

View File

@ -14,6 +14,7 @@ import net.mamoe.mirai.event.events.MessageEvent
import net.mamoe.mirai.internal.AbstractBot
import net.mamoe.mirai.internal.contact.logMessageReceived
import net.mamoe.mirai.internal.contact.replaceMagicCodes
import net.mamoe.mirai.internal.network.MultiPacket
import net.mamoe.mirai.internal.network.Packet
import net.mamoe.mirai.internal.network.ParseErrorPacket
import net.mamoe.mirai.internal.network.component.ComponentKey
@ -43,12 +44,27 @@ internal class PacketLoggingStrategyImpl(
}
override fun logReceived(logger: MiraiLogger, incomingPacket: IncomingPacket) {
incomingPacket.exception?.let {
logger.error(it)
return
}
val packet = incomingPacket.data ?: return
if (!bot.logger.isEnabled && !logger.isEnabled) return
when {
packet is ParseErrorPacket -> {
packet.direction.getLogger(bot).error(packet.error)
if (packet is ParseErrorPacket) {
packet.direction.getLogger(bot).error(packet.error)
}
if (incomingPacket.data is MultiPacket<*>) {
for (d in incomingPacket.data) {
logReceivedImpl(d, incomingPacket, logger)
}
}
if (incomingPacket.commandName !in blacklist) {
logReceivedImpl(packet, incomingPacket, logger)
}
}
private fun logReceivedImpl(packet: Packet, incomingPacket: IncomingPacket, logger: MiraiLogger) {
when {
packet is MessageEvent -> packet.logMessageReceived()
packet is Packet.NoLog -> {
// nothing to do
@ -67,12 +83,16 @@ internal class PacketLoggingStrategyImpl(
}
companion object {
@JvmField
val DEFAULT_BLACKLIST = setOf(
"MessageSvc.PbDeleteMsg",
"MessageSvc.PbGetMsg", // they are too verbose.
"OnlinePush.RespPush"
)
val DEFAULT_BLACKLIST: Set<String>
get() {
if (systemProp("mirai.debug.network.show.verbose.packets", false)) return emptySet()
return setOf(
"MessageSvc.PbDeleteMsg",
"MessageSvc.PbGetMsg", // they are too verbose.
"OnlinePush.RespPush",
"Heartbeat.Alive",
)
}
@JvmField
var SHOW_PACKET_DETAILS = systemProp("mirai.debug.network.show.packet.details", false)

View File

@ -271,11 +271,7 @@ internal open class NettyNetworkHandler(
}
private val configPush = this@NettyNetworkHandler.launch(CoroutineName("ConfigPush sync")) {
try {
context[ConfigPushProcessor].syncConfigPush(this@NettyNetworkHandler)
} catch (e: ConfigPushProcessor.RequireReconnectException) {
setState { StateConnecting(ExceptionCollector(e), false) }
}
context[ConfigPushProcessor].syncConfigPush(this@NettyNetworkHandler)
}
override suspend fun resumeConnection0() {
@ -318,7 +314,6 @@ internal open class NettyNetworkHandler(
try {
action()
heartbeatProcessor.doAliveHeartbeatNow(this@NettyNetworkHandler)
} catch (e: Throwable) {
setState {
StateConnecting(ExceptionCollector(IllegalStateException("Exception in $name job", e)))
@ -327,16 +322,15 @@ internal open class NettyNetworkHandler(
}
}.apply {
invokeOnCompletion { e ->
if (e != null) {
logger.info { "$name failed: $e." }
}
if (e is CancellationException) return@invokeOnCompletion // normally closed
if (e != null) logger.info { "$name failed: $e." }
}
}
}
private val heartbeat = launchHeartbeatJob(
"AliveHeartbeat",
{ context[SsoProcessorContext].configuration.heartbeatTimeoutMillis },
{ context[SsoProcessorContext].configuration.heartbeatPeriodMillis },
{ heartbeatProcessor.doAliveHeartbeatNow(this@NettyNetworkHandler) }
)
@ -360,6 +354,7 @@ internal open class NettyNetworkHandler(
override suspend fun resumeConnection0() {
joinCompleted(coroutineContext.job)
joinCompleted(heartbeat)
joinCompleted(statHeartbeat)
joinCompleted(configPush)
joinCompleted(keyRefresh)
} // noop

View File

@ -34,7 +34,7 @@ internal class RequestPushNotify(
@TarsId(13) @JvmField val svrip: Int?
) : JceStruct, Packet {
override fun toString(): String {
return "RequestPushNotify(uin=$uin, ctype=$ctype, strService=$strService, strCmd=$strCmd, usMsgType=$usMsgType, stMsgInfo=$stMsgInfo)"
return "RequestPushNotify(usMsgType=$usMsgType)"
}
}

View File

@ -25,7 +25,6 @@ import net.mamoe.mirai.contact.MemberPermission
import net.mamoe.mirai.contact.NormalMember
import net.mamoe.mirai.data.MemberInfo
import net.mamoe.mirai.event.AbstractEvent
import net.mamoe.mirai.event.Event
import net.mamoe.mirai.event.broadcast
import net.mamoe.mirai.event.events.*
import net.mamoe.mirai.internal.QQAndroidBot
@ -97,12 +96,9 @@ internal object MessageSvcPbGetMsg : OutgoingPacketFactory<MessageSvcPbGetMsg.Re
)
}
open class GetMsgSuccess(delegate: List<Packet>, syncCookie: ByteArray?, bot: QQAndroidBot) : Response(
MsgSvc.SyncFlag.STOP, delegate,
syncCookie,
bot
), Event,
Packet.NoLog {
open class GetMsgSuccess(delegate: List<Packet>, syncCookie: ByteArray?, bot: QQAndroidBot) :
Response(MsgSvc.SyncFlag.STOP, delegate, syncCookie, bot) {
override fun toString(): String = "MessageSvcPbGetMsg.GetMsgSuccess"
}
@ -117,7 +113,7 @@ internal object MessageSvcPbGetMsg : OutgoingPacketFactory<MessageSvcPbGetMsg.Re
AbstractEvent(),
MultiPacket<Packet>,
Iterable<Packet> by (delegate),
Packet.NoLog,
Packet.NoEventLog,
BotEvent {
override fun toString(): String =

View File

@ -163,7 +163,8 @@ internal class ConfigPushSvc {
bot.logger.info { "Server request to change server." }
bot.launch {
delay(1000)
BotOfflineEvent.RequireReconnect(bot).broadcast()
BotOfflineEvent.RequireReconnect(bot, IllegalStateException("Server request to change server."))
.broadcast()
}
}
}

View File

@ -0,0 +1,63 @@
/*
* Copyright 2019-2021 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/master/LICENSE
*/
package net.mamoe.mirai.internal.utils
import net.mamoe.mirai.utils.*
internal fun MiraiLogger.subLogger(name: String): MiraiLogger {
return SubLogger(name, this)
}
private class SubLogger(
private val name: String,
private val main: MiraiLogger,
) : MiraiLoggerPlatformBase() {
override val identity: String? get() = main.identity
override fun verbose0(message: String?, e: Throwable?) {
if (message != null) {
main.verbose({ "[$name] $message" }, e)
} else {
main.verbose(null, e)
}
}
override fun debug0(message: String?, e: Throwable?) {
if (message != null) {
main.debug({ "[$name] $message" }, e)
} else {
main.debug(null, e)
}
}
override fun info0(message: String?, e: Throwable?) {
if (message != null) {
main.info({ "[$name] $message" }, e)
} else {
main.info(null, e)
}
}
override fun warning0(message: String?, e: Throwable?) {
if (message != null) {
main.warning({ "[$name] $message" }, e)
} else {
main.warning(null, e)
}
}
override fun error0(message: String?, e: Throwable?) {
if (message != null) {
main.error({ "[$name] $message" }, e)
} else {
main.error(null, e)
}
}
}

View File

@ -1,32 +0,0 @@
/*
* Copyright 2019-2021 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/master/LICENSE
*/
package net.mamoe.mirai.internal.utils
import net.mamoe.mirai.Bot
import net.mamoe.mirai.event.Event
import net.mamoe.mirai.event.broadcast
import net.mamoe.mirai.internal.contact.replaceMagicCodes
import net.mamoe.mirai.internal.network.Packet
import net.mamoe.mirai.utils.verbose
@Deprecated("broad", ReplaceWith("this.broadcast()", "net.mamoe.mirai.event.broadcast"))
internal suspend fun <T : Event> T.broadcastWithBot(bot: Bot): T {
this.let log@{ event ->
val logger = bot.logger
if (event is Packet.NoLog) return@log
if (event is Packet.NoEventLog) return@log
if (event is Packet.NoEventLog) {
logger.verbose { "Recv: $event".replaceMagicCodes() }
} else {
logger.verbose { "Event: $event".replaceMagicCodes() }
}
}
return broadcast()
}

View File

@ -113,10 +113,10 @@ internal abstract class AbstractRealNetworkHandlerTest<H : NetworkHandler> : Abs
})
set(ContactCacheService, ContactCacheServiceImpl(bot))
set(ContactUpdater, ContactUpdaterImpl(bot, components, networkLogger))
set(BdhSessionSyncer, BdhSessionSyncerImpl(configuration, networkLogger, components))
set(BdhSessionSyncer, BdhSessionSyncerImpl(configuration, components, networkLogger))
set(ServerList, ServerListImpl())
set(PacketLoggingStrategy, PacketLoggingStrategyImpl(bot))
set(PacketHandler, LoggingPacketHandlerAdapter(networkLogger, get(PacketLoggingStrategy)))
set(PacketHandler, LoggingPacketHandlerAdapter(get(PacketLoggingStrategy), networkLogger))
set(PacketCodec, PacketCodecImpl())
set(OtherClientUpdater, OtherClientUpdaterImpl(bot, components, bot.logger))
set(ConfigPushSyncer, ConfigPushSyncerImpl())