Possible log file corruption when a node is terminated about copycat HOT 12 CLOSED

Actually, it may not be the case that the log is corrupted. FileBuffer currently doesn't scale itself for reads. That is, if the log tries to read bytes that extend beyond the current file size, it throws that exception. And of course, the first thing that happens when the log is opened is it rebuilds its index from disk. So, I think it's more likely that it's hitting the FileBuffer limit() when rebuilding its index (which is what is happening in the stack trace).

This is a critics bug since it prevents logs from being reopened once a segment has surpassed 1MB in size (the default buffer size). But it should be fixable and should work on existing logs assuming there's nothing else going on.

On Oct 21, 2015, at 11:25 AM, madjam [email protected] wrote:

I happened to notice this occasionally during some recent runs. Doesn't happen every time.

Here's a scenario I was running:

3 node cluster. s1, s2 and s3.
A separate client is logging commands on this cluster at the rate of few hundred per second.
Terminate a follower node (kill java process)
Try bringing it back up and you see the below exception trace.
09:04:31.681 [copycat-server-Address[localhost/127.0.0.1:5003]] ERROR i.a.c.u.c.SingleThreadContext - An uncaught exception occurred
java.lang.IndexOutOfBoundsException: null
at io.atomix.catalyst.buffer.AbstractBytes.checkOffset(AbstractBytes.java:47) ~[catalyst-buffer-1.0.0-rc3.jar:na]
at io.atomix.catalyst.buffer.AbstractBytes.checkRead(AbstractBytes.java:54) ~[catalyst-buffer-1.0.0-rc3.jar:na]
at io.atomix.catalyst.buffer.FileBytes.readUnsignedShort(FileBytes.java:286) ~[catalyst-buffer-1.0.0-rc3.jar:na]
at io.atomix.catalyst.buffer.AbstractBuffer.readUnsignedShort(AbstractBuffer.java:528) ~[catalyst-buffer-1.0.0-rc3.jar:na]
at io.atomix.copycat.server.storage.Segment.(Segment.java:81) ~[classes/:na]
at io.atomix.copycat.server.storage.SegmentManager.loadDiskSegment(SegmentManager.java:345) ~[classes/:na]
at io.atomix.copycat.server.storage.SegmentManager.loadSegment(SegmentManager.java:332) ~[classes/:na]
at io.atomix.copycat.server.storage.SegmentManager.loadSegments(SegmentManager.java:404) ~[classes/:na]
at io.atomix.copycat.server.storage.SegmentManager.open(SegmentManager.java:95) ~[classes/:na]
at io.atomix.copycat.server.storage.SegmentManager.(SegmentManager.java:58) ~[classes/:na]
at io.atomix.copycat.server.storage.Log.(Log.java:135) ~[classes/:na]
at io.atomix.copycat.server.storage.Storage.open(Storage.java:280) ~[classes/:na]
at io.atomix.copycat.server.state.ServerContext.lambda$0(ServerContext.java:72) ~[classes/:na]
at io.atomix.copycat.server.state.ServerContext$$Lambda$3/846238611.run(Unknown Source) ~[na:na]
at io.atomix.catalyst.util.concurrent.Runnables.lambda$logFailure$17(Runnables.java:20) ~[catalyst-common-1.0.0-rc3.jar:na]
at io.atomix.catalyst.util.concurrent.Runnables$$Lambda$4/1663166483.run(Unknown Source) [catalyst-common-1.0.0-rc3.jar:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_25]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_25]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_25]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_25]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_25]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_25]

—
Reply to this email directly or view it on GitHub.

from copycat.

Added an issue for this in Catalyst:
atomix/catalyst#2

from copycat.

Thanks. That makes sense. I need to spend some time looking at the catalyst package.

from copycat.

Actually, I think the issue I mentioned may not be the case. I do think this is more likely related to a bug in resizing buffers, but I have yet to reproduce the issue, so I'm going to reopen this.

This gist if this bug is this:

• When the log is recovered from disk, as each Segment is loaded, it reads all the entries in the segment file and rebuilds an in-memory index: https://github.com/atomix/copycat/blob/master/server/src/main/java/io/atomix/copycat/server/storage/Segment.java#L75-L83
• When StorageLevel.DISK is configured, a FileBuffer is used. The file buffer should automatically scale its capacity up to the maximum capacity on both reads and writes, and I haven't been able to break this in tests: https://github.com/atomix/catalyst/blob/master/buffer/src/main/java/io/atomix/catalyst/buffer/AbstractBuffer.java#L360-L378
• When bytes are read from a FileBuffer, they're ultimately read through a FileBytes object. The FileBytes object validates that it has been explicitly resized by the parent Buffer to the appropriate length for reads and writes: https://github.com/atomix/catalyst/blob/master/buffer/src/main/java/io/atomix/catalyst/buffer/AbstractBytes.java#L44-L59
• However, the bytes size validation is what is failing. Essentially, this means the Buffer thinks the Bytes object is larger than it is (since the read passes the Buffers bounds checks).

I haven't yet been able to find any issue in the resizing/validation logic in AbstractBytes and AbstractBuffer that would cause this issue, and I haven't been able to reproduce it at that level, but the fact that the bounds check in the Buffer passes and the bounds check in the Bytes object fails implies it's a bug in Catalyst. But I'd love for you @madjam to look at that code. I feel like I'm missing something.

In the meantime, I'm going to try to reproduce this in Copycat's log tests. If we can get a reproducer I'm sure the issue can be quickly resolved. I want to leave this issue open at least until it's verified that it is in Catalyst.

from copycat.

I was able to reproduce what's likely a related error:

java.nio.BufferUnderflowException
    at io.atomix.catalyst.buffer.AbstractBytes.checkRead(AbstractBytes.java:57)
    at io.atomix.catalyst.buffer.FileBytes.readLong(FileBytes.java:345)
    at io.atomix.catalyst.buffer.AbstractBuffer.readLong(AbstractBuffer.java:578)
    at io.atomix.copycat.server.storage.Segment.<init>(Segment.java:78)
    at io.atomix.copycat.server.storage.SegmentManager.loadDiskSegment(SegmentManager.java:345)
    at io.atomix.copycat.server.storage.SegmentManager.loadSegment(SegmentManager.java:332)
    at io.atomix.copycat.server.storage.SegmentManager.loadSegments(SegmentManager.java:404)
    at io.atomix.copycat.server.storage.SegmentManager.open(SegmentManager.java:95)
    at io.atomix.copycat.server.storage.SegmentManager.<init>(SegmentManager.java:58)
    at io.atomix.copycat.server.storage.Log.<init>(Log.java:135)
    at io.atomix.copycat.server.storage.Storage.open(Storage.java:280)
    at io.atomix.copycat.server.storage.LogTest.createLog(LogTest.java:50)
    at io.atomix.copycat.server.storage.FileLogTest.testRecoverAfterClose2(FileLogTest.java:68)

In order to produce this error, I had to introduce significant randomness and use fairly large segments in the tests. The current tests have only moderate randomness and use small segments. Hopefully I can find a way to reproduce it more reliably.

from copycat.

So I was able to reproduce the specific exception by changing SegmentManager.DEFAULT_BUFFER_SIZE to a lower value (from the default 1MB). I can share the specific log segment files if that is going to be useful.

from copycat.

Ahh great. I haven't found a great reproducer yet. If we can get a test that reproduces the issue consistently I'm sure I can fix it. I think it's really dependent on the entry and segment size as the exceptions occur only when the offsets (stored at the beginning of each entry in the log) exactly align with the initial segment Buffer/Bytes size. I'm able to reproduce the issue with randomization in about 1/10 tests, but that's enough to make it a major PITA to debug. The two stacktraces above are definitely related to the same issue, so either one would do.

from copycat.

Actually I should be able to create a reproducer once I can manage to catch the exception again.

from copycat.

I am able to reproduce the exception consistently with the log I have. So basically my log directory contains the files in this link

Also I am running with a configured value of 32768 for maxEntriesPerSegment

from copycat.

I actually just got a consistent reproducer too. Now should be able to figure this out...

from copycat.

Ahh I got it :-)

Gonna add some tests and submit a PR to Catalyst.

from copycat.

@madjam this PR fixes this issue AFAICT: atomix/catalyst#3

Thanks for the help! I'll push a new beta release of all of the above once it's merged.

from copycat.