[
https://issues.apache.org/jira/browse/HBASE-9022?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13721081#comment-13721081
]
stack commented on HBASE-9022:
------------------------------
It failed a few times over night including here
http://54.241.6.143/job/HBase-0.95-Hadoop-2/696/org.apache.hbase$hbase-server/testReport/junit/org.apache.hadoop.hbase.regionserver.wal/TestHLogSplitCompressed/testIOEOnOutputThread/
The debugging shows that we open a writer AFTER the clean up has run (probably
because loaded cluster and the thread gets scheduled later):
Here is section for the above logs:
{{monospaced}}
...
2013-07-26 05:02:48,439 DEBUG [WriterThread-1]
wal.HLogSplitter$LogRecoveredEditsOutputSink(1202): Creating writer
path=/hbase/t1/ccc/recovered.edits/0000000000000000002.temp region=ccc
2013-07-26 05:02:48,440 FATAL [WriterThread-1]
wal.HLogSplitter$LogRecoveredEditsOutputSink(1236): Got while writing log
entry to log
java.io.IOException: Injected
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$LogRecoveredEditsOutputSink.append(HLogSplitter.java:1227)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.writeBuffer(HLogSplitter.java:829)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.doRun(HLogSplitter.java:821)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.run(HLogSplitter.java:791)
2013-07-26 05:02:48,440 ERROR [WriterThread-1]
wal.HLogSplitter$WriterThread(793): Exiting thread
java.io.IOException: Injected
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$LogRecoveredEditsOutputSink.append(HLogSplitter.java:1227)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.writeBuffer(HLogSplitter.java:829)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.doRun(HLogSplitter.java:821)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.run(HLogSplitter.java:791)
2013-07-26 05:02:48,441 DEBUG [Thread-298]
wal.HLogSplitter$LogRecoveredEditsOutputSink(1032): {color:red}Submitting close
of /hbase/t1/ccc/recovered.edits/0000000000000000002.temp{color}
2013-07-26 05:02:48,443 INFO [IPC Server handler 6 on 60581]
namenode.FSNamesystem$DefaultAuditLogger(5567): allowed=true ugi=ec2-user
(auth:SIMPLE) ip=/127.0.0.1 cmd=mkdirs
src=/hbase/t1/bbb/recovered.edits dst=null
perm=ec2-user:supergroup:rwxr-xr-x
2013-07-26 05:02:48,445 INFO [IPC Server handler 9 on 60581]
namenode.FSNamesystem$DefaultAuditLogger(5567): allowed=true ugi=ec2-user
(auth:SIMPLE) ip=/127.0.0.1 cmd=getfileinfo
src=/hbase/t1/bbb/recovered.edits/0000000000000000001.temp dst=null
perm=null
2013-07-26 05:02:48,447 DEBUG [WriterThread-2]
wal.HLogSplitter$LogRecoveredEditsOutputSink(1202): Creating writer
path=/hbase/t1/bbb/recovered.edits/0000000000000000001.temp region=bbb
2013-07-26 05:02:48,447 FATAL [WriterThread-2]
wal.HLogSplitter$LogRecoveredEditsOutputSink(1236): Got while writing log
entry to log
java.io.IOException: Injected
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$LogRecoveredEditsOutputSink.append(HLogSplitter.java:1227)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.writeBuffer(HLogSplitter.java:829)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.doRun(HLogSplitter.java:821)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.run(HLogSplitter.java:791)
2013-07-26 05:02:48,447 ERROR [WriterThread-2]
wal.HLogSplitter$WriterThread(793): Exiting thread
java.io.IOException: Injected
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$LogRecoveredEditsOutputSink.append(HLogSplitter.java:1227)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.writeBuffer(HLogSplitter.java:829)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.doRun(HLogSplitter.java:821)
at
org.apache.hadoop.hbase.regionserver.wal.HLogSplitter$WriterThread.run(HLogSplitter.java:791)
2013-07-26 05:02:48,456 DEBUG [split-log-closeStream-1]
wal.HLogSplitter$LogRecoveredEditsOutputSink$2(1036): Closing
/hbase/t1/ccc/recovered.edits/0000000000000000002.temp
2013-07-26 05:02:48,458 INFO [split-log-closeStream-1]
wal.HLogSplitter$LogRecoveredEditsOutputSink$2(1044): Closed wap
/hbase/t1/ccc/recovered.edits/0000000000000000002.temp (wrote 0 edits in 0ms)
...
{{monospaced}}
So we schedule a writer thread. It opens a recovered.edits writer per region
encountered. The close happens after first region recovered.edits writer is
opened but before the second region is encountered.
> TestHLogSplit.testIOEOnOutputThread fails
> -----------------------------------------
>
> Key: HBASE-9022
> URL: https://issues.apache.org/jira/browse/HBASE-9022
> Project: HBase
> Issue Type: Bug
> Reporter: stack
> Attachments: 9022.addthreaddumping-part2.txt,
> 9022.addthreaddumping.txt, 9022.txt, 9022.txt, 9022.txt,
> 9022.yet-more-logging2.txt, 9022.yet-more-logging.txt
>
>
> https://builds.apache.org/job/PreCommit-HBASE-Build/6428//testReport/org.apache.hadoop.hbase.regionserver.wal/TestHLogSplit/testIOEOnOutputThread/
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
