From da1d8eb7c0626850bb921f770a4c880bfdc0a0f2 Mon Sep 17 00:00:00 2001
From: Hang Chen <chenhang@apache.org>
Date: Tue, 29 Aug 2023 14:51:16 +0800
Subject: [PATCH] Enable kv logs in log4j configuration (#3986)

### Motivation
We introduced DirectIO since BookKeeper 4.16.0, and the DirectIO classes use KV-based Slf4jSlogger. https://github.com/apache/bookkeeper/blob/master/bookkeeper-slogger/slf4j/src/main/java/org/apache/bookkeeper/slogger/slf4j/Slf4jSlogger.java

In order to print the KV out, we need to add `%X` flag in log4j2.yaml, otherwise the log will miss the detailed key and values.

<!-- Explain here the context, and why you're making that change. What is the problem you're trying to solve. -->

### Modifications
In order to reduce the impact on current logger appenders, I add MDC-based appenders for `CONSOLE`, `TRACEFILE`, and `ROLLINGFILE` by adding `%X` for log4j2.yaml Appender PatternLayout.
Only classes under `org.apache.bookkeeper.bookie.storage.directentrylogger` will enable MDC-based appender logger.

If the key value has items, the log will look like:
```
2023-06-19T16:01:56,685+0800 [main] INFO  org.apache.bookkeeper.bookie.storage.directentrylogger.EntryLogIdsImpl {dirs=[data/bookkeeper/ledgers/current], durationMs=0, event=ENTRYLOG_IDS_CANDIDATES_SELECTED, maxId=21474836
47, nextId=0} - ENTRYLOG_IDS_CANDIDATES_SELECTED
2023-06-19T16:01:56,721+0800 [main] INFO  org.apache.bookkeeper.bookie.storage.directentrylogger.DirectEntryLogger {directory=data/bookkeeper/ledgers/current, event=ENTRYLOGGER_CREATED, maxCachedReaders=32, maxCachedReader
sPerThread=4, maxFileSize=1073741824, maxSaneEntrySize=5252620, perThreadBufferSize=33554432, readBufferSize=8388608, singleWriteBufferSize=33554432, totalReadBufferSize=268435456, totalWriteBufferSize=268435456} - ENTRYLO
GGER_CREATED
```
---
 conf/log4j2.xml | 16 ++++++++++++++++
 1 file changed, 16 insertions(+)

diff --git a/conf/log4j2.xml b/conf/log4j2.xml
index 61c92a59353..08d5d5613c1 100644
--- a/conf/log4j2.xml
+++ b/conf/log4j2.xml
@@ -30,9 +30,15 @@
         <Console name="CONSOLE" target="SYSTEM_OUT">
             <PatternLayout pattern="%d{ISO8601} - %-5p - [%t:%C{1}@%L] - %m%n"/>
         </Console>
+        <Console name="CONSOLEMDC" target="SYSTEM_OUT">
+            <PatternLayout pattern="%d{ISO8601} - %-5p - [%t:%C{1}@%L] %X - %m%n"/>
+        </Console>
         <File name="TRACEFILE" fileName="${sys:bookkeeper.log.dir}/bookkeeper-trace.log">
             <PatternLayout pattern="%d{ISO8601} - %-5p [%t:%C{1}@%L][%ndc] - %m%n"/>
         </File>
+        <File name="TRACEFILEMDC" fileName="${sys:bookkeeper.log.dir}/bookkeeper-trace.log">
+            <PatternLayout pattern="%d{ISO8601} - %-5p [%t:%C{1}@%L][%ndc] %X - %m%n"/>
+        </File>
         <RollingFile name="ROLLINGFILE" fileName="${sys:bookkeeper.log.dir}/${sys:bookkeeper.log.file}" filePattern="${sys:bookkeeper.log.dir}/${sys:bookkeeper.log.file}%d{.yyyy-MM-dd}">
             <PatternLayout pattern="%d{ISO8601} - %-5p [%t:%C{1}@%L] - %m%n"/>
             <Policies>
@@ -40,10 +46,20 @@
             </Policies>
             <DefaultRolloverStrategy max="100"/>
         </RollingFile>
+        <RollingFile name="ROLLINGFILEMDC" fileName="${sys:bookkeeper.log.dir}/${sys:bookkeeper.log.file}" filePattern="${sys:bookkeeper.log.dir}/${sys:bookkeeper.log.file}%d{.yyyy-MM-dd}">
+            <PatternLayout pattern="%d{ISO8601} - %-5p [%t:%C{1}@%L] %X - %m%n"/>
+            <Policies>
+                <TimeBasedTriggeringPolicy modulate="true"/>
+            </Policies>
+            <DefaultRolloverStrategy max="100"/>
+        </RollingFile>
     </Appenders>
     <Loggers>
         <Root level="${sys:bookkeeper.log.root.level}">
             <AppenderRef ref="${sys:bookkeeper.log.root.appender}"/>
         </Root>
+        <Logger name="org.apache.bookkeeper.bookie.storage.directentrylogger" level="INFO">
+                <AppenderRef ref="${sys:bookkeeper.log.root.appender}MDC"/>
+        </Logger>
     </Loggers>
 </Configuration>