[
https://issues.apache.org/jira/browse/HDFS-14557?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16896246#comment-16896246
]
Stephen O'Donnell commented on HDFS-14557:
------------------------------------------
I now understand what happens to cause this "pre-transactional log" error, and
it is indeed related to running out of disk space.
The journal decides to roll the edit logs, converting edits_inprogress_* to
something like edits_0000000000000031679-0000000000000031704. The steps it goes
through are:
1. Rename the edits_inprogress file to the new name.
2. Create a new edits_inprogress file.
3. Write the header to the double buffer (note not yet to the file), which is
the layout version.
4. Then flush the buffer.
5. Prior to the buffer flushing, the new edits_inprogress file has some bytes
pre-allocated. I am not sure what controls the size, but it all my tests, it
allocates a file of 1MB, where every byte is 0xFF (-1 when Java calls
readByte() or readInt() on the file).
6. After the pre-allocation completes, write the buffer contents (containing
the file header) to disk.
If step 5 fails with a disk space error, you are left with a file somewhere
between zero and 1MB filled with 0xFF and that is what happened in the below
log segment:
{code}
2019-07-30 08:18:29,721 WARN
org.apache.hadoop.hdfs.server.namenode.FileJournalManager: Unable to start log
segment 31705 at
/boot/jn/nameservice1/current/edits_inprogress_0000000000000031705: No space
left on device
2019-07-30 08:18:29,721 FATAL
org.apache.hadoop.hdfs.qjournal.server.JournalNode: Error reported on file
/boot/jn/nameservice1/current/edits_inprogress_0000000000000031705... exiting
java.lang.Exception
at
org.apache.hadoop.hdfs.qjournal.server.JournalNode$ErrorReporter.reportErrorOnFile(JournalNode.java:301)
at
org.apache.hadoop.hdfs.server.namenode.FileJournalManager.startLogSegment(FileJournalManager.java:130)
at
org.apache.hadoop.hdfs.qjournal.server.Journal.startLogSegment(Journal.java:559)
at
org.apache.hadoop.hdfs.qjournal.server.JournalNodeRpcServer.startLogSegment(JournalNodeRpcServer.java:162)
at
org.apache.hadoop.hdfs.qjournal.protocolPB.QJournalProtocolServerSideTranslatorPB.startLogSegment(QJournalProtocolServerSideTranslatorPB.java:198)
at
org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocolProtos$QJournalProtocolService$2.callBlockingMethod(QJournalProtocolProtos.java:25425)
at
org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:617)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1073)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2281)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2277)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1924)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2275)
2019-07-30 08:18:29,721 INFO org.apache.hadoop.ipc.Server: Stopping server on
8485
2019-07-30 08:18:29,725 INFO org.mortbay.log: Stopped
HttpServer2$selectchannelconnectorwithsafestar...@host-10-17-100-171.coe.cloudera.com:8480
2019-07-30 08:18:29,726 INFO org.apache.hadoop.ipc.Server: Stopping IPC Server
Responder
2019-07-30 08:18:29,726 INFO org.apache.hadoop.ipc.Server: Stopping IPC Server
listener on 8485
2019-07-30 08:18:29,727 INFO org.apache.hadoop.hdfs.server.common.Storage:
Closing journal storage for Storage Directory /boot/jn/nameservice1
2019-07-30 08:18:29,729 WARN org.apache.hadoop.security.UserGroupInformation:
PriviledgedActionException as:hdfs (auth:SIMPLE) cause:java.io.IOException: No
space left on device
2019-07-30 08:18:29,729 INFO org.apache.hadoop.ipc.Server: IPC Server handler 3
on 8485, call
org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocol.startLogSegment from
10.17.100.160:46094 Call#632 Retry#0
java.io.IOException: No space left on device
at sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
at sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:66)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:89)
at sun.nio.ch.IOUtil.write(IOUtil.java:51)
at sun.nio.ch.FileChannelImpl.writeInternal(FileChannelImpl.java:778)
at sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:764)
at org.apache.hadoop.io.IOUtils.writeFully(IOUtils.java:341)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileOutputStream.preallocate(EditLogFileOutputStream.java:231)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileOutputStream.flushAndSync(EditLogFileOutputStream.java:203)
at
org.apache.hadoop.hdfs.server.namenode.EditLogOutputStream.flush(EditLogOutputStream.java:113)
at
org.apache.hadoop.hdfs.server.namenode.EditLogOutputStream.flush(EditLogOutputStream.java:107)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileOutputStream.create(EditLogFileOutputStream.java:122)
at
org.apache.hadoop.hdfs.server.namenode.FileJournalManager.startLogSegment(FileJournalManager.java:124)
at
org.apache.hadoop.hdfs.qjournal.server.Journal.startLogSegment(Journal.java:559)
at
org.apache.hadoop.hdfs.qjournal.server.JournalNodeRpcServer.startLogSegment(JournalNodeRpcServer.java:162)
at
org.apache.hadoop.hdfs.qjournal.protocolPB.QJournalProtocolServerSideTranslatorPB.startLogSegment(QJournalProtocolServerSideTranslatorPB.java:198)
at
org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocolProtos$QJournalProtocolService$2.callBlockingMethod(QJournalProtocolProtos.java:25425)
at
org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:617)
at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1073)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2281)
at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2277)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:422)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1924)
at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2275)
2019-07-30 08:18:29,730 INFO
org.apache.hadoop.hdfs.qjournal.server.JournalNode: SHUTDOWN_MSG:
{code}
Note the stack trace comes from preallocate:
{code}
java.io.IOException: No space left on device
at sun.nio.ch.FileDispatcherImpl.pwrite0(Native Method)
at sun.nio.ch.FileDispatcherImpl.pwrite(FileDispatcherImpl.java:66)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:89)
at sun.nio.ch.IOUtil.write(IOUtil.java:51)
at sun.nio.ch.FileChannelImpl.writeInternal(FileChannelImpl.java:778)
at sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:764)
at org.apache.hadoop.io.IOUtils.writeFully(IOUtils.java:341)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileOutputStream.preallocate(EditLogFileOutputStream.java:231)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileOutputStream.flushAndSync(EditLogFileOutputStream.java:203)
at
org.apache.hadoop.hdfs.server.namenode.EditLogOutputStream.flush(EditLogOutputStream.java:113)
at
org.apache.hadoop.hdfs.server.namenode.EditLogOutputStream.flush(EditLogOutputStream.java:107)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileOutputStream.create(EditLogFileOutputStream.java:122)
{code}
At this stage the JN aborts, and then on restart it will be unable to recover
unless this problem file is manually sidelined:
{code}
2019-07-30 08:18:34,995 WARN org.apache.hadoop.hdfs.server.namenode.FSImage:
Caught exception after scanning through 0 ops from
/boot/jn/nameservice1/current/edits_inprogress_0000000000000031705 while
determining its valid length. Position was 4
java.io.IOException: Can't scan a pre-transactional edit log.
at
org.apache.hadoop.hdfs.server.namenode.FSEditLogOp$LegacyReader.scanOp(FSEditLogOp.java:4610)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileInputStream.scanNextOp(EditLogFileInputStream.java:245)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileInputStream.scanEditLog(EditLogFileInputStream.java:355)
at
org.apache.hadoop.hdfs.server.namenode.FileJournalManager$EditLogFile.scanLog(FileJournalManager.java:551)
at
org.apache.hadoop.hdfs.qjournal.server.Journal.scanStorageForLatestEdits(Journal.java:193)
...
2019-07-30 08:18:35,032 WARN org.apache.hadoop.hdfs.server.namenode.FSImage:
After resync, position is 1044480
{code}
This also explains why different occurrences resync to a different position,
but always under 1MB in the cases I checked - the resync position is the amount
of space that was left on the disk when the log roll happened.
Knowing now how this happens, there are possibly two solutions:
1) If the preallocate method throws an exception, try to clean up the new edit
log it was trying to create, and either delete it or sideline it immediately as
at that stage we know it holds no data.
2) When starting up, if we detect a file with a header of "-1", it is certainly
an invalid header, and is almost certainly a file created after a disk space
issue, and it can be sidelined safely.
> JournalNode error: Can't scan a pre-transactional edit log
> ----------------------------------------------------------
>
> Key: HDFS-14557
> URL: https://issues.apache.org/jira/browse/HDFS-14557
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: ha
> Affects Versions: 2.6.0
> Reporter: Wei-Chiu Chuang
> Priority: Major
>
> We saw the following error in JournalNodes a few times before.
> {noformat}
> 2016-09-22 12:44:24,505 WARN org.apache.hadoop.hdfs.server.namenode.FSImage:
> Caught exception after scanning through 0 ops from /data/1/dfs/current/ed
> its_inprogress_0000000000000661942 while determining its valid length.
> Position was 761856
> java.io.IOException: Can't scan a pre-transactional edit log.
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLogOp$LegacyReader.scanOp(FSEditLogOp.java:4592)
> at
> org.apache.hadoop.hdfs.server.namenode.EditLogFileInputStream.scanNextOp(EditLogFileInputStream.java:245)
> at
> org.apache.hadoop.hdfs.server.namenode.EditLogFileInputStream.scanEditLog(EditLogFileInputStream.java:355)
> at
> org.apache.hadoop.hdfs.server.namenode.FileJournalManager$EditLogFile.scanLog(FileJournalManager.java:551)
> at
> org.apache.hadoop.hdfs.qjournal.server.Journal.scanStorageForLatestEdits(Journal.java:193)
> at org.apache.hadoop.hdfs.qjournal.server.Journal.<init>(Journal.java:153)
> at
> org.apache.hadoop.hdfs.qjournal.server.JournalNode.getOrCreateJournal(JournalNode.java:90)
> {noformat}
> The edit file was corrupt, and one possible culprit of this error is a full
> disk. The JournalNode can't recovered and must be resync manually from other
> JournalNodes.
--
This message was sent by Atlassian JIRA
(v7.6.14#76016)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
