rocketmq icon indicating copy to clipboard operation
rocketmq copied to clipboard

[Bug] PullRequestHoldService send to close channel

Open gogodjzhu opened this issue 7 months ago • 0 comments

Before Creating the Bug Report

  • [X] I found a bug, not just asking a question, which should be created in GitHub Discussions.

  • [X] I have searched the GitHub Issues and GitHub Discussions of this repository and believe that this is not a duplicate.

  • [X] I have confirmed that this bug belongs to the current repository, not other repositories of RocketMQ.

Runtime platform environment

ubuntu20.04

RocketMQ version

branch: release-5.2.0 version: 5.2.0 commitId: 92c922378aa7c92e4239f0b46be8ea97ed257c2e

JDK Version

jdk1.8

Describe the Bug

Each time PullRequestHoldService.checkHoldRequest() is invoked, it attempts to write a response to a channel event closed. The invocation stack is as follows:

org.apache.rocketmq.broker.longpolling.PullRequestHoldService#run()
 - checkHoldRequest()
 - notifyMessageArriving()
 - executeRequestWhenWakeup()
 - NettyRemotingAbstract.writeResponse(channel) // channel is closed

This results in the following error logs:

2024-07-04 20:36:31.841 [NettyEventExecutor] WARN  RocketmqBroker - NETTY EVENT: removing inactive channel[ClientChannelInfo [channel=[id: 0x4b0a5f5a, L:/192.168.64.4:10911 ! R:/192.168.64.4:53572], clientId=192.168.64.4@685#556745049325417, language=JAVA, version=453, lastUpdateTimestamp=1720096583998]] from ConsumerGroupInfo groupChannelTable, consumer group: please_rename_unique_group_name_4
2024-07-04 20:36:44.869 [NettyServerNIOSelector_3] ERROR RocketmqRemoting - Failed to write response [request code: 11, response code: 24, opaque: 96] to channel [id: 0x4b0a5f5a, L:/192.168.64.4:10911 ! R:/192.168.64.4:53572]
io.netty.channel.StacklessClosedChannelException: null
       at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
2024-07-04 20:36:44.871 [NettyServerNIOSelector_3] ERROR RocketmqBroker - processRequestWrapper response to /192.168.64.4:53572 failed
io.netty.channel.StacklessClosedChannelException: null
       at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source)
2024-07-04 20:36:44.871 [NettyServerNIOSelector_3] ERROR RocketmqBroker - RemotingCommand [code=11, language=JAVA, version=453, opaque=96, flag(B)=0, remark=null, extFields={queueId=2, maxMsgBytes=262144, maxMsgNums=32, sysFlag=3, suspendTimeoutMillis=15000, commitOffset=164, bname=broker-0, topic=TopicTest, queueOffset=250, expressionType=TAG, subVersion=1720096583976, consumerGroup=please_rename_unique_group_name_4}, serializeTypeCurrentRPC=JSON]
2024-07-04 20:36:44.871 [NettyServerNIOSelector_3] ERROR RocketmqBroker - RemotingCommand [code=24, language=JAVA, version=453, opaque=96, flag(B)=1, remark=the consumer's group info does not exist. See https://rocketmq.apache.org/docs/bestPractice/06FAQ for further details., extFields=null, serializeTypeCurrentRPC=JSON]

The issue with this bug is the misleading error logs. The connection/channel has been closed and should not be used, yet still attempts to write to it and logs an error.

Additionally, there is a related issue#7670 which removes PullRequest from the pullRequestTable. However, it should also check if the channel is active before attempting to write to it.

Steps to Reproduce

At client side, start Consumer to consume some Message then close it. You can see some error log in broker side.

sh ./bin/tools.sh org.apache.rocketmq.example.quickstart.Producer
sh ./bin/tools.sh org.apache.rocketmq.example.quickstart.Consumer

What Did You Expect to See?

It should not log an error when the consumer client has intentionally unregistered.

What Did You See Instead?

Each time the consumer unregisters, an error log is generated in the broker.

Additional Context

No response

gogodjzhu avatar Jul 04 '24 12:07 gogodjzhu