Uploaded image for project: 'Kafka'
  1. Kafka
  2. KAFKA-4496

LogCleaner thread exits with NoSuchElementException

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: 0.8.2.1
    • Fix Version/s: None
    • Component/s: core, offset manager
    • Labels:
      None
    • Environment:
      SLES 11.3, 20 node cluster

      Description

      After running for some time (about 60 hours in this case), we are seeing the LogCleaner thread exit with the messages below. Because of this, the consumer_offsets topic grows very large over time.

      [2016-12-01 20:00:44,050] INFO Cleaner 0: Building offset map for __consumer_offsets-19... (kafka.log.LogCleaner)
      [2016-12-01 20:00:44,183] INFO Cleaner 0: Building offset map for log __consumer_offsets-19 for 0 segments in offset range [15698821, 0). (kafka.log.LogCleaner)
      [2016-12-01 20:00:44,220] ERROR [kafka-log-cleaner-thread-0], Error due to (kafka.log.LogCleaner)
      java.util.NoSuchElementException: head of empty stream
      at scala.collection.immutable.Stream$Empty$.head(Stream.scala:1028)
      at scala.collection.immutable.Stream$Empty$.head(Stream.scala:1026)
      at kafka.log.Cleaner.buildOffsetMap(LogCleaner.scala:508)
      at kafka.log.Cleaner.clean(LogCleaner.scala:307)
      at kafka.log.LogCleaner$CleanerThread.cleanOrSleep(LogCleaner.scala:221)
      at kafka.log.LogCleaner$CleanerThread.doWork(LogCleaner.scala:199)
      at kafka.utils.ShutdownableThread.run(ShutdownableThread.scala:60)
      [2016-12-01 20:00:44,221] INFO [kafka-log-cleaner-thread-0], Stopped (kafka.log.LogCleaner)

      This looks similar to some other issues (KAFKA-1641, KAFKA-2235, etc.) but does not match exactly.

      Here is the server.properties:
      delete.topic.enable=true
      socket.send.buffer.bytes=102400
      socket.request.max.bytes=104857600
      log.cleaner.enable=true
      log.retention.check.interval.ms=300000
      zookeeper.session.timeout.ms=30000
      num.io.threads=8
      broker.id=0
      port=9092
      log.dirs=/kafka/broker_0
      auto.create.topics.enable=false
      num.network.threads=3
      socket.receive.buffer.bytes=102400
      log.retention.minutes=10
      log.cleaner.delete.retention.ms=1800000
      log.segment.bytes=1073741824
      num.recovery.threads.per.data.dir=1
      num.partitions=1
      zookeeper.connection.timeout.ms=30000
      zookeeper.connect=<zk servers>

      ...and here's what one of the consumer-offsets data directories looks like:
      kafka1:/kafka/broker_0/__consumer_offsets-19 # ls -lrt
      total 2611332
      rw-rr- 1 yarn yarn 104857433 Dec 1 23:17 00000000000000000000.log
      rw-rr- 1 yarn yarn 182272 Dec 1 23:17 00000000000000000000.index
      rw-rr- 1 yarn yarn 104857592 Dec 2 05:44 00000000000016820302.log
      rw-rr- 1 yarn yarn 201880 Dec 2 05:44 00000000000016820302.index
      rw-rr- 1 yarn yarn 104857497 Dec 2 10:18 00000000000017939487.log
      rw-rr- 1 yarn yarn 201464 Dec 2 10:18 00000000000017939487.index
      rw-rr- 1 yarn yarn 104857302 Dec 2 14:04 00000000000019061235.log
      rw-rr- 1 yarn yarn 201176 Dec 2 14:04 00000000000019061235.index
      rw-rr- 1 yarn yarn 104857594 Dec 2 17:43 00000000000020184726.log
      rw-rr- 1 yarn yarn 201120 Dec 2 17:43 00000000000020184726.index
      rw-rr- 1 yarn yarn 104857523 Dec 2 21:51 00000000000021308472.log
      rw-rr- 1 yarn yarn 201288 Dec 2 21:51 00000000000021308472.index
      rw-rr- 1 yarn yarn 104857509 Dec 3 03:20 00000000000022430910.log
      rw-rr- 1 yarn yarn 201600 Dec 3 03:20 00000000000022430910.index
      rw-rr- 1 yarn yarn 104857562 Dec 3 09:14 00000000000023551782.log
      rw-rr- 1 yarn yarn 201696 Dec 3 09:14 00000000000023551782.index
      rw-rr- 1 yarn yarn 104857526 Dec 3 13:12 00000000000024671856.log
      rw-rr- 1 yarn yarn 201216 Dec 3 13:12 00000000000024671856.index
      rw-rr- 1 yarn yarn 104857591 Dec 3 17:03 00000000000025794239.log
      rw-rr- 1 yarn yarn 201152 Dec 3 17:03 00000000000025794239.index
      rw-rr- 1 yarn yarn 104857522 Dec 3 21:17 00000000000026917212.log
      rw-rr- 1 yarn yarn 201336 Dec 3 21:17 00000000000026917212.index
      rw-rr- 1 yarn yarn 104857160 Dec 4 02:31 00000000000028039274.log
      rw-rr- 1 yarn yarn 201624 Dec 4 02:31 00000000000028039274.index
      rw-rr- 1 yarn yarn 104857524 Dec 4 08:49 00000000000029160221.log
      rw-rr- 1 yarn yarn 201728 Dec 4 08:49 00000000000029160221.index
      rw-rr- 1 yarn yarn 104857579 Dec 4 13:09 00000000000030279870.log
      rw-rr- 1 yarn yarn 201344 Dec 4 13:09 00000000000030279870.index
      rw-rr- 1 yarn yarn 104857581 Dec 4 17:10 00000000000031401545.log
      rw-rr- 1 yarn yarn 201320 Dec 4 17:10 00000000000031401545.index
      rw-rr- 1 yarn yarn 104857338 Dec 4 21:36 00000000000032523747.log
      rw-rr- 1 yarn yarn 201456 Dec 4 21:36 00000000000032523747.index
      rw-rr- 1 yarn yarn 104857579 Dec 5 03:38 00000000000033645679.log
      rw-rr- 1 yarn yarn 201744 Dec 5 03:38 00000000000033645679.index
      rw-rr- 1 yarn yarn 104857511 Dec 5 09:07 00000000000034765482.log
      rw-rr- 1 yarn yarn 201656 Dec 5 09:07 00000000000034765482.index
      rw-rr- 1 yarn yarn 104857537 Dec 5 13:00 00000000000035885509.log
      rw-rr- 1 yarn yarn 201224 Dec 5 13:00 00000000000035885509.index
      rw-rr- 1 yarn yarn 104857594 Dec 5 16:43 00000000000037008566.log
      rw-rr- 1 yarn yarn 201056 Dec 5 16:43 00000000000037008566.index
      rw-rr- 1 yarn yarn 104857407 Dec 5 20:49 00000000000038132175.log
      rw-rr- 1 yarn yarn 201192 Dec 5 20:49 00000000000038132175.index
      rw-rr- 1 yarn yarn 104857598 Dec 6 02:34 00000000000039255111.log
      rw-rr- 1 yarn yarn 201568 Dec 6 02:34 00000000000039255111.index
      rw-rr- 1 yarn yarn 104857531 Dec 6 08:30 00000000000040375848.log
      rw-rr- 1 yarn yarn 201736 Dec 6 08:30 00000000000040375848.index
      rw-rr- 1 yarn yarn 104857567 Dec 6 12:23 00000000000041495389.log
      rw-rr- 1 yarn yarn 201288 Dec 6 12:23 00000000000041495389.index
      rw-rr- 1 yarn yarn 104857542 Dec 6 16:07 00000000000042618234.log
      rw-rr- 1 yarn yarn 201088 Dec 6 16:07 00000000000042618234.index
      rw-rr- 1 yarn yarn 10485760 Dec 6 17:40 00000000000043741475.index
      rw-rr- 1 yarn yarn 44560223 Dec 6 17:40 00000000000043741475.log

      Prior to the thread exiting, we see the compacted directories containing only about 6 files or 100MB max (as expected).

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              mfigura Margaret Figura
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: