You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "stack (JIRA)" <ji...@apache.org> on 2010/09/08 08:25:32 UTC
[jira] Created: (HBASE-2967) Failed split: IOE 'File is Corrupt!'
-- sync length not being written out to SequenceFile
Failed split: IOE 'File is Corrupt!' -- sync length not being written out to SequenceFile
-----------------------------------------------------------------------------------------
Key: HBASE-2967
URL: https://issues.apache.org/jira/browse/HBASE-2967
Project: HBase
Issue Type: Bug
Reporter: stack
Priority: Blocker
Fix For: 0.90.0
We saw this on one of our clusters:
{code}
2010-09-07 18:07:16,229 WARN org.apache.hadoop.hbase.master.RegionServerOperationQueue: Failed processing: ProcessServerShutdown of sv4borg18,60020,1283516293515; putting onto delayed todo queue
java.io.IOException: File is corrupt!
at org.apache.hadoop.io.SequenceFile$Reader.readRecordLength(SequenceFile.java:1907)
at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1932)
at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1837)
at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1883)
at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:121)
at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:113)
at org.apache.hadoop.hbase.regionserver.wal.HLog.parseHLog(HLog.java:1493)
at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1256)
at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1143)
at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:299)
at org.apache.hadoop.hbase.master.RegionServerOperationQueue.process(RegionServerOperationQueue.java:147)
at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:532)
{code}
Because it was an IOE, it got requeued. Each time around we failed on it again.
A few things:
+ This exception needs to add filename and the position in file at which problem found.
+ Need to commit little patch over in HBASE-2889 that outputs position and ordinal of wal edit because it helps diagnose these kinds of issues.
+ We should be able to skip the bad edit; just postion ourselves at byte past the bad sync and start reading again
+ There must be something about our setup that makes it so we fail write of the sync 16 random bytes that make up the SF 'sync' marker though oddly for one of the files, the sync failure happens at 1/3rd of the way into a 64MB wal, edit #2000 out of 130k odd edits.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Resolved: (HBASE-2967) Failed split: IOE 'File is Corrupt!'
-- sync length not being written out to SequenceFile
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-2967?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
stack resolved HBASE-2967.
--------------------------
Resolution: Fixed
Committed branch and trunk.
> Failed split: IOE 'File is Corrupt!' -- sync length not being written out to SequenceFile
> -----------------------------------------------------------------------------------------
>
> Key: HBASE-2967
> URL: https://issues.apache.org/jira/browse/HBASE-2967
> Project: HBase
> Issue Type: Bug
> Reporter: stack
> Priority: Blocker
> Fix For: 0.90.0
>
>
> We saw this on one of our clusters:
> {code}
> 2010-09-07 18:07:16,229 WARN org.apache.hadoop.hbase.master.RegionServerOperationQueue: Failed processing: ProcessServerShutdown of sv4borg18,60020,1283516293515; putting onto delayed todo queue
> java.io.IOException: File is corrupt!
> at org.apache.hadoop.io.SequenceFile$Reader.readRecordLength(SequenceFile.java:1907)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1932)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1837)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1883)
> at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:121)
> at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:113)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.parseHLog(HLog.java:1493)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1256)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1143)
> at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:299)
> at org.apache.hadoop.hbase.master.RegionServerOperationQueue.process(RegionServerOperationQueue.java:147)
> at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:532)
> {code}
> Because it was an IOE, it got requeued. Each time around we failed on it again.
> A few things:
> + This exception needs to add filename and the position in file at which problem found.
> + Need to commit little patch over in HBASE-2889 that outputs position and ordinal of wal edit because it helps diagnose these kinds of issues.
> + We should be able to skip the bad edit; just postion ourselves at byte past the bad sync and start reading again
> + There must be something about our setup that makes it so we fail write of the sync 16 random bytes that make up the SF 'sync' marker though oddly for one of the files, the sync failure happens at 1/3rd of the way into a 64MB wal, edit #2000 out of 130k odd edits.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Assigned: (HBASE-2967) Failed split: IOE 'File is Corrupt!'
-- sync length not being written out to SequenceFile
Posted by "Jean-Daniel Cryans (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-2967?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jean-Daniel Cryans reassigned HBASE-2967:
-----------------------------------------
Assignee: stack
> Failed split: IOE 'File is Corrupt!' -- sync length not being written out to SequenceFile
> -----------------------------------------------------------------------------------------
>
> Key: HBASE-2967
> URL: https://issues.apache.org/jira/browse/HBASE-2967
> Project: HBase
> Issue Type: Bug
> Reporter: stack
> Assignee: stack
> Priority: Blocker
> Fix For: 0.90.0
>
>
> We saw this on one of our clusters:
> {code}
> 2010-09-07 18:07:16,229 WARN org.apache.hadoop.hbase.master.RegionServerOperationQueue: Failed processing: ProcessServerShutdown of sv4borg18,60020,1283516293515; putting onto delayed todo queue
> java.io.IOException: File is corrupt!
> at org.apache.hadoop.io.SequenceFile$Reader.readRecordLength(SequenceFile.java:1907)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1932)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1837)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1883)
> at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:121)
> at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:113)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.parseHLog(HLog.java:1493)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1256)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1143)
> at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:299)
> at org.apache.hadoop.hbase.master.RegionServerOperationQueue.process(RegionServerOperationQueue.java:147)
> at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:532)
> {code}
> Because it was an IOE, it got requeued. Each time around we failed on it again.
> A few things:
> + This exception needs to add filename and the position in file at which problem found.
> + Need to commit little patch over in HBASE-2889 that outputs position and ordinal of wal edit because it helps diagnose these kinds of issues.
> + We should be able to skip the bad edit; just postion ourselves at byte past the bad sync and start reading again
> + There must be something about our setup that makes it so we fail write of the sync 16 random bytes that make up the SF 'sync' marker though oddly for one of the files, the sync failure happens at 1/3rd of the way into a 64MB wal, edit #2000 out of 130k odd edits.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HBASE-2967) Failed split: IOE 'File is Corrupt!'
-- sync length not being written out to SequenceFile
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-2967?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12907433#action_12907433 ]
stack commented on HBASE-2967:
------------------------------
I got the lowdown from Todd.
Problem would seem to be here in SequenceFile:
{code}
/** create a sync point */
public void sync() throws IOException {
if (sync != null && lastSyncPos != out.getPos()) {
out.writeInt(SYNC_ESCAPE); // mark the start of the sync
out.write(sync); // write sync
lastSyncPos = out.getPos(); // update lastSyncPos
}
}
{code}
Notice how the method is unsynchronized and how it does two distinct writes to out.
If you browse down in SequenceFile to the append methods, you'll see that these methods ARE synchronized.
In concurrent times, you could imagine the above write of SYNC_ESCAPE followed by the actual 16 bytes of the sync array being interpolated by an append. On read, we'd fail the sync check.
So, not calling the sync would seem to be the way to go (This is what CDH does according to Todd). But says you, what if we ever want to make use of these sync sequences to skip records corrupted by cosmic rays up in HDFS? Well, turns out SF calls checkAndWriteSync internal to the append calls and will write the sync out at every SYNC_INTERVAL... so when we want to come back and handle these 'File is Corrupt!' messages later, we can.
Here's the change I'll make:
{code}
Index: src/main/java/org/apache/hadoop/hbase/regionserver/wal/SequenceFileLogWriter.java
===================================================================
--- src/main/java/org/apache/hadoop/hbase/regionserver/wal/SequenceFileLogWriter.java (revision 995156)
+++ src/main/java/org/apache/hadoop/hbase/regionserver/wal/SequenceFileLogWriter.java (working copy)
@@ -120,7 +120,6 @@
@Override
public void sync() throws IOException {
- this.writer.sync();
if (this.syncFs != null) {
try {
this.syncFs.invoke(this.writer, HLog.NO_ARGS);
{code}
Regards other items in the above, over in HBASE-2889, we add logging of filename+position to exception and did some fixup on HLog main to help diagnose these kinds of issues
> Failed split: IOE 'File is Corrupt!' -- sync length not being written out to SequenceFile
> -----------------------------------------------------------------------------------------
>
> Key: HBASE-2967
> URL: https://issues.apache.org/jira/browse/HBASE-2967
> Project: HBase
> Issue Type: Bug
> Reporter: stack
> Priority: Blocker
> Fix For: 0.90.0
>
>
> We saw this on one of our clusters:
> {code}
> 2010-09-07 18:07:16,229 WARN org.apache.hadoop.hbase.master.RegionServerOperationQueue: Failed processing: ProcessServerShutdown of sv4borg18,60020,1283516293515; putting onto delayed todo queue
> java.io.IOException: File is corrupt!
> at org.apache.hadoop.io.SequenceFile$Reader.readRecordLength(SequenceFile.java:1907)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1932)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1837)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1883)
> at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:121)
> at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:113)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.parseHLog(HLog.java:1493)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1256)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1143)
> at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:299)
> at org.apache.hadoop.hbase.master.RegionServerOperationQueue.process(RegionServerOperationQueue.java:147)
> at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:532)
> {code}
> Because it was an IOE, it got requeued. Each time around we failed on it again.
> A few things:
> + This exception needs to add filename and the position in file at which problem found.
> + Need to commit little patch over in HBASE-2889 that outputs position and ordinal of wal edit because it helps diagnose these kinds of issues.
> + We should be able to skip the bad edit; just postion ourselves at byte past the bad sync and start reading again
> + There must be something about our setup that makes it so we fail write of the sync 16 random bytes that make up the SF 'sync' marker though oddly for one of the files, the sync failure happens at 1/3rd of the way into a 64MB wal, edit #2000 out of 130k odd edits.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HBASE-2967) Failed split: IOE 'File is Corrupt!'
-- sync length not being written out to SequenceFile
Posted by "stack (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HBASE-2967?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12907478#action_12907478 ]
stack commented on HBASE-2967:
------------------------------
So, looking at a snapshot of log files on our production, about 1/2 had this issue. After rolling out the above change, subsequent log files are again parseable.
> Failed split: IOE 'File is Corrupt!' -- sync length not being written out to SequenceFile
> -----------------------------------------------------------------------------------------
>
> Key: HBASE-2967
> URL: https://issues.apache.org/jira/browse/HBASE-2967
> Project: HBase
> Issue Type: Bug
> Reporter: stack
> Priority: Blocker
> Fix For: 0.90.0
>
>
> We saw this on one of our clusters:
> {code}
> 2010-09-07 18:07:16,229 WARN org.apache.hadoop.hbase.master.RegionServerOperationQueue: Failed processing: ProcessServerShutdown of sv4borg18,60020,1283516293515; putting onto delayed todo queue
> java.io.IOException: File is corrupt!
> at org.apache.hadoop.io.SequenceFile$Reader.readRecordLength(SequenceFile.java:1907)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1932)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1837)
> at org.apache.hadoop.io.SequenceFile$Reader.next(SequenceFile.java:1883)
> at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:121)
> at org.apache.hadoop.hbase.regionserver.wal.SequenceFileLogReader.next(SequenceFileLogReader.java:113)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.parseHLog(HLog.java:1493)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1256)
> at org.apache.hadoop.hbase.regionserver.wal.HLog.splitLog(HLog.java:1143)
> at org.apache.hadoop.hbase.master.ProcessServerShutdown.process(ProcessServerShutdown.java:299)
> at org.apache.hadoop.hbase.master.RegionServerOperationQueue.process(RegionServerOperationQueue.java:147)
> at org.apache.hadoop.hbase.master.HMaster.run(HMaster.java:532)
> {code}
> Because it was an IOE, it got requeued. Each time around we failed on it again.
> A few things:
> + This exception needs to add filename and the position in file at which problem found.
> + Need to commit little patch over in HBASE-2889 that outputs position and ordinal of wal edit because it helps diagnose these kinds of issues.
> + We should be able to skip the bad edit; just postion ourselves at byte past the bad sync and start reading again
> + There must be something about our setup that makes it so we fail write of the sync 16 random bytes that make up the SF 'sync' marker though oddly for one of the files, the sync failure happens at 1/3rd of the way into a 64MB wal, edit #2000 out of 130k odd edits.
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.