Kafka
  1. Kafka
  2. KAFKA-721

FileNotFoundException on index file

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Blocker Blocker
    • Resolution: Cannot Reproduce
    • Affects Version/s: 0.8.0
    • Fix Version/s: None
    • Component/s: core, log
    • Labels:

      Description

      [2013-01-21 22:01:36,116] INFO [Kafka Log on Broker 1], Rolling log 'topicx-1' to /mnt/u001/kafka_08_long_running_test/kafka-logs/Mo
      bilePageViewEvent-1/00000000000000019578.log and /mnt/u001/kafka_08_long_running_test/kafka-logs/MobilePageViewEvent-1/00000000000000019578.index
      (kafka.log.Log)
      [2013-01-21 22:01:36,118] ERROR error in loggedRunnable (kafka.utils.Utils$)
      java.io.FileNotFoundException: /mnt/u001/kafka_08_long_running_test/kafka-logs/MobilePageViewEvent-1/00000000000000000000.index (No such file or directory)
      at java.io.RandomAccessFile.open(Native Method)
      at java.io.RandomAccessFile.<init>(RandomAccessFile.java:212)
      at kafka.log.OffsetIndex.resize(OffsetIndex.scala:244)
      at kafka.log.OffsetIndex.trimToValidSize(OffsetIndex.scala:233)
      at kafka.log.Log.rollToOffset(Log.scala:473)
      at kafka.log.Log.roll(Log.scala:457)
      at kafka.log.Log.markDeletedWhile(Log.scala:411)
      at kafka.log.LogManager.kafka$log$LogManager$$cleanupExpiredSegments(LogManager.scala:241)
      at kafka.log.LogManager$$anonfun$cleanupLogs$2.apply(LogManager.scala:277)
      at kafka.log.LogManager$$anonfun$cleanupLogs$2.apply(LogManager.scala:275)
      at scala.collection.Iterator$class.foreach(Iterator.scala:631)
      at scala.collection.JavaConversions$JIteratorWrapper.foreach(JavaConversions.scala:474)
      at scala.collection.IterableLike$class.foreach(IterableLike.scala:79)
      at scala.collection.JavaConversions$JCollectionWrapper.foreach(JavaConversions.scala:495)
      at kafka.log.LogManager.cleanupLogs(LogManager.scala:275)
      at kafka.log.LogManager$$anonfun$startup$1.apply$mcV$sp(LogManager.scala:141)
      at kafka.utils.Utils$$anon$2.run(Utils.scala:66)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
      at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
      at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:181)
      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:205)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:619)

      Before this, we have the following log that shows an index file is newly created.
      [2013-01-21 22:01:05,920] INFO Partition [MobilePageViewEvent, 1] on broker 1: Starting the follower state transition to follow leader 5 for topic MobilePageViewEvent partition 1 (kafka.cluster.Partition)
      [2013-01-21 22:01:05,920] INFO [ReplicaFetcherManager on broker 1] removing fetcher on topic MobilePageViewEvent, partition 1 (kafka.server.ReplicaFetcherManager)
      [2013-01-21 22:01:05,920] INFO Creating or reloading log segment /mnt/u001/kafka_08_long_running_test/kafka-logs/MobilePageViewEvent-1/00000000000000000000.log (kafka.log.FileMessageSet)
      [2013-01-21 22:01:05,920] INFO Created index file /mnt/u001/kafka_08_long_running_test/kafka-logs/MobilePageViewEvent-1/00000000000000000000.index with maxEntries = 1310720, maxIndexSize = 10485760, entries = 0, lastOffset = 0 (kafka.log.OffsetIndex)
      [2013-01-21 22:01:05,921] INFO [Log Manager on Broker 1] Created log for topic MobilePageViewEvent partition 1 in /mnt/u001/kafka_08_long_running_test/kafka-logs. (kafka.log.LogManager)
      [2013-01-21 22:01:05,921] WARN No highwatermark file is found. Returning 0 as the highwatermark for topic MobilePageViewEvent partition 1. (kafka.server.HighwaterMarkCheckpoint)
      [2013-01-21 22:01:05,921] INFO [Kafka Log on Broker 1], Truncated log segment /mnt/u001/kafka_08_long_running_test/kafka-logs/MobilePageViewEvent-1/00000000000000000000.log to target offset 0 (kafka.log.Log)
      [2013-01-21 22:01:05,921] INFO [ReplicaFetcherManager on broker 1] adding fetcher on topic MobilePageViewEvent, partion 1, initOffset 0 to broker 5 with fetcherId 0 (kafka.server.ReplicaFetcherManager)

        Activity

        Jun Rao created issue -
        Hide
        Jun Rao added a comment -

        The following is what happened:
        1. We are starting a follower replica. The corresponding log doesn't exist. So, we created a new one. At this step, 00000000000000000000.index should have been created.
        2. A log cleaner scheduler wakes up and decides to remove the only log segment. However, it couldn't seem to find 00000000000000000000.index.

        Not quite sure how the index file can be gone within 30 secs after creation.

        Also, a couple of other weird things.
        1. The log segment just got created. It's not clear why the segment needs to be GCed. Our retention time is at least 1 hour.
        2. The index segment continues to be appendable since there are new data added to the log. So it seems that mmap-ed buffer still works when the underlying file is gone?

        Show
        Jun Rao added a comment - The following is what happened: 1. We are starting a follower replica. The corresponding log doesn't exist. So, we created a new one. At this step, 00000000000000000000.index should have been created. 2. A log cleaner scheduler wakes up and decides to remove the only log segment. However, it couldn't seem to find 00000000000000000000.index. Not quite sure how the index file can be gone within 30 secs after creation. Also, a couple of other weird things. 1. The log segment just got created. It's not clear why the segment needs to be GCed. Our retention time is at least 1 hour. 2. The index segment continues to be appendable since there are new data added to the log. So it seems that mmap-ed buffer still works when the underlying file is gone?
        Hide
        Neha Narkhede added a comment -

        >> Not quite sure how the index file can be gone within 30 secs after creation.

        Maybe whatever got rid of the entire kafka-logs directory caused this ?

        Show
        Neha Narkhede added a comment - >> Not quite sure how the index file can be gone within 30 secs after creation. Maybe whatever got rid of the entire kafka-logs directory caused this ?
        Neha Narkhede made changes -
        Field Original Value New Value
        Labels p1
        Hide
        Neha Narkhede added a comment -

        Marking it cannot reproduce and leaving it open, just in case we see it again.

        Show
        Neha Narkhede added a comment - Marking it cannot reproduce and leaving it open, just in case we see it again.
        Neha Narkhede made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Cannot Reproduce [ 5 ]
        Neha Narkhede made changes -
        Status Resolved [ 5 ] Closed [ 6 ]

          People

          • Assignee:
            Jun Rao
            Reporter:
            Jun Rao
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development