Automatically produce detailed logs when failed to decode JceStructs, if 'mirai.jce.deserializer.debug' is set to true, helps #1899

This commit is contained in:
Him188 2022-03-16 15:28:15 +00:00
parent 366ea34fde
commit ceb192937f
5 changed files with 215 additions and 78 deletions

View File

@ -1,5 +1,5 @@
/*
* Copyright 2019-2021 Mamoe Technologies and contributors.
* 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.
@ -17,6 +17,7 @@ import kotlinx.io.core.*
import kotlinx.serialization.*
import kotlinx.serialization.modules.EmptySerializersModule
import kotlinx.serialization.modules.SerializersModule
import net.mamoe.mirai.internal.utils.io.serialization.tars.internal.DebugLogger
import net.mamoe.mirai.internal.utils.io.serialization.tars.internal.TarsDecoder
import net.mamoe.mirai.internal.utils.io.serialization.tars.internal.TarsInput
import net.mamoe.mirai.internal.utils.io.serialization.tars.internal.TarsOld
@ -38,8 +39,9 @@ internal class Tars(
}
}
fun <T> load(deserializer: DeserializationStrategy<T>, input: Input): T {
return TarsDecoder(TarsInput(input, charset), serializersModule).decodeSerializableValue(deserializer)
fun <T> load(deserializer: DeserializationStrategy<T>, input: Input, debugLogger: DebugLogger? = null): T {
val l = debugLogger ?: DebugLogger(null)
return TarsDecoder(TarsInput(input, charset, l), serializersModule, l).decodeSerializableValue(deserializer)
}
override fun <T> encodeToByteArray(serializer: SerializationStrategy<T>, value: T): ByteArray {
@ -48,7 +50,7 @@ internal class Tars(
override fun <T> decodeFromByteArray(deserializer: DeserializationStrategy<T>, bytes: ByteArray): T {
bytes.read {
return load(deserializer, this)
return load(deserializer, this, null)
}
}

View File

@ -1,10 +1,10 @@
/*
* Copyright 2019-2021 Mamoe Technologies and contributors.
* 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.
* 此源代码的使用受 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
* https://github.com/mamoe/mirai/blob/dev/LICENSE
*/
@file:Suppress("PrivatePropertyName")
@ -20,18 +20,37 @@ import kotlinx.serialization.internal.TaggedDecoder
import kotlinx.serialization.modules.SerializersModule
import net.mamoe.mirai.internal.utils.io.serialization.tars.Tars
import net.mamoe.mirai.internal.utils.io.serialization.tars.TarsId
import net.mamoe.mirai.utils.MiraiLogger
import java.io.PrintStream
internal class DebugLogger(
val out: PrintStream?
) {
var structureHierarchy: Int = 0
fun println(message: Any?) {
out?.println(" ".repeat(structureHierarchy) + message)
}
fun println() {
out?.println()
}
inline fun println(lazyMessage: () -> String) {
out?.println(" ".repeat(structureHierarchy) + lazyMessage())
}
}
@OptIn(InternalSerializationApi::class, ExperimentalSerializationApi::class)
internal class TarsDecoder(
val input: TarsInput, override val serializersModule: SerializersModule,
val input: TarsInput, override val serializersModule: SerializersModule, val debugLogger: DebugLogger
) : TaggedDecoder<TarsTag>() {
override fun SerialDescriptor.getTag(index: Int): TarsTag {
val annotations = this.getElementAnnotations(index)
val id = annotations.filterIsInstance<TarsId>().single().id
// ?: error("cannot find @TarsId or @ProtoNumber for ${this.getElementName(index)} in ${this.serialName}")
//println("getTag: ${this.getElementName(index)}=$id")
//debugLogger.println("getTag: ${this.getElementName(index)}=$id")
return TarsTagCommon(id)
}
@ -79,7 +98,7 @@ internal class TarsDecoder(
override fun decodeCollectionSize(descriptor: SerialDescriptor): Int {
// 不要读下一个 head
return input.currentHead.let { input.readTarsIntValue(it) }.also {
println { "SimpleByteArrayReader.decodeCollectionSize: $it" }
debugLogger.println { "SimpleByteArrayReader.decodeCollectionSize: $it" }
}
}
}
@ -114,7 +133,7 @@ internal class TarsDecoder(
override fun decodeString(): String = input.useHead { input.readTarsStringValue(it) }
override fun decodeCollectionSize(descriptor: SerialDescriptor): Int {
//println("decodeCollectionSize: ${descriptor.serialName}")
//debugLogger.println("decodeCollectionSize: ${descriptor.serialName}")
// 不读下一个 head
return input.useHead { input.readTarsIntValue(it) }
}
@ -131,19 +150,19 @@ internal class TarsDecoder(
override fun decodeElementIndex(descriptor: SerialDescriptor): Int = error("stub")
override fun endStructure(descriptor: SerialDescriptor) {
println { "MapReader.endStructure: ${input.currentHeadOrNull}" }
debugLogger.println { "MapReader.endStructure: ${input.currentHeadOrNull}" }
this@TarsDecoder.endStructure(descriptor)
}
override fun beginStructure(descriptor: SerialDescriptor): CompositeDecoder {
println { "MapReader.beginStructure: ${input.currentHead}" }
debugLogger.println { "MapReader.beginStructure: ${input.currentHead}" }
this@TarsDecoder.pushTag(
when (input.currentHead.tag) {
0 -> TarsTagMapEntryKey()
1 -> TarsTagMapEntryValue()
else -> error("illegal map entry head: ${input.currentHead.tag}")
}.also {
println("MapReader.pushTag $it")
debugLogger.println("MapReader.pushTag $it")
}
)
return this@TarsDecoder.beginStructure(descriptor)
@ -161,16 +180,16 @@ internal class TarsDecoder(
override fun decodeEnum(enumDescriptor: SerialDescriptor): Int = decodeInt()
override fun decodeString(): String = input.useHead { head ->
input.readTarsStringValue(head).also {
println { "MapReader.decodeString: $it" }
debugLogger.println { "MapReader.decodeString: $it" }
}
}
override fun decodeCollectionSize(descriptor: SerialDescriptor): Int {
println { "decodeCollectionSize in MapReader: ${descriptor.serialName}" }
debugLogger.println { "decodeCollectionSize in MapReader: ${descriptor.serialName}" }
// 不读下一个 head
return input.useHead { head ->
input.readTarsIntValue(head).also {
println { "decodeCollectionSize = $it" }
debugLogger.println { "decodeCollectionSize = $it" }
}
}
}
@ -178,10 +197,10 @@ internal class TarsDecoder(
override fun endStructure(descriptor: SerialDescriptor) {
structureHierarchy--
println { "endStructure: ${descriptor.serialName}, $currentTagOrNull, ${input.currentHeadOrNull}" }
debugLogger.structureHierarchy--
debugLogger.println { "endStructure: ${descriptor.serialName}, $currentTagOrNull, ${input.currentHeadOrNull}" }
if (currentTagOrNull?.isSimpleByteArray == true) {
println { "endStructure: prepareNextHead() called" }
debugLogger.println { "endStructure: prepareNextHead() called" }
currentTag.isSimpleByteArray = false
input.prepareNextHead() // read to next head
}
@ -193,10 +212,10 @@ internal class TarsDecoder(
val currentHead = input.currentHeadOrNull ?: return
if (currentHead.type == Tars.STRUCT_END) {
input.prepareNextHead()
//println("current end")
//debugLogger.println("current end")
break
}
//println("current $currentHead")
//debugLogger.println("current $currentHead")
input.skipField(currentHead.type)
input.prepareNextHead()
}
@ -208,48 +227,32 @@ internal class TarsDecoder(
companion object {
@Suppress("MemberVisibilityCanBePrivate")
var debuggingMode: Boolean = false
var structureHierarchy: Int = 0
inline fun println(value: () -> String) {
if (debuggingMode) {
kotlin.io.println(" ".repeat(structureHierarchy) + value())
}
}
@Suppress("NOTHING_TO_INLINE")
inline fun println(value: Any? = "") {
if (debuggingMode) {
kotlin.io.println(" ".repeat(structureHierarchy) + value)
}
}
val logger = MiraiLogger.Factory.create(TarsDecoder::class, "TarsDecoder")
}
override fun beginStructure(descriptor: SerialDescriptor): CompositeDecoder {
println()
println { "beginStructure: ${descriptor.serialName}, ${descriptor.kind}" }
structureHierarchy++
debugLogger.println()
debugLogger.println { "beginStructure: ${descriptor.serialName}, ${descriptor.kind}" }
debugLogger.structureHierarchy++
return when (descriptor.kind) {
is PrimitiveKind -> this@TarsDecoder
StructureKind.MAP -> {
val tag = popTag()
// println("!! MAP, tag=$tag")
// debugLogger.println("!! MAP, tag=$tag")
return input.skipToHeadAndUseIfPossibleOrFail(tag.id) {
it.checkType(Tars.MAP, "beginStructure", tag, descriptor)
MapReader
}
}
StructureKind.LIST -> {
//println("!! ByteArray")
//println("decoderTag: $currentTagOrNull")
//println("TarsHead: " + Tars.currentHeadOrNull)
//debugLogger.println("!! ByteArray")
//debugLogger.println("decoderTag: $currentTagOrNull")
//debugLogger.println("TarsHead: " + Tars.currentHeadOrNull)
return input.skipToHeadAndUseIfPossibleOrFail(currentTag.id) {
// don't check type. it's polymorphic
//println("listHead: $it")
//debugLogger.println("listHead: $it")
when (it.type) {
Tars.SIMPLE_LIST -> {
currentTag.isSimpleByteArray = true
@ -264,9 +267,9 @@ internal class TarsDecoder(
StructureKind.CLASS -> {
currentTagOrNull ?: return this@TarsDecoder // outermost
//println("!! CLASS")
//println("decoderTag: $currentTag")
//println("TarsHead: " + Tars.currentHeadOrNull)
//debugLogger.println("!! CLASS")
//debugLogger.println("decoderTag: $currentTag")
//debugLogger.println("TarsHead: " + Tars.currentHeadOrNull)
val tag = popTag()
return input.skipToHeadAndUseIfPossibleOrFail(tag.id) { TarsHead ->
TarsHead.checkType(Tars.STRUCT_BEGIN, "beginStructure", tag, descriptor)
@ -288,21 +291,21 @@ internal class TarsDecoder(
override fun decodeSequentially(): Boolean = false
override fun decodeElementIndex(descriptor: SerialDescriptor): Int {
var tarsHead = input.currentHeadOrNull ?: kotlin.run {
println("decodeElementIndex: currentHead == null")
debugLogger.println("decodeElementIndex: currentHead == null")
return CompositeDecoder.DECODE_DONE
}
println { "decodeElementIndex: ${input.currentHead}" }
debugLogger.println { "decodeElementIndex: ${input.currentHead}" }
while (!input.input.endOfInput) {
if (tarsHead.type == Tars.STRUCT_END) {
println { "decodeElementIndex: ${input.currentHead}" }
debugLogger.println { "decodeElementIndex: ${input.currentHead}" }
return CompositeDecoder.DECODE_DONE
}
repeat(descriptor.elementsCount) {
val tag = descriptor.getTarsTagId(it)
if (tag == tarsHead.tag) {
println {
debugLogger.println {
"name=" + descriptor.getElementName(
it
)
@ -313,11 +316,11 @@ internal class TarsDecoder(
input.skipField(tarsHead.type)
if (!input.prepareNextHead()) {
println { "decodeElementIndex EOF" }
debugLogger.println { "decodeElementIndex EOF" }
break
}
tarsHead = input.currentHead
println { "next! $tarsHead" }
debugLogger.println { "next! $tarsHead" }
}
return CompositeDecoder.DECODE_DONE // optional support

View File

@ -1,5 +1,5 @@
/*
* Copyright 2019-2021 Mamoe Technologies and contributors.
* 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.
@ -12,14 +12,13 @@ package net.mamoe.mirai.internal.utils.io.serialization.tars.internal
import kotlinx.io.charsets.Charset
import kotlinx.io.core.*
import net.mamoe.mirai.internal.utils.io.serialization.tars.Tars
import net.mamoe.mirai.internal.utils.io.serialization.tars.internal.TarsDecoder.Companion.println
/**
* Tars Input. 需要手动管理 head.
*/
internal class TarsInput(
val input: Input, private val charset: Charset,
val input: Input, private val charset: Charset, private val debugLogger: DebugLogger,
) {
private var _head: TarsHead? = null
private var _nextHead: TarsHead? = null
@ -114,7 +113,7 @@ internal class TarsInput(
crossinline message: () -> String = { "tag not found: $tag" },
crossinline block: (TarsHead) -> R,
): R {
return checkNotNull<R>(skipToHeadAndUseIfPossibleOrNull(tag, block), message)
return checkNotNull(skipToHeadAndUseIfPossibleOrNull(tag, block), message)
}
@Suppress("MemberVisibilityCanBePrivate")
@ -170,30 +169,30 @@ internal class TarsInput(
Tars.STRING1 -> this.input.discardExact(this.input.readUByte().toInt())
Tars.STRING4 -> this.input.discardExact(this.input.readInt())
Tars.MAP -> { // map
TarsDecoder.structureHierarchy++
debugLogger.structureHierarchy++
repeat(readInt32(0).also {
println("SIZE = $it")
} * 2) {
skipField(nextHead().type)
}
TarsDecoder.structureHierarchy--
debugLogger.structureHierarchy--
}
Tars.LIST -> { // list
TarsDecoder.structureHierarchy++
debugLogger.structureHierarchy++
repeat(readInt32(0).also {
println("SIZE = $it")
}) {
skipField(nextHead().type)
}
TarsDecoder.structureHierarchy--
debugLogger.structureHierarchy--
}
Tars.STRUCT_BEGIN -> {
TarsDecoder.structureHierarchy++
debugLogger.structureHierarchy++
var head: TarsHead
do {
head = nextHead()
if (head.type == Tars.STRUCT_END) {
TarsDecoder.structureHierarchy--
debugLogger.structureHierarchy--
skipField(head.type)
break
}
@ -203,7 +202,7 @@ internal class TarsInput(
Tars.STRUCT_END, Tars.ZERO_TYPE -> {
}
Tars.SIMPLE_LIST -> {
TarsDecoder.structureHierarchy++
debugLogger.structureHierarchy++
var head = nextHead()
check(head.type == Tars.BYTE) { "bad simple list element type: " + head.type + ", $head" }
check(head.tag == 0) { "simple list element tag must be 0, but was ${head.tag}" }
@ -211,7 +210,7 @@ internal class TarsInput(
head = nextHead()
check(head.tag == 0) { "tag for size for simple list must be 0, but was ${head.tag}" }
this.input.discardExact(readTarsIntValue(head))
TarsDecoder.structureHierarchy--
debugLogger.structureHierarchy--
}
else -> error("invalid type: $type")
}

View File

@ -1,10 +1,10 @@
/*
* Copyright 2019-2021 Mamoe Technologies and contributors.
* 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.
* 此源代码的使用受 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
* https://github.com/mamoe/mirai/blob/dev/LICENSE
*/
@file:JvmName("SerializationUtils")
@ -14,9 +14,11 @@
package net.mamoe.mirai.internal.utils.io.serialization
import kotlinx.io.core.*
import kotlinx.io.streams.asInput
import kotlinx.serialization.DeserializationStrategy
import kotlinx.serialization.SerializationStrategy
import kotlinx.serialization.descriptors.SerialDescriptor
import net.mamoe.mirai.internal.message.contextualBugReportException
import net.mamoe.mirai.internal.network.protocol.data.jce.RequestDataVersion2
import net.mamoe.mirai.internal.network.protocol.data.jce.RequestDataVersion3
import net.mamoe.mirai.internal.network.protocol.data.jce.RequestPacket
@ -24,9 +26,12 @@ import net.mamoe.mirai.internal.network.protocol.data.proto.OidbSso
import net.mamoe.mirai.internal.utils.io.JceStruct
import net.mamoe.mirai.internal.utils.io.ProtoBuf
import net.mamoe.mirai.internal.utils.io.serialization.tars.Tars
import net.mamoe.mirai.internal.utils.io.serialization.tars.internal.DebugLogger
import net.mamoe.mirai.internal.utils.io.serialization.tars.internal.TarsDecoder
import net.mamoe.mirai.internal.utils.printStructure
import net.mamoe.mirai.utils.read
import net.mamoe.mirai.utils.readPacketExact
import net.mamoe.mirai.utils.*
import java.io.ByteArrayOutputStream
import java.io.PrintStream
import kotlin.contracts.InvocationKind
import kotlin.contracts.contract
@ -39,7 +44,7 @@ internal fun <T : JceStruct> ByteArray.loadWithUniPacket(
internal fun <T : JceStruct> ByteArray.loadAs(
deserializer: DeserializationStrategy<T>,
): T = this.read { Tars.UTF_8.load(deserializer, this) }
): T = this.read { readJceStruct(deserializer) }
internal fun <T : JceStruct> BytePacketBuilder.writeJceStruct(
serializer: SerializationStrategy<T>,
@ -52,11 +57,58 @@ internal fun <T : JceStruct> ByteReadPacket.readJceStruct(
serializer: DeserializationStrategy<T>,
length: Int = this.remaining.toInt(),
): T {
this.readPacketExact(length).use {
return Tars.UTF_8.load(serializer, it)
if (JCE_DESERIALIZER_DEBUG) {
// since 2.11
this.useBytes(n = length) { data, arrayLength ->
try {
return data.inputStream(offset = 0, length = arrayLength).asInput().use { input ->
Tars.UTF_8.load(serializer, input)
}
} catch (originalException: Exception) {
val log = ByteArrayOutputStream()
try {
val value = PrintStream(log).use { stream ->
stream.println("\nData: ")
stream.println(data.toUHexString(length = arrayLength))
stream.println("Trace:")
data.inputStream(offset = 0, length = arrayLength).asInput().use { input ->
Tars.UTF_8.load(serializer, input, debugLogger = DebugLogger(stream))
}
}
return value.also {
TarsDecoder.logger.warning(
contextualBugReportException(
"解析 " + serializer.descriptor.serialName,
"启用 debug 模式后解析正常: $value \n\n${log.toByteArray().decodeToString()}",
originalException
)
)
}
} catch (secondFailure: Exception) {
throw contextualBugReportException(
"解析 " + serializer.descriptor.serialName,
log.toByteArray().decodeToString(),
ExceptionCollector.compressExceptions(originalException, secondFailure)
)
}
}
}
} else {
// since 2.0
return this.readPacketExact(length).use {
Tars.UTF_8.load(serializer, it)
}
}
}
/**
* @since 2.11
*/
internal var JCE_DESERIALIZER_DEBUG by lateinitMutableProperty {
systemProp("mirai.jce.deserializer.debug", false)
}
internal fun <T : JceStruct> BytePacketBuilder.writeJceRequestPacket(
version: Int = 3,
servantName: String,

View File

@ -0,0 +1,81 @@
/*
* 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.internal.utils.io.serialization.tars.internal
import kotlinx.serialization.Serializable
import net.mamoe.mirai.internal.test.AbstractTest
import net.mamoe.mirai.internal.utils.io.JceStruct
import net.mamoe.mirai.internal.utils.io.serialization.JCE_DESERIALIZER_DEBUG
import net.mamoe.mirai.internal.utils.io.serialization.readJceStruct
import net.mamoe.mirai.internal.utils.io.serialization.tars.Tars
import net.mamoe.mirai.internal.utils.io.serialization.tars.TarsId
import net.mamoe.mirai.internal.utils.io.serialization.toByteArray
import net.mamoe.mirai.utils.toReadPacket
import net.mamoe.mirai.utils.toUHexString
import org.junit.jupiter.api.Test
import java.io.ByteArrayOutputStream
import java.io.PrintStream
import kotlin.test.assertEquals
import kotlin.test.assertFails
class DebugLoggerTest : AbstractTest() {
init {
JCE_DESERIALIZER_DEBUG = true
}
@Serializable
data class Struct(
@TarsId(1) val str: String,
@TarsId(2) val int: Int,
) : JceStruct
@Test
fun `can log`() {
val out = ByteArrayOutputStream()
val logger = DebugLogger(PrintStream(out))
val original = Struct("string", 1)
val bytes = original.toByteArray(Struct.serializer())
val value = bytes.toReadPacket().use { Tars.UTF_8.load(Struct.serializer(), it, logger) }
assertEquals(original, value)
assertEquals(
"""
beginStructure: net.mamoe.mirai.internal.utils.io.serialization.tars.internal.DebugLoggerTest.Struct, CLASS
decodeElementIndex: TarsHead(tag=1, type=6(String1))
name=str
decodeElementIndex: TarsHead(tag=2, type=0(Byte))
name=int
decodeElementIndex: currentHead == null
endStructure: net.mamoe.mirai.internal.utils.io.serialization.tars.internal.DebugLoggerTest.Struct, null, null
""".trimIndent(), out.toByteArray().decodeToString().trim()
)
}
@Test
fun `can auto log`() {
val original = Struct("string", 1)
val bytes = original.toByteArray(Struct.serializer())
println(bytes.toUHexString()) // 16 06 73 74 72 69 6E 67 20 01
bytes[bytes.lastIndex - 1] = 0x30.toByte() // change tag
val exception = assertFails { bytes.toReadPacket().use { it.readJceStruct(Struct.serializer()) } }
assertEquals(
"""
解析 net.mamoe.mirai.internal.utils.io.serialization.tars.internal.DebugLoggerTest.Struct 时遇到了意料之中的问题. 请完整复制此日志提交给 mirai: https://github.com/mamoe/mirai/issues/new/choose 调试信息:
Data:
16 06 73 74 72 69 6E 67 30 01
Trace:
beginStructure: net.mamoe.mirai.internal.utils.io.serialization.tars.internal.DebugLoggerTest.Struct, CLASS
decodeElementIndex: TarsHead(tag=1, type=6(String1))
name=str
decodeElementIndex: TarsHead(tag=3, type=0(Byte))
""".trimIndent(), exception.message!!.trim()
)
}
}