[
https://issues.apache.org/jira/browse/HDFS-16507?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
tomscut updated HDFS-16507:
---------------------------
Environment: (was: {code:java}
// code placeholder
{code})
> Purged edit logs which is in process
> ------------------------------------
>
> Key: HDFS-16507
> URL: https://issues.apache.org/jira/browse/HDFS-16507
> Project: Hadoop HDFS
> Issue Type: Bug
> Reporter: tomscut
> Priority: Critical
>
> We introduced Standby read functionality in branch-3.1.0, but found a FATAL
> exception. It looks like it's purging edit logs which is in process.
> According to the analysis, I suspect that the Editlog to be purged does not
> finalize normally .
> I post some key logs for your reference:
> 1. ANN. Create editlog,
> {color:#FF0000}edits_InProgresS_0000000000024207987{color}.
>
> {code:java}
> 2022-03-15 17:24:52,558 INFO namenode.FSEditLog
> (FSEditLog.java:startLogSegment(1394)) - Starting log segment at 24207987
> 2022-03-15 17:24:52,609 INFO namenode.FSEditLog
> (FSEditLog.java:startLogSegment(1423)) - Ending log segment at 24207987
> 2022-03-15 17:24:52,610 INFO namenode.FSEditLog
> (FSEditLog.java:startLogSegmentAndWriteHeaderTxn(1432)) - logEdit at 24207987
> 2022-03-15 17:24:52,624 INFO namenode.FSEditLog
> (FSEditLog.java:startLogSegmentAndWriteHeaderTxn(1434)) - logSync at 24207987
> {code}
> 2. SNN. Checkpoint.
>
> {color:#FF0000}25892513 + 1 - 1000000 = 24892514{color}
> {color:#FF0000}dfs.namenode.num.extra.edits.retained=1000000{color}
>
> {code:java}
> 2022-03-15 17:28:02,640 INFO ha.StandbyCheckpointer
> (StandbyCheckpointer.java:doWork(443)) - Triggering checkpoint because there
> have been 1189661 txns since the last checkpoint, which exceeds the
> configured threshold 20000
> 2022-03-15 17:28:02,648 INFO namenode.FSImage
> (FSEditLogLoader.java:loadFSEdits(188)) - Edits file
> ByteStringEditLog[27082175, 27082606], ByteStringEditLog[27082175, 27082606],
> ByteStringEditLog[27082175, 27082606] of size 60008 edits # 432 loaded in 0
> seconds
> 2022-03-15 17:28:02,649 INFO namenode.FSImage
> (FSImage.java:saveNamespace(1121)) - Save namespace ...
> 2022-03-15 17:28:02,650 INFO namenode.FSImageFormatProtobuf
> (FSImageFormatProtobuf.java:save(718)) - Saving image file
> /data/hadoop/hdfs/namenode/current/fsimage.ckpt_0000000000027082606 using no
> compression
> 2022-03-15 17:28:03,180 INFO namenode.FSImageFormatProtobuf
> (FSImageFormatProtobuf.java:save(722)) - Image file
> /data/hadoop/hdfs/namenode/current/fsimage.ckpt_0000000000027082606 of size
> 17885002 bytes saved in 0 seconds .
> 2022-03-15 17:28:03,183 INFO namenode.NNStorageRetentionManager
> (NNStorageRetentionManager.java:getImageTxIdToRetain(211)) - Going to retain
> 2 images with txid >= 25892513
> 2022-03-15 17:28:03,183 INFO namenode.NNStorageRetentionManager
> (NNStorageRetentionManager.java:purgeImage(233)) - Purging old image
> FSImageFile(file=/data/hadoop/hdfs/namenode/current/fsimage_0000000000024794305,
> cpktTxId=0000000000024794305)
> 2022-03-15 17:28:03,188 INFO namenode.NNStorageRetentionManager
> (NNStorageRetentionManager.java:purgeOldStorage(169)) - purgeLogsFrom:
> 24892514
> 2022-03-15 17:28:03,282 INFO namenode.TransferFsImage
> (TransferFsImage.java:copyFileToStream(396)) - Sending fileName:
> /data/hadoop/hdfs/namenode/current/fsimage_0000000000027082606, fileSize:
> 17885002. Sent total: 17885002 bytes. Size of last segment intended to send:
> -1 bytes.
> 2022-03-15 17:28:03,536 INFO namenode.TransferFsImage
> (TransferFsImage.java:uploadImageFromStorage(240)) - Uploaded image with txid
> 27082606 to namenode at http://sg-test-ambari-nn1.bigdata.bigo.inner:50070 in
> 0.343 seconds
> 2022-03-15 17:28:03,640 INFO namenode.TransferFsImage
> (TransferFsImage.java:copyFileToStream(396)) - Sending fileName:
> /data/hadoop/hdfs/namenode/current/fsimage_0000000000027082606, fileSize:
> 17885002. Sent total: 17885002 bytes. Size of last segment intended to send:
> -1 bytes.
> 2022-03-15 17:28:03,684 INFO namenode.TransferFsImage
> (TransferFsImage.java:uploadImageFromStorage(240)) - Uploaded image with txid
> 27082606 to namenode at http://sg-test-ambari-dn1.bigdata.bigo.inner:50070 in
> 0.148 seconds
> 2022-03-15 17:28:03,748 INFO namenode.TransferFsImage
> (TransferFsImage.java:copyFileToStream(396)) - Sending fileName:
> /data/hadoop/hdfs/namenode/current/fsimage_0000000000027082606, fileSize:
> 17885002. Sent total: 17885002 bytes. Size of last segment intended to send:
> -1 bytes.
> 2022-03-15 17:28:03,798 INFO namenode.TransferFsImage
> (TransferFsImage.java:uploadImageFromStorage(240)) - Uploaded image with txid
> 27082606 to namenode at http://sg-test-ambari-dn2.bigdata.bigo.inner:50070 in
> 0.113 seconds
> 2022-03-15 17:28:03,798 INFO ha.StandbyCheckpointer
> (StandbyCheckpointer.java:doWork(482)) - Checkpoint finished successfully.
> {code}
> 3. ANN. Purge edit logs.
>
> {color:#FF0000}25892513 + 1 - 1000000 = 24892514{color}
> {color:#FF0000}dfs.namenode.num.extra.edits.retained=1000000{color}
> {code:java}
> 2022-03-15 17:28:03,515 INFO namenode.NNStorageRetentionManager
> (NNStorageRetentionManager.java:getImageTxIdToRetain(211)) - Going to retain
> 2 images with txid >= 25892513 {code}
> {code:java}
> 2022-03-15 17:28:03,523 INFO namenode.NNStorageRetentionManager
> (NNStorageRetentionManager.java:purgeOldStorage(169)) - purgeLogsFrom:
> 24892514 2022-03-15 17:28:03,523 INFO client.QuorumJournalManager
> (QuorumJournalManager.java:purgeLogsOlderThan(458)) - Purging remote journals
> older than txid 24892514 2022-03-15 17:28:03,524 INFO
> namenode.FileJournalManager (FileJournalManager.java:purgeLogsOlderThan(184))
> - Purging logs older than 24892514
> {code}
> 4. ANN. Purge {color:#FF0000}edits_inprogress_0000000000024207987{color}.
> {code:java}
> 2022-03-15 17:28:03,525 INFO namenode.NNStorageRetentionManager
> (NNStorageRetentionManager.java:purgeLog(227)) - Purging old edit log
> EditLogFile(file=/data/hadoop/hdfs/namenode/current/edits_inprogress_0000000000024207987,first=0000000000024207987,last=-000000000000012345,inProgress=true,hasCorruptHeader=false)
> {code}
> 5. JN. Purge edit logs include {color:#FF0000}24207987{color}.
> {color:#FF0000}No log file to finalize at transaction ID 24207987{color}
> {code:java}
> 2022-03-15 17:28:03,530 INFO common.Storage
> (JNStorage.java:purgeMatching(196)) - Purging no-longer needed file 24207986
> 2022-03-15 17:28:03,564 INFO common.Storage
> (JNStorage.java:purgeMatching(196)) - Purging no-longer needed file 24207987
> 2022-03-15 17:28:03,571 INFO common.Storage
> (JNStorage.java:purgeMatching(196)) - Purging no-longer needed file 24207981
> 2022-03-15 17:28:03,572 INFO common.Storage
> (JNStorage.java:purgeMatching(196)) - Purging no-longer needed file 24207984
> 2022-03-15 17:28:03,576 INFO common.Storage
> (JNStorage.java:purgeMatching(196)) - Purging no-longer needed file 24207982
> org.apache.hadoop.hdfs.qjournal.protocol.JournalOutOfSyncException: No log
> file to finalize at transaction ID 24207987 ; journal id: ambari-test
> {code}
> 6. ANN. Process exits because of the fatal exception from JNs.
> {code:java}
> 2022-03-15 17:28:52,709 INFO namenode.FSNamesystem
> (FSNamesystem.java:run(4232)) - NameNode rolling its own edit log because
> number of edits in open segment exceeds threshold of 100000
> 2022-03-15 17:28:52,709 INFO namenode.FSEditLog
> (FSEditLog.java:rollEditLog(1346)) - Rolling edit logs
> 2022-03-15 17:28:52,709 INFO namenode.FSEditLog
> (FSEditLog.java:endCurrentLogSegment(1442)) - Ending log segment 24207987,
> 27990691
> 2022-03-15 17:28:52,748 INFO namenode.FSEditLog
> (FSEditLog.java:printStatistics(806)) - Number of transactions: 3782706 Total
> time for transactions(ms): 25003 Number of transactions batched in Syncs:
> 3774095 Number of syncs: 8611 SyncTimes(ms): 11347 151932
> 2022-03-15 17:28:52,867 FATAL namenode.FSEditLog
> (JournalSet.java:mapJournalsAndReportErrors(393)) - Error: finalize log
> segment 24207987, 27990692 failed for required journal
> (JournalAndStream(mgr=QJM
> to [10.152.106.55:8485, 10.152.115.74:8485, 10.152.124.150:8485,
> 10.152.124.157:8485, 10.152.106.57:8485], stream=null))
> org.apache.hadoop.hdfs.qjournal.client.QuorumException: Got too many
> exceptions to achieve quorum size 3/5. 5 exceptions thrown:
> 10.152.124.157:8485: No log file to finalize at transaction ID 24207987 ;
> journal id: ambari-test
> at
> org.apache.hadoop.hdfs.qjournal.server.Journal.finalizeLogSegment(Journal.java:656)
> at
> org.apache.hadoop.hdfs.qjournal.server.JournalNodeRpcServer.finalizeLogSegment(JournalNodeRpcServer.java:210)
> at
> org.apache.hadoop.hdfs.qjournal.protocolPB.QJournalProtocolServerSideTranslatorPB.finalizeLogSegment(QJournalProtocolServerSideTranslatorPB.java:205)
> at
> org.apache.hadoop.hdfs.qjournal.protocol.QJournalProtocolProtos$QJournalProtocolService$2.callBlockingMethod(QJournalProtocolProtos.java:28890)
> at
> org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:550)
> at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1094)
> at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:1066)
> at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:1000)
> 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:1730)
> at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2989) {code}
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
