[
https://issues.apache.org/jira/browse/KAFKA-6679?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16410079#comment-16410079
]
Ari Uka edited comment on KAFKA-6679 at 3/22/18 6:36 PM:
---------------------------------------------------------
So I attempted to re-generate one of the topics we had and I've been able to
actually find a corrupt message in the `.log` file.
There exists 3 brokers: kafka-01, kafka-02, kafka-03 and the topic
influxdb-telemetry which contains 161,760,969 (161.7M) messages.
The topic description:
{noformat}
Topic:influxdb-telemetry PartitionCount:6 ReplicationFactor:3 Configs:
Topic: influxdb-telemetry Partition: 0 Leader: 2 Replicas: 2,1,3 Isr: 2
Topic: influxdb-telemetry Partition: 1 Leader: 3 Replicas: 3,2,1 Isr: 3
Topic: influxdb-telemetry Partition: 2 Leader: 1 Replicas: 1,3,2 Isr: 1
Topic: influxdb-telemetry Partition: 3 Leader: 2 Replicas: 2,3,1 Isr: 2
Topic: influxdb-telemetry Partition: 4 Leader: 3 Replicas: 3,1,2 Isr: 3
Topic: influxdb-telemetry Partition: 5 Leader: 1 Replicas: 1,2,3 Isr:
1{noformat}
After inserting only 71,235 messages, influxdb-telemetry-0 becomes corrupt on
kafka-02 and kafka-01 starts to complain:
{noformat}
[2018-03-22 17:00:00,690] ERROR [ReplicaManager broker=2] Error processing
fetch operation on partition influxdb-telemetry-0, offset 71236
(kafka.server.ReplicaManager)
{noformat}
The last good written RecordSet looks like this:
{noformat}
baseOffset: 71233 lastOffset: 71235 baseSequence: -1 lastSequence: -1
producerId: -1 producerEpoch: -1 partitionLeaderEpoch: 0 isTransactional: false
position: 10285560 CreateTime: -1 isvalid: true size: 471 magic: 2
compresscodec: NONE crc: 491186814{noformat}
The header of this RecordSet looks like so:
$ hd -s 10285560 -n 471
/var/db/kafka/influxdb-telemetry-0/00000000000000000000.log
{noformat}
009ce30d 00 00 00 00 00 01 16 27 00 00 01 4b 00 00 00 00 |.......'...K....|
009ce31d 02 ee 03 fd 04 00 00 00 00 00 01 ff ff ff ff ff |................|
009ce32d ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
009ce33d ff ff ff ff ff ff ff ff ff 00 00 00 02 a8 02 00 |................|
009ce34d 00 00 01 9a 02 00 8b 09 89 54 4f d9 dd 82 b2 14 |.........TO.....|
{noformat}
If we're looking at the log files on `kafka-01` (who is trying to replicate),
it hasn't replicated past message 71235 and it's just sitting there complaining.
If we go on the leader of this partition `kafka-02` and dump the next message
after the good message, it's indeed corrupt, this is what it looks like:
$ hd -s 10286031 -n 471
/var/db/kafka/influxdb-telemetry-0/00000000000000000000.log
{noformat}
009cf3cf 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
009cf59f
{noformat}
The asterisk ( * ) here means that every line is the same, so basically message
71,236 contains 471 zeroes. I picked 471 arbitrarily seen I don't actually know
how big the RecordSet is for the next Record.
If we try to dump `influxdb-telemetry-0` on the leader (kafka-02), it barfs and
ends early because of this exception:
{noformat}
$ ./kafka-run-class.sh kafka.tools.DumpLogSegments --deep-iteration --files
/var/db/kafka/influxdb-telemetry-0/00000000000000000000.log | tail -n 5
Exception in thread "main"
org.apache.kafka.common.errors.CorruptRecordException: Record size is smaller
than minimum record overhead (14).
{noformat}
So it only tails these messages when in reality the log is 1GB and message
71,236 is only about 10MB through the file.
{noformat}
offset: 71231 position: 10283251 CreateTime: -1 isvalid: true keysize: -1
valuesize: 130 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
offset: 71232 position: 10283251 CreateTime: -1 isvalid: true keysize: -1
valuesize: 125 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
offset: 71233 position: 10285560 CreateTime: -1 isvalid: true keysize: -1
valuesize: 130 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
offset: 71234 position: 10285560 CreateTime: -1 isvalid: true keysize: -1
valuesize: 126 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
offset: 71235 position: 10285560 CreateTime: -1 isvalid: true keysize: -1
valuesize: 127 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
{noformat}
What could cause kafka to dump 471 zeroes for a RecordSet?
was (Author: ari6123):
So I attempted to re-generate one of the topics we had and I've been able to
actually find a corrupt message in the `.log` file.
There exists 3 brokers: kafka-01, kafka-02, kafka-03 and the topic
influxdb-telemetry which contains 161,760,969 (161.7M) messages.
The topic description:
{noformat}
Topic:influxdb-telemetry PartitionCount:6 ReplicationFactor:3 Configs:
Topic: influxdb-telemetry Partition: 0 Leader: 2 Replicas: 2,1,3 Isr: 2
Topic: influxdb-telemetry Partition: 1 Leader: 3 Replicas: 3,2,1 Isr: 3
Topic: influxdb-telemetry Partition: 2 Leader: 1 Replicas: 1,3,2 Isr: 1
Topic: influxdb-telemetry Partition: 3 Leader: 2 Replicas: 2,3,1 Isr: 2
Topic: influxdb-telemetry Partition: 4 Leader: 3 Replicas: 3,1,2 Isr: 3
Topic: influxdb-telemetry Partition: 5 Leader: 1 Replicas: 1,2,3 Isr:
1{noformat}
After inserting only 71,235 messages, influxdb-telemetry-0 becomes corrupt on
kafka-02 and kafka-01 starts to complain:
{noformat}
[2018-03-22 17:00:00,690] ERROR [ReplicaManager broker=2] Error processing
fetch operation on partition influxdb-telemetry-0, offset 71236
(kafka.server.ReplicaManager)
{noformat}
The last good written RecordSet looks like this:
{noformat}
baseOffset: 71233 lastOffset: 71235 baseSequence: -1 lastSequence: -1
producerId: -1 producerEpoch: -1 partitionLeaderEpoch: 0 isTransactional: false
position: 10285560 CreateTime: -1 isvalid: true size: 471 magic: 2
compresscodec: NONE crc: 491186814{noformat}
The header of this RecordSet looks like so:
$ hd -s 10285560 -n 471
/var/db/kafka/influxdb-telemetry-0/00000000000000000000.log
{noformat}
009ce30d 00 00 00 00 00 01 16 27 00 00 01 4b 00 00 00 00 |.......'...K....|
009ce31d 02 ee 03 fd 04 00 00 00 00 00 01 ff ff ff ff ff |................|
009ce32d ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
009ce33d ff ff ff ff ff ff ff ff ff 00 00 00 02 a8 02 00 |................|
009ce34d 00 00 01 9a 02 00 8b 09 89 54 4f d9 dd 82 b2 14 |.........TO.....|
{noformat}
If we're looking at the log files on `kafka-01` (who is trying to replicate),
it hasn't replicated past message 71235 and it's just sitting there complaining.
If we go on the leader of this partition and dump the next message after the
good message, it's indeed corrupt, this is what it looks like:
$ hd -s 10286031 -n 471
/var/db/kafka/influxdb-telemetry-0/00000000000000000000.log
{noformat}
009cf3cf 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
009cf59f
{noformat}
The asterisk ( * ) here means that every line is the same, so basically message
71236 contains 471 zeroes. I picked 471 arbitrarily seen I don't actually know
how big the RecordSet is for the next Record.
If we try to dump `influxdb-telemetry-0` on the leader, it barfs and ends early
because of this exception:
{noformat}
$ ./kafka-run-class.sh kafka.tools.DumpLogSegments --deep-iteration --files
/var/db/kafka/influxdb-telemetry-0/00000000000000000000.log | tail -n 5
Exception in thread "main"
org.apache.kafka.common.errors.CorruptRecordException: Record size is smaller
than minimum record overhead (14).
{noformat}
So it only tails these messages when in reality the log is 1GB and message
71,236 is only about 10MB through the file.
{noformat}
offset: 71231 position: 10283251 CreateTime: -1 isvalid: true keysize: -1
valuesize: 130 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
offset: 71232 position: 10283251 CreateTime: -1 isvalid: true keysize: -1
valuesize: 125 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
offset: 71233 position: 10285560 CreateTime: -1 isvalid: true keysize: -1
valuesize: 130 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
offset: 71234 position: 10285560 CreateTime: -1 isvalid: true keysize: -1
valuesize: 126 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
offset: 71235 position: 10285560 CreateTime: -1 isvalid: true keysize: -1
valuesize: 127 magic: 2 compresscodec: NONE producerId: -1 producerEpoch: -1
sequence: -1 isTransactional: false headerKeys: []
{noformat}
What could cause kafka to dump 471 zeroes for a RecordSet?
> Random corruption (CRC validation issues)
> ------------------------------------------
>
> Key: KAFKA-6679
> URL: https://issues.apache.org/jira/browse/KAFKA-6679
> Project: Kafka
> Issue Type: Bug
> Components: consumer, replication
> Affects Versions: 0.10.2.0, 1.0.1
> Environment: FreeBSD 11.0-RELEASE-p8
> Reporter: Ari Uka
> Priority: Major
>
> I'm running into a really strange issue on production. I have 3 brokers and
> randomly consumers will start to fail with an error message saying the CRC
> does not match. The brokers are all on 1.0.1, but the issue started on 0.10.2
> with the hope that upgrading would help fix the issue.
> On the kafka side, I see errors related to this across all 3 brokers:
> ```
> [2018-03-17 20:59:58,967] ERROR [ReplicaFetcher replicaId=3, leaderId=1,
> fetcherId=0] Error for partition topic-a-0 to broker
> 1:org.apache.kafka.common.errors.CorruptRecordException: This message has
> failed its CRC checksum, exceeds the valid size, or is otherwise corrupt.
> (kafka.server.ReplicaFetcherThread)
> [2018-03-17 20:59:59,411] ERROR [ReplicaManager broker=3] Error processing
> fetch operation on partition topic-b-0, offset 23848795
> (kafka.server.ReplicaManager)
> org.apache.kafka.common.errors.CorruptRecordException: Record size is smaller
> than minimum record overhead (14).
> [2018-03-17 20:59:59,411] ERROR [ReplicaManager broker=3] Error processing
> fetch operation on partition topic-b-0, offset 23848795
> (kafka.server.ReplicaManager)
> org.apache.kafka.common.errors.CorruptRecordException: Record size is smaller
> than minimum record overhead (14)
> [2018-03-17 20:59:59,490] ERROR [ReplicaFetcher replicaId=3, leaderId=2,
> fetcherId=0] Error for partition topic-c-2 to broker
> 2:org.apache.kafka.common.errors.CorruptRecordException: This message has
> failed its CRC checksum, exceeds the valid size, or is otherwise corrupt.
> (kafka.server.ReplicaFetcherThread)
> ```
>
> To fix this, I have to use the kafka-consumer-groups.sh command line tool and
> do a binary search until I can find a non corrupt message and push the
> offsets forward. It's annoying because I can't actually push to a specific
> date because kafka-consumer-groups.sh starts to emit the same error,
> ErrInvalidMessage, CRC does not match.
> The error popped up again the next day after fixing it tho, so I'm trying to
> find the root cause.
> I'm using the Go consumer [https://github.com/Shopify/sarama] and
> [https://github.com/bsm/sarama-cluster].
> At first, I thought it could be the consumer libraries, but the error happens
> with kafka-console-consumer.sh as well when a specific message is corrupted
> in Kafka. I don't think it's possible for Kafka producers to actually push
> corrupt messages to Kafka and then cause all consumers to break right? I
> assume Kafka would reject corrupt messages, so I'm not sure what's going on
> here.
> Should I just re-create the cluster, I don't think it's hardware failure
> across the 3 machines tho.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
