apache / apache/pulsar

[Bug] Producer produced a message that consumer unable to receive (throw from ClientCnx.handleMessage)

Open
#21,961 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
Java
Stars
15.3k
Forks
3.8k
Avg merge
1d 14h
Merged PRs (30d)
160

Description

### Search before asking

- [X] I searched in the [issues](https://github.com/apache/pulsar/issues) and found nothing similar.

### Version

- producer 2.8.4 (java 11)
- consumer 2.8.4, 2.8.1, 3.0.1 all failed (java 11)
- broker 2.8.1.x (java 8)

### Minimal reproduce step

Producer application is under memory pressure (OOM occurs), I've write a simple program to simulate `ClientCnx.handleMessage` to process broken message.

### What did you expect to see?

- Producers or brokers should never generate or dispatch a corrupted message to consumers.
- If the above is unavoidable, consumers should be robust enough to handle receiving a corrupted message (perhaps by simply discarding it?)

### What did you see instead?

After a problematic application sent a large volume of messages to the broker, several brokers crashed due to Out-Of-Memory (OOM) errors related to direct memory.

Subsequently, we observed that one of our consumer applications consistently encountered errors while acknowledging messages:
```
org.apache.pulsar.client.api.PulsarClientException$ConnectException: Consumer connect fail! consumer state:Connecting
at org.apache.pulsar.client.api.PulsarClientException.unwrap(PulsarClientException.java:973)
at org.apache.pulsar.client.impl.ConsumerBase.acknowledge(ConsumerBase.java:317)
at org.apache.pulsar.client.impl.ConsumerBase.acknowledge(ConsumerBase.java:305)
```
There are some other error messages on the same consumer instance:
```
2024-01-22T13:22:02.240Z [pulsar-client-io-6-1] WARN org.apache.pulsar.client.impl.ClientCnx - \
[xx.xx.92.10/xx.xx.92.10:6650] Got exception java.lang.IndexOutOfBoundsException: \
readerIndex(92) + length(4) exceeds writerIndex(92): PooledSlicedByteBuf(ridx: 92, widx: 92, cap: 92/92, unwrapped: PooledUnsafeDirectByteBuf(ridx: 96, widx: 2048, cap: 2048))
at org.apache.pulsar.shade.io.netty.buffer.AbstractByteBuf.checkReadableBytes0(AbstractByteBuf.java:1442)
at org.apache.pulsar.shade.io.netty.buffer.AbstractByteBuf.readInt(AbstractByteBuf.java:809)
at org.apache.pulsar.shade.io.netty.buffer.AbstractByteBuf.readUnsignedInt(AbstractByteBuf.java:825)
at org.apache.pulsar.common.protocol.Commands.deSerializeSingleMessageInBatch(Commands.java:1634)
at org.apache.pulsar.client.impl.ConsumerImpl.receiveIndividualMessagesFromBatch(ConsumerImpl.java:1261)
at org.apache.pulsar.client.impl.ConsumerImpl.messageReceived(ConsumerImpl.java:1100)
at org.apache.pulsar.client.impl.ClientCnx.handleMessage(ClientCnx.java:451)
at org.apache.pulsar.common.protocol.PulsarDecoder.channelRead(PulsarDecoder.java:186)
at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at org.apache.pulsar.shade.io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327)
at org.apache.pulsar.shade.io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:314)
at org.apache.pulsar.shade.io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:435)
at org.apache.pulsar.shade.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:279)
at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
at org.apache.pulsar.shade.io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
at org.apache.pulsar.shade.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
at org.apache.pulsar.shade.io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:800)
at org.apache.pulsar.shade.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:487)
at org.apache.pulsar.shade.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:385)
at org.apache.pulsar.shade.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:995)
at org.apache.pulsar.shade.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at org.apache.pulsar.shade.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
```

I've seen that consumer client keep sent `RST` to close underling tcp connection through packet capture:
image
image
I believe this is the expected behavior when `ClientCnx` encounters unknown exceptions:
https://github.com/apache/pulsar/blob/480a229d8fb637232bd37b7a72dfe8a298c72000/pulsar-client/src/main/java/org/apache/pulsar/client/impl/ClientCnx.java#L343-L357

I've extracted the specific broken message from the capture, and write a simple program to read this protocol `MESSAGE` to simulate `ClientCnx.handleMessage`:
```java
import com.google.common.io.Files;
import org.apache.pulsar.common.api.proto.BaseCommand;
import org.apache.pulsar.common.api.proto.CommandMessage;
import org.apache.pulsar.common.api.proto.MessageIdData;
import org.apache.pulsar.common.api.proto.MessageMetadata;
import org.apache.pulsar.common.protocol.Commands;
import org.apache.pulsar.shade.io.netty.buffer.ByteBuf;
import org.apache.pulsar.shade.io.netty.buffer.ByteBufAllocator;

import java.io.File;
import java.io.IOException;
import java.nio.ByteBuffer;

class Scratch {
public static void main(String[] args) throws IOException {
File file = new File("broken-message-extracted.bin");
byte[] data = Files.asByteSource(file).read();
ByteBuffer msg = ByteBuffer.wrap(data);
int length = msg.getInt();
byte[] dst = new byte[length];
msg.get(dst);
ByteBuf buffer = ByteBufAllocator.DEFAULT.buffer().writeBytes(dst);
BaseCommand cmd = new BaseCommand();
cmd.parseFrom(buffer, (int) buffer.readUnsignedInt());
// print "MESSAGE"
System.out.println(cmd.getType());
CommandMessage message = cmd.getMessage();
MessageIdData messageId = message.getMessageId();
// print "ledgerId: 115091324, entryId: 1644, partition: 1"
System.out.printf("ledgerId: %d, entryId: %d, partition: %d\n", messageId.getLedgerId(), messageId.getEntryId(), messageId.getPartition());
MessageMetadata messageMetadata = Commands.parseMessageMetadata(buffer);
// print "sequenceId: -1, highestSequenceId: -1"
System.out.printf("sequenceId: %d, highestSequenceId: %d\n", messageMetadata.getSequenceId(), messageMetadata.getHighestSequenceId());
// print "compression: NONE, uncompressedSize: 0"
System.out.printf("compression: %s, uncompressedSize: %d\n", messageMetadata.getCompression(), messageMetadata.getUncompressedSize());
// print "publishTime: 1705902570650, eventTime: 0"
System.out.printf("publishTime: %d, eventTime: %d\n", messageMetadata.getPublishTime(), messageMetadata.getEventTime());
// print "producerName: pulsar-idc-a-464-428776, numMessagesInBatch: 1"
System.out.printf("producerName: %s, numMessagesInBatch: %d\n", messageMetadata.getProducerName(), messageMetadata.getNumMessagesInBatch());
// throw java.lang.IndexOutOfBoundsException: readerIndex(92) + length(4) exceeds writerIndex(92): PooledUnsafeDirectByteBuf(ridx: 92, widx: 92, cap: 256)
buffer.readUnsignedInt();
}
}
```
Here is `broken-message-extracted.bin` in base64:
`AAAAXAAAABIICUoOCDwSCgj8zvA2EOwMGAEOAW361skAAAA8ChdwdWxzYXItaWRjLWEtNDY0LTQyODc3NhD///////////8BGJr53f3SMVgBggEAwAH///////////8B`

Looks like it is a batch message with batchSize=1, but the `SingleMessageMetadata` and payload is missing. Therefore, the message decoding process will throw an `IndexOutOfBoundsException` in `Commands.deSerializeSingleMessageInBatch`:
https://github.com/apache/pulsar/blob/480a229d8fb637232bd37b7a72dfe8a298c72000/pulsar-common/src/main/java/org/apache/pulsar/common/protocol/Commands.java#L1876-L1885

### Anything else?

More context:
- Unloading the topic and restarting the broker does not resolve this issue. The only workaround seems to be skipping the broken message.
- The topic have 3 partitions, there are only one broken message found on partition-1
- Producer application have memory pressure, found some OOM error in the log around the `publishTime` of broken message
```
Caused by: java.lang.OutOfMemoryError: Java heap space
at java.base/java.util.Arrays.copyOf(Arrays.java:3689)
at java.base/java.util.ArrayList.grow(ArrayList.java:237)
at java.base/java.util.ArrayList.grow(ArrayList.java:242)
at java.base/java.util.ArrayList.add(ArrayList.java:485)
at java.base/java.util.ArrayList.add(ArrayList.java:498)
at org.apache.pulsar.client.impl.BatchMessageContainerImpl.add(BatchMessageContainerImpl.java:108)
at org.apache.pulsar.client.impl.BatchMessageKeyBasedContainer.add(BatchMessageKeyBasedContainer.java:52)
at org.apache.pulsar.client.impl.ProducerImpl.serializeAndSendMessage(ProducerImpl.java:548)
at org.apache.pulsar.client.impl.ProducerImpl.sendAsync(ProducerImpl.java:478)
at org.apache.pulsar.client.impl.ProducerImpl.internalSendAsync(ProducerImpl.java:310)
at org.apache.pulsar.client.impl.ProducerImpl.internalSendWithTxnAsync(ProducerImpl.java:381)
at org.apache.pulsar.client.impl.PartitionedProducerImpl.internalSendWithTxnAsync(PartitionedProducerImpl.java:191)
at org.apache.pulsar.client.impl.PartitionedProducerImpl.internalSendAsync(PartitionedProducerImpl.java:167)
at org.apache.pulsar.client.impl.TypedMessageBuilderImpl.sendAsync(TypedMessageBuilderImpl.java:103)
```
- There is a related issue #11930 closed as stale

### Are you willing to submit a PR?

- [ ] I'm willing to submit a PR!

Contributor guide

Open the contributing guide

Research direction

Start with ClientCnx.handleMessage and Commands.deSerializeSingleMessageInBatch at the linked revisions, then run the supplied Scratch reproducer against the provided broken message. Trace how ConsumerImpl.receiveIndividualMessagesFromBatch handles the incomplete batch and determine whether the intended change is producer/broker prevention or consumer-side handling. Done means the corrupted-message scenario has defined behavior and regression coverage.

Written by the indexing model from the issue text.

Assessment

Tech stack
java
Domain
distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.