[jira] [Commented] (HDFS-15114) JournalNodes' committed-txid file includes aborted transaction, breaks NameNode startup
[
https://issues.apache.org/jira/browse/HDFS-15114?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17042956#comment-17042956
]
Steven Rand commented on HDFS-15114:
Hi [~ayushtkn],
Unfortunately, I don't know how to reproduce what happened. We've performed
rolling restarts of the JournalNodes plenty of times without this happening.
I know that makes this JIRA very hard or impossible for anyone to take action
on, but I thought it was good to have the report anyway in case other people
see similar issues.
> JournalNodes' committed-txid file includes aborted transaction, breaks
> NameNode startup
> ---
>
> Key: HDFS-15114
> URL: https://issues.apache.org/jira/browse/HDFS-15114
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: journal-node, namenode
>Affects Versions: 3.2.1
>Reporter: Steven Rand
>Priority: Major
>
> A couple of days ago, our active NameNode in an HA setup aborted a
> {{QuorumOutputStream}} starting at tx 3389424 because tx 3389425 failed to be
> written. This was likely related to a rolling restart of the three
> JournalNodes that was happening at this time. The NameNode logged:
> {code:java}
> 2020-01-11 02:00:50,229 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from
> 10.6.1.181
> 2020-01-11 02:00:50,229 INFO
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs
> 2020-01-11 02:00:50,229 INFO
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 3389424,
> 3389424
> 2020-01-11 02:00:50,229 INFO
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 2
> Total time for transactions(ms): 1 Number of transactions batched in Syncs:
> 0 Number of syncs: 1 SyncTimes(ms): 1 7
> 2020-01-11 02:00:50,245 WARN
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Remote journal
> 10.6.2.187:8485 failed to write txns 3389425-3389425. Will try to write to
> this JN again after the next log roll.
> org.apache.hadoop.ipc.RemoteException(org.apache.hadoop.hdfs.qjournal.protocol.JournalOutOfSyncException):
> Can't write, no segment open ; journal id:
> at org.apache.hadoop.hdfs.qjournal.server.Journal.checkSync(Journal.java:545)
> ... rest of stacktrace ...
> // the same warning for the second JournalNode
> // the same warning for the third JournalNode
> 2020-01-11 02:00:50,246 ERROR
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: flush failed for
> required journal (JournalAndStream(mgr=QJM to [10.6.1.4:8485,
> 10.6.1.181:8485, 10.6.2.187:8485], stream=QuorumOutputStream starting at txid
> 3389424))
> org.apache.hadoop.hdfs.qjournal.client.QuorumException: Got too many
> exceptions to achieve quorum size 2/3. 3 exceptions thrown:
> // the same "Can't write, no segment open ; journal id: " error
> for all 3 JournalNodes
> 2020-01-11 02:00:50,246 WARN
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting
> QuorumOutputStream starting at txid 3389424
> 2020-01-11 02:00:50,255 INFO org.apache.hadoop.util.ExitUtil: Exiting with
> status 1: Error: flush failed for required journal (JournalAndStream(mgr=QJM
> to [10.6.1.4:8485, 10.6.1.181:8485, 10.6.2.187:8485],
> stream=QuorumOutputStream starting at txid 3389424))
> {code}
> Even though the stream was aborted, the {{committed-txid}} file on each of
> the three JournalNodes was updated to be {{3389424}}.
> This caused both NameNodes to fail to start with this error:
>
> {code:java}
> 2020-01-11 02:54:35,483 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Starting services
> required for active state
> 2020-01-11 02:54:35,491 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Starting
> recovery process for unclosed journal segments...
> 2020-01-11 02:54:35,537 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Successfully
> started new epoch 80
> 2020-01-11 02:54:35,537 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Beginning
> recovery of unclosed segment starting at txid 3389422
> 2020-01-11 02:54:35,574 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Recovery prepare
> phase complete. Responses:
> 10.6.1.4:8485: segmentState { startTxId: 3389422 endTxId: 3389423
> isInProgress: false } lastWriterEpoch: 57 lastCommittedTxId: 3389424
> 10.6.2.187:8485: segmentState { startTxId: 3389422 endTxId: 3389423
> isInProgress: false } lastWriterEpoch: 57 lastCommittedTxId: 3389424
> 2020-01-11 02:54:35,575 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Using longest
> log: 10.6.1.4:8485=segmentState {
> startTxId: 3389422
> endTxId: 3389423
> isInProgress: false
> }
> lastWriterEpoch: 57
> lastCommittedTxId: 3389424
> 2020-01-11
[jira] [Commented] (HDFS-15114) JournalNodes' committed-txid file includes aborted transaction, breaks NameNode startup
[
https://issues.apache.org/jira/browse/HDFS-15114?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17042696#comment-17042696
]
Ayush Saxena commented on HDFS-15114:
-
Thanx [~Steven Rand] for the report.
Are you able to reproduce the issue?
Will it be possible to extend a UT for it?
> JournalNodes' committed-txid file includes aborted transaction, breaks
> NameNode startup
> ---
>
> Key: HDFS-15114
> URL: https://issues.apache.org/jira/browse/HDFS-15114
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: journal-node, namenode
>Affects Versions: 3.2.1
>Reporter: Steven Rand
>Priority: Major
>
> A couple of days ago, our active NameNode in an HA setup aborted a
> {{QuorumOutputStream}} starting at tx 3389424 because tx 3389425 failed to be
> written. This was likely related to a rolling restart of the three
> JournalNodes that was happening at this time. The NameNode logged:
> {code:java}
> 2020-01-11 02:00:50,229 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Roll Edit Log from
> 10.6.1.181
> 2020-01-11 02:00:50,229 INFO
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs
> 2020-01-11 02:00:50,229 INFO
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 3389424,
> 3389424
> 2020-01-11 02:00:50,229 INFO
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 2
> Total time for transactions(ms): 1 Number of transactions batched in Syncs:
> 0 Number of syncs: 1 SyncTimes(ms): 1 7
> 2020-01-11 02:00:50,245 WARN
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Remote journal
> 10.6.2.187:8485 failed to write txns 3389425-3389425. Will try to write to
> this JN again after the next log roll.
> org.apache.hadoop.ipc.RemoteException(org.apache.hadoop.hdfs.qjournal.protocol.JournalOutOfSyncException):
> Can't write, no segment open ; journal id:
> at org.apache.hadoop.hdfs.qjournal.server.Journal.checkSync(Journal.java:545)
> ... rest of stacktrace ...
> // the same warning for the second JournalNode
> // the same warning for the third JournalNode
> 2020-01-11 02:00:50,246 ERROR
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: flush failed for
> required journal (JournalAndStream(mgr=QJM to [10.6.1.4:8485,
> 10.6.1.181:8485, 10.6.2.187:8485], stream=QuorumOutputStream starting at txid
> 3389424))
> org.apache.hadoop.hdfs.qjournal.client.QuorumException: Got too many
> exceptions to achieve quorum size 2/3. 3 exceptions thrown:
> // the same "Can't write, no segment open ; journal id: " error
> for all 3 JournalNodes
> 2020-01-11 02:00:50,246 WARN
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting
> QuorumOutputStream starting at txid 3389424
> 2020-01-11 02:00:50,255 INFO org.apache.hadoop.util.ExitUtil: Exiting with
> status 1: Error: flush failed for required journal (JournalAndStream(mgr=QJM
> to [10.6.1.4:8485, 10.6.1.181:8485, 10.6.2.187:8485],
> stream=QuorumOutputStream starting at txid 3389424))
> {code}
> Even though the stream was aborted, the {{committed-txid}} file on each of
> the three JournalNodes was updated to be {{3389424}}.
> This caused both NameNodes to fail to start with this error:
>
> {code:java}
> 2020-01-11 02:54:35,483 INFO
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem: Starting services
> required for active state
> 2020-01-11 02:54:35,491 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Starting
> recovery process for unclosed journal segments...
> 2020-01-11 02:54:35,537 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Successfully
> started new epoch 80
> 2020-01-11 02:54:35,537 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Beginning
> recovery of unclosed segment starting at txid 3389422
> 2020-01-11 02:54:35,574 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Recovery prepare
> phase complete. Responses:
> 10.6.1.4:8485: segmentState { startTxId: 3389422 endTxId: 3389423
> isInProgress: false } lastWriterEpoch: 57 lastCommittedTxId: 3389424
> 10.6.2.187:8485: segmentState { startTxId: 3389422 endTxId: 3389423
> isInProgress: false } lastWriterEpoch: 57 lastCommittedTxId: 3389424
> 2020-01-11 02:54:35,575 INFO
> org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Using longest
> log: 10.6.1.4:8485=segmentState {
> startTxId: 3389422
> endTxId: 3389423
> isInProgress: false
> }
> lastWriterEpoch: 57
> lastCommittedTxId: 3389424
> 2020-01-11 02:54:35,575 ERROR
> org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error:
> recoverUnfinalizedSegments failed for required journal
> (JournalAndStream(mgr=QJM to [10.6.1.4:8485, 10.6.1.181:8485,
> 10.6.2.187:8485], stre
