Benoit Sigoure created HBASE-28569: -------------------------------------- Summary: Race condition during WAL splitting leading to corrupt recovered.edits Key: HBASE-28569 URL: https://issues.apache.org/jira/browse/HBASE-28569 Project: HBase Issue Type: Bug Components: regionserver Affects Versions: 2.4.17 Reporter: Benoit Sigoure
There is a race condition that can happen when a regionserver aborts initialisation while splitting a WAL from another regionserver. This race leads to writing the WAL trailer for recovered edits while the writer threads are still running, thus the trailer gets interleaved with the edits corrupting the recovered edits file (and preventing the region to be assigned). We've seen this happening on HBase 2.4.17, but looking at the latest code it seems that the race can still happen there. The sequence of operations that leads to this issue: * {{org.apache.hadoop.hbase.wal.WALSplitter.splitWAL}} calls {{outputSink.close()}} after adding all the entries to the buffers * The output sink is {{org.apache.hadoop.hbase.wal.RecoveredEditsOutputSink}} and its {{close}} method calls first {{finishWriterThreads}} in a try block which in turn will call {{finish}} on every thread and then join it to make sure it's done. * However if the splitter thread gets interrupted because of RS aborting, the join will get interrupted and {{finishWriterThreads}} will rethrow without waiting for the writer threads to stop. * This is problematic because coming back to {{org.apache.hadoop.hbase.wal.RecoveredEditsOutputSink.close}} it will call {{closeWriters}} in a finally block (so it will execute even when the join was interrupted). * {{closeWriters}} will call {{org.apache.hadoop.hbase.wal.AbstractRecoveredEditsOutputSink.closeRecoveredEditsWriter}} which will call {{close}} on {{{}editWriter.writer{}}}. * When {{editWriter.writer}} is {{{}org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter{}}}, its {{close}} method will write the trailer before closing the file. * This trailer write will now go in parallel with writer threads writing entries causing corruption. * If there are no other errors, {{closeWriters}} will succeed renaming all temporary files to final recovered edits, causing problems next time the region is assigned. Logs evidence supporting the above flow: Abort is triggered (because it failed to open the WAL due to some ongoing infra issue): {noformat} regionserver-2 regionserver 06:22:00.384 [RS_OPEN_META-regionserver/host01:16201-0] ERROR org.apache.hadoop.hbase.regionserver.HRegionServer - ***** ABORTING region server host01,16201,1709187641249: WAL can not clean up after init failed *****{noformat} We can see that the writer threads were still active after closing (even considering that the ordering in the log might not be accurate, we see that they die because the channel is closed while still writing, not because they're stopping): {noformat} regionserver-2 regionserver 06:22:09.662 [DataStreamer for file /hbase/data/default/aeris_v2/53308260a6b22eaf6ebb8353f7df3077/recovered.edits/0000000003169600719-host02%2C16201%2C1709180140645.1709186722780.temp block BP-1645452845-192.168.2.230-1615455682886:blk_1076340939_2645368] WARN org.apache.hadoop.hdfs.DataStreamer - Error Recovery for BP-1645452845-192.168.2.230-1615455682886:blk_1076340939_2645368 in pipeline [DatanodeInfoWithStorage[192.168.2.230:15010,DS-2aa201ab-1027-47ec-b05f-b39d795fda85,DISK], DatanodeInfoWithStorage[192.168.2.232:15010,DS-39651d5a-67d2-4126-88f0-45cdee967dab,DISK], Datanode InfoWithStorage[192.168.2.231:15010,DS-e08a1d17-f7b1-4e39-9713-9706bd762f48,DISK]]: datanode 2(DatanodeInfoWithStorage[192.168.2.231:15010,DS-e08a1d17-f7b1-4e39-9713-9706bd762f48,DISK]) is bad. regionserver-2 regionserver 06:22:09.742 [split-log-closeStream-pool-1] INFO org.apache.hadoop.hbase.wal.RecoveredEditsOutputSink - Closed recovered edits writer path=hdfs://mycluster/hbase/data/default/aeris_v2/53308260a6b22eaf6ebb8353f7df3077/recovered.edits/0000000003169600719-host02%2C16201% 2C1709180140645.1709186722780.temp (wrote 5949 edits, skipped 0 edits in 93 ms) regionserver-2 regionserver 06:22:09.743 [RS_LOG_REPLAY_OPS-regionserver/host01:16201-1-Writer-0] ERROR org.apache.hadoop.hbase.wal.RecoveredEditsOutputSink - Failed to write log entry aeris_v2/53308260a6b22eaf6ebb8353f7df3077/3169611655=[#edits: 8 = <REDACTED>] to log regionserver-2 regionserver java.nio.channels.ClosedChannelException: null regionserver-2 regionserver at org.apache.hadoop.hdfs.ExceptionLastSeen.throwException4Close(ExceptionLastSeen.java:73) ~[hadoop-hdfs-client-3.2.4.jar:?] regionserver-2 regionserver at org.apache.hadoop.hdfs.DFSOutputStream.checkClosed(DFSOutputStream.java:153) ~[hadoop-hdfs-client-3.2.4.jar:?] regionserver-2 regionserver at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:105) ~[hadoop-common-3.2.4.jar:?] regionserver-2 regionserver at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:57) ~[hadoop-common-3.2.4.jar:?] regionserver-2 regionserver at java.io.DataOutputStream.write(Unknown Source) ~[?:?] regionserver-2 regionserver at org.apache.hadoop.hbase.io.ByteBufferWriterOutputStream.write(ByteBufferWriterOutputStream.java:94) ~[hbase-common-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.KeyValue.write(KeyValue.java:2093) ~[hbase-common-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.KeyValueUtil.oswrite(KeyValueUtil.java:737) ~[hbase-common-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.regionserver.wal.WALCellCodec$EnsureKvEncoder.write(WALCellCodec.java:365) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.append(ProtobufLogWriter.java:58) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.AbstractRecoveredEditsOutputSink$RecoveredEditsWriter.writeRegionEntries(AbstractRecoveredEditsOutputSink.java:237) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.RecoveredEditsOutputSink.append(RecoveredEditsOutputSink.java:66) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.OutputSink$WriterThread.writeBuffer(OutputSink.java:249) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.OutputSink$WriterThread.doRun(OutputSink.java:241) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.OutputSink$WriterThread.run(OutputSink.java:211) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver 06:22:09.745 [RS_LOG_REPLAY_OPS-regionserver/host01:16201-1-Writer-0] ERROR org.apache.hadoop.hbase.wal.OutputSink - Exiting thread regionserver-2 regionserver java.nio.channels.ClosedChannelException: null regionserver-2 regionserver at org.apache.hadoop.hdfs.ExceptionLastSeen.throwException4Close(ExceptionLastSeen.java:73) ~[hadoop-hdfs-client-3.2.4.jar:?] regionserver-2 regionserver at org.apache.hadoop.hdfs.DFSOutputStream.checkClosed(DFSOutputStream.java:153) ~[hadoop-hdfs-client-3.2.4.jar:?] regionserver-2 regionserver at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:105) ~[hadoop-common-3.2.4.jar:?] regionserver-2 regionserver at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:57) ~[hadoop-common-3.2.4.jar:?] regionserver-2 regionserver at java.io.DataOutputStream.write(Unknown Source) ~[?:?] regionserver-2 regionserver at org.apache.hadoop.hbase.io.ByteBufferWriterOutputStream.write(ByteBufferWriterOutputStream.java:94) ~[hbase-common-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.KeyValue.write(KeyValue.java:2093) ~[hbase-common-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.KeyValueUtil.oswrite(KeyValueUtil.java:737) ~[hbase-common-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.regionserver.wal.WALCellCodec$EnsureKvEncoder.write(WALCellCodec.java:365) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.append(ProtobufLogWriter.java:58) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.AbstractRecoveredEditsOutputSink$RecoveredEditsWriter.writeRegionEntries(AbstractRecoveredEditsOutputSink.java:237) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.RecoveredEditsOutputSink.append(RecoveredEditsOutputSink.java:66) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.OutputSink$WriterThread.writeBuffer(OutputSink.java:249) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.OutputSink$WriterThread.doRun(OutputSink.java:241) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.OutputSink$WriterThread.run(OutputSink.java:211) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver 06:22:09.749 [split-log-closeStream-pool-1] INFO org.apache.hadoop.hbase.wal.RecoveredEditsOutputSink - Rename recovered edits hdfs://mycluster/hbase/data/default/aeris_v2/53308260a6b22eaf6ebb8353f7df3077/recovered.edits/0000000003169600719-host02%2C16201%2C1709180140645.1709186722780.temp to hdfs://mycluster/hbase/data/default/aeris_v2/53308260a6b22eaf6ebb8353f7df3077/recovered.edits/0000000003169611654{noformat} And we can see the {{finishWriterThreads}} was interrupted: {noformat} regionserver-2 regionserver 06:22:20.643 [RS_LOG_REPLAY_OPS-regionserver/host01:16201-1] WARN org.apache.hadoop.hbase.regionserver.SplitLogWorker - Resigning, interrupted splitting WAL hdfs://mycluster/hbase/WALs/host02,16201,1709180140645-splitting/host02%2C16201%2C1709180140645.1709186722780 regionserver-2 regionserver java.io.InterruptedIOException: null regionserver-2 regionserver at org.apache.hadoop.hbase.wal.OutputSink.finishWriterThreads(OutputSink.java:139) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.RecoveredEditsOutputSink.close(RecoveredEditsOutputSink.java:94) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.WALSplitter.splitWAL(WALSplitter.java:414) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.WALSplitter.splitLogFile(WALSplitter.java:201) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.regionserver.SplitLogWorker.splitLog(SplitLogWorker.java:108) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.regionserver.SplitWALCallable.call(SplitWALCallable.java:100) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.regionserver.SplitWALCallable.call(SplitWALCallable.java:46) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.regionserver.handler.RSProcedureHandler.process(RSProcedureHandler.java:49) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:98) [hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?] regionserver-2 regionserver at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?] regionserver-2 regionserver at java.lang.Thread.run(Unknown Source) [?:?] regionserver-2 regionserver Caused by: java.lang.InterruptedException regionserver-2 regionserver at java.lang.Object.wait(Native Method) ~[?:?] regionserver-2 regionserver at java.lang.Thread.join(Unknown Source) ~[?:?] regionserver-2 regionserver at java.lang.Thread.join(Unknown Source) ~[?:?] regionserver-2 regionserver at org.apache.hadoop.hbase.wal.OutputSink.finishWriterThreads(OutputSink.java:137) ~[hbase-server-2.4.17.jar:2.4.17] regionserver-2 regionserver ... 11 more{noformat} The corrupted recovered edits file contained one additional piece of evidence towards a race condition. The 0 bytes that form the 32 bit trailer length were scattered through the file while the marker {{LAWP}} was written in one piece. This is because in OpenJDK11 {{writeInt}} writes each byte individually but byte arrays are written all at once. Original bug report from Vlad Hanciuta. -- This message was sent by Atlassian Jira (v8.20.10#820010)