search

mamoe / mirai

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

短暂断网重连失败产生大量异常 #2646

Closed MrY-Cat closed 1 year ago

MrY-Cat commented 1 year ago

问题描述

新版本短暂断网重连后，似乎出现问题，产生了大量异常，后续网络日志以每分钟45行的速度增加

复现

换WiFi短暂断网半分钟也许能复现

mirai-core 版本

2.15.0-M1

bot-protocol

ANDROID_WATCH

其他组件版本

No response

系统日志

No response

网络日志

2023-04-26 18:25:15 W/Net 2305339556: Exception in resumeConnection.
NettyChannelException(message=null, cause=java.net.SocketException: Connection reset)
    at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$handlePipelineException$1.invoke(NettyNetworkHandler.kt:46)
    at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$handlePipelineException$1.invoke(NettyNetworkHandler.kt:46)
    at net.mamoe.mirai.internal.network.handler.NetworkHandlerSupport.setStateImpl$mirai_core(NetworkHandlerSupport.kt:329)
    at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler.handlePipelineException(NettyNetworkHandler.kt:152)
    at net.mamoe.mirai.internal.network.impl.netty.NettyNetworkHandler$setupChannelPipeline$1.exceptionCaught(NettyNetworkHandler.kt:72)
    at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
    at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
    at io.netty.channel.AbstractChannelHandlerContext.fireExceptionCaught(AbstractChannelHandlerContext.java:273)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.exceptionCaught(DefaultChannelPipeline.java:1377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:302)
    at io.netty.channel.AbstractChannelHandlerContext.invokeExceptionCaught(AbstractChannelHandlerContext.java:281)
    at io.netty.channel.DefaultChannelPipeline.fireExceptionCaught(DefaultChannelPipeline.java:907)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.handleReadException(AbstractNioByteChannel.java:125)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:177)
    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:833)
Caused by: java.net.SocketException: Connection reset
    at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:394)
    at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:426)
    at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
    at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
    ... 8 more

2023-04-26 18:25:15 V/Net 2305339556: Validated caches.
2023-04-26 18:25:15 V/Net 2305339556: Loading server list from cache.
2023-04-26 18:25:15 V/Net 2305339556: Server list: 111.30.169.83:80, 120.232.27.24:80, 36.155.224.104:8080, 36.155.245.243:443, 36.155.227.171:443, 120.232.31.192:80, msfwifi.3g.qq.com:8080, 111.30.169.45:8080, 111.30.169.58:14000.
2023-04-26 18:25:15 I/Net 2305339556: ECDH key is invalid, start to fetch ecdh public key from server.
2023-04-26 18:25:16 E/Net 2305339556: Failed to fetch ECDH public key from server, using default key instead
javax.net.ssl.SSLHandshakeException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
    at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:131)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:370)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:313)
    at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:308)
    at java.base/sun.security.ssl.CertificateMessage$T12CertificateConsumer.checkServerCerts(CertificateMessage.java:654)
    at java.base/sun.security.ssl.CertificateMessage$T12CertificateConsumer.onCertificate(CertificateMessage.java:473)
    at java.base/sun.security.ssl.CertificateMessage$T12CertificateConsumer.consume(CertificateMessage.java:369)
    at java.base/sun.security.ssl.SSLHandshake.consume(SSLHandshake.java:396)
    at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:480)
    at java.base/sun.security.ssl.HandshakeContext.dispatch(HandshakeContext.java:458)
    at java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:200)
    at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:172)
    at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1500)
    at java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(SSLSocketImpl.java:1415)
    at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:450)
    at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:421)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.RealConnection.connectTls(RealConnection.kt:379)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.RealConnection.establishProtocol(RealConnection.kt:337)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.RealConnection.connect(RealConnection.kt:209)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.ExchangeFinder.findConnection(ExchangeFinder.kt:226)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.ExchangeFinder.findHealthyConnection(ExchangeFinder.kt:106)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.ExchangeFinder.find(ExchangeFinder.kt:74)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.RealCall.initExchange$okhttp(RealCall.kt:255)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.kt:32)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.kt:95)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.kt:83)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.kt:76)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.kt:109)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.RealCall.getResponseWithInterceptorChain$okhttp(RealCall.kt:201)
    at net.mamoe.mirai.internal.deps.okhttp3.internal.connection.RealCall$AsyncCall.run(RealCall.kt:517)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
    at java.base/sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:439)
    at java.base/sun.security.validator.PKIXValidator.engineValidate(PKIXValidator.java:306)
    at java.base/sun.security.validator.Validator.validate(Validator.java:264)
    at java.base/sun.security.ssl.X509TrustManagerImpl.checkTrusted(X509TrustManagerImpl.java:231)
    at java.base/sun.security.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:132)
    at java.base/sun.security.ssl.CertificateMessage$T12CertificateConsumer.checkServerCerts(CertificateMessage.java:638)
    ... 31 more
Caused by: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target
    at java.base/sun.security.provider.certpath.SunCertPathBuilder.build(SunCertPathBuilder.java:141)
    at java.base/sun.security.provider.certpath.SunCertPathBuilder.engineBuild(SunCertPathBuilder.java:126)
    at java.base/java.security.cert.CertPathBuilder.build(CertPathBuilder.java:297)
    at java.base/sun.security.validator.PKIXValidator.doBuild(PKIXValidator.java:434)
    ... 36 more

2023-04-26 18:25:17 V/Net 2305339556: Send: wtlogin.exchange_emp(10:fast-login)
2023-04-26 18:25:22 V/Net 2305339556: Send: wtlogin.exchange_emp(10:fast-login)
2023-04-26 18:25:27 D/Net 2305339556: CAS: JustInitialized -> CreatingProducer: true
2023-04-26 18:25:27 D/Net 2305339556: CAS: CreatingProducer -> ProducerReady: true
2023-04-26 18:25:27 D/Net 2305339556: CAS: ProducerReady -> Producing(deferred.completed=false): true
2023-04-26 18:25:27 V/Net 2305339556: [AuthControl/auth] Authorization started
2023-04-26 18:25:27 W/Net 2305339556: Exception in resumeConnection.
net.mamoe.mirai.internal.network.handler.selector.SelectorRequireReconnectException

2023-04-26 18:25:27 D/Net 2305339556: CAS: Producing(deferred.completed=false) -> Consuming(value=null): true
2023-04-26 18:25:30 I/Net 2305339556: ECDH key is invalid, start to fetch ecdh public key from server.
2023-04-26 18:25:30 I/Net 2305339556: Successfully fetched ecdh public key from server.
2023-04-26 18:25:30 V/Net 2305339556: [AuthControl/acquire] Acquiring auth method
2023-04-26 18:25:30 D/Net 2305339556: CAS: Consuming(value=QRCode) -> Consumed(LatchImpl(CompletableDeferredImpl{Active}@4ed109b9)): true
2023-04-26 18:25:30 D/Net 2305339556: [AuthControl/acquire] Authorization responded: QRCode
2023-04-26 18:25:30 D/Net 2305339556: requesting qrcode.
2023-04-26 18:25:30 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:25:30 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:25:30 D/Net 2305339556: querying qrcode state.
2023-04-26 18:25:30 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:25:30 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:25:30 D/Net 2305339556: qrcode state changed: WAITING_FOR_SCAN
2023-04-26 18:25:35 D/Net 2305339556: querying qrcode state.
2023-04-26 18:25:35 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:25:35 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:25:40 D/Net 2305339556: querying qrcode state.
2023-04-26 18:25:40 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:25:40 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:25:45 D/Net 2305339556: querying qrcode state.
2023-04-26 18:25:45 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:25:45 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:25:50 D/Net 2305339556: querying qrcode state.
2023-04-26 18:25:50 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:25:50 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:25:55 D/Net 2305339556: querying qrcode state.
2023-04-26 18:25:55 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:25:56 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:01 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:01 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:01 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:06 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:06 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:06 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:11 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:11 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:11 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:16 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:16 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:16 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:21 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:21 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:21 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:26 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:26 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:26 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:31 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:31 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:31 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:36 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:36 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:36 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:41 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:41 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:41 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:46 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:46 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:46 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:51 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:51 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:51 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:26:56 D/Net 2305339556: querying qrcode state.
2023-04-26 18:26:56 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:26:56 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:01 D/Net 2305339556: querying qrcode state.
2023-04-26 18:27:01 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:01 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:06 D/Net 2305339556: querying qrcode state.
2023-04-26 18:27:06 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:07 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:12 D/Net 2305339556: querying qrcode state.
2023-04-26 18:27:12 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:12 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:17 D/Net 2305339556: querying qrcode state.
2023-04-26 18:27:17 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:17 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:22 D/Net 2305339556: querying qrcode state.
2023-04-26 18:27:22 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:22 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:27 D/Net 2305339556: querying qrcode state.
2023-04-26 18:27:27 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:27 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:32 D/Net 2305339556: querying qrcode state.
2023-04-26 18:27:32 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:32 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:32 D/Net 2305339556: qrcode state changed: TIMEOUT
2023-04-26 18:27:32 D/Net 2305339556: requesting qrcode.
2023-04-26 18:27:32 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:32 V/Net 2305339556: Recv: wtlogin.trans_emp
2023-04-26 18:27:32 D/Net 2305339556: querying qrcode state.
2023-04-26 18:27:32 V/Net 2305339556: Send: wtlogin.trans_emp
2023-04-26 18:27:32 D/Net 2305339556: qrcode state changed: WAITING_FOR_SCAN

补充信息

No response

MrY-Cat commented 1 year ago

仔细看了一下似乎后面每分钟新增45行的日志是让扫码（没开控制台窗口刚刚没看到）...

那就如果前半部分的异常报错也没问题就可以close了（看不太懂前半部分）

也许就是单纯的扫码登录过期了重连失败

Him188 commented 1 year ago

前面挺对的