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: [email protected]
For additional commands, e-mail: [email protected]
