diff --git a/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/block/SCMDeletedBlockTransactionStatusManager.java b/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/block/SCMDeletedBlockTransactionStatusManager.java index b43e91e0592f..d03062113509 100644 --- a/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/block/SCMDeletedBlockTransactionStatusManager.java +++ b/hadoop-hdds/server-scm/src/main/java/org/apache/hadoop/hdds/scm/block/SCMDeletedBlockTransactionStatusManager.java @@ -201,7 +201,7 @@ protected void onSent(UUID dnId, long scmCmdId) { } protected void onDatanodeDead(UUID dnId) { - LOG.info("Clean SCMCommand record for DN: {}", dnId); + LOG.info("Clean SCMCommand record for Datanode: {}", dnId); scmCmdStatusRecord.remove(dnId); } @@ -252,12 +252,14 @@ private void updateStatus(UUID dnId, long scmCmdId, CommandStatus.Status newStatus) { Map recordForDn = scmCmdStatusRecord.get(dnId); if (recordForDn == null) { - LOG.warn("Unknown Datanode: {} scmCmdId {} newStatus {}", + LOG.warn("Unknown Datanode: {} Scm Command ID: {} report status {}", dnId, scmCmdId, newStatus); return; } if (recordForDn.get(scmCmdId) == null) { - LOG.warn("Unknown SCM Command: {} Datanode {} newStatus {}", + // Because of the delay in the DN report, the DN sometimes report obsolete + // Command status that are cleared by the SCM. + LOG.debug("Unknown SCM Command ID: {} Datanode: {} report status {}", scmCmdId, dnId, newStatus); return; } @@ -293,22 +295,23 @@ private void updateStatus(UUID dnId, long scmCmdId, // which should not normally occur. LOG.error("Received {} status for a command marked TO_BE_SENT. " + "This indicates a potential issue in command handling. " + - "SCM Command ID: {}, Datanode ID: {}, Current Status: {}", + "SCM Command ID: {}, Datanode: {}, Current status: {}", newStatus, scmCmdId, dnId, oldStatus); removeScmCommand(dnId, scmCmdId); changed = true; } break; default: - LOG.error("Can not update to Unknown new Status: {}", newStatus); + LOG.error("Unexpected status from Datanode: {}. SCM Command ID: {} with status: {}.", + dnId, scmCmdId, newStatus); break; } if (!changed) { - LOG.warn("Cannot update illegal status for DN: {} ScmCommandId {} " + - "Status From {} to {}", dnId, scmCmdId, oldStatus, newStatus); + LOG.warn("Cannot update illegal status for Datanode: {} SCM Command ID: {} " + + "status {} by DN report status {}", dnId, scmCmdId, oldStatus, newStatus); } else { - LOG.debug("Successful update DN: {} ScmCommandId {} Status From {} to" + - " {}", dnId, scmCmdId, oldStatus, newStatus); + LOG.debug("Successful update Datanode: {} SCM Command ID: {} status From {} to" + + " {}, DN report status {}", dnId, scmCmdId, oldStatus, statusData.getStatus(), newStatus); } } @@ -320,11 +323,8 @@ private void removeTimeoutScmCommand(UUID dnId, if (updateTime != null && Duration.between(updateTime, now).toMillis() > timeoutMs) { CmdStatusData state = removeScmCommand(dnId, scmCmdId); - LOG.warn("Remove Timeout SCM BlockDeletionCommand {} for DN {} " + - "after without update {}ms}", state, dnId, timeoutMs); - } else { - LOG.warn("Timeout SCM scmCmdIds {} for DN {} " + - "after without update {}ms}", scmCmdIds, dnId, timeoutMs); + LOG.warn("SCM BlockDeletionCommand {} for Datanode: {} was removed after {}ms without update", + state, dnId, timeoutMs); } } } @@ -335,7 +335,7 @@ private CmdStatusData removeScmCommand(UUID dnId, long scmCmdId) { return null; } CmdStatusData statusData = record.remove(scmCmdId); - LOG.debug("Remove ScmCommand {} for DN: {} ", statusData, dnId); + LOG.debug("Remove ScmCommand {} for Datanode: {} ", statusData, dnId); return statusData; } @@ -483,7 +483,7 @@ public void commitTransactions( // Mostly likely it's a retried delete command response. if (LOG.isDebugEnabled()) { LOG.debug( - "Transaction txId={} commit by dnId={} for containerID={}" + "Transaction txId: {} commit by Datanode: {} for ContainerId: {}" + " failed. Corresponding entry not found.", txID, dnId, containerId); } @@ -508,13 +508,13 @@ public void commitTransactions( transactionToDNsCommitMap.remove(txID); transactionToRetryCountMap.remove(txID); if (LOG.isDebugEnabled()) { - LOG.debug("Purging txId={} from block deletion log", txID); + LOG.debug("Purging txId: {} from block deletion log", txID); } txIDsToBeDeleted.add(txID); } } if (LOG.isDebugEnabled()) { - LOG.debug("Datanode txId={} containerId={} committed by dnId={}", + LOG.debug("Datanode txId: {} ContainerId: {} committed by Datanode: {}", txID, containerId, dnId); } } catch (IOException e) { @@ -557,7 +557,7 @@ private void processSCMCommandStatus(List deleteBlockStatus, lastStatus.put(cmdStatus.getCmdId(), cmdStatus); summary.put(cmdStatus.getCmdId(), cmdStatus.getStatus()); }); - LOG.debug("CommandStatus {} from Datanode {} ", summary, dnID); + LOG.debug("CommandStatus {} from Datanode: {} ", summary, dnID); for (Map.Entry entry : lastStatus.entrySet()) { CommandStatus.Status status = entry.getValue().getStatus(); scmDeleteBlocksCommandStatusManager.updateStatusByDNCommandStatus( @@ -568,11 +568,11 @@ private void processSCMCommandStatus(List deleteBlockStatus, private boolean isTransactionFailed(DeleteBlockTransactionResult result) { if (LOG.isDebugEnabled()) { LOG.debug( - "Got block deletion ACK from datanode, TXIDs={}, " + "success={}", + "Got block deletion ACK from datanode, TXIDs {}, " + "success {}", result.getTxID(), result.getSuccess()); } if (!result.getSuccess()) { - LOG.warn("Got failed ACK for TXID={}, prepare to resend the " + LOG.warn("Got failed ACK for TXID {}, prepare to resend the " + "TX in next interval", result.getTxID()); return true; }