mamoe / mirai

高效率 QQ 机器人支持库
https://mirai.mamoe.net
GNU Affero General Public License v3.0
14.5k stars 2.55k forks source link

上传图片调用Contact.uploadImage(externalResource)时偶尔会抛出TimeoutCancellationException #2147

Closed nt1r closed 2 years ago

nt1r commented 2 years ago

问题描述

上传图片调用Contact.uploadImage(externalResource)时偶尔会抛出TimeoutCancellationException。

抛出的异常:

kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 5000 ms at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:184) at kotlinx.coroutines.TimeoutCoroutine.run(Timeout.kt:154) at kotlinx.coroutines.EventLoopImplBase$DelayedRunnableTask.run(EventLoop.common.kt:502) at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:279) at kotlinx.coroutines.DefaultExecutor.run(DefaultExecutor.kt:108) at java.base/java.lang.Thread.run(Thread.java:829)

日志中只有这一种错误,仔细检查了没有其他的Exception被throw出来。用Google查了一下类似的问题和Issues中的已经有的类似问题 #1957 #1893,可能是网络波动导致的,但这个问题一下午可以复现5~6次,不是100%复现成功,大概30%可能复现成功。

对照了Releases,相关问题未在近期更新中解决。(不确定

复现

复现系统环境:

腾讯云ubuntu服务器,oracle jre11

mirai core和core-api版本: 2.10.2

// version.mirai=2.10.2 implementation("net.mamoe:mirai-core-api:${properties["version.mirai"]}") implementation("net.mamoe:mirai-core:${properties["version.mirai"]}")

复现kotlin代码:

val imageResource = File(imageUrl).toExternalResource().toAutoCloseable() val image = bot.getFriendOrFail(Constant.DEV_ID).uploadImage(imageResource) // MessageChainBuilder.append(image)

复现使用的图片(大小为10kb左右的表情包) touch_red

mirai-core 版本

2.10.2

bot-protocol

ANDROID_PHONE

其他组件版本

build.gradle.kts:

plugins { kotlin("jvm") version "1.6.20" } ... // version.mirai=2.10.2 implementation("net.mamoe:mirai-core-api:${properties["version.mirai"]}") implementation("net.mamoe:mirai-core:${properties["version.mirai"]}") implementation("org.hibernate:hibernate-core:5.6.8.Final") implementation("org.projectlombok:lombok:1.18.24") implementation("org.apache.logging.log4j:log4j-core:2.17.2") implementation("mysql:mysql-connector-java:8.0.29")

implementation("com.squareup.retrofit2:retrofit:2.9.0") implementation("com.squareup.retrofit2:converter-gson:2.9.0") implementation("com.squareup.retrofit2:converter-scalars:2.9.0")

implementation("org.ktorm:ktorm-core:3.5.0") implementation("org.ktorm:ktorm-support-mysql:3.5.0")

implementation("com.alibaba:druid:1.2.11")

testImplementation(kotlin("test")) testImplementation("com.h2database:h2:2.1.214") testImplementation("io.mockk:mockk:1.12.4")

系统日志

只有群号打了马赛克,群聊里复现这个Exception的触发词是:摸摸red
// 并不是100%复现成功

2022-07-11 09:53:25 V/Net 2818592254: Send: LongConn.OffPicUp(LongConn.OffPicUp)
2022-07-11 09:53:30 V/Net 2818592254: Send: LongConn.OffPicUp(LongConn.OffPicUp)
2022-07-11 09:53:35 E/Bot 2818592254: Exception in unnamed coroutine.
kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 5000 ms
    at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:184)
    at kotlinx.coroutines.TimeoutCoroutine.run(Timeout.kt:154)
    at kotlinx.coroutines.EventLoopImplBase$DelayedRunnableTask.run(EventLoop.common.kt:502)
    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:279)
    at kotlinx.coroutines.DefaultExecutor.run(DefaultExecutor.kt:108)
    at java.base/java.lang.Thread.run(Thread.java:829)

2022-07-11 09:53:35 V/Bot 2818592254: [✨狐狐大列巴夏日盒蛋开拍❗❗❗(xxxxxx)] 【困困車】超高校的摸鱼貓(2731646018) -> 摸摸red
2022-07-11 09:53:35 V/Net 2818592254: Recv: LongConn.OffPicUp
2022-07-11 09:53:35 V/Net 2818592254: Recv: LongConn.OffPicUp
2022-07-11 09:53:35 V/Net 2818592254: Send: LongConn.OffPicUp(LongConn.OffPicUp)
2022-07-11 09:53:36 V/Net 2818592254: Recv: LongConn.OffPicUp
2022-07-11 09:53:36 V/Net 2818592254: Send: MessageSvc.PbSendMsg(MessageSvc.PbSendMsg)
2022-07-11 09:53:36 V/Bot 2818592254: [✨狐狐大列巴夏日盒蛋开拍❗❗❗(xxxxxx)] 【困困車】超高校的摸鱼貓(2731646018) -> 摸摸red
2022-07-11 09:53:36 V/Net 2818592254: Recv: MessageSvc.PbSendMsg
2022-07-11 09:53:35 V/Net 2818592254: Send: LongConn.OffPicUp(LongConn.OffPicUp)
2022-07-11 09:53:36 V/Net 2818592254: Recv: LongConn.OffPicUp
2022-07-11 09:53:36 V/Net 2818592254: Send: MessageSvc.PbSendMsg(MessageSvc.PbSendMsg)
2022-07-11 09:53:36 V/Bot 2818592254: [✨狐狐大列巴夏日盒蛋开拍❗❗❗(xxxxxx)] 【困困車】超高校的摸鱼貓(2731646018) -> 摸摸red
2022-07-11 09:53:36 V/Net 2818592254: Recv: MessageSvc.PbSendMsg
2022-07-11 09:53:36 V/Bot 2818592254: Group(xxxxxx) <- [mirai:quote:[266050],[988260161]]会掉毛的啦!!\n[mirai:image:{163318E5-C693-1EF5-72BC-3F2DF00EAF47}.jpg]\n

// 这张表情包就是上传的图片
[mirai:image:{163318E5-C693-1EF5-72BC-3F2DF00EAF47}.jpg]

网络日志

No response

补充信息

我自己目前临时的解决方案:

本地内存缓存已经upload过的Image对象,需要再次上传同一张图时调用image.isUploaded判断,减少访问ImgStore的次数,治标不治本。

Him188 commented 2 years ago

试试2.12

nt1r commented 2 years ago

nohup.txt

试试2.12

今天将mirai core和core-api版本从2.10.2更换到了2.12。尝试对这个问题进行了测试,抛出了更多种类的异常,具体日志在附件nohup.txt。

群聊消息中的摸摸red是触发词,bot会随机回复,其中有一种回复包含了上述的表情包,调用的方法顺序是:

=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-

HeartbeatFailedException: 2818592254.AliveHeartbeat, recoverable=true, cause=PacketTimeoutException(message=2818592254.AliveHeartbeat Scheduler: Timeout receiving action response, cause=kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 5000 ms) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$StateOK$heartbeatJobs$1$1.invoke(NettyNetworkHandler.kt:369) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$StateOK$heartbeatJobs$1$1.invoke(NettyNetworkHandler.kt:369) at net.mamoe.mirai.internal.network.handler.NetworkHandlerSupport.setStateImpl$mirai_core(NetworkHandlerSupport.kt:288) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$StateOK$heartbeatJobs$1.invoke(NettyNetworkHandler.kt:421) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$StateOK$heartbeatJobs$1.invoke(NettyNetworkHandler.kt:368) at net.mamoe.mirai.internal.network.components.TimeBasedHeartbeatSchedulerImpl$launchHeartbeatJobAsync$1.invokeSuspend(HeartbeatScheduler.kt:130) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:33) at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46) at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:33) at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46) at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104) at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:570) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:749) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:677) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:664) Caused by: PacketTimeoutException(message=2818592254.AliveHeartbeat Scheduler: Timeout receiving action response, cause=kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 5000 ms) at net.mamoe.mirai.internal.network.components.TimeBasedHeartbeatSchedulerImpl$launchHeartbeatJobAsync$1.invokeSuspend(HeartbeatScheduler.kt:132) ... 12 more Caused by: kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 5000 ms at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:184) at kotlinx.coroutines.TimeoutCoroutine.run(Timeout.kt:154) at kotlinx.coroutines.EventLoopImplBase$DelayedRunnableTask.run(EventLoop.common.kt:502) at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:279) at kotlinx.coroutines.DefaultExecutor.run(DefaultExecutor.kt:108) at java.base/java.lang.Thread.run(Thread.java:829)

2022-07-12 13:30:48 W/Bot 2818592254: An exception occurred when processing event. Subscriber scope: ''. Broadcaster scope: 'Bot.2818592254.EventDispatcher' java.lang.IllegalStateException: NetworkHandler is already closed. at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$StateClosed.sendPacketImpl(NettyNetworkHandler.kt:407) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler.sendPacketImpl(NettyNetworkHandler.kt:41) at net.mamoe.mirai.internal.network.handler.NetworkHandlerSupport.sendAndExpect(NetworkHandlerSupport.kt:105) at net.mamoe.mirai.internal.network.handler.NetworkHandlerSupport$sendAndExpect$1.invokeSuspend(NetworkHandlerSupport.kt) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:33) at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102) at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46) at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104) at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:570) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:749) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:677) at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:664) Suppressed: kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 5000 ms at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:184) at kotlinx.coroutines.TimeoutCoroutine.run(Timeout.kt:154) at kotlinx.coroutines.EventLoopImplBase$DelayedRunnableTask.run(EventLoop.common.kt:502) at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:279) at kotlinx.coroutines.DefaultExecutor.run(DefaultExecutor.kt:108) at java.base/java.lang.Thread.run(Thread.java:829)

2022-07-12 13:30:48 E/Net 2818592254: Exception in coroutine 'unnamed' ExceptionInPacketCodecException(cause=net.mamoe.mirai.internal.utils.crypto.DecryptionFailedException) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler.handleExceptionInDecoding$passToExceptionHandler(NettyNetworkHandler.kt:61) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler.handleExceptionInDecoding(NettyNetworkHandler.kt:77) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$ByteBufToIncomingPacketDecoder.channelRead0(NettyNetworkHandler.kt:98) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$ByteBufToIncomingPacketDecoder.channelRead0(NettyNetworkHandler.kt:88) at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:311) at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:432) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:829) Caused by: net.mamoe.mirai.internal.utils.crypto.DecryptionFailedException at net.mamoe.mirai.internal.utils.crypto.TEA.fail(TEA.kt:298) at net.mamoe.mirai.internal.utils.crypto.TEA.doOption$decrypt(TEA.kt:274) at net.mamoe.mirai.internal.utils.crypto.TEA.doOption(TEA.kt:294) at net.mamoe.mirai.internal.utils.crypto.TEA.decrypt(TEA.kt:318) at net.mamoe.mirai.internal.network.components.PacketCodecImpl.decodeRaw(PacketCodec.kt:122) at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$ByteBufToIncomingPacketDecoder.channelRead0(NettyNetworkHandler.kt:95) ... 25 more

Him188 commented 2 years ago

看起来是你的网络环境太不稳定了, 那这些异常都是正常的

nt1r commented 2 years ago

看起来是你的网络环境太不稳定了, 那这些异常都是正常的

好的,辛苦您抽空排查了,非常感谢。没想到腾讯自家的腾讯云服务器网络会这样,我再排查排查网络问题,再次感谢。

PS: 没有其他问题的话可以close这个issue。