hadoop-hdfs-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Stephen O'Donnell (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HDFS-14557) JournalNode error: Can't scan a pre-transactional edit log
Date Tue, 30 Jul 2019 15:43:00 GMT

    [ 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$SelectChannelConnectorWithSafeStartup@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: hdfs-issues-unsubscribe@hadoop.apache.org
For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org


Mime
View raw message