From hdfs-issues-return-281048-archive-asf-public=cust-asf.ponee.io@hadoop.apache.org Fri Aug 30 09:07:04 2019 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 [207.244.88.153]) by mx-eu-01.ponee.io (Postfix) with SMTP id 087EB18065E for ; Fri, 30 Aug 2019 11:07:03 +0200 (CEST) Received: (qmail 20732 invoked by uid 500); 30 Aug 2019 09:07:03 -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 20705 invoked by uid 99); 30 Aug 2019 09:07:03 -0000 Received: from mailrelay1-us-west.apache.org (HELO mailrelay1-us-west.apache.org) (209.188.14.139) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 30 Aug 2019 09:07:03 +0000 Received: from jira-he-de.apache.org (static.172.67.40.188.clients.your-server.de [188.40.67.172]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 32133E3106 for ; Fri, 30 Aug 2019 09:07:02 +0000 (UTC) Received: from jira-he-de.apache.org (localhost.localdomain [127.0.0.1]) by jira-he-de.apache.org (ASF Mail Server at jira-he-de.apache.org) with ESMTP id 8200078229B for ; Fri, 30 Aug 2019 09:07:00 +0000 (UTC) Date: Fri, 30 Aug 2019 09:07:00 +0000 (UTC) From: "Jinglun (Jira)" To: hdfs-issues@hadoop.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Comment Edited] (HDFS-14800) Data race between block report and recoverLease() 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-14800?page=3Dcom.atlassian= .jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D1691= 9344#comment-16919344 ]=20 Jinglun edited comment on HDFS-14800 at 8/30/19 9:06 AM: --------------------------------------------------------- Hi [~jojochuang], I think the problem is caused by adding the recovery atte= mp before initializing the block recovery. When the first recoverLease call arrives it will be added to pendingRecove= ryBlocks by addBlockRecoveryAttempt().=C2=A0 If the NameNode has not got an= y block report for the last block, the initializeBLockRecovery() will fail.= =C2=A0 So the block recovery doesn't start. Then the later recoverLease calls arrive and are all rejected by addBlockR= ecoveryAttempt() until the first is timeout. The failing unit test only retry 10 times so it failed. {code:java} if (blockManager.addBlockRecoveryAttempt(lastBlock)) { long blockRecoveryId =3D nextGenerationStamp( blockManager.isLegacyBlock(lastBlock)); if(copyOnTruncate) { lastBlock.setGenerationStamp(blockRecoveryId); } else if(truncateRecovery) { recoveryBlock.setGenerationStamp(blockRecoveryId); } uc.initializeBlockRecovery(lastBlock, blockRecoveryId, true); // Cannot close file right now, since the last block requires recovery. // This may potentially cause infinite loop in lease recovery // if there are no valid replicas on data-nodes. NameNode.stateChangeLog.warn( "DIR* NameSystem.internalReleaseLease: " + "File " + src + " has not been closed." + " Lease recovery is in progress. " + "RecoveryId =3D " + blockRecoveryId + " for block " + lastBlock); }{code} =C2=A0 Here is the corresponding log. //*The 1st recoverLease call. Failed because no blocks found.* 2019-08-29 13:34:31,788 [IPC Server handler 9 on default port 39637] INFO n= amenode.FSNamesystem (FSNamesystem.java:recoverLeaseInternal(2682)) - recov= erLease: [Lease. Holder: DFSClient_8256078, pending creates: 13], src=3D/1k= b-multiple-checksum-blocks-64-16 from client DFSClient_8256078 2019-08-29 13:34:31,788 [IPC Server handler 9 on default port 39637] INFO = namenode.FSNamesystem (FSNamesystem.java:internalReleaseLease(3424)) - Reco= vering [Lease. Holder: DFSClient_8256078, pending creates: 13], src=3D/1kb-= multiple-checksum-blocks-64-16 2019-08-29 13:34:31,789 [IPC Server handler 9 on default port 39637] WARN = BlockStateChange (BlockUnderConstructionFeature.java:initializeBlockRecover= y(238)) - BLOCK* BlockUnderConstructionFeature.initializeBlockRecovery: No = blocks found, lease removed. 2019-08-29 13:34:31,790 [IPC Server handler 9 on default port 39637] WARN = hdfs.StateChange (FSNamesystem.java:internalReleaseLease(3550)) - DIR* Name= System.internalReleaseLease: File /1kb-multiple-checksum-blocks-64-16 has n= ot been closed. Lease recovery is in progress. RecoveryId =3D 1031 for bloc= k blk_7162739548153522810_1020 =C2=A0 //*The 2st recoverLease call. Failed because the previous attempt doesn't t= imeout.* 2019-08-29 13:34:32,795 [IPC Server handler 8 on default port 39637] INFO = namenode.FSNamesystem (FSNamesystem.java:recoverLeaseInternal(2682)) - reco= verLease: [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending crea= tes: 1], src=3D/1kb-multiple-checksum-blocks-64-16 from client DFSClient_NO= NMAPREDUCE_1352689944_1 2019-08-29 13:34:32,795 [IPC Server handler 8 on default port 39637] INFO = namenode.FSNamesystem (FSNamesystem.java:internalReleaseLease(3424)) - Reco= vering [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending creates= : 1], src=3D/1kb-multiple-checksum-blocks-64-16 2019-08-29 13:34:32,796 [IPC Server handler 8 on default port 39637] INFO = blockmanagement.BlockManager (PendingRecoveryBlocks.java:add(80)) - Block r= ecovery attempt for blk_7162739548153522810_1020 rejected, as the previous = attempt times out in 88 seconds. =C2=A0 //*The 3st recoverLease call.* 2019-08-29 13:34:33,798 [IPC Server handler 0 on default port 39637] INFO = namenode.FSNamesystem (FSNamesystem.java:recoverLeaseInternal(2682)) - reco= verLease: [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending crea= tes: 1], src=3D/1kb-multiple-checksum-blocks-64-16 from client DFSClient_NO= NMAPREDUCE_1352689944_1 2019-08-29 13:34:33,799 [IPC Server handler 0 on default port 39637] INFO = namenode.FSNamesystem (FSNamesystem.java:internalReleaseLease(3424)) - Reco= vering [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending creates= : 1], src=3D/1kb-multiple-checksum-blocks-64-16 2019-08-29 13:34:33,799 [IPC Server handler 0 on default port 39637] INFO = blockmanagement.BlockManager (PendingRecoveryBlocks.java:add(80)) - Block r= ecovery attempt for blk_7162739548153522810_1020 rejected, as the previous = attempt times out in 87 seconds. =C2=A0 //*There are another 4st~10st recoverLease logs and are the same with the 2= st and 3st. Ignore them.* was (Author: lijinglun): Hi [~jojochuang], I think the problem is caused by adding the recovery atte= mp before initializing the block recovery. When the first recoverLease call arrives it will be added to pendingRecover= yBlocks by addBlockRecoveryAttempt().=C2=A0 If the NameNode has not got any= block report for the last block, the initializeBLockRecovery() will fail.= =C2=A0 So the block recovery doesn't start. Then the later recoverLease calls arrive and are all rejected by addBlockRe= coveryAttempt() until the first is timeout. The failing unit test only retry 10 times so it failed. {code:java} if (blockManager.addBlockRecoveryAttempt(lastBlock)) { long blockRecoveryId =3D nextGenerationStamp( blockManager.isLegacyBlock(lastBlock)); if(copyOnTruncate) { lastBlock.setGenerationStamp(blockRecoveryId); } else if(truncateRecovery) { recoveryBlock.setGenerationStamp(blockRecoveryId); } uc.initializeBlockRecovery(lastBlock, blockRecoveryId, true); // Cannot close file right now, since the last block requires recovery. // This may potentially cause infinite loop in lease recovery // if there are no valid replicas on data-nodes. NameNode.stateChangeLog.warn( "DIR* NameSystem.internalReleaseLease: " + "File " + src + " has not been closed." + " Lease recovery is in progress. " + "RecoveryId =3D " + blockRecoveryId + " for block " + lastBlock); }{code} =C2=A0 Here is the corresponding log. ## The 1st recoverLease call. Failed because no blocks found. 2019-08-29 13:34:31,788 [IPC Server handler 9 on default port 39637] INFO n= amenode.FSNamesystem (FSNamesystem.java:recoverLeaseInternal(2682)) - recov= erLease: [Lease. Holder: DFSClient_8256078, pending creates: 13], src=3D/1k= b-multiple-checksum-blocks-64-16 from client DFSClient_8256078 2019-08-29 13:34:31,788 [IPC Server handler 9 on default port 39637] INFO n= amenode.FSNamesystem (FSNamesystem.java:internalReleaseLease(3424)) - Recov= ering [Lease. Holder: DFSClient_8256078, pending creates: 13], src=3D/1kb-m= ultiple-checksum-blocks-64-16 2019-08-29 13:34:31,789 [IPC Server handler 9 on default port 39637] WARN B= lockStateChange (BlockUnderConstructionFeature.java:initializeBlockRecovery= (238)) - BLOCK* BlockUnderConstructionFeature.initializeBlockRecovery: No b= locks found, lease removed. 2019-08-29 13:34:31,790 [IPC Server handler 9 on default port 39637] WARN h= dfs.StateChange (FSNamesystem.java:internalReleaseLease(3550)) - DIR* NameS= ystem.internalReleaseLease: File /1kb-multiple-checksum-blocks-64-16 has no= t been closed. Lease recovery is in progress. RecoveryId =3D 1031 for block= blk_7162739548153522810_1020 ## The 2st recoverLease call. Failed because the previous attempt doesn't t= imeout. 2019-08-29 13:34:32,795 [IPC Server handler 8 on default port 39637] INFO n= amenode.FSNamesystem (FSNamesystem.java:recoverLeaseInternal(2682)) - recov= erLease: [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending creat= es: 1], src=3D/1kb-multiple-checksum-blocks-64-16 from client DFSClient_NON= MAPREDUCE_1352689944_1 2019-08-29 13:34:32,795 [IPC Server handler 8 on default port 39637] INFO n= amenode.FSNamesystem (FSNamesystem.java:internalReleaseLease(3424)) - Recov= ering [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending creates:= 1], src=3D/1kb-multiple-checksum-blocks-64-16 2019-08-29 13:34:32,796 [IPC Server handler 8 on default port 39637] INFO b= lockmanagement.BlockManager (PendingRecoveryBlocks.java:add(80)) - Block re= covery attempt for blk_7162739548153522810_1020 rejected, as the previous a= ttempt times out in 88 seconds. ## The 3st recoverLease call. 2019-08-29 13:34:33,798 [IPC Server handler 0 on default port 39637] INFO n= amenode.FSNamesystem (FSNamesystem.java:recoverLeaseInternal(2682)) - recov= erLease: [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending creat= es: 1], src=3D/1kb-multiple-checksum-blocks-64-16 from client DFSClient_NON= MAPREDUCE_1352689944_1 2019-08-29 13:34:33,799 [IPC Server handler 0 on default port 39637] INFO n= amenode.FSNamesystem (FSNamesystem.java:internalReleaseLease(3424)) - Recov= ering [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending creates:= 1], src=3D/1kb-multiple-checksum-blocks-64-16 2019-08-29 13:34:33,799 [IPC Server handler 0 on default port 39637] INFO b= lockmanagement.BlockManager (PendingRecoveryBlocks.java:add(80)) - Block re= covery attempt for blk_7162739548153522810_1020 rejected, as the previous a= ttempt times out in 87 seconds. ## There are another 4st~10st recoverLease logs and are the same with the 2= st and 3st. Ignore them. > Data race between block report and recoverLease() > ------------------------------------------------- > > Key: HDFS-14800 > URL: https://issues.apache.org/jira/browse/HDFS-14800 > Project: Hadoop HDFS > Issue Type: Bug > Reporter: Wei-Chiu Chuang > Priority: Major > Attachments: PreCommit-HDFS-Build #27717 test - testUpgradeFromRe= l1BBWImage [Jenkins].pdf > > > I thought I fixed it in HDFS-10240, but I am seeing a similar race condit= ion in a precommit test again. > https://builds.apache.org/job/PreCommit-HDFS-Build/27717/testReport/org.a= pache.hadoop.hdfs/TestDFSUpgradeFromImage/testUpgradeFromRel1BBWImage/ > {noformat} > 2019-08-29 13:34:31,788 [IPC Server handler 9 on default port 39637] INFO= namenode.FSNamesystem (FSNamesystem.java:recoverLeaseInternal(2682)) - re= coverLease: [Lease. Holder: DFSClient_8256078, pending creates: 13], src= =3D/1kb-multiple-checksum-blocks-64-16 from client DFSClient_8256078 > 2019-08-29 13:34:31,788 [IPC Server handler 9 on default port 39637] INFO= namenode.FSNamesystem (FSNamesystem.java:internalReleaseLease(3424)) - Re= covering [Lease. Holder: DFSClient_8256078, pending creates: 13], src=3D/1= kb-multiple-checksum-blocks-64-16 > 2019-08-29 13:34:31,789 [IPC Server handler 9 on default port 39637] WARN= BlockStateChange (BlockUnderConstructionFeature.java:initializeBlockRecov= ery(238)) - BLOCK* BlockUnderConstructionFeature.initializeBlockRecovery: N= o blocks found, lease removed. > 2019-08-29 13:34:31,790 [IPC Server handler 9 on default port 39637] WARN= hdfs.StateChange (FSNamesystem.java:internalReleaseLease(3550)) - DIR* Na= meSystem.internalReleaseLease: File /1kb-multiple-checksum-blocks-64-16 has= not been closed. Lease recovery is in progress. RecoveryId =3D 1031 for bl= ock blk_7162739548153522810_1020 > 2019-08-29 13:34:31,791 [Block report processor] INFO BlockStateChange (= BlockManager.java:processReport(2645)) - BLOCK* processReport 0x8f0bcadff51= 597e8: Processing first storage report for DS-dd914776-8c9f-4f0d-9bd3-91a55= 2bdc351 from datanode 187b2e09-75e8-4bd0-ab46-90e32839a21d > 2019-08-29 13:34:31,793 [Block report processor] INFO BlockStateChange (= BlockManager.java:processReport(2674)) - BLOCK* processReport 0x8f0bcadff51= 597e8: from storage DS-dd914776-8c9f-4f0d-9bd3-91a552bdc351 node DatanodeRe= gistration(127.0.0.1:32987, datanodeUuid=3D187b2e09-75e8-4bd0-ab46-90e32839= a21d, infoPort=3D42569, infoSecurePort=3D0, ipcPort=3D39147, storageInfo=3D= lv=3D-57;cid=3DtestClusterId;nsid=3D889473900;c=3D1567085670457), blocks: 1= 3, hasStaleStorage: false, processing time: 2 msecs, invalidatedBlocks: 0 > 2019-08-29 13:34:31,808 [BP-268013932-172.17.0.2-1567085670423 heartbeati= ng to localhost/127.0.0.1:39637] INFO datanode.DataNode (BPServiceActor.ja= va:blockReport(432)) - Successfully sent block report 0x8f0bcadff51597e8, = containing 1 storage report(s), of which we sent 1. The reports had 13 tota= l blocks and used 1 RPC(s). This took 4 msecs to generate and 33 msecs for = RPC and NN processing. Got back no commands. > 2019-08-29 13:34:32,795 [IPC Server handler 8 on default port 39637] INFO= namenode.FSNamesystem (FSNamesystem.java:recoverLeaseInternal(2682)) - re= coverLease: [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending c= reates: 1], src=3D/1kb-multiple-checksum-blocks-64-16 from client DFSClient= _NONMAPREDUCE_1352689944_1 > 2019-08-29 13:34:32,795 [IPC Server handler 8 on default port 39637] INFO= namenode.FSNamesystem (FSNamesystem.java:internalReleaseLease(3424)) - Re= covering [Lease. Holder: DFSClient_NONMAPREDUCE_1352689944_1, pending crea= tes: 1], src=3D/1kb-multiple-checksum-blocks-64-16 > 2019-08-29 13:34:32,796 [IPC Server handler 8 on default port 39637] INFO= blockmanagement.BlockManager (PendingRecoveryBlocks.java:add(80)) - Block= recovery attempt for blk_7162739548153522810_1020 rejected, as the previou= s attempt times out in 88 seconds. > {noformat} > Looks like if client calls recoverLease on a file before NameNode receive= s a block report from DataNodes, it will fail to recover the lease, and the= file remains unclosed. -- This message was sent by Atlassian Jira (v8.3.2#803003) --------------------------------------------------------------------- To unsubscribe, e-mail: hdfs-issues-unsubscribe@hadoop.apache.org For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org