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.

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

[Bug] Failed to verify checksum #21557

Closed
2 tasks done
zifengmo opened this issue Nov 10, 2023 · 15 comments · Fixed by #21684
Closed
2 tasks done

[Bug] Failed to verify checksum #21557

zifengmo opened this issue Nov 10, 2023 · 15 comments · Fixed by #21684
Assignees
Labels
type/bug The PR fixed a bug or issue reported a bug

Comments

@zifengmo
Copy link
Contributor

Search before asking

  • I searched in the issues and found nothing similar.

Version

brokers : 3.0.1
clients : 2.5.2 and 3.0.1

Minimal reproduce step

When I upgraded the broker to version 3.0.1, I started experiencing an issue with the producer sending messages. This issue doesn't always occur and seems to be related to the size of the messages being sent. It happens intermittently, with intervals ranging from a few hours to a few minutes.I can confirm that the message length is very short, less than 1k.And when I upgraded the client version from 2.5.2 to 3.0.1, the errors did not decrease, but instead became more frequent.

What did you expect to see?

No error is occurring.

What did you see instead?

2023-11-09T08:05:10,961+0000 [pulsar-io-4-3] ERROR org.apache.pulsar.broker.service.Producer - [PersistentTopic{topic=persistent://testa/out/event-partition-19}] [mqe-71-347] Failed to verify checksum
2023-11-09T08:05:10,964+0000 [pulsar-io-4-3] WARN org.apache.pulsar.broker.service.ServerCnx - [/172.0.3.33:53878] Got exception io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 5253120: 101194516 - discarded
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:507)
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.failIfNecessary(LengthFieldBasedFrameDecoder.java:493)
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.exceededFrameLength(LengthFieldBasedFrameDecoder.java:377)
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:423)
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:333)
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
at org.apache.pulsar.common.protocol.OptionalProxyProtocolDecoder.channelRead(OptionalProxyProtocolDecoder.java:52)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.handler.flush.FlushConsolidationHandler.channelRead(FlushConsolidationHandler.java:152)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:397)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:842)

Anything else?

No response

Are you willing to submit a PR?

  • I'm willing to submit a PR!
@zifengmo zifengmo added the type/bug The PR fixed a bug or issue reported a bug label Nov 10, 2023
@poorbarcode poorbarcode self-assigned this Nov 17, 2023
@poorbarcode
Copy link
Contributor

@zifengmo Could you share the code of the producer builder? And a Broker heap dump when the issue occurs.

@poorbarcode
Copy link
Contributor

BTW, the messages will be packaged as a batched message if you enabled enableBatching(default value is true)

@poorbarcode
Copy link
Contributor

poorbarcode commented Nov 17, 2023

@BewareMyPower
Copy link
Contributor

@poorbarcode Is there any workaround if it's a Netty bug?

@zifengmo
Copy link
Contributor Author

BTW, the messages will be packaged as a batched message if you enabled enableBatching(default value is true)

The code of the producer builder:

private Producer getProducer(String topic) throws PulsarClientException {
Producer producer = producerMap.get(topic);
if (producer != null) {
return producer;
}
producerCreationLock.lock();
try {
producer = producerMap.get(topic);
if (producer == null) {
producer = pulsarClient.newProducer()
.sendTimeout(3, TimeUnit.SECONDS)
.enableBatching(false)
.topic(topic)
.messageRoutingMode(MessageRoutingMode.CustomPartition).messageRouter(new MessageRouter() {
@OverRide
public int choosePartition(Message<?> message, TopicMetadata metadata) {
int topicPartitionNum = metadata.numPartitions();
int keyHashCode = message.getKey().hashCode();
if (keyHashCode == Integer.MIN_VALUE) {
keyHashCode = topicPartitionNum - 1;
}
return Math.abs(keyHashCode) % topicPartitionNum;
}
}).create();
producerMap.put(topic, producer);
}
} finally {
producerCreationLock.unlock();
}
return producer;
}

@zifengmo
Copy link
Contributor Author

The code of the message builder :
TypedMessageBuilder messageBuilder = producer.newMessage().key(key).value(data.toString().getBytes());
CompletableFuture messageIdCompletableFuture= messageBuilder.sendAsync();

And because of this problem, the broker has been rolled back.But it cannot be reproduced locally. I will redeploy it later to check.

@poorbarcode
Copy link
Contributor

@zifengmo

And because of this problem, the broker has been rolled back. But it cannot be reproduced locally. I will redeploy it later to check.

Thanks. Could you provide the client logs around the issue occurring?

@qiaofazhan
Copy link

qiaofazhan commented Nov 21, 2023

I have the same problem.

version: broker 3.0.1 client 3.0.1

The same problem often occurs when I use remote replication in multiple clusters. This prevents messages from being replicated to the remote cluster. At the moment, I can only temporarily resolve this by restarting the pulsar brokers.

logs like this:

2023-11-08T08:01:04,101+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server
2023-11-08T08:01:04,109+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker
2023-11-08T08:01:04,109+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server
2023-11-08T08:01:04,118+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker
2023-11-08T08:01:04,118+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server
2023-11-08T08:01:04,128+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker
2023-11-08T08:01:04,128+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server
2023-11-08T08:01:04,137+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker
2023-11-08T08:01:04,137+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server
2023-11-08T08:01:04,147+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker
2023-11-08T08:01:04,147+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server
2023-11-08T08:01:04,155+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker

@poorbarcode
Copy link
Contributor

poorbarcode commented Nov 21, 2023

@qiaofazhan Could we start a meeting to talk about how to reproduce this issue?

cc: @zifengmo


@qiaofazhan Could you provide more logs that before the issue occurs?

@zifengmo
Copy link
Contributor Author

@zifengmo

And because of this problem, the broker has been rolled back. But it cannot be reproduced locally. I will redeploy it later to check.

Thanks. Could you provide the client logs around the issue occurring?

This is the debug log before and after the issue occurred.

2023-11-09T09:02:44,589+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,589+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 29:1250 mqe-79-11:1250 size: 396, partition key is: 65d1f5964e5191e0422vmi, ordering key is null, uncompressedSize is 332
2023-11-09T09:02:44,589+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] asyncAddEntry size=396 state=LedgerOpened
2023-11-09T09:02:44,589+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,589+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 12:780 mqe-79-22:780 size: 971, partition key is: 6556a2caf3c1a01cc0s9cl, ordering key is null, uncompressedSize is 907
2023-11-09T09:02:44,589+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-12] asyncAddEntry size=971 state=LedgerOpened
2023-11-09T09:02:44,589+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - Created new OpAddEntry OpAddEntry{mlName=dlghphniuyhgydjmvkld/out/persistent/event-partition-29, ledgerId=null, entryId=-1, startTime=7439057180093416, dataLength=396}
2023-11-09T09:02:44,589+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] Write into current ledger lh=881992 entries=1332
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 9:1005 mqe-79-23:1005 size: 971, partition key is: 658205705425a83918pueo, ordering key is null, uncompressedSize is 907
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-9] asyncAddEntry size=971 state=LedgerOpened
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 47:1013 mqe-79-4:1013 size: 414, partition key is: 65d838ee1d11d40104yifc, ordering key is null, uncompressedSize is 351
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-47] asyncAddEntry size=414 state=LedgerOpened
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 47:1014 mqe-79-4:1014 size: 414, partition key is: 65ab6d7740f1604bc3ysbx, ordering key is null, uncompressedSize is 351
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-47] asyncAddEntry size=414 state=LedgerOpened
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 53:1003 mqe-79-2:1003 size: 478, partition key is: 65c2c89f849a506c26hwpl, ordering key is null, uncompressedSize is 415
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-53] asyncAddEntry size=478 state=LedgerOpened
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 0:1199 mqe-79-30:1199 size: 396, partition key is: 65492b7f84a96906b3xgah, ordering key is null, uncompressedSize is 332
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-0] asyncAddEntry size=396 state=LedgerOpened
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 34:1268 mqe-79-9:1268 size: 478, partition key is: 65a45c1b6e57b38e08ygvd, ordering key is null, uncompressedSize is 415
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-34] asyncAddEntry size=478 state=LedgerOpened
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 24:1353 mqe-79-15:1353 size: 413, partition key is: 576285373c71bf37f221, ordering key is null, uncompressedSize is 351
2023-11-09T09:02:44,591+0000 [pulsar-io-4-4] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-24] asyncAddEntry size=413 state=LedgerOpened
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - Created new OpAddEntry OpAddEntry{mlName=dlghphniuyhgydjmvkld/out/persistent/event-partition-47, ledgerId=null, entryId=-1, startTime=7439057182221115, dataLength=414}
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-47] Write into current ledger lh=881971 entries=1158
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - Created new OpAddEntry OpAddEntry{mlName=dlghphniuyhgydjmvkld/out/persistent/event-partition-47, ledgerId=null, entryId=-1, startTime=7439057182247525, dataLength=414}
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-47] Write into current ledger lh=881971 entries=1159
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - Created new OpAddEntry OpAddEntry{mlName=dlghphniuyhgydjmvkld/out/persistent/event-partition-53, ledgerId=null, entryId=-1, startTime=7439057182256545, dataLength=478}
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-53] Write into current ledger lh=881967 entries=1041
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - Created new OpAddEntry OpAddEntry{mlName=dlghphniuyhgydjmvkld/out/persistent/event-partition-24, ledgerId=null, entryId=-1, startTime=7439057182268765, dataLength=413}
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-24] Write into current ledger lh=881985 entries=1572
2023-11-09T09:02:44,591+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.proto.PerChannelBookieClient - Got Add response from bookie:172.26.3.151:3181 rc:EOK, ledger:881992:entry:1331
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.proto.PerChannelBookieClient - Got Add response from bookie:172.26.3.149:3181 rc:EOK, ledger:881992:entry:1331
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.client.PendingAddOp - Submit callback (lid:881992, eid: 1331). rc:0
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.OpAddEntry - [OpAddEntry{mlName=dlghphniuyhgydjmvkld/out/persistent/event-partition-29, ledgerId=881992, entryId=1331, startTime=7439057180093416, dataLength=396}] [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] write-complete: ledger-id=881992 entry-id=1331 size=396 rc=0
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.cache.RangeEntryCacheImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] Adding entry to cache: 881992:1331 - size: 396
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.pulsar.broker.service.Producer - [PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-29}] [mqe-79-11] [29] triggered send callback. cnx /172.22.2.22:44262, sequenceId 1250
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] [dlghphniuyhgydjmvkld-sub] Received ml notification
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] [dlghphniuyhgydjmvkld-sub] Received notification of new messages persisted, reading at 881992:1331 -- last: 881992:1331
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] Consumer dlghphniuyhgydjmvkld-sub cursor notification: other counters: consumed 1331 mdPos 881992:1330 rdPos 881992:1331
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedLedgerImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] Reading entries from ledger 881992 - first=1331 last=1331
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.cache.RangeEntryCacheImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] Reading entries range ledger 881992: 1331 to 1331
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.cache.RangeEntryCacheImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] Ledger 881992 -- Found in cache entries: 1331-1331
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.OpReadEntry - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29][dlghphniuyhgydjmvkld-sub] Read entries succeeded batch_size=1 cumulative_size=0 requested_count=100
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] [dlghphniuyhgydjmvkld-sub] Filtering entries [881992:1331..881992:1331] - alreadyDeleted: []
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] [dlghphniuyhgydjmvkld-sub] No filtering needed for entries [881992:1331..881992:1331]
2023-11-09T09:02:44,592+0000 [BookKeeperClientWorker-OrderedExecutor-0-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://dlghphniuyhgydjmvkld/out/event-partition-29 / dlghphniuyhgydjmvkld-sub] Distributing 1 messages to 7 consumers
2023-11-09T09:02:44,592+0000 [broker-topic-workers-OrderedExecutor-1-0] DEBUG org.apache.pulsar.broker.service.Consumer - [persistent://dlghphniuyhgydjmvkld/out/event-partition-29-PersistentSubscription{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-29, name=dlghphniuyhgydjmvkld-sub}] Added 881992:1331 ledger entry with batchSize of 1 to pendingAcks in broker.service.Consumer for consumerId: 29
2023-11-09T09:02:44,592+0000 [broker-topic-workers-OrderedExecutor-1-0] DEBUG org.apache.pulsar.broker.service.Consumer - [persistent://dlghphniuyhgydjmvkld/out/event-partition-29-PersistentSubscription{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-29, name=dlghphniuyhgydjmvkld-sub}] Added 0 minus 1 messages to MESSAGE_PERMITS_UPDATER in broker.service.Consumer for consumerId: 29; avgMessagesPerEntry is 1.0
2023-11-09T09:02:44,592+0000 [broker-topic-workers-OrderedExecutor-1-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://dlghphniuyhgydjmvkld/out/event-partition-29 / dlghphniuyhgydjmvkld-sub] Added -(1 minus 0) permits to TOTAL_AVAILABLE_PERMITS_UPDATER in PersistentDispatcherMultipleConsumers
2023-11-09T09:02:44,592+0000 [broker-topic-workers-OrderedExecutor-1-0] DEBUG org.apache.pulsar.broker.service.persistent.PersistentDispatcherMultipleConsumers - [persistent://dlghphniuyhgydjmvkld/out/event-partition-29 / dlghphniuyhgydjmvkld-sub] Schedule read of 100 messages for 7 consumers
2023-11-09T09:02:44,592+0000 [broker-topic-workers-OrderedExecutor-1-0] DEBUG org.apache.bookkeeper.mledger.impl.ManagedCursorImpl - [dlghphniuyhgydjmvkld/out/persistent/event-partition-29] [dlghphniuyhgydjmvkld-sub] Deferring retry of read at position 881992:1332
2023-11-09T09:02:44,592+0000 [pulsar-io-4-2] DEBUG org.apache.pulsar.broker.service.PulsarCommandSenderImpl - [persistent://dlghphniuyhgydjmvkld/out/event-partition-29-PersistentSubscription{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-29, name=dlghphniuyhgydjmvkld-sub}] Sending message to consumerId 29, msg id 881992-1331 with batchSize 1
2023-11-09T09:02:44,592+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - [PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-29}] [mqe-79-11] [29] Persisted message. cnx org.apache.pulsar.broker.service.ServerCnx@11792789, sequenceId 1250
2023-11-09T09:02:44,593+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.common.protocol.PulsarDecoder - [/172.22.2.22:44262] Received cmd SEND
2023-11-09T09:02:44,593+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Received send message request. producer: 7:696 mqe-79-25:696 size: 1015, partition key is: 65c74c268d2d078505195o, ordering key is null, uncompressedSize is 951
2023-11-09T09:02:44,593+0000 [pulsar-io-4-4] ERROR org.apache.pulsar.broker.service.Producer - [PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-7}] [mqe-79-25] Failed to verify checksum
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] WARN org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Got exception io.netty.handler.codec.TooLongFrameException: Adjusted frame length exceeds 5253120: 134623753 - discarded
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.fail(LengthFieldBasedFrameDecoder.java:507)
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.failIfNecessary(LengthFieldBasedFrameDecoder.java:493)
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.exceededFrameLength(LengthFieldBasedFrameDecoder.java:377)
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:423)
at io.netty.handler.codec.LengthFieldBasedFrameDecoder.decode(LengthFieldBasedFrameDecoder.java:333)
at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529)
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468)
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
at org.apache.pulsar.common.protocol.OptionalProxyProtocolDecoder.channelRead(OptionalProxyProtocolDecoder.java:52)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.handler.flush.FlushConsolidationHandler.channelRead(FlushConsolidationHandler.java:152)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499)
at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:397)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base/java.lang.Thread.run(Thread.java:842)

2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] connect state change to : [Failed]
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] INFO org.apache.pulsar.broker.service.ServerCnx - Closed connection from /172.22.2.22:44262
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-0] [mqe-79-30] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=0, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-0}, client=/172.22.2.22:44262, producerName=mqe-79-30, producerId=0}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-0}, client=/172.22.2.22:44262, producerName=mqe-79-30, producerId=0}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-21] [mqe-79-17] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=21, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-21}, client=/172.22.2.22:44262, producerName=mqe-79-17, producerId=21}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-21}, client=/172.22.2.22:44262, producerName=mqe-79-17, producerId=21}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-42] [mqe-79-7] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=42, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-42}, client=/172.22.2.22:44262, producerName=mqe-79-7, producerId=42}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-42}, client=/172.22.2.22:44262, producerName=mqe-79-7, producerId=42}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-4] [mqe-79-27] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=4, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-4}, client=/172.22.2.22:44262, producerName=mqe-79-27, producerId=4}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-4}, client=/172.22.2.22:44262, producerName=mqe-79-27, producerId=4}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-9] [mqe-79-23] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=9, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-9}, client=/172.22.2.22:44262, producerName=mqe-79-23, producerId=9}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-9}, client=/172.22.2.22:44262, producerName=mqe-79-23, producerId=9}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-47] [mqe-79-4] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=47, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-47}, client=/172.22.2.22:44262, producerName=mqe-79-4, producerId=47}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-47}, client=/172.22.2.22:44262, producerName=mqe-79-4, producerId=47}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-13] [mqe-79-21] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=13, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-13}, client=/172.22.2.22:44262, producerName=mqe-79-21, producerId=13}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-13}, client=/172.22.2.22:44262, producerName=mqe-79-21, producerId=13}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-25] [mqe-79-14] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=25, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-25}, client=/172.22.2.22:44262, producerName=mqe-79-14, producerId=25}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-25}, client=/172.22.2.22:44262, producerName=mqe-79-14, producerId=25}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-8] [mqe-79-24] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=8, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-8}, client=/172.22.2.22:44262, producerName=mqe-79-24, producerId=8}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-8}, client=/172.22.2.22:44262, producerName=mqe-79-24, producerId=8}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-53] [mqe-79-2] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=53, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-53}, client=/172.22.2.22:44262, producerName=mqe-79-2, producerId=53}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-53}, client=/172.22.2.22:44262, producerName=mqe-79-2, producerId=53}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-1] [mqe-79-29] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=1, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-1}, client=/172.22.2.22:44262, producerName=mqe-79-29, producerId=1}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-1}, client=/172.22.2.22:44262, producerName=mqe-79-29, producerId=1}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-12] [mqe-79-22] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=12, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-12}, client=/172.22.2.22:44262, producerName=mqe-79-22, producerId=12}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-12}, client=/172.22.2.22:44262, producerName=mqe-79-22, producerId=12}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://kea7r5qxrxmrvwq4vjxe/out/event-partition-6] [mqe-79-34] Removed producer -- count: 1
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=67, producer=Producer{topic=PersistentTopic{topic=persistent://kea7r5qxrxmrvwq4vjxe/out/event-partition-6}, client=/172.22.2.22:44262, producerName=mqe-79-34, producerId=67}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://kea7r5qxrxmrvwq4vjxe/out/event-partition-6}, client=/172.22.2.22:44262, producerName=mqe-79-34, producerId=67}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-26] [mqe-79-13] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=26, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-26}, client=/172.22.2.22:44262, producerName=mqe-79-13, producerId=26}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-26}, client=/172.22.2.22:44262, producerName=mqe-79-13, producerId=26}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-5] [mqe-79-26] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=5, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-5}, client=/172.22.2.22:44262, producerName=mqe-79-26, producerId=5}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-5}, client=/172.22.2.22:44262, producerName=mqe-79-26, producerId=5}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-16] [mqe-79-20] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=16, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-16}, client=/172.22.2.22:44262, producerName=mqe-79-20, producerId=16}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-16}, client=/172.22.2.22:44262, producerName=mqe-79-20, producerId=16}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-17] [mqe-79-19] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=17, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-17}, client=/172.22.2.22:44262, producerName=mqe-79-19, producerId=17}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-17}, client=/172.22.2.22:44262, producerName=mqe-79-19, producerId=17}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://kea7r5qxrxmrvwq4vjxe/out/event-partition-9] [mqe-79-35] Removed producer -- count: 1
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=70, producer=Producer{topic=PersistentTopic{topic=persistent://kea7r5qxrxmrvwq4vjxe/out/event-partition-9}, client=/172.22.2.22:44262, producerName=mqe-79-35, producerId=70}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://kea7r5qxrxmrvwq4vjxe/out/event-partition-9}, client=/172.22.2.22:44262, producerName=mqe-79-35, producerId=70}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-29] [mqe-79-11] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=29, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-29}, client=/172.22.2.22:44262, producerName=mqe-79-11, producerId=29}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-29}, client=/172.22.2.22:44262, producerName=mqe-79-11, producerId=29}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-52] [mqe-79-3] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=52, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-52}, client=/172.22.2.22:44262, producerName=mqe-79-3, producerId=52}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-52}, client=/172.22.2.22:44262, producerName=mqe-79-3, producerId=52}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.AbstractTopic - [persistent://dlghphniuyhgydjmvkld/out/event-partition-43] [mqe-79-6] Removed producer -- count: 8
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.ServerCnx - [/172.22.2.22:44262] Removed producer: producerId=43, producer=Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-43}, client=/172.22.2.22:44262, producerName=mqe-79-6, producerId=43}
2023-11-09T09:02:44,594+0000 [pulsar-io-4-4] DEBUG org.apache.pulsar.broker.service.Producer - Removed producer: Producer{topic=PersistentTopic{topic=persistent://dlghphniuyhgydjmvkld/out/event-partition-43}, client=/172.22.2.22:44262, producerName=mqe-79-6, producerId=43}

@zifengmo
Copy link
Contributor Author

I have the same problem.

version: broker 3.0.1 client 3.0.1

The same problem often occurs when I use remote replication in multiple clusters. This prevents messages from being replicated to the remote cluster. At the moment, I can only temporarily resolve this by restarting the pulsar brokers.

logs like this:

2023-11-08T08:01:04,101+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server 2023-11-08T08:01:04,109+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker 2023-11-08T08:01:04,109+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server 2023-11-08T08:01:04,118+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker 2023-11-08T08:01:04,118+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server 2023-11-08T08:01:04,128+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker 2023-11-08T08:01:04,128+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server 2023-11-08T08:01:04,137+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker 2023-11-08T08:01:04,137+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server 2023-11-08T08:01:04,147+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker 2023-11-08T08:01:04,147+0000 [pulsar-io-8-8] INFO org.apache.pulsar.client.impl.ProducerImpl - [persistent://it_develop/gndp-enp/event03] [pulsar.repl.idc-pulsar-sit-->aliyun-pulsar-sit] Re-Sending 173 messages to server 2023-11-08T08:01:04,155+0000 [pulsar-io-8-8] WARN org.apache.pulsar.client.impl.ClientCnx - [id: 0xf4214837, L:/10.251.21.37:49360 - R:10.182.137.13/10.182.137.13:6650] Received send error from server: ChecksumError : Checksum failed on the broker

The client logs are the same as his.

@zifengmo
Copy link
Contributor Author

@qiaofazhan Could we start a meeting to talk about how to reproduce this issue?
cc: @zifengmo
@qiaofazhan Could you provide more logs that before the issue occurs?

Sure, when is a suitable time for you? You can either directly send the meeting invitation code ,or your social media.

@zifengmo zifengmo reopened this Nov 21, 2023
@poorbarcode
Copy link
Contributor

@poorbarcode
Copy link
Contributor

@qiaofazhan

I think I found the root cause:

@zifengmo

The issue fixed by apache/bookkeeper#4140 is different from the issue you hit.

@poorbarcode
Copy link
Contributor

@zifengmo

Are you using HaProxy or other proxies? One user hit the same problem caused by using HaProxy. see the doc

Screenshot 2023-12-06 at 17 43 27

poorbarcode added a commit that referenced this issue Dec 8, 2023
…21684)

Fixes #21557

### Motivation

There is a network package loss issue after enabling `haProxyProtocolEnabled`, which leads the error `Checksum failed on the broker` and `Adjusted frame length exceeds`, you can reproduce the issue by the test `testSlowNetwork`. 

### Modifications

Fix the bug.
poorbarcode added a commit that referenced this issue Dec 13, 2023
…21684)

Fixes #21557

### Motivation

There is a network package loss issue after enabling `haProxyProtocolEnabled`, which leads the error `Checksum failed on the broker` and `Adjusted frame length exceeds`, you can reproduce the issue by the test `testSlowNetwork`.

### Modifications

Fix the bug.

(cherry picked from commit 6e18874)
poorbarcode added a commit that referenced this issue Dec 13, 2023
…21684)

Fixes #21557

There is a network package loss issue after enabling `haProxyProtocolEnabled`, which leads the error `Checksum failed on the broker` and `Adjusted frame length exceeds`, you can reproduce the issue by the test `testSlowNetwork`.

Fix the bug.

(cherry picked from commit 6e18874)
poorbarcode added a commit that referenced this issue Dec 13, 2023
…21684)

Fixes #21557

### Motivation

There is a network package loss issue after enabling `haProxyProtocolEnabled`, which leads the error `Checksum failed on the broker` and `Adjusted frame length exceeds`, you can reproduce the issue by the test `testSlowNetwork`.

### Modifications

Fix the bug.

(cherry picked from commit 6e18874)
poorbarcode added a commit that referenced this issue Dec 13, 2023
…21684)

Fixes #21557

### Motivation

There is a network package loss issue after enabling `haProxyProtocolEnabled`, which leads the error `Checksum failed on the broker` and `Adjusted frame length exceeds`, you can reproduce the issue by the test `testSlowNetwork`.

### Modifications

Fix the bug.

(cherry picked from commit 6e18874)
nikhil-ctds pushed a commit to datastax/pulsar that referenced this issue Dec 20, 2023
…pache#21684)

Fixes apache#21557

### Motivation

There is a network package loss issue after enabling `haProxyProtocolEnabled`, which leads the error `Checksum failed on the broker` and `Adjusted frame length exceeds`, you can reproduce the issue by the test `testSlowNetwork`.

### Modifications

Fix the bug.

(cherry picked from commit 6e18874)
srinath-ctds pushed a commit to datastax/pulsar that referenced this issue Dec 20, 2023
…pache#21684)

Fixes apache#21557

### Motivation

There is a network package loss issue after enabling `haProxyProtocolEnabled`, which leads the error `Checksum failed on the broker` and `Adjusted frame length exceeds`, you can reproduce the issue by the test `testSlowNetwork`.

### Modifications

Fix the bug.

(cherry picked from commit 6e18874)
nodece pushed a commit to nodece/pulsar that referenced this issue Feb 23, 2024
…pache#21684)

Fixes apache#21557

There is a network package loss issue after enabling `haProxyProtocolEnabled`, which leads the error `Checksum failed on the broker` and `Adjusted frame length exceeds`, you can reproduce the issue by the test `testSlowNetwork`.

Fix the bug.

(cherry picked from commit 6e18874)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type/bug The PR fixed a bug or issue reported a bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants