[ https://issues.apache.org/jira/browse/HDFS-13236?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16531436#comment-16531436 ]
Kihwal Lee edited comment on HDFS-13236 at 7/3/18 1:58 PM: ----------------------------------------------------------- The "restart fails after upgrade" issue is being addressed in HDFS-13596. Workaround is to do "saveNamespace" against the active NN after an upgrade from 2.x to 3.x. The Standby NN will need to be re-bootstrapped. was (Author: kihwal): The restart after upgrade issue is being addressed in HDFS-13596. > Standby NN down with error encountered while tailing edits > ---------------------------------------------------------- > > Key: HDFS-13236 > URL: https://issues.apache.org/jira/browse/HDFS-13236 > Project: Hadoop HDFS > Issue Type: Bug > Components: journal-node, namenode > Affects Versions: 3.0.0 > Reporter: Yuriy Malygin > Priority: Major > > After update Hadoop from 2.7.3 to 3.0.0 standby NN down with error > encountered while tailing edits from JN: > {code:java} > Feb 28 01:58:31 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:31,594 > INFO [FSImageSaver for /one/hadoop-data/dfs of type IMAGE_AND_EDITS] > FSImageFormatProtobuf - Image file > /one/hadoop-data/dfs/current/fsimage.ckpt_00000000012748979 > 98 of size 4595971949 bytes saved in 93 seconds. > Feb 28 01:58:33 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:33,445 > INFO [Standby State Checkpointer] NNStorageRetentionManager - Going to retain > 2 images with txid >= 1274897935 > Feb 28 01:58:33 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:33,445 > INFO [Standby State Checkpointer] NNStorageRetentionManager - Purging old > image > FSImageFile(file=/one/hadoop-data/dfs/current/fsimage_0000000001274897875, > cpktTxId > =0000000001274897875) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:34,660 > INFO [Edit log tailer] FSImage - Reading > org.apache.hadoop.hdfs.server.namenode.RedundantEditLogInputStream@6a168e6f > expecting start txid #1274897999 > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:34,660 > INFO [Edit log tailer] FSImage - Start loading edits file > http://srvd87.local:8480/getJournal?jid=datalab-hadoop-backup&segmentTxId=1274897999&storageInfo=-64%3A10 > 56233980%3A0%3ACID-1fba08aa-c8bd-4217-aef5-6ed206893848&inProgressOk=true, > http://srve2916.local:8480/getJournal?jid=datalab-hadoop-backup&segmentTxId=1274897999&storageInfo=-64%3A1056233980%3A0%3ACID-1fba08aa-c8bd-4217-aef5-6ed206893848& > inProgressOk=true > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:34,661 > INFO [Edit log tailer] RedundantEditLogInputStream - Fast-forwarding stream > 'http://srvd87.local:8480/getJournal?jid=datalab-hadoop-backup&segmentTxId=1274897999&s > torageInfo=-64%3A1056233980%3A0%3ACID-1fba08aa-c8bd-4217-aef5-6ed206893848&inProgressOk=true, > > http://srve2916.local:8480/getJournal?jid=datalab-hadoop-backup&segmentTxId=1274897999&storageInfo=-64%3A1056233980%3A0%3ACID-1fba08aa-c8bd-4217 > -aef5-6ed206893848&inProgressOk=true' to transaction ID 1274897999 > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:34,661 > INFO [Edit log tailer] RedundantEditLogInputStream - Fast-forwarding stream > 'http://srvd87.local:8480/getJournal?jid=datalab-hadoop-backup&segmentTxId=1274897999&storageInfo=-64%3A1056233980%3A0%3ACID-1fba08aa-c8bd-4217-aef5-6ed206893848&inProgressOk=true' > to transaction ID 1274897999 > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:34,680 > ERROR [Edit log tailer] FSEditLogLoader - Encountered exception on operation > AddOp [length=0, inodeId=145550319, > path=/kafka/parquet/infrastructureGrace/date=2018-02-28/_temporary/1/_temporary/attempt_1516181147167_20856_r_000098_0/part-r-00098.gz.parquet, > replication=3, mtime=1519772206615, atime=1519772206615, > blockSize=134217728, blocks=[], permissions=root:supergroup:rw-r--r--, > aclEntries=null, > clientName=DFSClient_attempt_1516181147167_20856_r_000098_0_1523538799_1, > clientMachine=10.137.2.142, overwrite=false, RpcClientId=, > RpcCallId=271996603, storagePolicyId=0, erasureCodingPolicyId=0, > opCode=OP_ADD, txid=1274898002] > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: > java.lang.IllegalArgumentException: Invalid clientId - length is 0 expected > length 16 > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > com.google.common.base.Preconditions.checkArgument(Preconditions.java:92) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.ipc.RetryCache$CacheEntry.<init>(RetryCache.java:74) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.ipc.RetryCache$CacheEntry.<init>(RetryCache.java:86) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.ipc.RetryCache$CacheEntryWithPayload.<init>(RetryCache.java:163) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.ipc.RetryCache.addCacheEntryWithPayload(RetryCache.java:322) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.addCacheEntryWithPayload(FSNamesystem.java:946) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.applyEditLogOp(FSEditLogLoader.java:397) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadEditRecords(FSEditLogLoader.java:249) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadFSEdits(FSEditLogLoader.java:158) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:882) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:863) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer.doTailEdits(EditLogTailer.java:293) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.doWork(EditLogTailer.java:427) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.access$400(EditLogTailer.java:380) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread$1.run(EditLogTailer.java:397) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.security.SecurityUtil.doAsLoginUserOrFatal(SecurityUtil.java:481) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.run(EditLogTailer.java:393) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:34,688 > FATAL [Edit log tailer] EditLogTailer - Unknown error encountered while > tailing edits. Shutting down standby NN. > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: java.io.IOException: > java.lang.IllegalStateException: Cannot skip to less than the current value > (=145550319), where newValue=145550318 > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSDirectory.resetLastInodeId(FSDirectory.java:1941) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadEditRecords(FSEditLogLoader.java:298) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader.loadFSEdits(FSEditLogLoader.java:158) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:882) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSImage.loadEdits(FSImage.java:863) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer.doTailEdits(EditLogTailer.java:293) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.doWork(EditLogTailer.java:427) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.access$400(EditLogTailer.java:380) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread$1.run(EditLogTailer.java:397) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.security.SecurityUtil.doAsLoginUserOrFatal(SecurityUtil.java:481) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.ha.EditLogTailer$EditLogTailerThread.run(EditLogTailer.java:393) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: Caused by: > java.lang.IllegalStateException: Cannot skip to less than the current value > (=145550319), where newValue=145550318 > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.util.SequentialNumber.skipTo(SequentialNumber.java:58) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: at > org.apache.hadoop.hdfs.server.namenode.FSDirectory.resetLastInodeId(FSDirectory.java:1939) > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: ... 10 more > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:34,708 > INFO [Edit log tailer] ExitUtil - Exiting with status 1: java.io.IOException: > java.lang.IllegalStateException: Cannot skip to less than the current value > (=145550319), where newValue=145550318 > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: 2018-02-28 01:58:34,722 > INFO [pool-1-thread-1] NameNode - SHUTDOWN_MSG: > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: > /************************************************************ > Feb 28 01:58:34 srvd2135 datalab-namenode[15566]: SHUTDOWN_MSG: Shutting down > NameNode at srvd2135.local/10.137.2.39 > {code} > > Additional information about errors after update to 3.0.0: > In active NN logs many messages about replication errors (caused by Rack > Awareness): > {code:java} > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: 2018-02-28 01:57:20,804 WARN > [IPC Server handler 10 on 8020] PmsRackMapping - Got empty rack for > 10.136.2.149, reverting to default. > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: 2018-02-28 01:57:20,806 DEBUG > [IPC Server handler 10 on 8020] BlockPlacementPolicy - Failed to choose from > local rack (location = /default-rack); the second replica is not found, retry > choosing randomly > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicy$NotEnoughReplicasException: > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseRandom(BlockPlacementPolicyDefault.java:792) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseRandom(BlockPlacementPolicyDefault.java:691) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseLocalRack(BlockPlacementPolicyDefault.java:598) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseLocalStorage(BlockPlacementPolicyDefault.java:558) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTargetInOrder(BlockPlacementPolicyDefault.java:461) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:392) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:268) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:121) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockPlacementPolicyDefault.chooseTarget(BlockPlacementPolicyDefault.java:137) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.chooseTarget4NewBlock(BlockManager.java:2093) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.namenode.FSDirWriteFileOp.chooseTargetForNewBlock(FSDirWriteFileOp.java:287) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:2602) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.addBlock(NameNodeRpcServer.java:864) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.addBlock(ClientNamenodeProtocolServerSideTranslatorPB.java:549) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:523) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.ipc.RPC$Server.call(RPC.java:991) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:869) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:815) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > java.security.AccessController.doPrivileged(Native Method) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > javax.security.auth.Subject.doAs(Subject.java:422) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1962) > Feb 28 01:57:20 srvg671 datalab-namenode[1807]: at > org.apache.hadoop.ipc.Server$Handler.run(Server.java:2675) > {code} > {code:java} > $ zgrep -c NotEnoughReplicasException > archive/datalab-namenode.log-20180{22*,3*}.gz > archive/datalab-namenode.log-20180228.gz:0 #hadoop 2.7.3 > archive/datalab-namenode.log-20180301.gz:173492 #hadoop 3.0.0 > archive/datalab-namenode.log-20180302.gz:153192 #hadoop 3.0.0 > archive/datalab-namenode.log-20180303.gz:0 #hadoop 2.7.3{code} > In JN logs: > {code:java} > Feb 28 01:57:51 srvd87 datalab-journalnode[29960]: 2018-02-28 01:57:51,552 > INFO [IPC Server handler 4 on 8485] FileJournalManager - Finalizing edits > file > /one/hadoop-data/journal/datalab-hadoop-backup/current/edits_inprogress_00000 > 00001274897999 -> > /one/hadoop-data/journal/datalab-hadoop-backup/current/edits_0000000001274897999-0000000001274898515 > Feb 28 01:58:34 srvd87 datalab-journalnode[29960]: 2018-02-28 01:58:34,671 > INFO [qtp414690789-164] TransferFsImage - Sending fileName: > /one/hadoop-data/journal/datalab-hadoop-backup/current/edits_0000000001274897999-0000000001274898515, > fileSize: 80772. Sent total: 80772 bytes. Size of last segment intended to > send: -1 bytes. > {code} > {code:java} > $ zgrep -c 'Size of last segment intended to send' > archive/datalab-journalnode.log-20180{22*,3*}.gz > archive/datalab-journalnode.log-20180227.gz:0 #hadoop 2.7.3 > archive/datalab-journalnode.log-20180301.gz:109 #hadoop 3.0.0 > archive/datalab-journalnode.log-20180302.gz:111 #hadoop 3.0.0 > archive/datalab-journalnode.log-20180304.gz:0 #hadoop 2.7.3 > {code} -- This message was sent by Atlassian JIRA (v7.6.3#76005) --------------------------------------------------------------------- To unsubscribe, e-mail: hdfs-issues-unsubscr...@hadoop.apache.org For additional commands, e-mail: hdfs-issues-h...@hadoop.apache.org