[
https://issues.apache.org/jira/browse/HDDS-16218?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dian-Xuan Yang updated HDDS-16218:
----------------------------------
Status: Patch Available (was: Open)
> Malformed log arguments in SCM HA hide the checkpoint transaction index, the
> reverted state index and the SCM id
> ----------------------------------------------------------------------------------------------------------------
>
> Key: HDDS-16218
> URL: https://issues.apache.org/jira/browse/HDDS-16218
> Project: Apache Ozone
> Issue Type: Bug
> Components: SCM HA
> Reporter: Dian-Xuan Yang
> Assignee: Dian-Xuan Yang
> Priority: Major
> Labels: pull-request-available
>
> Four logging statements in {{hadoop-hdds/server-scm}} pass their arguments in
> a way SLF4J cannot render as
> intended, so the values an operator needs are missing from the log exactly
> when something has failed.
> 1. {{SCMHAManagerImpl.installCheckpoint}} (SCMHAManagerImpl.java:323, from
> HDDS-6161):
> {code:java}
> LOG.error("Failed to install Snapshot as SCM failed to replace"
> + " DB with downloaded checkpoint. Checkpoint transaction {}", e,
> checkpointTxnInfo.getTransactionIndex());
> {code}
> SLF4J only promotes the *last* argument to a throwable. Here the last
> argument is a {{long}}, so the
> exception is consumed by the single {{{}}} placeholder and printed where the
> transaction index belongs,
> while the index itself is dropped. The line reads {{Checkpoint transaction
> java.io.IOException: <message>}}
> and carries no stack trace of its own.
> 2. The revert path of the same method (SCMHAManagerImpl.java:344, from
> HDDS-6161):
> {code:java}
> LOG.error("Replacing SCM state with Term : {} and Index:",
> termIndex.getTerm(), termIndex.getTerm());
> {code}
> The message has no placeholder for the index and the term accessor is passed
> twice, so the index of the
> state SCM fell back to is never recorded before {{exitManager.exitSystem(1,
> ...)}} terminates the process.
> 3. and 4. {{SCMRatisServerImpl.addSCM}} and {{removeSCM}}
> (SCMRatisServerImpl.java:359 from HDDS-4718,
> SCMRatisServerImpl.java:395 from HDDS-7853):
> {code:java}
> LOG.error("Failed to add new SCM: {}. Ratis reply: {}" +
> request.getScmId(), raftClientReply);
> {code}
> The SCM id is concatenated onto the format string with {{+}} instead of being
> passed as an argument, so the
> Ratis reply lands in the slot meant for the id, the second {{{}}} is emitted
> literally, and the id trails
> after the message: {{Failed to add new SCM: <reply>. Ratis reply: {}<scmId>}}.
> h3. How to reproduce
> * Site 1 is reached whenever {{HAUtils.replaceDBWithCheckpoint}} fails during
> a follower's Ratis
> install-snapshot — an ordinary IO error on the SCM metadata directory is
> enough.
> * Sites 3 and 4 are reached whenever {{addSCM}}/{{removeSCM}} receives an
> unsuccessful Ratis reply, e.g.
> bootstrapping a new SCM into a ring that cannot reach quorum.
> The rendering was confirmed against slf4j-api 2.0.18 + slf4j-reload4j 2.0.18
> + reload4j 1.2.26, the binding
> Ozone ships: for {{error("... transaction {}", exception, indexLong)}},
> {{MessageFormatter.arrayFormat(...).getThrowable()}} returns {{null}}, the
> message inlines the exception's
> {{toString()}} where the index should be, and the index appears nowhere in
> the output. With the arguments in
> the intended order the index renders in the placeholder and the full stack
> trace is attached.
> h3. Expected
> Every message renders the value it advertises, and exceptions are passed in
> the trailing throwable position.
> No behaviour change is involved — only the rendered log lines.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
