[jira] [Created] (KAFKA-9826) Log cleaning goes in infinite loop when first dirty offset is past start of active segment

["Steve Rodrigues (Jira)" <ji...@apache.org>]

Steve Rodrigues created KAFKA-9826:
--------------------------------------

             Summary: Log cleaning goes in infinite loop when first dirty offset is past start of active segment
                 Key: KAFKA-9826
                 URL: https://issues.apache.org/jira/browse/KAFKA-9826
             Project: Kafka
          Issue Type: Bug
          Components: log cleaner
    Affects Versions: 2.4.1
            Reporter: Steve Rodrigues
            Assignee: Steve Rodrigues


Seen on a system where a given partition had a single segment, and for whatever reason (deleteRecords?), the logStartOffset was greater than the base segment of the log, there were a continuous series of 

```

[2020-03-03 16:56:31,374] WARN Resetting first dirty offset of  FOO-3 to log start offset 55649 since the checkpointed offset 0 is invalid. (kafka.log.LogCleanerManager$)

```

messages (partition name changed, it wasn't really FOO). This was expected to be resolved by KAFKA-6266 but clearly wasn't. 

Further investigation revealed that  a few segments were continuously cleaning and generating messages in the `log-cleaner.log` of the form:

```

[2020-03-31 13:34:50,924] INFO Cleaner 1: Beginning cleaning of log FOO-3 (kafka.log.LogCleaner)

[2020-03-31 13:34:50,924] INFO Cleaner 1: Building offset map for FOO-3... (kafka.log.LogCleaner)

[2020-03-31 13:34:50,927] INFO Cleaner 1: Building offset map for log FOO-3 for 0 segments in offset range [55287, 54237). (kafka.log.LogCleaner)

[2020-03-31 13:34:50,927] INFO Cleaner 1: Offset map for log FOO-3 complete. (kafka.log.LogCleaner)

[2020-03-31 13:34:50,927] INFO Cleaner 1: Cleaning log FOO-3 (cleaning prior to Wed Dec 31 19:00:00 EST 1969, discarding tombstones prior to Tue Dec 10 13:39:08 EST 2019)... (kafka.log.LogCleaner)

[2020-03-31 13:34:50,927] INFO [kafka-log-cleaner-thread-1]: Log cleaner thread 1 cleaned log FOO-3 (dirty section = [55287, 55287])

0.0 MB of log processed in 0.0 seconds (0.0 MB/sec).

Indexed 0.0 MB in 0.0 seconds (0.0 Mb/sec, 100.0% of total time)

Buffer utilization: 0.0%

Cleaned 0.0 MB in 0.0 seconds (NaN Mb/sec, 0.0% of total time)

Start size: 0.0 MB (0 messages)

End size: 0.0 MB (0 messages) NaN% size reduction (NaN% fewer messages) (kafka.log.LogCleaner)

```

What seems to have happened here (data determined for a different partition) is:

There exist a number of partitions here which get relatively low traffic, including our friend FOO-5. For whatever reason, LogStartOffset of this partition has moved beyond the baseOffset of the active segment. (Notes in other issues indicate that this is a reasonable scenario.) So there’s one segment, starting at 166266, and a log start of 166301.

grabFilthiestCompactedLog runs and reads the checkpoint file. We see that this topicpartition needs to be cleaned, and call cleanableOffsets on it which returns an OffsetsToClean with firstDirtyOffset == logStartOffset == 166301 and firstUncleanableOffset = max(logStart, activeSegment.baseOffset) = 116301, and forceCheckpoint = true.

The checkpoint file is updated in grabFilthiestCompactedLog (this is the fix for KAFKA-6266). We then create a LogToClean object based on the firstDirtyOffset and firstUncleanableOffset of 166301 (past the active segment’s base offset).

The LogToClean object has cleanBytes = logSegments(-1, firstDirtyOffset).map(_.size).sum → the size of this segment. It has firstUncleanableOffset and cleanableBytes determined by calculateCleanableBytes. calculateCleanableBytes returns:
{{}}
{{val firstUncleanableSegment = log.nonActiveLogSegmentsFrom(uncleanableOffset).headOption.getOrElse(log.activeSegment)}}
{{val firstUncleanableOffset = firstUncleanableSegment.baseOffset}}
{{val cleanableBytes = log.logSegments(firstDirtyOffset, math.max(firstDirtyOffset, firstUncleanableOffset)).map(_.size.toLong).sum

(firstUncleanableOffset, cleanableBytes)}}
firstUncleanableSegment is activeSegment. firstUncleanableOffset is the base offset, 166266. cleanableBytes is looking for logSegments(166301, max(166301, 166266) → which _is the active segment_

So there are “cleanableBytes” > 0.

We then filter out segments with totalbytes (clean + cleanable) > 0. This segment has totalBytes > 0, and it has cleanablebytes, so great! It’s filthiest.

The cleaner picks it, calls cleanLog on it, which then does cleaner.clean, which returns nextDirtyOffset and cleaner stats. cleaner.clean callls doClean, which builds an offsetMap. The offsetMap looks at non-active segments, when building, but there aren’t any. So the endOffset of the offsetMap is lastOffset (default -1) + 1 → 0. We record the stats (including logging to log-cleaner.log). After this we call cleanerManager.doneCleaning, which writes the checkpoint file with the latest value… of 0.

And then the process starts all over.

It appears that there's at least one bug here, where `log.logSegments(from, to)` will return an empty list if from == to and both are segment-aligned, but _not_ if they are in the middle of a segment, and possibly that LogToClean does start=firstDirtyOffset, end = max(firstDirtyOffset, firstUncleanableOffset) – it can move the firstUncleanableOffset even when the firstDirtyOffset is past firstUncleanable.

 



--
This message was sent by Atlassian Jira
(v8.3.4#803005)