log4j2
日志记录-保持操作的时间跟踪-对于任何关键任务系统,无论大小,都至关重要。 我们的Project-X框架也是如此,这就是为什么我们希望从一开始就正确地做到这一点。
基于我们在传奇的UltraESB上的登录经验, 上下文日志记录(每条日志行自动记录其原始逻辑上下文(例如,它来自特定单元还是来自基础框架))一直是我们期待的事情。
我们已经知道log4j2通过其CloseableThreadContext
实现提供了上下文日志记录,几乎包含了我们所需要的一切。 但我们需要更多:
- 我们需要一个合适的日志代码管理机制,其中每个日志行包含一个唯一的日志代码,分别表示子系统,模块(包),甚至是特定的日志语句的准确“指标”,这样我们就不再需要
grep
通过整个代码库,以找出bugger的来源。 - 我们需要注入具有特定前缀的环境变量和系统属性,以自动将其注入日志记录上下文,以便特定的应用程序可以将其运行时参数注入日志(例如,对于我们的Integration Platform ,为集群ID )。
我们还需要独立于log4j2的API,因为我们应该保留与log4j2分离的自由,并在需要时利用其他日志记录框架(例如logback )。 尽管我们可以利用第三方包装器(例如SLF4J),但找不到适合所有需求的包装器。
因此,与以前的UltraESB一样,我们用x-logging
封装了log4j2,这是我们自己的日志记录实现。 x-logging
由一个API和一组到实际日志框架(例如log4j2和logback)的绑定组成,其中一个可以在服务器启动时使用Java的旧式ServiceLoader机制动态地插入。 这有助于我们避免将log4j2特定内容泄漏到我们的实现中,因为可以将基于log4j2的实现(以及因此log4j2本身)从编译时依赖项集合中完全删除。
来自我们团队的Ruwan (也是Project-X的发起者)用log4j2破解了一段时间,最后提出了一个很酷的设计,可以自动传播日志行的当前上下文,即它是否源自平台(系统(又名engine )或已部署的项目(如果是后者),则是该项目的其他元数据(例如版本)。 最酷的部分是,一旦执行离开特定上下文,此上下文将自动清理。
如果您熟悉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!
该机制非常适合我们使用,因为我们需要包括线程的当前执行上下文以及该线程生成的每个日志行:
- 在Project-X ( UltraESB-X的基础引擎)中,维护在基本框架级别的辅助 线程池负责代表属于特定项目的集成流处理入站消息。
- 仅在将消息注入到特定集成流的入口连接器之后,我们才认为该线程位于项目的上下文中。 在此之前,工作线程应该做很多工作,所有这些工作都被认为属于
system
上下文。 - 我们会在整个过程中生成日志,因此应该自动为它们添加适当的上下文标记。
- 此外,由于每个日志行都有特定的错误代码,因此,每次实际输出日志行时,我们都需要打开一个新的上下文,该日志行除了包含其他上下文参数外,还包含所需的日志代码。
因此,池中线程的生命周期将是一个无休止的循环,例如:
// 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,该接口的log4j2变体(显然是Log4j2CloseableContext
)将以相同的方式操作CloseableThreadContext
实例:
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
框架中的上下文日志记录的故事。
也许我们将来也可以解释我们的日志代码治理方法; 在那之前,祝您伐木愉快!
log4j2