java · 2020-10-15 0

Java日志(slf4j+logback)打印彩色日志及原理

一、maven依赖

在pom文件增加slf4j+logback依赖

<!-- slf4j依赖包 -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.36</version>
</dependency>

<!-- logback-classic桥接器 -->
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.2.11</version>
</dependency>

<!-- logback实现 -->
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-core</artifactId>
    <version>1.2.11</version>
</dependency>

二、logback配置文件

在类路径下建logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds" debug="false">
    <property name="APP_NAME" value="MY_APP_NAME" />
    <property name="LOG_DIR" value="logs" />
    <property name="FILE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS}  %-5level [%thread] %logger{15} - %msg%n" />
    <!-- 彩色日志格式 -->
    <property name="CONSOLE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%-5level) %boldYellow([%thread])  %cyan(%logger{15}) %msg%n"/>

    <contextName>${APP_NAME}</contextName>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
        <file>${LOG_DIR}/logFile.log</file>
        <append>true</append>
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <appender name="RollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_DIR}/dayLogFile.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <!-- 使用root的appender-ref -->
    <logger name="com.example.Logger1" level="DEBUG" additivity="true">
    </logger>

    <!-- 不使用root的appender-ref -->
    <logger name="com.example.Logger2" level="DEBUG" additivity="false">
    </logger>

    <logger name="com.example.Logger3" level="DEBUG" additivity="false">
        <appender-ref ref="STDOUT"/>
    </logger>

    <root level="DEBUG">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="FILE" />
        <appender-ref ref="RollingFile" />
    </root>
</configuration>

下方是可以打印方法名和行号的 <pattern>,说明:

<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %highlight(%-5level) %boldYellow([%14.14thread]) %cyan(%logger{15}) [%M] [%line] %msg%n</pattern>
  • %d{yyyy-MM-dd HH:mm:ss.SSS}:这部分指定了日期和时间的格式,yyyy-MM-dd HH:mm:ss.SSS表示年-月-日 时:分:秒.毫秒

  • %highlight(%-5level):这部分指定了日志级别的格式,并使用 %highlight() 标记将其着色。%-5level 表示左对齐的日志级别,如果级别长度小于5,则会用空格填充。

  • %boldYellow([%14.14thread]):这部分将线程名称加粗并着色为黄色,用于标识日志所在的线程。%14.14thread指定了线程名的长度为14,超出部分将被截断。

  • %cyan(%logger{15}):这部分将Logger名称着色为青色,并指定了 Logger 名称的长度为15,超出部分将被截断。

  • [%M]:这部分输出方法名。

  • [%line]:这部分输出日志所在的行号。

  • %msg:这部分输出日志消息。

  • %n:表示换行符。

  • %5:这个标记表示字段宽度为5,如果字段的长度小于5,则会用空格在左侧进行填充,使得字段总宽度为5。如果字段的长度超过5,则不进行截断,而是显示完整的字段。

  • %-5:这个标记与%5相似,不同之处在于它会在右侧进行填充,使得字段总宽度为5。

  • %.5:这个标记表示精度为5,它通常用于限制字符串类型字段的输出长度。如果字段的长度大于5,则会截断字符串并只输出前5个字符;如果字段的长度小于等于5,则输出整个字段。注意,这个标记通常用于字符类型的字段,对于数值型字段则表示小数点后的位数。

三、测试

1.java类

Loggor1.java

package com.example;

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

public class Logger1 {

    private static Logger LOGGER = LoggerFactory.getLogger(Logger1.class);

    static {
        LOGGER.info("This is logger1");
    }
}

Loggor2.java

package com.example;

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

public class Logger2 {

    private static Logger LOGGER = LoggerFactory.getLogger(Logger2.class);

    static {
        LOGGER.info("This is logger2");
    }
}

Loggor3.java

package com.example;

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

public class Logger3 {

    private static Logger LOGGER = LoggerFactory.getLogger(Logger3.class);

    static {
        LOGGER.info("This is logger3");
    }
}

Main.java

package com.example;

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

public class Main {

    private static Logger LOGGER = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {
        new Logger1();
        new Logger2();
        new Logger3();
        LOGGER.debug("this is debug");
        LOGGER.info("this is info");
        LOGGER.warn("this is warn");
        LOGGER.error("this is error");
    }
}

2.结果

logback

四、logback配置说明

1.<configuration>节点

属性有:

  • scan: 当此属性设置为true时,配置文件如果发生改变,将会被重新加载,默认值为true。
  • scanPeriod: 设置监测配置文件是否有修改的时间间隔,如果没有给出时间单位,默认单位是毫秒。当scan为true时,此属性生效。默认的时间间隔为1分钟。
  • debug: 当此属性设置为true时,将打印出logback内部日志信息,实时查看logback运行状态。默认值为false。

2.<contextName>节点

每个logger都关联到logger上下文,默认上下文名称为“default”。但可以使用<contextName>设置成其他名字,用于区分不同应用程序的记录。一旦设置,不能修改。可以通过%contextName来打印日志上下文名称,一般来说我们不用这个属性,可有可无

3.<property>节点

用来定义变量值的标签

4.<logger>节点

<logger> 用来设置某一个包或者具体的某一个类的日志打印级别、以及指定<appender>

<logger>可以包含零个或多个<appender-ref>元素,标识这个appender将会添加到这个logger。

属性有:

  • name: 用来指定受此logger约束的某一个包或者具体的某一个类。
  • level: 用来设置打印级别,大小写无关:TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF,还有一个特俗值INHERITED或者同义词NULL,代表强制执行上级的级别。如果未设置此属性,那么当前loger将会继承上级的级别。
  • additivity: 是否向上级logger传递打印信息。默认是true。

additivity的作用在于 children-logger(<logger>标签)是否使用 rootLogger(<root> 标签)配置的appender进行输出。

false:表示只用当前logger(<logger> 标签)的appender-ref。

true:表示当前logger(<logger>标签)的appender-ref和rootLogger(<root> 标签)的appender-ref都有效。

5.<root>节点

root节点和logger节点其实都是表示Logger组件,root是最顶层的logger。root节点只有一个level属性。

<root>可以包含零个或多个<appender-ref>元素,标识这个appender将会添加到这个logger。

属性有:

  • level: 用来设置打印级别,大小写无关:TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF,不能设置为INHERITED或者同义词NULL。默认是DEBUG。

6.<appender>节点

<appender> 是负责写日志的组件。<appender>有两个必要属性name和class。

属性有:

  • name: appender名称
  • class: appender的全限定名。

class取值有:

  • ch.qos.logback.core.ConsoleAppender
  • ch.qos.logback.core.FileAppender
  • ch.qos.logback.core.rolling.RollingFileAppender

7.ch.qos.logback.core.ConsoleAppender

节点有:

  • <encoder>:对日志进行格式化
  • <target>:字符串 System.out 或者 System.err ,默认 System.out

8.ch.qos.logback.core.FileAppender

FileAppender 把日志添加到文件

节点有:

  • <file>:被写入的文件名,可以是相对目录,也可以是绝对目录,如果上级目录不存在会自动创建,没有默认值
  • <append>:如果是 true,日志被追加到文件结尾,如果是 false,清空现存文件,默认是true
  • <encoder>:对记录事件进行格式化
  • <prudent>:如果是 true,日志会被安全的写入文件,即使其他的FileAppender也在向此文件做写入操作,效率低,默认是 false

9.ch.qos.logback.core.rolling.RollingFileAppender

RollingFileAppender 滚动记录文件,先将日志记录到指定文件,当符合某个条件时,将日志记录到其他文件

节点有:

  • <file>:被写入的文件名,可以是相对目录,也可以是绝对目录,如果上级目录不存在会自动创建,没有默认值。
  • <append>:如果是 true,日志被追加到文件结尾,如果是 false,清空现存文件,默认是true。
  • <encoder>:对记录事件进行格式化。(具体参数稍后讲解 )
  • <rollingPolicy>:当发生滚动时,决定 RollingFileAppender 的行为,涉及文件移动和重命名。
  • <triggeringPolicy >: 告知 RollingFileAppender 合适激活滚动。
  • <prudent>:当为true时,不支持FixedWindowRollingPolicy。支持TimeBasedRollingPolicy,但是有两个限制,1不支持也不允许文件压缩,2不能设置file属性,必须留空。

<rollingPolicy>节点的class可取值:ch.qos.logback.core.rolling.TimeBasedRollingPolicy

TimeBasedRollingPolicy: 最常用的滚动策略,它根据时间来制定滚动策略,既负责滚动也负责出发滚动。

TimeBasedRollingPolicy有子节点:

  • <fileNamePattern>: 必要节点,包含文件名及“%d”转换符, “%d”可以包含一个java.text.SimpleDateFormat指定的时间格式,如:%d{yyyy-MM}。如果直接使用 %d,默认格式是 yyyy-MM-dd。RollingFileAppender 的file字节点可有可无,通过设置file,可以为活动文件和归档文件指定不同位置,当前日志总是记录到file指定的文件(活动文件),活动文件的名字不会改变;如果没设置file,活动文件的名字会根据fileNamePattern的值,每隔一段时间改变一次。“/”或者“”会被当做目录分隔符。
  • <maxHistory>: 可选节点,控制保留的归档文件的最大数量,超出数量就删除旧文件

10.<encoder><pattern>节点

<pattern>: 设置日志的输入格式。使用“%”加“转换符”方式,如果要输出“%”,则必须用“”对“%”进行转义。

五、slf4j原理

1.LoggerFactory 会找到 StaticLoggerBinder.class 文件

在 bind() 方法中,调用 findPossibleStaticLoggerBinderPathSet() 方法可以查找到 logback-classic 的 jar 包中有 StaticLoggerBinder.class;调用 StaticLoggerBinder.getSingleton() 进行初始化配置

此时,StaticLoggerBinder 是 logback-classi.jar 下的 org.slf4j.impl.StaticLoggerBinder

slf4j-api.jar

// LoggerFactory.java
    public static Logger getLogger(Class<?> clazz) {
        Logger logger = getLogger(clazz.getName());
        if (DETECT_LOGGER_NAME_MISMATCH) {
            Class<?> autoComputedCallingClass = Util.getCallingClass();
            if (autoComputedCallingClass != null && nonMatchingClasses(clazz, autoComputedCallingClass)) {
                Util.report(String.format("Detected logger name mismatch. Given name: "%s"; computed name: "%s".", logger.getName(),
                                autoComputedCallingClass.getName()));
                Util.report("See " + LOGGER_NAME_MISMATCH_URL + " for an explanation");
            }
        }
        return logger;
    }

    public static Logger getLogger(String name) {
        ILoggerFactory iLoggerFactory = getILoggerFactory();
        return iLoggerFactory.getLogger(name);
    }

    public static ILoggerFactory getILoggerFactory() {
        if (INITIALIZATION_STATE == UNINITIALIZED) {
            synchronized (LoggerFactory.class) {
                if (INITIALIZATION_STATE == UNINITIALIZED) {
                    INITIALIZATION_STATE = ONGOING_INITIALIZATION;
                    performInitialization();
                }
            }
        }
        switch (INITIALIZATION_STATE) {
        case SUCCESSFUL_INITIALIZATION:
            return StaticLoggerBinder.getSingleton().getLoggerFactory();
        case NOP_FALLBACK_INITIALIZATION:
            return NOP_FALLBACK_FACTORY;
        case FAILED_INITIALIZATION:
            throw new IllegalStateException(UNSUCCESSFUL_INIT_MSG);
        case ONGOING_INITIALIZATION:
            // support re-entrant behavior.
            // See also http://jira.qos.ch/browse/SLF4J-97
            return SUBST_FACTORY;
        }
        throw new IllegalStateException("Unreachable code");
    }

    private final static void performInitialization() {
        bind();
        if (INITIALIZATION_STATE == SUCCESSFUL_INITIALIZATION) {
            versionSanityCheck();
        }
    }

    private final static void bind() {
        try {
            Set<URL> staticLoggerBinderPathSet = null;
            // skip check under android, see also
            // http://jira.qos.ch/browse/SLF4J-328
            if (!isAndroid()) {
                staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
                reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
            }
            // the next line does the binding
            StaticLoggerBinder.getSingleton();
            INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
            reportActualBinding(staticLoggerBinderPathSet);
            fixSubstituteLoggers();
            replayEvents();
            // release all resources in SUBST_FACTORY
            SUBST_FACTORY.clear();
        } catch (NoClassDefFoundError ncde) {
            String msg = ncde.getMessage();
            if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
                INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
                Util.report("Failed to load class "org.slf4j.impl.StaticLoggerBinder".");
                Util.report("Defaulting to no-operation (NOP) logger implementation");
                Util.report("See " + NO_STATICLOGGERBINDER_URL + " for further details.");
            } else {
                failedBinding(ncde);
                throw ncde;
            }
        } catch (java.lang.NoSuchMethodError nsme) {
            String msg = nsme.getMessage();
            if (msg != null && msg.contains("org.slf4j.impl.StaticLoggerBinder.getSingleton()")) {
                INITIALIZATION_STATE = FAILED_INITIALIZATION;
                Util.report("slf4j-api 1.6.x (or later) is incompatible with this binding.");
                Util.report("Your binding is version 1.5.5 or earlier.");
                Util.report("Upgrade your binding to version 1.6.x.");
            }
            throw nsme;
        } catch (Exception e) {
            failedBinding(e);
            throw new IllegalStateException("Unexpected initialization failure", e);
        }
    }

    private static String STATIC_LOGGER_BINDER_PATH = "org/slf4j/impl/StaticLoggerBinder.class";

    static Set<URL> findPossibleStaticLoggerBinderPathSet() {
        // use Set instead of list in order to deal with bug #138
        // LinkedHashSet appropriate here because it preserves insertion order
        // during iteration
        Set<URL> staticLoggerBinderPathSet = new LinkedHashSet<URL>();
        try {
            ClassLoader loggerFactoryClassLoader = LoggerFactory.class.getClassLoader();
            Enumeration<URL> paths;
            if (loggerFactoryClassLoader == null) {
                paths = ClassLoader.getSystemResources(STATIC_LOGGER_BINDER_PATH);
            } else {
                paths = loggerFactoryClassLoader.getResources(STATIC_LOGGER_BINDER_PATH);
            }
            while (paths.hasMoreElements()) {
                URL path = paths.nextElement();
                staticLoggerBinderPathSet.add(path);
            }
        } catch (IOException ioe) {
            Util.report("Error getting resources from path", ioe);
        }
        return staticLoggerBinderPathSet;
    }

2.配置 loggerContext

logback-classic.jar

// StaticLoggerBinder.java
    static {
        SINGLETON.init();
    }

    void init() {
        try {
            try {
                new ContextInitializer(defaultLoggerContext).autoConfig();
            } catch (JoranException je) {
                Util.report("Failed to auto configure default logger context", je);
            }
            // logback-292
            if (!StatusUtil.contextHasStatusListener(defaultLoggerContext)) {
                StatusPrinter.printInCaseOfErrorsOrWarnings(defaultLoggerContext);
            }
            contextSelectorBinder.init(defaultLoggerContext, KEY);
            initialized = true;
        } catch (Throwable t) {
            // we should never get here
            Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
        }
    }

findURLOfDefaultConfigurationFile() 方法从 System.getProperty("logback.configurationFile") 找到配置文件路径,若没有设置这个变量,从 classload 中 (即从 classpath 中) 依次查找 logback.groovy,logback-test.xml,logback.xml 文件。然后配置 ch.qos.logback.classic.LoggerContext 对象

// ContextInitializer.java
    public void autoConfig() throws JoranException {
        StatusListenerConfigHelper.installIfAsked(loggerContext);
        URL url = findURLOfDefaultConfigurationFile(true);
        if (url != null) {
            configureByResource(url);
        } else {
            Configurator c = EnvUtil.loadFromServiceLoader(Configurator.class);
            if (c != null) {
                try {
                    c.setContext(loggerContext);
                    c.configure(loggerContext);
                } catch (Exception e) {
                    throw new LogbackException(String.format("Failed to initialize Configurator: %s using ServiceLoader", c != null ? c.getClass()
                                    .getCanonicalName() : "null"), e);
                }
            } else {
                BasicConfigurator basicConfigurator = new BasicConfigurator();
                basicConfigurator.setContext(loggerContext);
                basicConfigurator.configure(loggerContext);
            }
        }
    }

    public void configureByResource(URL url) throws JoranException {
        if (url == null) {
            throw new IllegalArgumentException("URL argument cannot be null");
        }
        final String urlString = url.toString();
        if (urlString.endsWith("groovy")) {
            if (EnvUtil.isGroovyAvailable()) {
                // avoid directly referring to GafferConfigurator so as to avoid
                // loading groovy.lang.GroovyObject . See also http://jira.qos.ch/browse/LBCLASSIC-214
                GafferUtil.runGafferConfiguratorOn(loggerContext, this, url);
            } else {
                StatusManager sm = loggerContext.getStatusManager();
                sm.add(new ErrorStatus("Groovy classes are not available on the class path. ABORTING INITIALIZATION.", loggerContext));
            }
        } else if (urlString.endsWith("xml")) {
            JoranConfigurator configurator = new JoranConfigurator();
            configurator.setContext(loggerContext);
            configurator.doConfigure(url);
        } else {
            throw new LogbackException("Unexpected filename extension of file [" + url.toString() + "]. Should be either .groovy or .xml");
        }
    }

3.获得 ch.qos.logback.classic.LoggerContext 对象

logback-classic.jar 中 org.slf4j.impl.StaticLoggerBinder.getLoggerFactory() 方法,返回的是 ch.qos.logback.classic.LoggerContext 对象

// StaticLoggerBinder.java
    private static StaticLoggerBinder SINGLETON = new StaticLoggerBinder();

    private LoggerContext defaultLoggerContext = new LoggerContext();

    static {
        SINGLETON.init();
    }

     public static StaticLoggerBinder getSingleton() {
        return SINGLETON;
    }

    void init() {
        try {
            try {
                new ContextInitializer(defaultLoggerContext).autoConfig();
            } catch (JoranException je) {
                Util.report("Failed to auto configure default logger context", je);
            }
            // logback-292
            if (!StatusUtil.contextHasStatusListener(defaultLoggerContext)) {
                StatusPrinter.printInCaseOfErrorsOrWarnings(defaultLoggerContext);
            }
            contextSelectorBinder.init(defaultLoggerContext, KEY);
            initialized = true;
        } catch (Throwable t) {
            // we should never get here
            Util.report("Failed to instantiate [" + LoggerContext.class.getName() + "]", t);
        }
    }

    public ILoggerFactory getLoggerFactory() {
        if (!initialized) {
            return defaultLoggerContext;
        }

        if (contextSelectorBinder.getContextSelector() == null) {
            throw new IllegalStateException("contextSelector cannot be null. See also " + NULL_CS_URL);
        }
        return contextSelectorBinder.getContextSelector().getLoggerContext();
    }

4.获得 Logger 对象

logback-classic.jar 中,获得 ch.qos.logback.classic.Logger对象

// LoggerContext.java
    @Override
    public final Logger getLogger(final String name) {

        if (name == null) {
            throw new IllegalArgumentException("name argument cannot be null");
        }

        // if we are asking for the root logger, then let us return it without
        // wasting time
        if (Logger.ROOT_LOGGER_NAME.equalsIgnoreCase(name)) {
            return root;
        }

        int i = 0;
        Logger logger = root;

        // check if the desired logger exists, if it does, return it
        // without further ado.
        Logger childLogger = (Logger) loggerCache.get(name);
        // if we have the child, then let us return it without wasting time
        if (childLogger != null) {
            return childLogger;
        }

        // if the desired logger does not exist, them create all the loggers
        // in between as well (if they don't already exist)
        String childName;
        while (true) {
            int h = LoggerNameUtil.getSeparatorIndexOf(name, i);
            if (h == -1) {
                childName = name;
            } else {
                childName = name.substring(0, h);
            }
            // move i left of the last point
            i = h + 1;
            synchronized (logger) {
                childLogger = logger.getChildByName(childName);
                if (childLogger == null) {
                    childLogger = logger.createChildByName(childName);
                    loggerCache.put(childName, childLogger);
                    incSize();
                }
            }
            logger = childLogger;
            if (h == -1) {
                return childLogger;
            }
        }
    }

logback-classic.jar

// Logger.java
    Logger createChildByName(final String childName) {
        int i_index = LoggerNameUtil.getSeparatorIndexOf(childName, this.name.length() + 1);
        if (i_index != -1) {
            throw new IllegalArgumentException("For logger [" + this.name + "] child name [" + childName
                            + " passed as parameter, may not include '.' after index" + (this.name.length() + 1));
        }

        if (childrenList == null) {
            childrenList = new CopyOnWriteArrayList<Logger>();
        }
        Logger childLogger;
        childLogger = new Logger(childName, this, this.loggerContext);
        childrenList.add(childLogger);
        childLogger.effectiveLevelInt = this.effectiveLevelInt;
        return childLogger;
    }

logger