Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 5 additions & 6 deletions core/src/main/scala/kafka/log/Log.scala
Original file line number Diff line number Diff line change
Expand Up @@ -1471,10 +1471,7 @@ class Log(@volatile private var _dir: File,
// Because we don't use the lock for reading, the synchronization is a little bit tricky.
// We create the local variables to avoid race conditions with updates to the log.
val endOffsetMetadata = nextOffsetMetadata
val endOffset = nextOffsetMetadata.messageOffset
if (startOffset == endOffset)
return emptyFetchDataInfo(endOffsetMetadata, includeAbortedTxns)

val endOffset = endOffsetMetadata.messageOffset
var segmentEntry = segments.floorEntry(startOffset)

// return error on attempt to read beyond the log end offset or read below log start offset
Expand All @@ -1483,12 +1480,14 @@ class Log(@volatile private var _dir: File,
s"but we only have log segments in the range $logStartOffset to $endOffset.")

val maxOffsetMetadata = isolation match {
case FetchLogEnd => nextOffsetMetadata
case FetchLogEnd => endOffsetMetadata
case FetchHighWatermark => fetchHighWatermarkMetadata
case FetchTxnCommitted => fetchLastStableOffsetMetadata
}

if (startOffset > maxOffsetMetadata.messageOffset) {
if (startOffset == maxOffsetMetadata.messageOffset) {
return emptyFetchDataInfo(maxOffsetMetadata, includeAbortedTxns)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why in this case we use maxOffsetMetadata and in the else if we use startOffsetMetadata as emptyFetchDataInfo#fetchOffsetMetadata? Is there a specific rationale for that?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If the start offset matches max offset, then we do not need to lookup the metadata as we already have it. Really this is the bug fix. Without this, then we will proceed to read from the log segment, which results in an error like the following:

java.util.concurrent.ExecutionException: org.apache.kafka.common.KafkaException: java.io.EOFException: Failed to read `log header` from file channel `sun.nio.ch.FileChannelImpl@cc86429`. Expected to read 17 bytes, but reached end of file after reading 0 bytes. Started read from position 85.

	at java.util.concurrent.FutureTask.report(FutureTask.java:122)
	at java.util.concurrent.FutureTask.get(FutureTask.java:192)
	at kafka.log.LogConcurrencyTest.testUncommittedDataNotConsumed(LogConcurrencyTest.scala:75)
	at kafka.log.LogConcurrencyTest.testUncommittedDataNotConsumedFrequentSegmentRolls(LogConcurrencyTest.scala:61)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
	at com.intellij.rt.execution.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:47)
	at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:242)
	at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:70)
Caused by: org.apache.kafka.common.KafkaException: java.io.EOFException: Failed to read `log header` from file channel `sun.nio.ch.FileChannelImpl@cc86429`. Expected to read 17 bytes, but reached end of file after reading 0 bytes. Started read from position 85.
	at org.apache.kafka.common.record.RecordBatchIterator.makeNext(RecordBatchIterator.java:40)
	at org.apache.kafka.common.record.RecordBatchIterator.makeNext(RecordBatchIterator.java:24)
	at org.apache.kafka.common.utils.AbstractIterator.maybeComputeNext(AbstractIterator.java:79)
	at org.apache.kafka.common.utils.AbstractIterator.hasNext(AbstractIterator.java:45)
	at org.apache.kafka.common.record.FileRecords.searchForOffsetWithSize(FileRecords.java:302)
	at kafka.log.LogSegment.translateOffset(LogSegment.scala:275)
	at kafka.log.LogSegment.read(LogSegment.scala:298)
	at kafka.log.Log.$anonfun$read$2(Log.scala:1515)
	at kafka.log.Log.read(Log.scala:2333)
	at kafka.log.LogConcurrencyTest$ConsumerTask.call(LogConcurrencyTest.scala:95)
	at kafka.log.LogConcurrencyTest$ConsumerTask.call(LogConcurrencyTest.scala:85)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.io.EOFException: Failed to read `log header` from file channel `sun.nio.ch.FileChannelImpl@cc86429`. Expected to read 17 bytes, but reached end of file after reading 0 bytes. Started read from position 85.
	at org.apache.kafka.common.utils.Utils.readFullyOrFail(Utils.java:966)
	at org.apache.kafka.common.record.FileLogInputStream.nextBatch(FileLogInputStream.java:68)
	at org.apache.kafka.common.record.FileLogInputStream.nextBatch(FileLogInputStream.java:41)
	at org.apache.kafka.common.record.RecordBatchIterator.makeNext(RecordBatchIterator.java:35)
	... 14 more

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I understand this is the bug fix, I'm only curious to see why we used

emptyFetchDataInfo(maxOffsetMetadata, includeAbortedTxns)

not

emptyFetchDataInfo(startOffsetMetadata, includeAbortedTxns)

I realized it is just the same, so curious if you intentionally use maxOffsetMetadata for any other reasons, but I think it is just to avoid unnecessary convertToOffsetMetadataOrThrow :)

@hachikuji hachikuji Apr 15, 2020

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It lets us skip the call to convertToOffsetMetadataOrThrow in order to find startOffsetMetadata. I tried changing the check below to >= and hit a similar error when trying to translate the offset in LogSegment. We might also be able to fix this by adding some additional checks in LogSegment to avoid the offset translation when the max position matches the start position of the requested offset.

} else if (startOffset > maxOffsetMetadata.messageOffset) {
val startOffsetMetadata = convertToOffsetMetadataOrThrow(startOffset)
return emptyFetchDataInfo(startOffsetMetadata, includeAbortedTxns)
}
Expand Down
183 changes: 183 additions & 0 deletions core/src/test/scala/unit/kafka/log/LogConcurrencyTest.scala
Original file line number Diff line number Diff line change
@@ -0,0 +1,183 @@
/*
* Licensed to the Apache Software Foundation (ASF) under one or more
* contributor license agreements. See the NOTICE file distributed with
* this work for additional information regarding copyright ownership.
* The ASF licenses this file to You under the Apache License, Version 2.0
* (the "License"); you may not use this file except in compliance with
* the License. You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/

package kafka.log

import java.util.Properties
import java.util.concurrent.{Callable, Executors}

import kafka.server.{BrokerTopicStats, FetchHighWatermark, LogDirFailureChannel}
import kafka.utils.{KafkaScheduler, TestUtils}
import org.apache.kafka.common.record.SimpleRecord
import org.apache.kafka.common.utils.{Time, Utils}
import org.junit.Assert._
import org.junit.{After, Before, Test}

import scala.collection.mutable.ListBuffer
import scala.util.Random

class LogConcurrencyTest {
private val brokerTopicStats = new BrokerTopicStats
private val random = new Random()
private val scheduler = new KafkaScheduler(1)
private val tmpDir = TestUtils.tempDir()
private val logDir = TestUtils.randomPartitionLogDir(tmpDir)

@Before
def setup(): Unit = {
scheduler.startup()
}

@After
def shutdown(): Unit = {
scheduler.shutdown()
Utils.delete(tmpDir)
}

@Test
def testUncommittedDataNotConsumed(): Unit = {
testUncommittedDataNotConsumed(createLog())
}

@Test
def testUncommittedDataNotConsumedFrequentSegmentRolls(): Unit = {
val logProps = new Properties()
logProps.put(LogConfig.SegmentBytesProp, 237: Integer)
val logConfig = LogConfig(logProps)
testUncommittedDataNotConsumed(createLog(logConfig))
}

def testUncommittedDataNotConsumed(log: Log): Unit = {

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm just curious how long would a single run take with 5000 records and a max batchsize of 10? Being a bit paranoid of it taking too long.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It takes about 10 second locally, which seems reasonable for a concurrency test.

val executor = Executors.newFixedThreadPool(2)
try {
val maxOffset = 5000
val consumer = new ConsumerTask(log, maxOffset)
val appendTask = new LogAppendTask(log, maxOffset)

val consumerFuture = executor.submit(consumer)
val fetcherTaskFuture = executor.submit(appendTask)

fetcherTaskFuture.get()
consumerFuture.get()

validateConsumedData(log, consumer.consumedBatches)
} finally executor.shutdownNow()
}

/**
* Simple consumption task which reads the log in ascending order and collects
* consumed batches for validation
*/
private class ConsumerTask(log: Log, lastOffset: Int) extends Callable[Unit] {
val consumedBatches = ListBuffer.empty[FetchedBatch]

override def call(): Unit = {
var fetchOffset = 0L
while (log.highWatermark < lastOffset) {
val readInfo = log.read(
startOffset = fetchOffset,
maxLength = 1,
isolation = FetchHighWatermark,
minOneMessage = true
)
readInfo.records.batches().forEach { batch =>
consumedBatches += FetchedBatch(batch.baseOffset, batch.partitionLeaderEpoch)
fetchOffset = batch.lastOffset + 1
}
}
}
}

/**
* This class simulates basic leader/follower behavior.
*/
private class LogAppendTask(log: Log, lastOffset: Long) extends Callable[Unit] {
override def call(): Unit = {
var leaderEpoch = 1
var isLeader = true

while (log.highWatermark < lastOffset) {
random.nextInt(2) match {
case 0 =>
val logEndOffsetMetadata = log.logEndOffsetMetadata
val logEndOffset = logEndOffsetMetadata.messageOffset
val batchSize = random.nextInt(9) + 1
val records = (0 to batchSize).map(i => new SimpleRecord(s"$i".getBytes))

if (isLeader) {
log.appendAsLeader(TestUtils.records(records), leaderEpoch)
log.maybeIncrementHighWatermark(logEndOffsetMetadata)
} else {
log.appendAsFollower(TestUtils.records(records,
baseOffset = logEndOffset,
partitionLeaderEpoch = leaderEpoch))
log.updateHighWatermark(logEndOffset)
}

case 1 =>
isLeader = !isLeader
leaderEpoch += 1

if (!isLeader) {
log.truncateTo(log.highWatermark)
}
}
}
}
}

private def createLog(config: LogConfig = LogConfig(new Properties())): Log = {
Log(dir = logDir,
config = config,
logStartOffset = 0L,
recoveryPoint = 0L,
scheduler = scheduler,
brokerTopicStats = brokerTopicStats,
time = Time.SYSTEM,
maxProducerIdExpirationMs = 60 * 60 * 1000,
producerIdExpirationCheckIntervalMs = LogManager.ProducerIdExpirationCheckIntervalMs,
logDirFailureChannel = new LogDirFailureChannel(10))
}

private def validateConsumedData(log: Log, consumedBatches: Iterable[FetchedBatch]): Unit = {
val iter = consumedBatches.iterator
log.logSegments.foreach { segment =>
segment.log.batches.forEach { batch =>
if (iter.hasNext) {
val consumedBatch = iter.next()
try {
assertEquals("Consumed batch with unexpected leader epoch",

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could we check last / next offset of the batch as well?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We could, but I thought it would be overkill since the generation logic generates batches which are unique by base offset and leader epoch.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cool

batch.partitionLeaderEpoch, consumedBatch.epoch)
assertEquals("Consumed batch with unexpected base offset",
batch.baseOffset, consumedBatch.baseOffset)
} catch {
case t: Throwable =>
throw new AssertionError(s"Consumed batch $consumedBatch " +
s"does not match next expected batch in log $batch", t)
}
}
}
}
}

private case class FetchedBatch(baseOffset: Long, epoch: Int) {
override def toString: String = {
s"FetchedBatch(baseOffset=$baseOffset, epoch=$epoch)"
}
}

}