You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Rushabh Shah (Jira)" <ji...@apache.org> on 2021/05/17 18:17:01 UTC
[jira] [Created] (HBASE-25893) Corruption in recovered WAL in
WALSplitter
Rushabh Shah created HBASE-25893:
------------------------------------
Summary: Corruption in recovered WAL in WALSplitter
Key: HBASE-25893
URL: https://issues.apache.org/jira/browse/HBASE-25893
Project: HBase
Issue Type: Improvement
Components: regionserver, wal
Affects Versions: 1.6.0
Reporter: Rushabh Shah
Assignee: Rushabh Shah
Recently we encountered RS aborts due to NPE while replaying edits from split logs during region open.
{noformat}
2021-05-13 19:34:28,871 ERROR [<hostname>:60020-17] handler.OpenRegionHandler - Failed open of region=<table-name>,1619036437822.0556ab96be88000b6f5f3fad47938ccd., starting to roll back the global memstore size.
java.lang.NullPointerException
at org.apache.hadoop.hbase.CellUtil.matchingFamily(CellUtil.java:411)
at org.apache.hadoop.hbase.regionserver.HRegion.replayRecoveredEdits(HRegion.java:4682)
at org.apache.hadoop.hbase.regionserver.HRegion.replayRecoveredEditsForPaths(HRegion.java:4557)
at org.apache.hadoop.hbase.regionserver.HRegion.replayRecoveredEditsIfAny(HRegion.java:4470)
at org.apache.hadoop.hbase.regionserver.HRegion.initializeRegionInternals(HRegion.java:949)
at org.apache.hadoop.hbase.regionserver.HRegion.initialize(HRegion.java:908)
at org.apache.hadoop.hbase.regionserver.HRegion.openHRegion(HRegion.java:7253)
at org.apache.hadoop.hbase.regionserver.HRegion.openHRegion(HRegion.java:7214)
at org.apache.hadoop.hbase.regionserver.HRegion.openHRegion(HRegion.java:7185)
at org.apache.hadoop.hbase.regionserver.HRegion.openHRegion(HRegion.java:7141)
at org.apache.hadoop.hbase.regionserver.HRegion.openHRegion(HRegion.java:7092)
at org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler.openRegion(OpenRegionHandler.java:364)
at org.apache.hadoop.hbase.regionserver.handler.OpenRegionHandler.process(OpenRegionHandler.java:131)
at org.apache.hadoop.hbase.executor.EventHandler.run(EventHandler.java:129)
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)
{noformat}
Tracing back how the corrupt wal was generated.
{noformat}
2021-05-12 05:21:23,333 FATAL [<hostname>:60020-0-Writer-1] wal.WALSplitter - 556ab96be88000b6f5f3fad47938ccd/5039807= to log
java.nio.channels.ClosedChannelException
at org.apache.hadoop.hdfs.DataStreamer$LastExceptionInStreamer.throwException4Close(DataStreamer.java:331)
at org.apache.hadoop.hdfs.DFSOutputStream.checkClosed(DFSOutputStream.java:151)
at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:105)
at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:58)
at java.io.DataOutputStream.write(DataOutputStream.java:107)
at org.apache.hadoop.hbase.KeyValue.write(KeyValue.java:2543)
at org.apache.phoenix.hbase.index.wal.KeyValueCodec.write(KeyValueCodec.java:104)
at org.apache.hadoop.hbase.regionserver.wal.IndexedWALEditCodec$IndexKeyValueEncoder.write(IndexedWALEditCodec.java:218)
at org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.append(ProtobufLogWriter.java:128)
at org.apache.hadoop.hbase.wal.WALSplitter$LogRecoveredEditsOutputSink.appendBuffer(WALSplitter.java:1742)
at org.apache.hadoop.hbase.wal.WALSplitter$LogRecoveredEditsOutputSink.append(WALSplitter.java:1714)
at org.apache.hadoop.hbase.wal.WALSplitter$WriterThread.writeBuffer(WALSplitter.java:1179)
at org.apache.hadoop.hbase.wal.WALSplitter$WriterThread.doRun(WALSplitter.java:1171)
at org.apache.hadoop.hbase.wal.WALSplitter$WriterThread.run(WALSplitter.java:1141)
2021-05-12 05:21:23,333 ERROR [<hostname>:60020-0-Writer-1] wal.WALSplitter - Exiting thread
java.nio.channels.ClosedChannelException
at org.apache.hadoop.hdfs.DataStreamer$LastExceptionInStreamer.throwException4Close(DataStreamer.java:331)
at org.apache.hadoop.hdfs.DFSOutputStream.checkClosed(DFSOutputStream.java:151)
at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:105)
at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:58)
at java.io.DataOutputStream.write(DataOutputStream.java:107)
at org.apache.hadoop.hbase.KeyValue.write(KeyValue.java:2543)
at org.apache.phoenix.hbase.index.wal.KeyValueCodec.write(KeyValueCodec.java:104)
at org.apache.hadoop.hbase.regionserver.wal.IndexedWALEditCodec$IndexKeyValueEncoder.write(IndexedWALEditCodec.java:218)
at org.apache.hadoop.hbase.regionserver.wal.ProtobufLogWriter.append(ProtobufLogWriter.java:128)
at org.apache.hadoop.hbase.wal.WALSplitter$LogRecoveredEditsOutputSink.appendBuffer(WALSplitter.java:1742)
at org.apache.hadoop.hbase.wal.WALSplitter$LogRecoveredEditsOutputSink.append(WALSplitter.java:1714)
at org.apache.hadoop.hbase.wal.WALSplitter$WriterThread.writeBuffer(WALSplitter.java:1179)
at org.apache.hadoop.hbase.wal.WALSplitter$WriterThread.doRun(WALSplitter.java:1171)
at org.apache.hadoop.hbase.wal.WALSplitter$WriterThread.run(WALSplitter.java:1141)
{noformat}
3 milliseconds ago, it looks like we closed the log file
{noformat}
2021-05-12 05:21:23,330 DEBUG [it-log-closeStream-1] wal.WALSplitter - Closed wap hdfs://<cluster-name>/hbase/data/default/<table-name>/0556ab96be88000b6f5f3fad47938ccd/recovered.edits/0000000000005039408-<hostname>%2C60020%2C1620792238779.1620794103718.temp (wrote 85 edits, skipped 0 edits in 204ms
2021-05-12 05:21:23,343 INFO [it-log-closeStream-1] wal.WALSplitter - Rename hdfs://<cluster-name>/hbase/data/default/<table-name>/0556ab96be88000b6f5f3fad47938ccd/recovered.edits/0000000000005039408-<hostname>%2C60020%2C1620792238779.1620794103718.temp to hdfs://<cluster-name>/hbase/data/default/<table-name>/0556ab96be88000b6f5f3fad47938ccd/recovered.edits/0000000000005039806
{noformat}
It looks like we closed the log file while the writer thread is still writing to it.
Here is the code from branch-1
{code:java}
@Override
public List<Path> finishWritingAndClose() throws IOException {
boolean isSuccessful = false;
List<Path> result = null;
try {
isSuccessful = finishWriting(false);
} finally {
result = close(); ------> We close the log file here
List<IOException> thrown = closeLogWriters(null); -------> We close the writer here.
if (thrown != null && !thrown.isEmpty()) {
throw MultipleIOException.createIOException(thrown);
}
}
{code}
We should close the writer first and then close the log file.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)