启动raft后不断报出与rpc相关日志

[LinHuiG]

Your question

启动raft后，控制台不断打印出如下日志

[DEBUG] 2023-06-16 17:04:43.662[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x013c26eb, L:/127.0.0.1:6011 - R:/127.0.0.1:64480]. [DEBUG] 2023-06-16 17:04:43.663[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message [com.alipay.remoting.rpc.HeartbeatAckCommand@173e4e29, com.alipay.remoting.rpc.HeartbeatAckCommand@61788d5f] that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:04:43.663[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xfe93c2a9, L:/127.0.0.1:64480 - R:/127.0.0.1:6011]. [DEBUG] 2023-06-16 17:04:58.662[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatCommand@4262901e that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:04:58.662[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x013c26eb, L:/127.0.0.1:6011 - R:/127.0.0.1:64480]. [DEBUG] 2023-06-16 17:04:58.662[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatAckCommand@5df09e35 that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:04:58.663[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xfe93c2a9, L:/127.0.0.1:64480 - R:/127.0.0.1:6011]. [DEBUG] 2023-06-16 17:05:13.663[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatCommand@10daf9d that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:05:13.664[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x013c26eb, L:/127.0.0.1:6011 - R:/127.0.0.1:64480]. [DEBUG] 2023-06-16 17:05:13.664[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatAckCommand@30ccace9 that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:05:13.664[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatCommand@1381ad3 that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:05:13.664[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xfe93c2a9, L:/127.0.0.1:64480 - R:/127.0.0.1:6011]. [DEBUG] 2023-06-16 17:05:13.664[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x013c26eb, L:/127.0.0.1:6011 - R:/127.0.0.1:64480]. [DEBUG] 2023-06-16 17:05:13.664[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatAckCommand@1a314cd9 that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:05:13.665[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xfe93c2a9, L:/127.0.0.1:64480 - R:/127.0.0.1:6011]. [DEBUG] 2023-06-16 17:05:28.664[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatCommand@441ccc9a that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:05:28.664[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x013c26eb, L:/127.0.0.1:6011 - R:/127.0.0.1:64480]. [DEBUG] 2023-06-16 17:05:28.665[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatAckCommand@6cd0390e that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:05:28.665[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xfe93c2a9, L:/127.0.0.1:64480 - R:/127.0.0.1:6011]. [DEBUG] 2023-06-16 17:05:43.665[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatCommand@7ebb38e0 that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:05:43.666[Rpc-netty-server-worker-7-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, serverIdleHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0x013c26eb, L:/127.0.0.1:6011 - R:/127.0.0.1:64480]. [DEBUG] 2023-06-16 17:05:43.667[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1182 -Discarded inbound message com.alipay.remoting.rpc.HeartbeatAckCommand@21e4b6bb that reached at the tail of the pipeline. Please check your pipeline configuration. [DEBUG] 2023-06-16 17:05:43.667[bolt-netty-client-worker-1-thread-1]io.netty.channel.DefaultChannelPipeline.onUnhandledInboundMessage:1198 -Discarded message pipeline : [flushConsolidationHandler, decoder, encoder, idleStateHandler, heartbeatHandler, connectionEventHandler, handler, DefaultChannelPipeline$TailContext#0]. Channel : [id: 0xfe93c2a9, L:/127.0.0.1:64480 - R:/127.0.0.1:6011].

Your scenes

Describe your use scenes (why need this feature)

Your advice

Describe the advice or solution you'd like

Environment

• SOFAJRaft version:
• JVM version (e.g. java -version):
• OS version (e.g. uname -a):
• Maven version:
• IDE version:

[killme2008]

你都开 DEBUG 日志了，这不是很正常？ 怎么关某个类库的日志，自行 google 吧。

[LinHuiG]

你都开 DEBUG 日志了，这不是很正常？ 怎么关某个类库的日志，自行 google 吧。

我想问的是这句：com.alipay.remoting.rpc.HeartbeatAckCommand@21e4b6bb that reached at the tail of the pipeline. Please check your pipeline configuration.

[killme2008]

似乎只是个 warning，跟 bolt 的 pipeline 设置有关 cc @fengjiachun

[fengjiachun]

似乎不应该出现这个日志，可以看看是否对 bolt 做了什么更改，通信的双端的 bolt 版本是否一致，建议把这个问题报告的 bolt 社区

[LinHuiG]

似乎不应该出现这个日志，可以看看是否对 bolt 做了什么更改，通信的双端的 bolt 版本是否一致，建议把这个问题报告的 bolt 社区

没有对bolt做更改，通信双端的代码是就是raft的集群，同一套代码，目前看上去除了不断报出这个warning外没有其他问题，功能是正常的。 启动rpc的代码是：RaftRpcServerFactory.createRaftRpcServer(address).init(null);

[fengjiachun]

看起来是 bolt 协议层处理心跳有点问题，可以报告到 bolt 社区看看

[LinHuiG]

好的，我去问问

[LinHuiG]

看起来是 bolt 协议层处理心跳有点问题，可以报告到 bolt 社区看看

问了一下那边的，debug进去看无法处理的类有俩个：com.alipay.sofa.jraft.rpc.RpcRequests$AppendEntriesRequest和 com.alipay.sofa.jraft.rpc.RpcRequests$AppendEntriesResponse debug的时候没有提交日志，应该是心跳吧

打印出来是： {"requestObject":{"bitField0":127,"groupId":"em_strategy_sh_202306210","serverId":"10.10.184.174:6011::1000","peerId":"10.10.184.172:6011","term":35,"prevLogTerm":35,"prevLogIndex":193,"entries":[],"committedIndex":193,"data":{"bytes":[],"hash":0},"memoizedIsInitialized":1,"unknownFields":{"fields":{},"fieldsDescending":{}},"memoizedSize":-1,"memoizedHashCode":0},"requestClass":"com.alipay.sofa.jraft.rpc.RpcRequests$AppendEntriesRequest","customSerializer":{},"requestHeader":{"bitField0":7,"groupId_":"em_strategy_sh_202306210","serverId":"10.10.184.174:6011::1000","peerId_":"10.10.184.172:6011","memoizedIsInitialized":1,"unknownFields":{"fields":{},"fieldsDescending":{}},"memoizedSize":-1,"memoizedHashCode":0},"timeout":1500,"cmdCode":"RPC_REQUEST","version":1,"type":1,"serializer":1,"protocolSwitch":{"bs":[]},"id":2839499,"clazzLength":58,"headerLength":73,"contentLength":83,"clazz":[99,111,109,46,97,108,105,112,97,121,46,115,111,102,97,46,106,114,97,102,116,46,114,112,99,46,82,112,99,82,101,113,117,101,115,116,115,36,65,112,112,101,110,100,69,110,116,114,105,101,115,82,101,113,117,101,115,116],"header":[10,25,101,109,95,115,116,114,97,116,101,103,121,95,115,104,95,50,48,50,51,48,54,50,49,95,48,18,24,49,48,46,49,48,46,49,56,52,46,49,55,52,58,54,48,49,49,58,58,49,48,48,48,26,18,49,48,46,49,48,46,49,56,52,46,49,55,50,58,54,48,49,49],"content":[10,25,101,109,95,115,116,114,97,116,101,103,121,95,115,104,95,50,48,50,51,48,54,50,49,95,48,18,24,49,48,46,49,48,46,49,56,52,46,49,55,52,58,54,48,49,49,58,58,49,48,48,48,26,18,49,48,46,49,48,46,49,56,52,46,49,55,50,58,54,48,49,49,32,35,40,35,48,-63,1,64,-63,1],"invokeContext":null}

[LinHuiG]

request和response我debug进去各打了一个 request {"requestObject":{"bitField0":127,"groupId":"em_strategy_sh_202306210","serverId":"10.10.184.174:6011::1000","peerId":"10.10.184.171:6011","term":35,"prevLogTerm":35,"prevLogIndex":193,"entries":[],"committedIndex":193,"data":{"bytes":[],"hash":0},"memoizedIsInitialized":1,"unknownFields":{"fields":{},"fieldsDescending":{}},"memoizedSize":-1,"memoizedHashCode":0},"requestClass":"com.alipay.sofa.jraft.rpc.RpcRequests$AppendEntriesRequest","customSerializer":{},"requestHeader":{"bitField0":7,"groupId_":"em_strategy_sh_202306210","serverId":"10.10.184.174:6011::1000","peerId_":"10.10.184.171:6011","memoizedIsInitialized":1,"unknownFields":{"fields":{},"fieldsDescending":{}},"memoizedSize":-1,"memoizedHashCode":0},"timeout":1500,"cmdCode":"RPC_REQUEST","version":1,"type":1,"serializer":1,"protocolSwitch":{"bs":[]},"id":2843316,"clazzLength":58,"headerLength":73,"contentLength":83,"clazz":[99,111,109,46,97,108,105,112,97,121,46,115,111,102,97,46,106,114,97,102,116,46,114,112,99,46,82,112,99,82,101,113,117,101,115,116,115,36,65,112,112,101,110,100,69,110,116,114,105,101,115,82,101,113,117,101,115,116],"header":[10,25,101,109,95,115,116,114,97,116,101,103,121,95,115,104,95,50,48,50,51,48,54,50,49,95,48,18,24,49,48,46,49,48,46,49,56,52,46,49,55,52,58,54,48,49,49,58,58,49,48,48,48,26,18,49,48,46,49,48,46,49,56,52,46,49,55,49,58,54,48,49,49],"content":[10,25,101,109,95,115,116,114,97,116,101,103,121,95,115,104,95,50,48,50,51,48,54,50,49,95,48,18,24,49,48,46,49,48,46,49,56,52,46,49,55,52,58,54,48,49,49,58,58,49,48,48,48,26,18,49,48,46,49,48,46,49,56,52,46,49,55,49,58,54,48,49,49,32,35,40,35,48,-63,1,64,-63,1],"invokeContext":null}

response {"responseObject":{"bitField0":7,"term":202,"success":true,"lastLogIndex":289,"errorResponse_":null,"memoizedIsInitialized":1,"unknownFields":{"fields":{},"fieldsDescending":{}},"memoizedSize":-1,"memoizedHashCode":0},"responseClass":"com.alipay.sofa.jraft.rpc.RpcRequests$AppendEntriesResponse","customSerializer":{},"responseHeader":null,"errorMsg":null,"responseStatus":"SUCCESS","responseTimeMillis":1689928118355,"responseHost":{},"cause":null,"cmdCode":"RPC_RESPONSE","version":1,"type":0,"serializer":1,"protocolSwitch":{"bs":[]},"id":613,"clazzLength":59,"headerLength":0,"contentLength":8,"clazz":[99,111,109,46,97,108,105,112,97,121,46,115,111,102,97,46,106,114,97,102,116,46,114,112,99,46,82,112,99,82,101,113,117,101,115,116,115,36,65,112,112,101,110,100,69,110,116,114,105,101,115,82,101,115,112,111,110,115,101],"header":null,"content":[8,-54,1,16,1,24,-95,2],"invokeContext":{"context":{"bolt.client.conn.createtime":0,"bolt.client.local.ip":"10.10.184.171","bolt.invoke.request.id":613,"bolt.invoke.crc.switch":true,"bolt.client.remote.ip":"10.10.184.172","bolt.client.remote.port":6011,"bolt.client.local.port":32874,"bolt.client.conn.create.end.nano":1401265422549935,"bolt.client.conn.create.start.nano":1401265422546149}}}

[killme2008]

这两个是有处理的，没处理 raft 算法都没法工作了

这个 warn log 是 netty pipeline 设置的问题