Exception when sending read requests

[merlimat]

BUG REPORT

Describe the bug

Got reports from Pulsar users (with BK 4.9.0) of these errors:

17:24:16.302 [BookKeeperClientWorker-OrderedExecutor-0-0] ERROR org.apache.bookkeeper.common.util.SafeRunnable - Unexpected throwable caught 
java.lang.ArrayIndexOutOfBoundsException: -2
    at com.google.common.collect.RegularImmutableList.get(RegularImmutableList.java:60) ~[com.google.guava-guava-21.0.jar:?]
    at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.sendNextRead(PendingReadOp.java:400) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.PendingReadOp$SequenceReadRequest.read(PendingReadOp.java:382) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.PendingReadOp.initiate(PendingReadOp.java:526) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.client.PendingReadOp.safeRun(PendingReadOp.java:536) ~[org.apache.bookkeeper-bookkeeper-server-4.9.0.jar:4.9.0]
    at org.apache.bookkeeper.common.util.SafeRunnable.run(SafeRunnable.java:36) [org.apache.bookkeeper-bookkeeper-common-4.9.0.jar:4.9.0]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_181]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_181]
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_181]

[eolivelli]

Do you already have a reproducer?

[merlimat]

No, I haven't seen this error myself yet

[grantwwu]

I was the user reporting this - my current cluster is throwing this pretty much continuously - let me know if there's anything I can do.

[ivankelly]

Relates to apache/pulsar#3715

[chairmank]

I have observed this bug with BookKeeper 4.9.0 when using the tiered storage feature of Pulsar 2.3.0.

I added logging to org.apache.bookkeeper.client.RoundRobinDistributionSchedule and found that the getWriteSet method is being called with entryId = -2. getWriteSet calls the static create method of WriteSetImpl, which calls the private reset method, which looks like this:

        private void reset(int ensembleSize, int writeQuorumSize,
                           long entryId) {
            setSize(writeQuorumSize);
            for (int w = 0; w < writeQuorumSize; w++) {
                set(w, (int) ((entryId + w) % ensembleSize));
            }
        }

The % operator returns a negative number when the first operand is negative. This is bad because (entryId + w) % ensembleSize) must be a valid integer index into a list of available bookies in the ensemble, between 0 (inclusive) and ensembleSize (exclusive).

We can avoid the resulting ArrayIndexOutOfBoundsException by replacing % with java.lang.Math.floorMod. I think that this is a good defensive change.

But changing the WriteSet implementation is not a real solution because it doesn't address the real bug: Why is entryId a negative number? I don't know whether this is a bug in Pulsar or BookKeeper.

[sijie]

I don't think bookkeeper should accept any reads reading entries with negative ids. there is already a defensive sanity check in readAsync call.

        // Little sanity check
        if (firstEntry < 0 || firstEntry > lastEntry) {
            LOG.error("IncorrectParameterException on ledgerId:{} firstEntry:{} lastEntry:{}",
                    ledgerId, firstEntry, lastEntry);
            return FutureUtils.exception(new BKIncorrectParameterException());
        }

[klevy-toast]

Hi. I am also seeing this, when running the some benchmarks with 100GB of backlog.

[sijie]

FYI I am currently looking into this issue as well. Will post updates once I got any.