Read committed consumer returns error when reading large amount of consecutive aborted messages

[DylanMeador]

Description

I retrieve the following error when trying to read my topic:
Message at offset 2163394 might be too large to fetch, try increasing receive.message.max.bytes

I tried setting receive.message.max.bytes to the maximum value (100000000), but that didn't help at all.

I believe what is happening is that librdkafka is reaching the maximum allowable size for one of it's buffers and then returning an error. I believe this is being caused by the fact that there are a lot of messages that are uncommitted before actually reaching a committed message.

Note:
I think there is an error with the debug statement causing it to log the transaction abort offset instead of the skipped message offset. See here: https://github.com/edenhill/librdkafka/blob/master/src/rdkafka_msgset_reader.c#L1107-L1115

How to reproduce

Transactionally emit a bunch of messages to a topic and then abort the transaction instead of committing (I personally was experiencing a transaction timeout, but assuming that shouldn't matter). Do this a lot, to ensure that the maximum size of the buffer will be reached. For my message size, it would read about 1.8 million messages before returning an error. After the topic is populated (with a bunch of aborted messages), attempt to read all the messages on this topic and you should eventually see an error.

Note: I'm using confluent-kafka-go, but after looking at the source, I think this is a problem with librdkafka.

Checklist

• librdkafka version: librdkafka v1.4.2
• Apache Kafka version: unknown
• librdkafka client configuration:
  "isolation.level": "read_committed" - This causes the error
  "isolation.level": "read_uncommitted" - This works without any errors
• Operating system: macOS
• Logs

Protocol read buffer underflow at 4193825/4194398 (rd_kafka_msgset_reader_v2:1044): expected 1319 bytes > 573 remaining bytes (truncated response from broker (ok)): mytopic [0] MessageSet at offset 867123 payload size 1319
Increasing max fetch bytes to 8388608
...
...
Skipping 3 message(s) in aborted transaction at offset 1736725
Skipping 3 message(s) in aborted transaction at offset 1736725
Skipping 3 message(s) in aborted transaction at offset 1736725
Skipping 3 message(s) in aborted transaction at offset 1736725
Skipping 3 message(s) in aborted transaction at offset 1736725
Skipping 3 message(s) in aborted transaction at offset 1736725
Skipping 3 message(s) in aborted transaction at offset 1736725
Skipping 3 message(s) in aborted transaction at offset 1736725
Skipping 3 message(s) in aborted transaction at offset 1736725
Message at offset 2163394 might be too large to fetch, try increasing receive.message.max.bytes

• Provide broker log excerpts
• Critical issue

[mhowlett]

That consume error is emitted when there were no messages from parsing a message set, and the reason for that in this case seems to be that the message set is malformed: (Protocol read buffer underflow at 4193825/4194398), or there is a bug in the parsing of the message set.

Are you using librdkafka to produce messages?

thanks, the debug message can be improved ( feel free to open a PR :-) )

[edenhill]

Could you enable "debug": "msg,protocol,eos" and provide us with a log excerpt that shows us the part where it gets stuck at an offset, preferably with some preamble?

[yuanboliu]

@mhowlett Thanks for your comments.
I'm new to librdkafka
Do you mean that the size of single batch(Memoryrecords) from kafka cannot exceed 4193825/4194398 ?

[edenhill]

Brokers return batches of messages and if the the requested size is smaller than the batch size the batch will be truncated, in this case the client will increase its receive buffer and re-fetch the messages automatically.
This is why you are seeing the 'truncated' log line, which does not in itself indenticate a problem.

[jacobmikesell]

Hi all,

I created a go app to reproduce this error
https://github.com/jacobmikesell/MinimumReproduceableLibrdkafkaTransactionBug

Just
go run main.go -- produces 40 mil messages to a topic called test (will create it if necessary)
go run main.go -r --(attempts to read next message)

and then wait for the error to surface. Can also be repro'd with kafkacat using
go run main.go -- to produce messages
kafkacat -C -b 127.0.0.1:9092 -t test -o 0

[laszlox]

Hi,

We also bumped into this issue using version 1.8.2.

I created a go app to reproduce this error
https://github.com/jacobmikesell/MinimumReproduceableLibrdkafkaTransactionBug

This repro worked, the consumer (both .net and kafkacat) got the same error.

[edenhill]

Thank you for the reproducer, @jacobmikesell , but I can't reproduce this with a standard AK 2.8 cluster.

@laszlox What broker version are you on and does it have non-standard topic message size (or related) configs?

[laszlox]

@laszlox What broker version are you on and does it have non-standard topic message size (or related) configs?

Our broker version is 2.8.0 and this broker setting we have may be relevant:

message.max.bytes=2097152

FYI, I wrote a little java producer to produce the big rolled back transaction, I didn't try the go repro above. But the idea was very similar: sending lot of messages in a transaction, then aborting it. I used message-size of about 1000 bytes and sent 1250000 of them (into a single partition).

[edenhill]

Thanks, that did it 👍

[edenhill]

Fixed in PR #3639. Please try it out if possible (issue2993 branch).