[KAFKA-5747] Broker crashes on startup when trying to parse empty snapshot files

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.11.0.0
• Fix Version/s: 0.11.0.1
• Assignee: Jason Gustafson
• Reporter: Lukasz Mierzwa
• Created: 17/Aug/17 19:01
• Updated: 22/Aug/17 10:33
• Resolved: 21/Aug/17 17:23

Description

A broker server crash can sometime result in empty snapshot files on disk (depending on FS, barrier setting etc), when Kafka tries to parse such files it crashes, gets restarted and crashes again, this happens until you remove empty snapshot files with:

find /logs/dir -name \*.snapshot -size 0 -delete

Log:

Aug 15 22:52:11 localhost kafka[23681]: INFO Recovering unflushed segment 0 in log __consumer_offsets-16. (kafka.log.Log)
Aug 15 22:52:11 localhost kafka[23681]: INFO Loading producer state from offset 1207 for partition __consumer_offsets-16 with message format version 0 (kafka.log.Log)
Aug 15 22:52:11 localhost kafka[23681]: INFO Completed load of log __consumer_offsets-16 with 1 log segments, log start offset 0 and log end offset 1207 in 15 ms (kafka.log.Log)
Aug 15 22:52:11 localhost kafka[23681]: WARN Found a corrupted index file due to requirement failed: Corrupt index found, index file (/disk/data/kafka/mycluster/mytopic-64/00000000300519800823.index) has non-zero size but the last offset is 300519800823 which is no larger than the base offset 300519800823.}. deleting /disk/data/kafka/mycluster/mytopic-64/00000000300519800823.timeindex, /disk/data/kafka/mycluster/mytopic-64/00000000300519800823.index, and /disk/data/kafka/mycluster/mytopic-64/00000000300519800823.txnindex and rebuilding index... (kafka.log.Log)
Aug 15 22:52:11 localhost kafka[23681]: INFO Loading producer state from snapshot file 00000000300519800823.snapshot for partition mytopic-64 (kafka.log.ProducerStateManager)
Aug 15 22:52:11 localhost kafka[23681]: ERROR There was an error in one of the threads during logs loading: org.apache.kafka.common.protocol.types.SchemaException: Error reading field 'version': java.nio.BufferUnderflowException (kafka.log.LogManager)
Aug 15 22:52:11 localhost kafka[23681]: FATAL [Kafka Server 10139], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)
Aug 15 22:52:11 localhost kafka[23681]: org.apache.kafka.common.protocol.types.SchemaException: Error reading field 'version': java.nio.BufferUnderflowException
Aug 15 22:52:11 localhost kafka[23681]:         at org.apache.kafka.common.protocol.types.Schema.read(Schema.java:76)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.ProducerStateManager$.readSnapshot(ProducerStateManager.scala:289)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.ProducerStateManager.loadFromSnapshot(ProducerStateManager.scala:440)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.ProducerStateManager.truncateAndReload(ProducerStateManager.scala:499)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.Log.recoverSegment(Log.scala:327)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.Log.$anonfun$loadSegmentFiles$3(Log.scala:314)
Aug 15 22:52:11 localhost kafka[23681]:         at scala.collection.TraversableLike$WithFilter.$anonfun$foreach$1(TraversableLike.scala:789)
Aug 15 22:52:11 localhost kafka[23681]:         at scala.collection.IndexedSeqOptimized.foreach(IndexedSeqOptimized.scala:32)
Aug 15 22:52:11 localhost kafka[23681]:         at scala.collection.IndexedSeqOptimized.foreach$(IndexedSeqOptimized.scala:29)
Aug 15 22:52:11 localhost kafka[23681]:         at scala.collection.mutable.ArrayOps$ofRef.foreach(ArrayOps.scala:191)
Aug 15 22:52:11 localhost kafka[23681]:         at scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:788)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.Log.loadSegmentFiles(Log.scala:272)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.Log.loadSegments(Log.scala:376)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.Log.<init>(Log.scala:179)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.Log$.apply(Log.scala:1581)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.log.LogManager.$anonfun$loadLogs$12(LogManager.scala:172)
Aug 15 22:52:11 localhost kafka[23681]:         at kafka.utils.CoreUtils$$anon$1.run(CoreUtils.scala:57)
Aug 15 22:52:11 localhost kafka[23681]:         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
Aug 15 22:52:11 localhost kafka[23681]:         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Aug 15 22:52:11 localhost kafka[23681]:         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Aug 15 22:52:11 localhost kafka[23681]:         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Aug 15 22:52:11 localhost kafka[23681]:         at java.lang.Thread.run(Thread.java:748)
Aug 15 22:52:11 localhost kafka[23681]: INFO [Kafka Server 10139], shutting down (kafka.server.KafkaServer)
Aug 15 22:52:11 localhost kafka[23681]: INFO Terminate ZkClient event thread. (org.I0Itec.zkclient.ZkEventThread)
Aug 15 22:52:11 localhost kafka[23681]: INFO Session: 0x15de80e0a37004c closed (org.apache.zookeeper.ZooKeeper)
Aug 15 22:52:11 localhost kafka[23681]: INFO EventThread shut down for session: 0x15de80e0a37004c (org.apache.zookeeper.ClientCnxn)
Aug 15 22:52:11 localhost kafka[23681]: INFO [Kafka Server 10139], shut down completed (kafka.server.KafkaServer)
Aug 15 22:52:11 localhost kafka[23681]: FATAL Exiting Kafka. (kafka.server.KafkaServerStartable)
Aug 15 22:52:11 localhost kafka[23681]: INFO [Kafka Server 10139], shutting down (kafka.server.KafkaServer)
Aug 15 22:52:12 localhost systemd[1]: kafka.service: Main process exited, code=exited, status=1/FAILURE
Aug 15 22:52:12 localhost systemd[1]: kafka.service: Unit entered failed state.
Aug 15 22:52:12 localhost systemd[1]: kafka.service: Failed with result 'exit-code'.

Happens with 0.10 & 0.11

Issue Links

• duplicates: KAFKA-5751 Kafka cannot start; corrupted index file(s)
• links to: GitHub Pull Request #3688