登录风格：log4j 2、上下文、自动清理……所有这些都没有附加条件！

日志记录——维护操作的时间跟踪——对于任何关键任务系统都是至关重要的，无论大小。我们的 Project-X 框架 也是如此，这就是为什么我们希望从一开始就把它做好。

根据我们在登录传说中的 UltraESB。

我们已经知道 log4j2 通过其 CloseableThreadContext 实现 提供上下文日志记录，几乎包含我们需要的一切；但我们需要更多：

1. 我们需要一个适当的日志代码治理机制，其中每个日志行都包含一个唯一的日志代码，指示子系统、模块（包）甚至特定日志语句的确切“索引”，因此我们将不再需要 grep 遍历整个代码库来找出窃听器的来源。
2. 我们需要注入带有特定前缀的环境变量和系统属性，以自动注入日志上下文，以便特定应用程序可以将其运行时参数注入日志（例如集群 ID 对于我们的集成平台）。

我们还需要 API 独立于 log4j2，因为我们应该保留与 log4j2 分离的自由，并在需要时使用不同的日志框架（例如 logback）。虽然我们可以使用诸如 SLF4J 之类的第三方包装器，但我们找不到可以轻松满足我们所有需求的包装器。

因此，与之前的 UltraESB 一样，我们用我们自己的日志记录实现 x-logging 包装了 log4j2。 x-logging 包含一个 API 和一组与真实日志记录框架（如 log4j2 和 logback）的绑定，其中一个可以在服务器启动时使用 Java 亲爱的旧 ServiceLoader机制。这有助于我们避免将 log4j2 特定的内容泄漏到我们的实现中，因为基于 log4j2 的实现（以及 log4j2 本身）可以从编译时依赖项集中完全删除。

Ruwan 来自我们的团队，他也是 Project-X 的鼻祖，用 log4j2 搞了一段时间，最后想出了一个很酷的设计来自动传播日志行的当前上下文，即它是源自平台（系统，又名 engine）还是源自已部署的 project，如果是后者，则为项目的其他元数据（例如版本）。最酷的部分是，一旦执行离开该特定上下文，该上下文就会自动清理。

如果您熟悉 CloseableThreadContext，这听起来可能非常简单。对于其他人来说，只要提到 CloseableThreadContext 有助于将键值对注入日志上下文就足够了，这样当上下文关闭时，只有注入到当前上下文中的键值对才能获得清理干净。注入的值自动提供给调用线程的日志上下文（ThreadContext）；或者，用英语来说，该线程打印的每个日志行都在其线程上下文中看到该参数（或用老派术语说是 MDC）。

好吧，我承认上面的内容可能有点难以理解。也许示例片段可以做得更好：

// assume we are walking in, with nothing useful inside the context

try (CloseableThreadContext.Instance level1 = CloseableThreadContext.put("level", "1")) {

    // now the context has "1" as "level"
    logger.debug("Commencing operation"); // will see {level=1} as the context
    // let's also put in a "clearance" value
    level1.put("clearance", "nypd");
    // now, any log lines would see {level=1,clearance=nypd}

    // let's go deeper
    try (CloseableThreadContext.Instance level2 = CloseableThreadContext.put("level", "2").put("clearance", "fbi")) {

        // now both of the above "level" and "clearance" values are "masked" by the new ones
        // and yes, you can chain together the context mutations
        logger.debug("Commencing investigation"); // will see {level=2,clearance=fbi}

        // putting in some more
        level2.put("access", "privileged");
        // now context is {level=2,clearance=fbi,access=privileged}

        // still deeper...
        try (CloseableThreadContext.Instance level3 = CloseableThreadContext.put("level", "3").put("clearance", "cia")) {

            // "level" and "clearance" are overridden, but "access" remains unchanged
            logger.debug("Commencing consipracy"); // {level=3,clearance=cia,access=privileged}

        }

        // cool thing is, once you're out of the level3 block, the context will be restored to that of level2 (thanks to the AutoCloseable nature of CloseableThreadContext.Instance)

        logger.debug("Back to investigation"); // {level=2,clearance=fbi,access=privileged}
    }

    // same for exiting level 2
    logger.debug("Back to operation"); // {level=1,clearance=nypd}; access is gone!

}

logger.debug("Back to square one"); // {}; oh no, all gone!

这种机制非常适合我们使用，因为我们需要包括线程的当前执行上下文以及该线程生成的每个日志行：

1. 在Project-X中，UltraESB-X的底层引擎，一个维护在base framework级别的worker threadpool负责处理代表属于特定项目的集成流程的入站消息。
2. 只有在消息被注入特定集成流的ingress connector 之后，我们才认为线程处于项目上下文中。工作线程应该在此之前做相当多的工作，所有这些都将被视为属于 system 上下文。
3. 我们会在整个过程中生成日志，因此它们应该会自动使用适当的上下文进行标记。
4. 此外，由于我们对每个日志行都有特定的错误代码，因此我们需要在每次实际输出日志行时打开一个新的上下文，其中除了其他上下文参数之外还包含所需的日志代码。

因此，池中线程的生命周期将是一个无限循环，如下所示：

// wake up from thread pool

// do system level stuff

loggerA.debug(143, "Now I'm doing this cool thing : {}", param);

try (CloseableThreadContext.Instance projectCtx = CloseableThreadContext.put("project", project.getName()).put("version", project.getVersion())) {

    // do project level stuff

    loggerM.debug(78, "About to get busy : {}", param);

    // more stuff, tra la la la
}

// back to system level, do still more stuff

// jump back to thread pool and have some sleep

在内部，loggerA、loggerM 和其他的最终会调用一个logImpl(code, message, params) 方法：

// context already has system/project info,
// logger already has a pre-computed codePrefix

try (CloseableThreadContext.Instance logCtx = CloseableThreadContext.put("logcode", codePrefix + code)) {
    // publish the actual log line
}

// only "logcode" cleared from the context, others remain intact

我们通过引入 CloseableContext 接口模拟了这种行为，但没有绑定到 log4j2方式：

import java.io.Closeable;

public interface CloseableContext extends Closeable {

    CloseableContext append(final String key, final String value);

    void close();
}

和：

import org.adroitlogic.x.logging.CloseableContext;
import org.apache.logging.log4j.CloseableThreadContext;

public class Log4j2CloseableContext implements CloseableContext {

    private final CloseableThreadContext.Instance ctx;

    /
     * Creates an instance wrapping a new default MDC instance
     */
    Log4j2CloseableContext() {
        this.ctx = CloseableThreadContext.put("impl", "project-x");
    }

    /
     * Adds the provided key-value pair to the currently active log4j logging (thread) context
     *
     * @param key   the key to be inserted into the context
     * @param value the value to be inserted, corresponding to {@code key}
     * @return the current instance, wrapping the same logging context
     */
    @Override
    public CloseableContext append(String key, String value) {
        ctx.put(key, value);
        return this;
    }

    /
     * Closes the log4j logging context wrapped by the current instance
     */
    @Override
    public void close() {
        ctx.close();
    }
}

现在，我们所要做的就是通过一个漂亮的管理界面打开一个合适的上下文，LogContextProvider：

// system context is active by default

...

try (CloseableContext projectCtx = LogContextProvider.forProject(project.getName(), project.getVersion())) {

    // now in project context

}

// back to system context

在 logImpl 中：

try (CloseableContext logCtx = LogContextProvider.overlayContext("logcode", codePrefix + code)) {
    // call the underlying logging framework
}

由于我们将 CloseableContext 实现与记录器绑定一起加载（通过 ServiceLoader），我们知道 LogContextProvider 最终将调用正确的实现。

这就是我们的 x-logging 框架中上下文日志记录的故事。

也许我们还可以在以后的帖子中解释我们的日志代码治理方法；在那之前，祝您伐木愉快！

标签2： Java教程

地址：https://www.cundage.com/article/jcg-logging-style-log4j-2-contextuality-auto-cleanup-no-strings-attached.html