什么是过滤器(Filter)

logback 过滤器基于三元逻辑(ternary logic ),允许它们有序地组装或者链接在一起组成一个任意复杂的过滤策略。那么你可能就会问了:哎呀什么是三元逻辑呢?跟Java的三元运算符概念差不多吗?答案当然是跟三元运算符不一样了,它更偏向是二元逻辑,只有真假两种。我们来看一下维基百科上对三元逻辑的解释吧:

有三种状态来表示真、假和一个表示不确定的第三值;;这相对于基础的二元逻辑(比如布尔逻辑,它只提供真假两种状态)

我们现在知道了原来三元逻辑就是有三种状态啊,既然是基于三元逻辑的过滤器应该也有三个类似的状态值吧?是的,没错!过滤器的decide(ILoggingEvent event)方法会被调用,且返回值只能是FilterReply中定义的ACCEPTDENYNEUTRAL的三个枚举值的其中一个。

如果返回DENY,那么日志事件立即被抛弃,不再经过剩余过滤器;

如果返回NEUTRAL,那么有序列表里的下一个过滤器会接着处理记录事件;

如果返回ACCEPT,那么日志事件被立即处理,不再经过剩余过滤器。

在 logback-classic 中,有两种类型的过滤器,regular 过滤器以及 turbo 过滤器。

在 logback-classic 中,过滤器可以被直接添加到 Appender 实例上。通过将一个或者多个过滤器添加到 appender 上,你可以通过任意标准来过滤日志事件。例如,日志消息的内容,MDC 的内容,时间,或者日志事件的其它部分。

Regular 过滤器

reqular 过滤器继承自ch.qos.logback.core.filter.Filter这个抽象类。本质上它由一个单一的 decide() 方法组成,接收一个 ILoggingEvent 实例作为参数。

通常情况下,过滤器的逻辑由两个正交的部分组成,match/mismatch 的检验以及基于 match/mismatch 的返回值。logback 的 AbstractMatcherFilter类,提供了一个有用的骨架用来指定在 match 与 mismatch 情况下的返回值,这两个属性名分别叫做 OnMatchOnMismatch。logback 中大部分的 regular 过滤器都源于 AbstractMatcherFilter,他们的初始值在这个类中均为NEUTRAL,在配置中可以指定他们的新值但必须是FilterReply中的三个枚举值之一。下面介绍几个常用的过滤器:

LevelFilter

LevelFilter基于级别来过滤日志事件。如果事件的级别与配置的级别相等,过滤器会根据配置的 onMatchonMismatch 属性,接受或者拒绝事件。如下是一个简单的示例:

<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <filter class="ch.qos.logback.classic.filter.LevelFilter">
      <level>INFO</level>
      <onMatch>ACCEPT</onMatch>
      <onMismatch>DENY</onMismatch>
    </filter>
    <encoder>
      <pattern>
        %-4relative [%thread] %-5level %logger{30} - %msg%n
      </pattern>
    </encoder>
  </appender>
  <root level="DEBUG">
    <appender-ref ref="CONSOLE" />
  </root>
</configuration>

测试类:

package com.exercise.testfilter;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
 * @author chenly
 * @create 2020-01-11 13:15
 */
public class LevelFilter {
    public static final Logger LOGGER=LoggerFactory.getLogger(LevelFilter.class);
    public static void main(String[] args) {
        for (int i = 0; i < 3; i++) {
            LOGGER.info(" this is info log ");

            LOGGER.debug(" this is debug log ");

            LOGGER.error(" this is error log ");
        }
    }
}

根据配置信息对于Info级别的日志才输出,其他级别全部拒绝输出。输出:

180  [main] INFO  c.e.testfilter.LevelFilter -  this is info log 
180  [main] INFO  c.e.testfilter.LevelFilter -  this is info log 
180  [main] INFO  c.e.testfilter.LevelFilter -  this is info log 

ThresholdFilter

基于给定的临界值来过滤事件。如果事件的级别等于或高于给定的临界值,当调用 decide() 时,ThresholdFilter 将会返回 NEUTRAL。但是事件的级别低于临界值将会被拒绝。下面是一个简单的例子:

<configuration>
  <appender name="CONSOLE"
    class="ch.qos.logback.core.ConsoleAppender">
    <!-- deny all events with a level below INFO, that is TRACE and DEBUG -->
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
      <level>INFO</level>
    </filter>
    <encoder>
      <pattern>
        %-4relative [%thread] %-5level %logger{30} - %msg%n
      </pattern>
    </encoder>
  </appender>
  <root level="DEBUG">
    <appender-ref ref="CONSOLE" />
  </root>
</configuration>

还是上面的测试类,这次的输出:

174  [main] INFO  c.e.testfilter.LevelFilter -  this is info log 
174  [main] ERROR c.e.testfilter.LevelFilter -  this is error log 
174  [main] INFO  c.e.testfilter.LevelFilter -  this is info log 
174  [main] ERROR c.e.testfilter.LevelFilter -  this is error log 
174  [main] INFO  c.e.testfilter.LevelFilter -  this is info log 
174  [main] ERROR c.e.testfilter.LevelFilter -  this is error log 

我们会发现error级别的日志也会被输出,因为error级别的高于临界值info,所以返回NEUTRAL,由于没有其他过滤器需要执行,那么直接会触发打印。

以上是regular过滤器常用的两个,其他的请查阅官方文档,如果logback提供的过滤器无法满足你的需求的话,你也可以自己实现一个过滤器,成本也很小,只需要继承 Filter 并且实现 decide() 方法就可以了。你也可以参照上面两个的源码进行创建自定义的过滤器。

TurboFilters

TurboFilter 过滤器和 regular 过滤器过滤的原理差不多。但是TurboFilter 对象被绑定刚在 logger 上下文中。因此,在使用给定的 appender 以及每次发出的日志请求都会调用 TurboFilter 对象。因此,TurboFilter 可以为日志事件提供高性能的过滤,即使是在事件被创建之前。

DuplicateMessageFilter

DuplicateMessageFilter 过滤器检测重复的消息,在重复了一定次数之后,丢弃掉重复的消息。

可以通过 AllowedRepetitions 属性来指定允许重复的次数。如果这个属性被设置为 1,那么第二条以及后续的日志消息都会被丢弃掉。类似的,如果被设置为 2,那么第三条及后续的日志消息会被丢弃掉。这个值默认设置为 5

为了检测重复,过滤器需要在内部的缓存中保留对旧消息的引用。通过 CacheSize 来控制缓存的大小。这个值默认为 100

配置示例

<configuration>

    <turboFilter class="ch.qos.logback.classic.turbo.DuplicateMessageFilter">
        <AllowedRepetitions>1</AllowedRepetitions>
    </turboFilter>

    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%date [%thread] %-5level %logger - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="console" />
    </root>
</configuration>

例子还是regularFilters的测试类,info,error日志均只会输出一次。输出结果:

2020-01-11 13:36:20,760 [main] INFO  com.exercise.testfilter.LevelFilter -  this is info log 
2020-01-11 13:36:20,760 [main] ERROR com.exercise.testfilter.LevelFilter -  this is error log 
2020-01-11 13:36:20,760 [main] INFO  com.exercise.testfilter.LevelFilter -  this is info log 
2020-01-11 13:36:20,760 [main] ERROR com.exercise.testfilter.LevelFilter -  this is error log 

但是请注意!如果按照以下形式组装参数打印日志,那么这个过滤器是会做全匹配的

logger.debug("Hello "+name0);
logger.debug("Hello "+name1);

即会匹配Hello name0Hello name1拼接起来的字符串是否相等来计算重复次数;

如果你使用的是参数化打印的方式如

logger.debug("Hello {}.", name0);
logger.debug("Hello {}.", name1);

那么它比较的是Hello {}.部分是否相等来计算重复次数。

验证一下,我们将上面的过滤器AllowedRepetitions配置成3,测试类主方法

public static void main(String[] args) {
        for (int i = 0; i < 5; i++) {
            LOGGER.info(" this is info log "+i);

            LOGGER.debug(" this is debug log "+i);

        }
    }

输出:

2020-01-11 13:48:11,003 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 0
2020-01-11 13:48:11,013 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 1
2020-01-11 13:48:11,013 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 2
2020-01-11 13:48:11,013 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 3
2020-01-11 13:48:11,013 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 4

我们可以看到所有的info日志都被打印出来了,很显然都没有被过滤,那我们用参数化的输出试试!

调整日志的形式:

LOGGER.info(" this is info log {}",i);
LOGGER.debug(" this is debug log {}",i);

输出:

2020-01-11 13:51:03,190 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 0
2020-01-11 13:51:03,195 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 1
2020-01-11 13:51:03,195 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 2
2020-01-11 13:51:03,195 [main] INFO  com.exercise.testfilter.TurboFilter -  this is info log 3

很清楚看到原来this is info log 4的那条日志没有被打印。这里我们也需要知道一个点就是TurboFilters是在日志判断之前做的,Logback(4) 从日志打印两次看日志打印流程我们可以简单窥见日志打印的流程。

其他常用过滤器:MDCFilterDynamicThresholdFilterMarkerFilter

MDCFilter用来检查给定的值在 MDC 中是否存在。DynamicThresholdFilter根据 MDC key/level 相关的阀值来进行过滤。MarkerFilter用来检查日志请求中指定的 marker 是否存在。

在使用之前我们先简单了解一下什么是MDC(Mapped Diagnostic Context ):映射调试上下文,是为了便于我们诊断线上问题而出现的工具类。在多个客户端(在web项目中你可以理解成每次请求)并发访问的情况下,通过给每个客户端的请求指定一个唯一标记,从而方便日志排查。你这里可以简单理解成一个map类型的上下文,可以在当前请求的生命周期里被访问。

MDCFilter自身有两个属性:MDCKey,value,顾名思义即key-value的值。

Marker是常常被用来丰富log状态的对象。遵守slf4j的日志系统实现,决定了信息怎样在使用的Marker之间传达。实际上,很多遵守规范的日志系统会忽视掉marker数据。所以我们这里只是简单提一下,有兴趣深入了解的查阅官方文档。

看个例子

<configuration>

  <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">
    <MDCKey>username</MDCKey>
    <Value>sebastien</Value>
    <OnMatch>ACCEPT</OnMatch>
  </turboFilter>

  <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>billing</Marker>
    <OnMatch>DENY</OnMatch>
  </turboFilter>

  <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%date [%thread] %-5level %logger - %msg%n</pattern>
    </encoder>
  </appender>

  <root level="INFO">
    <appender-ref ref="console" />
  </root>  
</configuration>

测试类:

package com.exercise.testfilter;

import org.slf4j.*;

/**
 * @author chenly
 * @create 2020-01-11 14:05
 */
public class MdcFilter {
    public static final Logger logger = LoggerFactory.getLogger(MdcFilter.class);

    public static void main(String[] args) {

        for (int i = 0; i < 10; i++) {
            if (i == 3) {
                MDC.put("username", "sebastien");
                logger.debug("logging statement {}", i);
                MDC.remove("username");
            } else if (i == 6) {
                Marker billing = MarkerFactory.getMarker("billing");
                logger.error(billing, "billing statement {}", i);
            } else {
                logger.info("logging statement {}", i);
            }
        }
    }
}

输出:

2020-01-11 20:18:48,455 [main] INFO  com.exercise.testfilter.MdcFilter - logging statement 0
2020-01-11 20:18:48,458 [main] INFO  com.exercise.testfilter.MdcFilter - logging statement 1
2020-01-11 20:18:48,458 [main] INFO  com.exercise.testfilter.MdcFilter - logging statement 2
2020-01-11 20:18:48,458 [main] DEBUG com.exercise.testfilter.MdcFilter - logging statement 3
2020-01-11 20:18:48,458 [main] INFO  com.exercise.testfilter.MdcFilter - logging statement 4
2020-01-11 20:18:48,458 [main] INFO  com.exercise.testfilter.MdcFilter - logging statement 5
2020-01-11 20:18:48,458 [main] INFO  com.exercise.testfilter.MdcFilter - logging statement 7
2020-01-11 20:18:48,458 [main] INFO  com.exercise.testfilter.MdcFilter - logging statement 8
2020-01-11 20:18:48,458 [main] INFO  com.exercise.testfilter.MdcFilter - logging statement 9

让我们分析一下日志的结果,从代码中我们知道当i=3时,我们赋值了一个MDC中一个加了一个键值对,且当条日志等级为debug,因为 MDC 的 key "username" 在第三条请求之前设置为 "sebastien",之后被移除,所以 当i=3时,MDCFilter 接受这条请求 (仅仅只有这条请求),打印了这条日志(也再次印证了过滤器的优先级是高于日志等级判断的)。第 6 条请求的级别为 ERROR,被标记为 "billing"。因此,它会被 MarkerFilter (配置文件中第二个 turbo 过滤器) 拒绝。

看个DynamicThresholdFilter示例,从DynamicThresholdFilter这个类的源码中我们大致知道这个过滤器有这么几个参数:valueLevelMap对应xml中的MDCValueLevelPair的value-level,Key,DefaultThreshold(默认ERROR),onHigherOrEqual(默认NEUTRAL),onLower(默认DENY)。都是字面意思,可以从这个类的javadoc注释大致了解。

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>TEST %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
        </encoder>
    </appender>

    <turboFilter class="ch.qos.logback.classic.turbo.DynamicThresholdFilter">
        <Key>userId</Key>
        <DefaultThreshold>ERROR</DefaultThreshold>
        <OnHigherOrEqual>ACCEPT</OnHigherOrEqual>
        <OnLower>DENY</OnLower>
        <MDCValueLevelPair>
            <value>user1</value>
            <level>WARN</level>
        </MDCValueLevelPair>
        <MDCValueLevelPair>
            <value>user2</value>
            <level>TRACE</level>
        </MDCValueLevelPair>
    </turboFilter>

    <logger name="com.exercise.testfilter" level="TRACE"/>

    <root level="ERROR">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

测试类:

package com.exercise.testfilter;

import org.slf4j.*;

/**
 * @author chenly
 * @create 2020-01-11 20:24
 */
public class DynamicFilter {
    public static final Logger logger = LoggerFactory.getLogger(DynamicFilter.class);

    public static void main(String[] args) {

        for (int i = 0; i < 10; i++) {
            if (i == 3) {
                MDC.put("userId", "user1");
                logger.debug("logging statement {}", i);
                MDC.remove("userId");
            } else if (i == 4) {
                MDC.put("userId", "user1");
                logger.warn("logging statement {}", i);
                MDC.remove("userId");
            } else if (i == 6) {
                MDC.put("userId", "user2");
                logger.debug("logging statement {}", i);
                MDC.remove("userId");
            } else {
                MDC.put("userId", "user3");
                logger.info("logging statement {}", i);
                MDC.remove("userId");
            }
        }
    }
}

输出:

TEST 20:34:31.879 [main] WARN  c.exercise.testfilter.DynamicFilter - logging statement 4
TEST 20:34:31.882 [main] DEBUG c.exercise.testfilter.DynamicFilter - logging statement 6

MDCValueLevelPair的作用是当key为userId,value为某个值的时候什么级别的日志可以输出,当key为userId时,高于等于ERROR级别的日志应该直接输出,低于ERROR的直接不输出。

以上就是常见的过滤器的介绍,下面我们将具体介绍我们上面简单提到的MDC。

MDC(Mapped Diagnostic Context)

logback 设计的目标之一是审计与调试复杂的分布式应用。大部分的分布式系统需要同时处理多个客户端。在一个系统典型的多线程实现中,不同的线程处理不同的客户端。一种可能但是不建议的方式是在每个客户端实例化一个新的且独立的 logger,来区分一个客户端与另一个客户端的日志输出。这种方式会导致 logger 急剧增加并且会增加维护成本。

一种轻量级的技术是给每个为客户端服务的 logger 打一个标记。Neil Harrison 在 Patterns for Logging Diagnostic Messages in Pattern Languages of Program Design 3, edited by R. Martin, D. Riehle, and F. Buschmann (Addison-Wesley, 1997) 这本书中描述了这种方法。logback 在 SLF4J API 利用了这种技术的变体:诊断上下文映射 (MDC)。logback 在 SLF4J API 利用了这种技术的变体:诊断上下文映射 (MDC)。

为了给每个请求打上唯一的标记,用户需要将上下文信息放到 MDC (Mapped Diagnostic Context 的缩写) 中。

package org.slf4j;

public class MDC {
  //Put a context value as identified by key
  //into the current thread's context map.
  public static void put(String key, String val);

  //Get the context identified by the key parameter.
  public static String get(String key);

  //Remove the context identified by the key parameter.
  public static void remove(String key);

  //Clear all entries in the MDC.
  public static void clear();
}

MDC 类中只包含静态方法。它让开发人员可以在 诊断上下文 中放置信息,而后通过特定的 logback 组件去获取。MDC每个线程的基础上 管理上下文信息。通常,当为一个新客户端启动服务时,开发人员会将特定的上文信息插入到 MDC 中。例如,客户端 id,客户端 IP 地址,请求参数等。多次插入同一个 key,新值会覆盖旧值。我们通过logback配置文件配置这些参数跟着日志进行输出。

请注意,logback-classic 实现的 MDC,假设值以适当的频率放置。还需注意的一点是,子线程不会自动继承父线程的 MDC。

MDC 在客户端服务器架构中最为重要。通常,服务器上的多个线程为多个客户端提供服务。尽管 MDC 中的方法是静态的,但是是以每个线程为基础来进行管理的,允许每个服务线程都打上一个 MDC 标记。MDC 中的 put()get() 操作仅仅只影响当前线程中的 MDC。其它线程中 MDC 不会受到影响。给定的 MDC 信息在每个线程的基础上进行管理。每个线程都有一份 MDC 的拷贝。因此,在对 MDC 进行编程时,开发人员没有必要去考虑线程安全或者同步问题。它自己会安全的处理这些问题。

如果是一个SpringMVC项目,我们一般会继承HandlerInterceptorAdapter类写自己的拦截器,在preHandle()方法中放置MDC,如生成一个requestId,标识当前请求的唯一标记,便于日志的查找,在afterCompletion()清理MDC。