From hdfs-issues-return-210756-archive-asf-public=cust-asf.ponee.io@hadoop.apache.org Wed Feb 21 20:56:09 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id D422618061A for ; Wed, 21 Feb 2018 20:56:08 +0100 (CET) Received: (qmail 13779 invoked by uid 500); 21 Feb 2018 19:56:07 -0000 Mailing-List: contact hdfs-issues-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list hdfs-issues@hadoop.apache.org Received: (qmail 13764 invoked by uid 99); 21 Feb 2018 19:56:07 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 21 Feb 2018 19:56:07 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 4878EC0529 for ; Wed, 21 Feb 2018 19:56:07 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -109.511 X-Spam-Level: X-Spam-Status: No, score=-109.511 tagged_above=-999 required=6.31 tests=[ENV_AND_HDR_SPF_MATCH=-0.5, KAM_ASCII_DIVIDERS=0.8, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, T_RP_MATCHES_RCVD=-0.01, USER_IN_DEF_SPF_WL=-7.5, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id vukadz0moY-o for ; Wed, 21 Feb 2018 19:56:05 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTP id 9FD865FBA2 for ; Wed, 21 Feb 2018 19:56:01 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id D4FD7E02AC for ; Wed, 21 Feb 2018 19:56:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 27D9121092 for ; Wed, 21 Feb 2018 19:56:00 +0000 (UTC) Date: Wed, 21 Feb 2018 19:56:00 +0000 (UTC) From: "Chao Sun (JIRA)" To: hdfs-issues@hadoop.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Comment Edited] (HDFS-13145) SBN crash when transition to ANN with in-progress edit tailing enabled MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HDFS-13145?page=3Dcom.atlassian= .jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D1637= 1921#comment-16371921 ]=20 Chao Sun edited comment on HDFS-13145 at 2/21/18 7:55 PM: ---------------------------------------------------------- Did more research on this issue. I think=C2=A0this issue happens in the fol= lowing order: 1. Active NN exits right before flushing the dummy batch. Also, because of= the=C2=A0abrupt exit (in our case, it exited with SIGNAL 15: SIGTERM, even= when we call {{hadoop-daemon.sh stop namenode}}), it will not stop the act= ive services, and most importantly, will not finalize the current log segme= nt.=C2=A0As result, the {{committedTxnId}} on the remote journal will be le= ss than the {{endTxId}}. 2. When the SBN take over, it will [catch up to the latest edits from old a= ctive|https://github.com/apache/hadoop/blob/trunk/hadoop-hdfs-project/hadoo= p-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystem.ja= va#L1214]. When selecting input stream, it will set the {{endTxId}} to be {= {committedTxnId}} if the latter is smaller:=C2=A0 {code:java} // If it's bounded by durable Txns, endTxId could not be larger // than committedTxnId. This ensures the consistency. if (onlyDurableTxns && inProgressOk) { endTxId =3D Math.min(endTxId, committedTxnId); if (endTxId < remoteLog.getStartTxId()) { LOG.warn("Found endTxId (" + endTxId + ") that is less than " + "the startTxId (" + remoteLog.getStartTxId() + ") - setting it to startTxId."); endTxId =3D remoteLog.getStartTxId(); } } {code} 3. After catching up all edits, the SBN [set the nextTnId to be endTxId + = 1|https://github.com/apache/hadoop/blob/trunk/hadoop-hdfs-project/hadoop-hd= fs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystem.java#L= 1238]{{}} and call {{FSEditLog::openForWrite}}, which will select all input= streams from remote journals using the {{nextTnId}} as the starting transa= ction ID. The result will be non-empty because of the issue in 1).=C2=A0 4. Exception is thrown because of 3). [~xkrogen]: I could be wrong but I think the step 1) could still happen eve= n if we get rid of the dummy patch, unless we constantly making sure that t= he {{committedTxnId}}=C2=A0is up-to-date with the {{endTxId}}.=C2=A0One pot= ential fix=C2=A0would be to *not* tail in-progress log when the SBN catches= up the latest edits in failover. This seems to me benign.The change is sim= ple and I've tested in our dev environment.=C2=A0 was (Author: csun): Did more research on this issue. I think=C2=A0this issue happens in the fol= lowing order: 1. Active NN exits right before flushing the dummy batch. Also, because of= the=C2=A0abrupt exit (in our case, it exited with SIGNAL 15: SIGTERM, even= when we call {{hadoop-daemon.sh stop namenode}}), it will not stop the act= ive services, and most importantly, will not finalize the current log segme= nt.=C2=A0As result, the {{committedTxnId}} on the remote journal will be le= ss than the {{endTxId}}. 2. When the SBN take over, it will [catch up to the latest edits from old a= ctive|https://github.com/apache/hadoop/blob/trunk/hadoop-hdfs-project/hadoo= p-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystem.ja= va#L1214]. When selecting input stream, it will set the {{endTxId}} to be {= {committedTxnId}} if the latter is smaller:=C2=A0 {code:java} // If it's bounded by durable Txns, endTxId could not be larger // than committedTxnId. This ensures the consistency. if (onlyDurableTxns && inProgressOk) { endTxId =3D Math.min(endTxId, committedTxnId); if (endTxId < remoteLog.getStartTxId()) { LOG.warn("Found endTxId (" + endTxId + ") that is less than " + "the startTxId (" + remoteLog.getStartTxId() + ") - setting it to startTxId."); endTxId =3D remoteLog.getStartTxId(); } } {code} 3. After catching up all edits, the SBN [set the nextTnId to be endTxId + = 1|https://github.com/apache/hadoop/blob/trunk/hadoop-hdfs-project/hadoop-hd= fs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystem.java#L= 1238]{{}} and call {{FSEditLog::openForWrite}}, which will select all input= streams from remote journals using the {{nextTnId}} as the starting transa= ction ID. The result will be non-empty because of the issue in 1).=C2=A0 4. Exception is thrown because of 3). =C2=A0 [~xkrogen]: I could be wrong but I think the step 1) could still happen eve= n if we get rid of the dummy patch, unless we constantly making sure that t= he {{committedTxnId}}=C2=A0is up-to-date with the {{endTxId}}.=C2=A0One pot= ential fix=C2=A0would be to *not* tail in-progress log when the SBN catches= up the latest edits in failover. This seems to me benign.The change is sim= ple and I've tested in our dev environment.=C2=A0 > SBN crash when transition to ANN with in-progress edit tailing enabled > ---------------------------------------------------------------------- > > Key: HDFS-13145 > URL: https://issues.apache.org/jira/browse/HDFS-13145 > Project: Hadoop HDFS > Issue Type: Bug > Components: ha, namenode > Reporter: Chao Sun > Assignee: Chao Sun > Priority: Major > > With edit log in-progress edit log tailing enabled, {{QuorumOutputStream}= } will send two batches to JNs, one normal edit batch followed by a dummy b= atch to update the commit ID on JNs. > {code} > QuorumCall qcall =3D loggers.sendEdits( > segmentTxId, firstTxToFlush, > numReadyTxns, data); > loggers.waitForWriteQuorum(qcall, writeTimeoutMs, "sendEdits"); > =20 > // Since we successfully wrote this batch, let the loggers know. An= y future > // RPCs will thus let the loggers know of the most recent transacti= on, even > // if a logger has fallen behind. > loggers.setCommittedTxId(firstTxToFlush + numReadyTxns - 1); > // If we don't have this dummy send, committed TxId might be one-ba= tch > // stale on the Journal Nodes > if (updateCommittedTxId) { > QuorumCall fakeCall =3D loggers.sendEdits( > segmentTxId, firstTxToFlush, > 0, new byte[0]); > loggers.waitForWriteQuorum(fakeCall, writeTimeoutMs, "sendEdits")= ; > } > {code} > Between each batch, it will wait for the JNs to reach a quorum. However, = if the ANN crashes in between, then SBN will crash while transiting to ANN: > {code} > java.lang.IllegalStateException: Cannot start writing at txid 24312595802= when there is a stream available for read: ...... > at org.apache.hadoop.hdfs.server.namenode.FSEditLog.openForWrite(= FSEditLog.java:329) > at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.startActiv= eServices(FSNamesystem.java:1196) > at org.apache.hadoop.hdfs.server.namenode.NameNode$NameNodeHACont= ext.startActiveServices(NameNode.java:1839) > at org.apache.hadoop.hdfs.server.namenode.ha.ActiveState.enterSta= te(ActiveState.java:61) > at org.apache.hadoop.hdfs.server.namenode.ha.HAState.setStateInte= rnal(HAState.java:64) > at org.apache.hadoop.hdfs.server.namenode.ha.StandbyState.setStat= e(StandbyState.java:49) > at org.apache.hadoop.hdfs.server.namenode.NameNode.transitionToAc= tive(NameNode.java:1707) > at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.trans= itionToActive(NameNodeRpcServer.java:1622) > at org.apache.hadoop.ha.protocolPB.HAServiceProtocolServerSideTra= nslatorPB.transitionToActive(HAServiceProtocolServerSideTranslatorPB.java:1= 07) > at org.apache.hadoop.ha.proto.HAServiceProtocolProtos$HAServicePr= otocolService$2.callBlockingMethod(HAServiceProtocolProtos.java:4460) > at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvo= ker.call(ProtobufRpcEngine.java:447) > at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:989) > at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:851) > at org.apache.hadoop.ipc.Server$RpcCall.run(Server.java:794) > at java.security.AccessController.doPrivileged(Native Method) > at javax.security.auth.Subject.doAs(Subject.java:422) > at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroup= Information.java:1836) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2490) > 2018-02-13 00:43:20,728 INFO org.apache.hadoop.util.ExitUtil: Exiting wit= h status 1 > {code} > This is because without the dummy batch, the {{commitTxnId}} will lag beh= ind the {{endTxId}}, which caused the check in {{openForWrite}} to fail: > {code} > List streams =3D new ArrayList(); > journalSet.selectInputStreams(streams, segmentTxId, true, false); > if (!streams.isEmpty()) { > String error =3D String.format("Cannot start writing at txid %s " + > "when there is a stream available for read: %s", > segmentTxId, streams.get(0)); > IOUtils.cleanupWithLogger(LOG, > streams.toArray(new EditLogInputStream[0])); > throw new IllegalStateException(error); > } > {code} > In our environment, this can be reproduced pretty consistently, which wil= l leave the cluster with no running namenodes. Even though we are using a 2= .8.2 backport, I believe the same issue also exist in 3.0.x.=20 -- This message was sent by Atlassian JIRA (v7.6.3#76005) --------------------------------------------------------------------- To unsubscribe, e-mail: hdfs-issues-unsubscribe@hadoop.apache.org For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org