StaxEventItemReader.read.count skips a number [BATCH-2355]

Erwin Vervaet opened BATCH-2355 and commented

We're leveraging the "StaxEventItemReader.read.count" counter maintained by the StaxEventItemReader (ultimately by the AbstractItemCountingItemStreamItemReader) to learn about the index of the item being processed. We're only reading this value, not updating it. That is left to the Spring Batch code.

Our step looks like this:

<batch:step id="doc.doIntegration" next="doc.doAck">
	<batch:tasklet transaction-manager="transactionManager">
		<batch:chunk
			reader="doc.indexReader" processor="doc.integrationProcessor" writer="doc.ackWriter"
			commit-interval="1" retry-limit="3">
			<batch:retryable-exception-classes>
				<batch:include class="net...batches.support.TemporaryTechnicalException"/>
			</batch:retryable-exception-classes>
		</batch:chunk>
	</batch:tasklet>
</batch:step>

The "doc.integrationProcessor" is an ItemProcessor that also logs the item index:

@Override
public final I process(I item) throws Exception {
	...
	activityDebug("Processing item " + getItemIndex() + " of batch [" + getBatchId() + "]");
	...
}

The getItemIndex() method is implemented by simply looking up the "StaxEventItemReader.read.count" in the step execution context:

protected int getItemIndex() {
	return stepExecution.getExecutionContext().getInt("StaxEventItemReader.read.count");
}

The strange thing is that from time to time (very rarely) we see the following:

Processing item 214 of batch [9208fa8a5e9645a1949d6db8d1e7041d]
Processing item 215 of batch [9208fa8a5e9645a1949d6db8d1e7041d]
Processing item 216 of batch [9208fa8a5e9645a1949d6db8d1e7041d]
Processing item 216 of batch [9208fa8a5e9645a1949d6db8d1e7041d]
Processing item 218 of batch [9208fa8a5e9645a1949d6db8d1e7041d]
Processing item 219 of batch [9208fa8a5e9645a1949d6db8d1e7041d]

Notice that item 217 is missing and 216 is mentioned twice.

We see no errors in our logs but item 216 is not committed to our database so it seems some transaction rolled back somewhere. Directly after that the counter is out of whack and item 217 is processed as if it were 216. Then things recover and the counter jumps directly to 218. After that, everything is back to normal.

I'm trying to understand how this can happen. Could this be a bug in Spring Batch?
Or is this normal behavior in certain circumstances and should we be using another way to get the item index (probably ItemCountAware as mentioned in BATCH-1906)?

Affects: 2.2.7

Start with StaxEventItemReader and AbstractItemCountingItemStreamItemReader, then inspect how the step execution context is updated across chunk retries and transaction rollbacks. Compare the observed counter behavior with the ItemCountAware approach mentioned in BATCH-1906. Done means determining whether this is expected behavior or a reproducible Spring Batch defect and documenting the supported way to obtain the item index.