[jira] [Created] (HDDS-16218) Malformed log arguments in SCM HA hide the checkpoint transaction index, the reverted state index and the SCM id

["Dian-Xuan Yang (Jira)" <ji...@apache.org>]

Dian-Xuan Yang created HDDS-16218:
-------------------------------------

             Summary: 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


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: issues-unsubscribe@ozone.apache.org
For additional commands, e-mail: issues-help@ozone.apache.org