search

sofastack / sofa-bolt

SOFABolt is a lightweight, easy to use and high performance remoting framework based on Netty.
https://www.sofastack.tech/projects/sofa-bolt/
Apache License 2.0
2.42k stars 860 forks source link

debug日志报出Please check your pipeline configuration #331

Closed LinHuiG closed 4 months ago

LinHuiG commented 1 year ago

Your question

启动sofa-jraft后，debug不断打印： 2023-07-17 13:04:08.323 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-6]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@7935e926 that reached at the tail of the pipeline. Please check your pipeline configuration. 请问这是什么问题 日志如下

2023-07-17 13:04:07.678 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-10]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x537dec69, L:/10.10.184.171:58732 - R:10.10.184.174/10.10.184.174:6011]. 2023-07-17 13:04:07.686 io.netty.channel.DefaultChannelPipeline [Rpc-netty-server-worker-10-thread-3]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcRequestCommand@afe0e76 that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:07.686 io.netty.channel.DefaultChannelPipeline [Rpc-netty-server-worker-10-thread-3]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xab528365, L:/10.10.184.171:6011 - R:/10.10.184.174:43266]. 2023-07-17 13:04:07.711 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.175:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:07.712 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-4]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@689d5ab3 that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:07.712 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send7]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.175:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:07.712 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-4]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xc8745f4b, L:/10.10.184.171:46488 - R:10.10.184.175/10.10.184.175:6011]. 2023-07-17 13:04:07.719 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.173:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:07.720 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-6]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@5527f0d9 that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:07.721 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send1]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.173:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:07.721 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-6]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x49fcb741, L:/10.10.184.171:55832 - R:10.10.184.173/10.10.184.173:6011]. 2023-07-17 13:04:07.807 io.netty.channel.DefaultChannelPipeline [Rpc-netty-server-worker-10-thread-4]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcRequestCommand@1353583c that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:07.808 io.netty.channel.DefaultChannelPipeline [Rpc-netty-server-worker-10-thread-4]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xbe921d13, L:/10.10.184.171:6011 - R:/10.10.184.174:43272]. 2023-07-17 13:04:07.959 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.172:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:07.959 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-8]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@56bc36d1 that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:07.960 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send0]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.172:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:07.960 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-8]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x82bfc456, L:/10.10.184.171:56084 - R:10.10.184.172/10.10.184.172:6011]. 2023-07-17 13:04:07.978 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.174:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:07.979 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-10]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@5f4b71d2 that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:07.979 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send2]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.174:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:07.980 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-10]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x537dec69, L:/10.10.184.171:58732 - R:10.10.184.174/10.10.184.174:6011]. 2023-07-17 13:04:07.988 io.netty.channel.DefaultChannelPipeline [Rpc-netty-server-worker-10-thread-3]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcRequestCommand@77c1b58c that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:07.988 io.netty.channel.DefaultChannelPipeline [Rpc-netty-server-worker-10-thread-3]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xab528365, L:/10.10.184.171:6011 - R:/10.10.184.174:43266]. 2023-07-17 13:04:08.012 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.175:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:08.014 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-4]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@5814d9ed that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:08.014 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send7]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.175:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:08.014 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-4]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xc8745f4b, L:/10.10.184.171:46488 - R:10.10.184.175/10.10.184.175:6011]. 2023-07-17 13:04:08.021 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.173:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:08.022 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-6]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@74b0648d that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:08.023 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send1]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.173:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:08.023 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-6]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x49fcb741, L:/10.10.184.171:55832 - R:10.10.184.173/10.10.184.173:6011]. 2023-07-17 13:04:08.260 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.172:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:08.261 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-8]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@4226711d that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:08.261 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send0]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.172:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:08.261 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-8]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x82bfc456, L:/10.10.184.171:56084 - R:10.10.184.172/10.10.184.172:6011]. 2023-07-17 13:04:08.279 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.174:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:08.280 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-10]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@e499c21 that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:08.280 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send2]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.174:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:08.280 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-10]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x537dec69, L:/10.10.184.171:58732 - R:10.10.184.174/10.10.184.174:6011]. 2023-07-17 13:04:08.290 io.netty.channel.DefaultChannelPipeline [Rpc-netty-server-worker-10-thread-3]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcRequestCommand@7ace4a98 that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:08.290 io.netty.channel.DefaultChannelPipeline [Rpc-netty-server-worker-10-thread-3]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xab528365, L:/10.10.184.171:6011 - R:/10.10.184.174:43266]. 2023-07-17 13:04:08.314 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.175:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:08.316 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-4]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@197076c that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:08.316 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send7]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.175:6011 prevLogIndex=28 prevLogTerm=8 2023-07-17 13:04:08.316 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-4]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xc8745f4b, L:/10.10.184.171:46488 - R:10.10.184.175/10.10.184.175:6011]. 2023-07-17 13:04:08.322 com.alipay.sofa.jraft.core.Replicator [JRaft-Rpc-Closure-Executor-11]-[DEBUG] Node <em_strategy_sz_20230621_0/10.10.184.171:6011::1000> send HeartbeatRequest to 10.10.184.173:6011 term 8 lastCommittedIndex 28 2023-07-17 13:04:08.323 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-6]-[DEBUG] Discarded inbound message com.alipay.remoting.rpc.protocol.RpcResponseCommand@7935e926 that reached at the tail of the pipeline. Please check your pipeline configuration. 2023-07-17 13:04:08.323 io.netty.channel.DefaultChannelPipeline [bolt-netty-client-worker-1-thread-6]-[DEBUG] Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x49fcb741, L:/10.10.184.171:55832 - R:10.10.184.173/10.10.184.173:6011]. 2023-07-17 13:04:08.323 com.alipay.sofa.jraft.core.Replicator [Append-Entries-Thread-Send1]-[DEBUG] Node em_strategy_sz_20230621_0:10.10.184.171:6011::1000 received HeartbeatResponse from 10.10.184.173:6011 prevLogIndex=28 prevLogTerm=8

Your scenes

describe your use scenes (why need this feature)

Your advice

describe the advice or solution you'd like

Environment

jraft-core 版本是1.3.13

chuailiwu commented 1 year ago

看报错提示就是对应的请求在pipeline中没有对应的hander处理，分析下是不是pipeline的设置有什么变动，或者debug看下

LinHuiG commented 1 year ago

看报错提示就是对应的请求在pipeline中没有对应的hander处理，分析下是不是pipeline的设置有什么变动，或者debug看下

断点进去看了一下，无法处理的请求是com.alipay.remoting.rpc.HeartbeatCommand和RpcResponseCommand，看上去像是bolt的心跳

LinHuiG commented 1 year ago

看报错提示就是对应的请求在pipeline中没有对应的hander处理，分析下是不是pipeline的设置有什么变动，或者debug看下

断点进去看了一下，无法处理的请求是com.alipay.remoting.rpc.HeartbeatCommand和RpcResponseCommand，看上去像是bolt的心跳

debug看了一下，requestClass好像是com.alipay.sofa.jraft.rpc.RpcRequests$AppendEntriesRequest，是raft层的问题吗

LinHuiG commented 1 year ago

看报错提示就是对应的请求在pipeline中没有对应的hander处理，分析下是不是pipeline的设置有什么变动，或者debug看下

断点进去看了一下，无法处理的请求是com.alipay.remoting.rpc.HeartbeatCommand和RpcResponseCommand，看上去像是bolt的心跳

debug看了一下，requestClass好像是com.alipay.sofa.jraft.rpc.RpcRequests$AppendEntriesRequest，是raft层的问题吗

应该不是raft应用层的问题，不然raft就挂了，目前看上去就一直报这个日志，功能倒是正常==

LinHuiG commented 1 year ago

在com.alipay.remoting.rpc.RpcServer类中，第341行加入了rpcHandler，在342行中，如果extendedHandlers为null，则pipeline不会再继续addLast，也就意味着rpcHandler会是pipeline的最后一个Handler。 而RpcHandler的第61行 ctx.fireChannelRead(msg); 却试图将msg传递给下一个Handler，因此报出以上日志。 可以帮我确认一下是否是以上逻辑吗？

Allen-Bush commented 6 months ago

怎么解决的

chuailiwu commented 5 months ago

hat reached at the tail of the pipeline. Please check your pipeline configuration.

image 这里就是如你分析的，为了支持extendedHandlers，但是默认这个配置是null会有如上debug日志，不过这个日志可以忽略