search

apache / rocketmq

Apache RocketMQ is a cloud native messaging and streaming platform, making it simple to build event-driven applications.
https://rocketmq.apache.org/
Apache License 2.0
21.19k stars 11.67k forks source link

[Bug] RocketMQ client netty throw an exception：TooLongFrameException ｜ Adjusted frame length exceeds 16777216: 1347569956 - discarded #8086

Closed JanYork closed 5 months ago

JanYork commented 5 months ago

Before Creating the Bug Report

Runtime platform environment

System: Macos intel Node version: 18.17.0 RocketMQ: latest version client version: latest

RocketMQ version

latest version

JDK Version

JDK 11、17、8

Describe the Bug

First of all, the configuration of RocketMQ has not been changed. They are all default. The broker has turned on the proxy mode and is running normally without any logs. Namesrv logs appeared, and errors occurred. See below for details. Ultimately resulting in client Grpc error: 'Call canceled', The message is only 35 bytes

Use rocketmq nodejs grpc client to test the following code：

require('module-alias/register');

import { Producer } from "@/producer";

const producer = new Producer({
  endpoints: '192.168.1.162:9876',
});

(async () => {
    // 启动生产者
    await producer.startup();

    // 发送消息
    producer.send({
      topic: 'TopicTest',
      tag: 'nodejs',
      body: Buffer.from(JSON.stringify({
        now: new Date().toString(),
      })),
    }).catch(console.error);
})();

Error occurred：

io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 16777216: 1347569956 - discarded
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:503)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.failIfNecessary(LengthFieldBasedFrameDecoder.java:489)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.exceededFrameLength(LengthFieldBasedFrameDecoder.java:376)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:419)
    at org.apache.rocketmq.remoting.netty.NettyDecoder.decode(NettyDecoder.java:44)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:332)
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
    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 org.apache.rocketmq.remoting.netty.NettyRemotingServer$TlsModeHandler.channelRead0(NettyRemotingServer.java:543)
    at org.apache.rocketmq.remoting.netty.NettyRemotingServer$TlsModeHandler.channelRead0(NettyRemotingServer.java:490)
    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.handlerRemoved(ByteToMessageDecoder.java:253)
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:514)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:61)
    at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:370)
    at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at java.base/java.lang.Thread.run(Thread.java:840)

detailed log：

2024-05-01 20:37:10 INFO NettyServerCodecThread_1 - NETTY SERVER PIPELINE: channelRegistered 192.168.1.162:50574
2024-05-01 20:37:10 INFO NettyServerCodecThread_1 - NETTY SERVER PIPELINE: channelActive, the channel[192.168.1.162:50574]
2024-05-01 20:37:10 ERROR NettyServerCodecThread_1 - decode exception, 192.168.1.162:50574
io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 16777216: 1347569956 - discarded
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:503)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.failIfNecessary(LengthFieldBasedFrameDecoder.java:489)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.exceededFrameLength(LengthFieldBasedFrameDecoder.java:376)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:419)
    at org.apache.rocketmq.remoting.netty.NettyDecoder.decode(NettyDecoder.java:44)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:332)
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
    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 org.apache.rocketmq.remoting.netty.NettyRemotingServer$TlsModeHandler.channelRead0(NettyRemotingServer.java:543)
    at org.apache.rocketmq.remoting.netty.NettyRemotingServer$TlsModeHandler.channelRead0(NettyRemotingServer.java:490)
    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.handlerRemoved(ByteToMessageDecoder.java:253)
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:514)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:61)
    at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:370)
    at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at java.base/java.lang.Thread.run(Thread.java:840)
2024-05-01 20:37:10 INFO NettyServerNIOSelector_1 - closeChannel: close the connection to remote address[192.168.1.162:50574] result: true
2024-05-01 20:37:10 INFO NettyServerCodecThread_1 - NETTY SERVER PIPELINE: channelInactive, the channel[192.168.1.162:50574]
2024-05-01 20:37:10 INFO NettyServerCodecThread_1 - NETTY SERVER PIPELINE: channelUnregistered, the channel[192.168.1.162:50574]

Client detailed log：

❯ GRPC_VERBOSITY=DEBUG GRPC_TRACE=all node ./dist/src/examples/producer.js

D 2024-05-01T12:37:10.095Z | index | Loading @grpc/grpc-js version 1.9.1
D 2024-05-01T12:37:10.186Z | resolving_load_balancer | dns:192.168.1.162:9876 IDLE -> IDLE
D 2024-05-01T12:37:10.186Z | connectivity_state | (1) dns:192.168.1.162:9876 IDLE -> IDLE
D 2024-05-01T12:37:10.187Z | dns_resolver | Resolver constructed for target dns:192.168.1.162:9876
D 2024-05-01T12:37:10.187Z | channel | (1) dns:192.168.1.162:9876 Channel constructed with options {}
D 2024-05-01T12:37:10.187Z | channel_stacktrace | (1) Channel constructed 
    at new InternalChannel (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/internal-channel.js:237:23)
    at new ChannelImplementation (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/channel.js:35:32)
    at new Client (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client.js:65:36)
    at new ServiceClientImpl (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/make-client.js:58:5)
    at new RpcClient (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client.js:19:23)
    at #getRpcClient (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client-manger.js:36:25)
    at RpcClientManger.queryRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client-manger.js:49:45)
    at #fetchTopicRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-base-client.js:160:54)
    at Producer.getRouteData (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-base-client.js:152:57)
    at #getPublishingLoadBalancer (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/producer/producer.js:209:43)
D 2024-05-01T12:37:10.189Z | channel | (1) dns:192.168.1.162:9876 createResolvingCall [0] method="/apache.rocketmq.v2.MessagingService/QueryRoute", deadline=2024-05-01T12:37:13.188Z
D 2024-05-01T12:37:10.189Z | resolving_call | [0] Created
D 2024-05-01T12:37:10.189Z | resolving_call | [0] Deadline: 2024-05-01T12:37:13.188Z
D 2024-05-01T12:37:10.189Z | resolving_call | [0] Deadline will be reached in 2999ms
D 2024-05-01T12:37:10.190Z | resolving_call | [0] start called
D 2024-05-01T12:37:10.190Z | dns_resolver | Returning IP address for target dns:192.168.1.162:9876
D 2024-05-01T12:37:10.191Z | resolving_load_balancer | dns:192.168.1.162:9876 IDLE -> CONNECTING
D 2024-05-01T12:37:10.191Z | connectivity_state | (1) dns:192.168.1.162:9876 IDLE -> CONNECTING
D 2024-05-01T12:37:10.191Z | channel | (1) dns:192.168.1.162:9876 callRefTimer.ref | configSelectionQueue.length=1 pickQueue.length=0
D 2024-05-01T12:37:10.191Z | resolving_call | [0] startRead called
D 2024-05-01T12:37:10.192Z | resolving_call | [0] write() called with message of length 37
D 2024-05-01T12:37:10.192Z | resolving_call | [0] halfClose called
D 2024-05-01T12:37:10.194Z | subchannel | (2) 192.168.1.162:9876 Subchannel constructed with options {}
D 2024-05-01T12:37:10.194Z | subchannel_refcount | (2) 192.168.1.162:9876 refcount 0 -> 1
D 2024-05-01T12:37:10.194Z | subchannel_refcount | (2) 192.168.1.162:9876 refcount 1 -> 2
D 2024-05-01T12:37:10.195Z | pick_first | Start connecting to subchannel with address 192.168.1.162:9876
D 2024-05-01T12:37:10.195Z | pick_first | IDLE -> CONNECTING
D 2024-05-01T12:37:10.195Z | resolving_load_balancer | dns:192.168.1.162:9876 CONNECTING -> CONNECTING
D 2024-05-01T12:37:10.195Z | channel | (1) dns:192.168.1.162:9876 callRefTimer.unref | configSelectionQueue.length=1 pickQueue.length=0
D 2024-05-01T12:37:10.195Z | connectivity_state | (1) dns:192.168.1.162:9876 CONNECTING -> CONNECTING
D 2024-05-01T12:37:10.196Z | subchannel | (2) 192.168.1.162:9876 IDLE -> CONNECTING
D 2024-05-01T12:37:10.197Z | transport | dns:192.168.1.162:9876 creating HTTP/2 session to 192.168.1.162:9876
D 2024-05-01T12:37:10.198Z | channel | (1) dns:192.168.1.162:9876 createRetryingCall [1] method="/apache.rocketmq.v2.MessagingService/QueryRoute"
D 2024-05-01T12:37:10.198Z | resolving_call | [0] Created child [1]
D 2024-05-01T12:37:10.198Z | retrying_call | [1] start called
D 2024-05-01T12:37:10.199Z | channel | (1) dns:192.168.1.162:9876 createLoadBalancingCall [2] method="/apache.rocketmq.v2.MessagingService/QueryRoute"
D 2024-05-01T12:37:10.199Z | retrying_call | [1] Created child call [2] for attempt 1
D 2024-05-01T12:37:10.199Z | load_balancing_call | [2] start called
D 2024-05-01T12:37:10.199Z | load_balancing_call | [2] Pick called
D 2024-05-01T12:37:10.199Z | load_balancing_call | [2] Pick result: QUEUE subchannel: null status: undefined undefined
D 2024-05-01T12:37:10.199Z | channel | (1) dns:192.168.1.162:9876 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2024-05-01T12:37:10.200Z | retrying_call | [1] startRead called
D 2024-05-01T12:37:10.200Z | load_balancing_call | [2] startRead called
D 2024-05-01T12:37:10.200Z | retrying_call | [1] write() called with message of length 42
D 2024-05-01T12:37:10.200Z | load_balancing_call | [2] write() called with message of length 42
D 2024-05-01T12:37:10.200Z | retrying_call | [1] halfClose called
D 2024-05-01T12:37:10.203Z | subchannel | (2) 192.168.1.162:9876 CONNECTING -> READY
D 2024-05-01T12:37:10.203Z | pick_first | Pick subchannel with address 192.168.1.162:9876
D 2024-05-01T12:37:10.203Z | subchannel_refcount | (2) 192.168.1.162:9876 refcount 2 -> 3
D 2024-05-01T12:37:10.203Z | subchannel_refcount | (2) 192.168.1.162:9876 refcount 3 -> 2
D 2024-05-01T12:37:10.204Z | pick_first | CONNECTING -> READY
D 2024-05-01T12:37:10.204Z | resolving_load_balancer | dns:192.168.1.162:9876 CONNECTING -> READY
D 2024-05-01T12:37:10.204Z | channel | (1) dns:192.168.1.162:9876 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-05-01T12:37:10.204Z | load_balancing_call | [2] Pick called
D 2024-05-01T12:37:10.204Z | load_balancing_call | [2] Pick result: COMPLETE subchannel: (2) 192.168.1.162:9876 status: undefined undefined
D 2024-05-01T12:37:10.204Z | connectivity_state | (1) dns:192.168.1.162:9876 CONNECTING -> READY
D 2024-05-01T12:37:10.206Z | transport_flowctrl | (3) 192.168.1.162:9876 local window size: 65535 remote window size: 65535
D 2024-05-01T12:37:10.206Z | transport_internals | (3) 192.168.1.162:9876 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2024-05-01T12:37:10.206Z | load_balancing_call | [2] Created child call [3]
D 2024-05-01T12:37:10.206Z | subchannel_call | [3] write() called with message of length 42
D 2024-05-01T12:37:10.206Z | subchannel_call | [3] sending data chunk of length 42
D 2024-05-01T12:37:10.207Z | load_balancing_call | [2] halfClose called
D 2024-05-01T12:37:10.207Z | subchannel_call | [3] end() called
D 2024-05-01T12:37:10.207Z | subchannel_call | [3] calling end() on HTTP/2 stream
D 2024-05-01T12:37:10.210Z | transport | (3) 192.168.1.162:9876 session closed
D 2024-05-01T12:37:10.210Z | subchannel | (2) 192.168.1.162:9876 READY -> IDLE
D 2024-05-01T12:37:10.210Z | subchannel_refcount | (2) 192.168.1.162:9876 refcount 2 -> 1
D 2024-05-01T12:37:10.210Z | pick_first | READY -> IDLE
D 2024-05-01T12:37:10.210Z | resolving_load_balancer | dns:192.168.1.162:9876 READY -> IDLE
D 2024-05-01T12:37:10.210Z | connectivity_state | (1) dns:192.168.1.162:9876 READY -> IDLE
D 2024-05-01T12:37:10.210Z | subchannel_call | [3] HTTP/2 stream closed with code 8
D 2024-05-01T12:37:10.211Z | subchannel_call | [3] ended with status: code=1 details="Call cancelled"
D 2024-05-01T12:37:10.211Z | load_balancing_call | [2] Received status
D 2024-05-01T12:37:10.211Z | load_balancing_call | [2] ended with status: code=1 details="Call cancelled"
D 2024-05-01T12:37:10.211Z | retrying_call | [1] Received status from child [2]
D 2024-05-01T12:37:10.211Z | retrying_call | [1] state=TRANSPARENT_ONLY handling status with progress PROCESSED from child [2] in state ACTIVE
D 2024-05-01T12:37:10.211Z | retrying_call | [1] ended with status: code=1 details="Call cancelled"
D 2024-05-01T12:37:10.212Z | resolving_call | [0] Received status
D 2024-05-01T12:37:10.212Z | resolving_call | [0] ended with status: code=1 details="Call cancelled"
Error: 1 CANCELLED: Call cancelled
    at callErrorFromStatus (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/call.js:31:19)
    at Object.onReceiveStatus (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client.js:192:76)
    at Object.onReceiveStatus (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:360:141)
    at Object.onReceiveStatus (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:323:181)
    at /Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/resolving-call.js:99:78
    at process.processTicksAndRejections (node:internal/process/task_queues:77:11)
for call at
    at ServiceClientImpl.makeUnaryRequest (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client.js:160:32)
    at ServiceClientImpl.queryRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/make-client.js:105:19)
    at /Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client.js:45:20
    at new Promise (<anonymous>)
    at RpcClient.queryRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client.js:44:16)
    at RpcClientManger.queryRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client-manger.js:51:32)
    at #fetchTopicRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-base-client.js:160:54)
    at Producer.getRouteData (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-base-client.js:152:57)
    at #getPublishingLoadBalancer (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/producer/producer.js:209:43)
    at #send (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/producer/producer.js:130:67) {
  code: 1,
  details: 'Call cancelled',
  metadata: Metadata { internalRepr: Map(0) {}, options: {} }
}
D 2024-05-01T12:37:11.192Z | resolving_load_balancer | dns:192.168.1.162:9876 IDLE -> CONNECTING
D 2024-05-01T12:37:11.192Z | connectivity_state | (1) dns:192.168.1.162:9876 IDLE -> CONNECTING
D 2024-05-01T12:37:12.648Z | resolving_load_balancer | dns:192.168.1.162:9876 CONNECTING -> IDLE
D 2024-05-01T12:37:12.648Z | connectivity_state | (1) dns:192.168.1.162:9876 CONNECTING -> IDLE
D 2024-05-01T12:37:20.195Z | subchannel_refcount | (2) 192.168.1.162:9876 refcount 1 -> 0
D 2024-05-01T12:37:40.184Z | channel | (1) dns:192.168.1.162:9876 createResolvingCall [4] method="/apache.rocketmq.v2.MessagingService/QueryRoute", deadline=2024-05-01T12:37:43.184Z
D 2024-05-01T12:37:40.185Z | resolving_call | [4] Created
D 2024-05-01T12:37:40.185Z | resolving_call | [4] Deadline: 2024-05-01T12:37:43.184Z
D 2024-05-01T12:37:40.185Z | resolving_call | [4] Deadline will be reached in 2999ms
D 2024-05-01T12:37:40.185Z | resolving_call | [4] start called
D 2024-05-01T12:37:40.185Z | resolving_load_balancer | dns:192.168.1.162:9876 IDLE -> CONNECTING
D 2024-05-01T12:37:40.185Z | connectivity_state | (1) dns:192.168.1.162:9876 IDLE -> CONNECTING
D 2024-05-01T12:37:40.185Z | resolving_call | [4] startRead called
D 2024-05-01T12:37:40.185Z | resolving_call | [4] write() called with message of length 37
D 2024-05-01T12:37:40.185Z | resolving_call | [4] halfClose called
D 2024-05-01T12:37:40.186Z | channel | (1) dns:192.168.1.162:9876 createRetryingCall [5] method="/apache.rocketmq.v2.MessagingService/QueryRoute"
D 2024-05-01T12:37:40.186Z | resolving_call | [4] Created child [5]
D 2024-05-01T12:37:40.186Z | retrying_call | [5] start called
D 2024-05-01T12:37:40.186Z | channel | (1) dns:192.168.1.162:9876 createLoadBalancingCall [6] method="/apache.rocketmq.v2.MessagingService/QueryRoute"
D 2024-05-01T12:37:40.186Z | retrying_call | [5] Created child call [6] for attempt 1
D 2024-05-01T12:37:40.186Z | load_balancing_call | [6] start called
D 2024-05-01T12:37:40.186Z | load_balancing_call | [6] Pick called
D 2024-05-01T12:37:40.186Z | load_balancing_call | [6] Pick result: QUEUE subchannel: null status: undefined undefined
D 2024-05-01T12:37:40.186Z | channel | (1) dns:192.168.1.162:9876 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2024-05-01T12:37:40.186Z | retrying_call | [5] startRead called
D 2024-05-01T12:37:40.186Z | load_balancing_call | [6] startRead called
D 2024-05-01T12:37:40.186Z | retrying_call | [5] write() called with message of length 42
D 2024-05-01T12:37:40.186Z | load_balancing_call | [6] write() called with message of length 42
D 2024-05-01T12:37:40.186Z | retrying_call | [5] halfClose called
D 2024-05-01T12:37:40.191Z | dns_resolver | Returning IP address for target dns:192.168.1.162:9876
D 2024-05-01T12:37:40.192Z | subchannel | (4) 192.168.1.162:9876 Subchannel constructed with options {}
D 2024-05-01T12:37:40.192Z | subchannel_refcount | (4) 192.168.1.162:9876 refcount 0 -> 1
D 2024-05-01T12:37:40.192Z | subchannel_refcount | (4) 192.168.1.162:9876 refcount 1 -> 2
D 2024-05-01T12:37:40.192Z | pick_first | Start connecting to subchannel with address 192.168.1.162:9876
D 2024-05-01T12:37:40.192Z | pick_first | IDLE -> CONNECTING
D 2024-05-01T12:37:40.192Z | resolving_load_balancer | dns:192.168.1.162:9876 CONNECTING -> CONNECTING
D 2024-05-01T12:37:40.192Z | channel | (1) dns:192.168.1.162:9876 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=0
D 2024-05-01T12:37:40.192Z | load_balancing_call | [6] Pick called
D 2024-05-01T12:37:40.192Z | load_balancing_call | [6] Pick result: QUEUE subchannel: null status: undefined undefined
D 2024-05-01T12:37:40.192Z | channel | (1) dns:192.168.1.162:9876 callRefTimer.ref | configSelectionQueue.length=0 pickQueue.length=1
D 2024-05-01T12:37:40.192Z | connectivity_state | (1) dns:192.168.1.162:9876 CONNECTING -> CONNECTING
D 2024-05-01T12:37:40.192Z | channel | (1) dns:192.168.1.162:9876 callRefTimer.unref | configSelectionQueue.length=0 pickQueue.length=1
D 2024-05-01T12:37:40.192Z | subchannel | (4) 192.168.1.162:9876 IDLE -> CONNECTING
D 2024-05-01T12:37:40.192Z | transport | dns:192.168.1.162:9876 creating HTTP/2 session to 192.168.1.162:9876
D 2024-05-01T12:37:40.193Z | subchannel | (4) 192.168.1.162:9876 CONNECTING -> READY
D 2024-05-01T12:37:40.193Z | pick_first | Pick subchannel with address 192.168.1.162:9876
D 2024-05-01T12:37:40.193Z | subchannel_refcount | (4) 192.168.1.162:9876 refcount 2 -> 3
D 2024-05-01T12:37:40.194Z | subchannel_refcount | (4) 192.168.1.162:9876 refcount 3 -> 2
D 2024-05-01T12:37:40.194Z | pick_first | CONNECTING -> READY
D 2024-05-01T12:37:40.194Z | resolving_load_balancer | dns:192.168.1.162:9876 CONNECTING -> READY
D 2024-05-01T12:37:40.194Z | load_balancing_call | [6] Pick called
D 2024-05-01T12:37:40.194Z | load_balancing_call | [6] Pick result: COMPLETE subchannel: (4) 192.168.1.162:9876 status: undefined undefined
D 2024-05-01T12:37:40.194Z | connectivity_state | (1) dns:192.168.1.162:9876 CONNECTING -> READY
D 2024-05-01T12:37:40.194Z | transport_flowctrl | (5) 192.168.1.162:9876 local window size: 65535 remote window size: 65535
D 2024-05-01T12:37:40.194Z | transport_internals | (5) 192.168.1.162:9876 session.closed=false session.destroyed=false session.socket.destroyed=false
D 2024-05-01T12:37:40.195Z | load_balancing_call | [6] Created child call [7]
D 2024-05-01T12:37:40.195Z | subchannel_call | [7] write() called with message of length 42
D 2024-05-01T12:37:40.195Z | subchannel_call | [7] sending data chunk of length 42
D 2024-05-01T12:37:40.195Z | load_balancing_call | [6] halfClose called
D 2024-05-01T12:37:40.195Z | subchannel_call | [7] end() called
D 2024-05-01T12:37:40.195Z | subchannel_call | [7] calling end() on HTTP/2 stream
D 2024-05-01T12:37:40.196Z | transport | (5) 192.168.1.162:9876 session closed
D 2024-05-01T12:37:40.196Z | subchannel | (4) 192.168.1.162:9876 READY -> IDLE
D 2024-05-01T12:37:40.196Z | subchannel_refcount | (4) 192.168.1.162:9876 refcount 2 -> 1
D 2024-05-01T12:37:40.196Z | pick_first | READY -> IDLE
D 2024-05-01T12:37:40.196Z | resolving_load_balancer | dns:192.168.1.162:9876 READY -> IDLE
D 2024-05-01T12:37:40.196Z | connectivity_state | (1) dns:192.168.1.162:9876 READY -> IDLE
D 2024-05-01T12:37:40.196Z | subchannel_call | [7] HTTP/2 stream closed with code 8
D 2024-05-01T12:37:40.196Z | subchannel_call | [7] ended with status: code=1 details="Call cancelled"
D 2024-05-01T12:37:40.196Z | load_balancing_call | [6] Received status
D 2024-05-01T12:37:40.197Z | load_balancing_call | [6] ended with status: code=1 details="Call cancelled"
D 2024-05-01T12:37:40.197Z | retrying_call | [5] Received status from child [6]
D 2024-05-01T12:37:40.197Z | retrying_call | [5] state=TRANSPARENT_ONLY handling status with progress PROCESSED from child [6] in state ACTIVE
D 2024-05-01T12:37:40.197Z | retrying_call | [5] ended with status: code=1 details="Call cancelled"
D 2024-05-01T12:37:40.197Z | resolving_call | [4] Received status
D 2024-05-01T12:37:40.197Z | resolving_call | [4] ended with status: code=1 details="Call cancelled"
node:internal/process/promises:288
            triggerUncaughtException(err, true /* fromPromise */);
            ^

Error: 1 CANCELLED: Call cancelled
    at callErrorFromStatus (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/call.js:31:19)
    at Object.onReceiveStatus (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client.js:192:76)
    at Object.onReceiveStatus (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:360:141)
    at Object.onReceiveStatus (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:323:181)
    at /Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/resolving-call.js:99:78
    at process.processTicksAndRejections (node:internal/process/task_queues:77:11)
for call at
    at ServiceClientImpl.makeUnaryRequest (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/client.js:160:32)
    at ServiceClientImpl.queryRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/node_modules/.pnpm/@grpc+grpc-js@1.9.1/node_modules/@grpc/grpc-js/build/src/make-client.js:105:19)
    at /Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client.js:45:20
    at new Promise (<anonymous>)
    at RpcClient.queryRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client.js:44:16)
    at RpcClientManger.queryRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-client-manger.js:51:32)
    at #fetchTopicRoute (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-base-client.js:160:54)
    at Producer.updateRoutes (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-base-client.js:145:40)
    at Timeout._onTimeout (/Users/muyouzhi/Code/rocketmq-grpc-client/dist/src/server/client/rpc-base-client.js:78:18)
    at listOnTimeout (node:internal/timers:569:17) {
  code: 1,
  details: 'Call cancelled',
  metadata: Metadata { internalRepr: Map(0) {}, options: {} }
}

Node.js v18.17.0

Steps to Reproduce

It is just a simple deployment and using the client to initiate message production requests. Everything is implemented in accordance with the official documents.

What Did You Expect to See?

success

What Did You See Instead?

io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 16777216: 1347569956 - discarded
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:503)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.failIfNecessary(LengthFieldBasedFrameDecoder.java:489)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.exceededFrameLength(LengthFieldBasedFrameDecoder.java:376)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:419)
    at org.apache.rocketmq.remoting.netty.NettyDecoder.decode(NettyDecoder.java:44)
    at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:332)
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:507)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
    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 org.apache.rocketmq.remoting.netty.NettyRemotingServer$TlsModeHandler.channelRead0(NettyRemotingServer.java:543)
    at org.apache.rocketmq.remoting.netty.NettyRemotingServer$TlsModeHandler.channelRead0(NettyRemotingServer.java:490)
    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.handlerRemoved(ByteToMessageDecoder.java:253)
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:514)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:446)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:61)
    at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:370)
    at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at java.base/java.lang.Thread.run(Thread.java:840)

Additional Context

image image image
coffee1110 commented 5 days ago

Hello, may I ask if this issue has been resolved? I am using RocketMQ version 4.7.1, and after checking the broker.log, I encountered the same problem mentioned above.