[jira] [Commented] (RATIS-2728) Structured logging by MDC

["Rui Wang (Jira)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/RATIS-2728?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18121793#comment-18121793 ] 

Rui Wang commented on RATIS-2728:
---------------------------------

As an example, Apache Spark introduced such framework already: https://issues.apache.org/jira/browse/SPARK-47240

> Structured logging by MDC
> -------------------------
>
>                 Key: RATIS-2728
>                 URL: https://issues.apache.org/jira/browse/RATIS-2728
>             Project: Ratis
>          Issue Type: Improvement
>            Reporter: Rui Wang
>            Assignee: Rui Wang
>            Priority: Major
>
> h2. Problem
> Ratis has no structured way to record which Raft group a log line belongs to. In a
> multi-raft deployment, where one JVM hosts many groups, all of their log lines
> interleave into a single file and a single group's timeline cannot be reconstructed.
> Today correlation is hand-rolled: a call site manually passes an identifier as the
> first format argument. This is inconsistent in three separate ways.
> *1. Coverage.* Of the 312 log statements in ratis-server/src/main, 201 begin with a
> hand-written {{{{}}{}}} self-identifier and 111 have none at all. Whole subsystems where
> "which group?" is the first question an operator asks carry no identity: 
> RaftStorageDirectoryImpl, RaftStorageImpl, StorageImplUtils, SnapshotManager and 
> SegmentedRaftLogCache never reference a member id, so their disk and snapshot 
> failures are anonymous.
> *2. The value is not always the group.* Among the 201 statements that do self-identify,
> the leading placeholder is filled by at least eight different expressions:
> ||Expression||Count||Contains group id?||
> |getMemberId()|54|yes (peer@group)|
> |this|40|depends on the class toString()|
> |name / getName()|43|depends on how name was built|
> |getId()|11|no - peer only|
> |id|7|varies|
> |termIndex, rootPath, dir|4|no - not an identity at all|
> BaseStateMachine is a good example of the {{getId()}} case. It returns a RaftPeerId,
> not a member id, so this line on a per-division class identifies the peer but not the
> group:
> {code:java}
> LOG.trace("{}: update lastAppliedTermIndex from {} to {}", getId(), oldTI, newTI);
> {code}
> On a server hosting 200 groups that message appears 200 times, once per group, with
> nothing to tell them apart.
> *3. Format.* The separator after the identifier varies and is not consistent : 171 use "{}: ", 28 use "{} ", and one uses "{}-".
> h2. Why this matters beyond tidiness
> Even for the 54 statements that do print getMemberId(), the identity sits inside the
> message body at a position and format that vary by call site. No log aggregator can
> extract it as an indexed field. That means no per-group filter in Kibana, Loki or
> Splunk, no per-group dashboard, and grep that is approximate rather than exact.
> This is a gap the project has already acknowledged. ratis-docs .../concept/advanced.md
> recommends multi-raft for scaling, then warns that "More groups mean more leaders to
> monitor, more logs to manage, and more complex failure scenarios" and advises readers
> to "Implement comprehensive monitoring for all groups" - without shipping any
> mechanism that makes group-scoped logs possible. Downstream this is not hypothetical:
> an Ozone datanode hosts one Raft group per pipeline in a single JVM.
> h2. Proposal
> Publish the Raft identifiers to the SLF4J MDC so a log layout can render them, rather
> than requiring every call site to format them into the message.
> ||MDC key||Value||
> |raftGroup|the RaftGroupId this work belongs to|
> |raftPeer|the RaftPeerId of the local server|
> |raftClient|the ClientId, while serving a client request|
> |raftCallId|the call id, while serving a client request|
> Two application strategies, matching the two kinds of threads in Ratis:
>  * Threads dedicated to one division set the context once at thread start and never
> clear it. This is wired through a new Daemon.Builder.setMdcContext(..) and
> MDC-aware ConcurrentUtils overloads, which turn out to be a narrow choke point
> covering the state machine updater, log appenders, leader election, follower state,
> the leader event processor, the reply flusher, the segmented log worker, and the
> per-server thread pools.
>  * Shared threads (the gRPC handler pools) use a scope in try-with-resources at the
> RaftServerImpl RPC entry points, restoring the previous value rather than clearing,
> because a pooled thread serves many divisions in turn.
> Operators then filter one group out of a busy log with an exact match:
> {code:java}
> log4j.appender.RFA.layout.ConversionPattern=%d{ISO8601} %p %c [%X{raftGroup}]: %m%n
> $ grep 'group-D71324CBF873' ratis.log
> {code}
> h2. Why MDC rather than fixing the call sites
>  * It is the standard SLF4J mechanism and slf4j-api is already a dependency, so no new
> dependency is introduced.
>  * It moves the identity out of the message body into structured context, which is what
> makes it an indexable field downstream.
>  * Rendering is an operator decision made in the log layout, with no code change.
>  * Code with no access to a member id is covered for free - ConfUtils, the storage
> classes and third-party state machines inherit the tag simply by running on a
> tagged thread.
>  * It is additive. The existing "{}: " prefixes are left untouched, so nothing
> regresses for anyone parsing Ratis logs today, and this is not a 312-call-site
> refactor.



--
This message was sent by Atlassian Jira
(v8.20.10#820010)