Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
LinHuiG opened this issue Jul 17, 2023 · 7 comments
Closed

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

LinHuiG opened this issue Jul 17, 2023 · 7 comments

Comments

@LinHuiG
Copy link

LinHuiG commented Jul 17, 2023

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

  • SOFABolt version: 1.6.4
  • JVM version (e.g. java -version): 1.8
  • OS version (e.g. uname -a): centos7.8
  • Maven version: 3.8.1
  • IDE version:
@chuailiwu
Copy link
Collaborator

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

@LinHuiG
Copy link
Author

LinHuiG commented Jul 21, 2023 •
edited

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

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

@LinHuiG
Copy link
Author

LinHuiG commented Jul 21, 2023

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

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

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

@LinHuiG
Copy link
Author

LinHuiG commented Jul 21, 2023

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

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

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

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

@LinHuiG
Copy link
Author

LinHuiG commented Aug 3, 2023

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

@Allen-Bush
Copy link

怎么解决的

@chuailiwu
Copy link
Collaborator

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

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@chuailiwu @Allen-Bush @LinHuiG