Java日志隔离功能实现

by 杰西

背景

我们都知道日志至于任何系统、软件都是十分重要的组成部分，通过日志我们可以方便地了解到现在系统运行是否正常、是否有异常情况。
但有时候日志太多了也会有幸福地烦恼，发生异常想通过日志进行排查，可是满屏地日志都是不那么重要地内容，像心跳日志、debug日志等等。

这在java应用尤为严重，你每引入地一个jar都有可能引入一堆打印的日志，这样一来要从日志中找到你所需要的内容将是一件极其困难的事情。
当然，你会说，java拥有这么多优秀的日志框架系统，可以简单地通过相应地配置文件将这些内容根据不同的输出级别输出到不同的目录文件，
可是如果将这件事情都交给终端用户去处理，那将会是一件极其复杂的工程，他得明白哪些是他需要的、哪些是他不需要的，而这些信息应该是对应的开发人员最清楚不过的，
因此让开发人员提前将这些日志进行归类，输出到指定的文件，那对应使用者来说将会变得很简单。

案例

pilot是公司目前的微服务应用框架，这个框架提供基础的日志管理功能，实现中间件日志对应用的无入侵，同时中间件日志和应用日志的隔离，输出到指定的目录,做到标准化

实现

首先想到的应该就是通过日志的配置文件，添加不同的appender和logger。

可是这些配置文件应该是存在与用户的应用中的，作为一个被引入的module该如何去修改这份文件呢？而且用户最终采用的是哪个日志框架我同样不能左右，我该根据哪个实现呢？

第一个问题，很好解决，现在大部分的日志框架都提供了基于java 代码的方式来添加appender和logger的配置，因此我们只需要在应用启动时，获取LoggerContext对象，然后添加自定义的appender和logger即可，

例如阿里的TDDL中就有相关的实现：

// slf4j只是一个代理工程，需要判断一下具体的实现类
if (checkLogger(logger, LOGBACK)) {
    if (canUseEncoder) {
        dynamic = new DynamicLogbackLogger();
    } else {
        dynamic = new DynamicLogback918Logger();
    }
} else if (checkLogger(logger, LOG4J_Adapter)) {
    dynamic = new DynamicLog4jAdapterLogger();
} else if (checkLogger(logger, LOG4J)) {
    dynamic = new DynamicLog4jLogger();
}  else {
    logger.warn("logger is not a log4j/logback instance, dynamic logger is disabled");
}

先判断具体地实现框架是哪个，然后再获得对应实现框架的loggerContext，例如logback：

if (loggerContext == null) {
    ILoggerFactory lcObject = LoggerFactory.getILoggerFactory();
    if (!(lcObject instanceof LoggerContext)) {
        throw new LogbackException("Expected LOGBACK binding with SLF4J, but another log system has taken the place: " + lcObject.getClass().getSimpleName());
    }
    loggerContext = (LoggerContext) lcObject;
    if (props != null) {
        for (Map.Entry<String, String> entry : props.entrySet()) {
            loggerContext.putProperty(entry.getKey(), entry.getValue());
        }
    }
}

接着再添加自身所需的appender和logger：

protected Appender buildAppender(String name, String fileName, String pattern) {
	RollingFileAppender appender = new RollingFileAppender();
	appender.setContext(loggerContext);
	appender.setName(name);
	appender.setAppend(true);
	appender.setFile(new File(getLogPath(), fileName).getAbsolutePath());

	TimeBasedRollingPolicy rolling = new TimeBasedRollingPolicy();
	rolling.setContext(loggerContext);
	rolling.setParent(appender);
	rolling.setFileNamePattern(new File(getLogPath(), fileName).getAbsolutePath() + ".%d{yyyy-MM-dd}");
	rolling.start();
	appender.setRollingPolicy(rolling);

	PatternLayoutEncoder layout = new PatternLayoutEncoder();
	layout.setContext(loggerContext);
	layout.setPattern(pattern);
	layout.setCharset(Charset.forName(getEncoding()));
	layout.start();
	appender.setEncoder(layout);
	// 启动
	appender.start();
	return appender;
}

可是这样做，存在的问题也是很明显的：

  • 需自己判断应用采用的实现框架，但可以通过抽取的方式构建一个公共jar，例如common包
  • 该实现框架需要能够支持通过动态的形式添加appender
  • 仍然与应用的Log耦合在一起

那除此之外，还有其他的方式能够实现同样的功能吗？答案当时是***有***。

默认情况下一个应用启动后，只会存在一个loggerContext，因为日志框架都是单例模式的，也是为了减少开销。那如果我们有多个loggerContext呢，是不是可以每个需要的modeule都拥有一份单独的loggerContext，那不就可以通过加载配置文件的形式更轻量级地来实现需要动态添加appender的功能呢。

大致的实现逻辑应该是这样：

  • 需要一个map来管理所有的这些loggerContext，key为唯一的，类似每个module需要一个唯一的名称，可采用packageName
  • 每个module自身需要有一份配置文件，当然由于日志实现很多你可能需要多份文件，同样你可以定义自己的格式，然后通过java code的形式去转化为最终的各个不同实现
  • 需要能通过唯一的Id，例如packageName定位到你的配置文件

这样大致的一个可以做到日志隔离的简单框架就搭建起来了，使用配置文件还有一个好处就是，一些日志框架可以动态刷新配置文件，这就使得你可以在运行时动态改变日志参数，例如日志级别。

获取一个单独的logger对象：

MiddlewareLoggerManager.getLoggerByPackageName(name, "packageName");

维护logger相关对象：

final ConcurrentHashMap<MiddlewareLogId, MiddlewareLogInfo> MIDDLEWARE_MAP =
            new ConcurrentHashMap<>(8)

@Data
public class MiddlewareLogId {

    private final Map<String, String> tags = new HashMap<>(8);

    private final String              packageName;

    public MiddlewareLogId addTag(String key, String value) {
        tags.put(key, value);
        return this;
    }
}

@NoArgsConstructor
public class MiddlewareLogInfo {
    @Getter
    @Setter
    // 根据具体实现会创建不同的loggerFactory对象，然后不同的logFactory对象会创建不同的loggerContext对象
    private AbstractLoggerMiddlewareFactory abstractLoggerMiddlewareFactory;
    @Getter
    private Properties properties = new Properties();
}

创建factory过程：

private static AbstractLoggerMiddlewareFactory createILoggerFactory(MiddlewareLogId middlewareLogId, ClassLoader middlewareClassLoader) {
	if (System.getProperty(Constants.PILOT_MIDDLEWARE_LOG_DISABLE_PROP_KEY) != null
			&& Boolean.TRUE.toString().equalsIgnoreCase(
			System.getProperty(Constants.PILOT_MIDDLEWARE_LOG_DISABLE_PROP_KEY))) {
		Constants.DEFAULT_LOGGER.warn("Pilot-Middleware-Log is disabled!  -D{}=true", Constants.PILOT_MIDDLEWARE_LOG_DISABLE_PROP_KEY);
		return JVM_LOGGER_FACTORY;
	}
	// set log props
	LogTypeJudgeUtil.processGlobalSystemLogProperties();

	// do create
	try {
		// first log4j2
		if (LogTypeJudgeUtil.isLog4j2Usable(middlewareClassLoader)) {
            ...
			return log4j2LoggerFactory;
		}

		//second logback
		if (LogTypeJudgeUtil.isLogbackUsable(middlewareClassLoader)) {
			...
            return logbackLoggerFactory;
		}

		// third log4j
		if (LogTypeJudgeUtil.isLog4jUsable(middlewareClassLoader)) {
			...
            return log4jLoggerFactory;
		}

		Constants.DEFAULT_LOGGER.warn("No log util is usable, Default app logger will be used.");
	} catch (Throwable e) {
		Constants.DEFAULT_LOGGER.error("Build ILoggerFactory error! Default app logger will be used.",
				e);
	}

	return JVM_LOGGER_FACTORY;
}

以log4j2为例，获取loggerFactory：

/**
 * confFileUrl 为根据传入的packageName以及具体的日志实现框架，拼接出路径
 * 例如 packageName 为 com.company.xxx.xxx
 * 则 log4j2的文件路径为：classpath*:com/company/xxx/xxx/log/log4j2/log-conf.xml
 */
protected AbstractLoggerMiddlewareFactory doBuild(final String packageName, final ClassLoader middlewareClassLoader, final URL confFileUrl) {
	try {
        //构建单独的loggerContext对象
		final LoggerContext context = new LoggerContext(packageName, null, confFileUrl.toURI());
		Configuration config = null;
		ConfigurationFactory configurationFactory = ConfigurationFactory.getInstance();
		try {
			Class[] parameterTypes = new Class[3];
			parameterTypes[0] = String.class;
			parameterTypes[1] = URI.class;
			parameterTypes[2] = ClassLoader.class;
			Method getConfigurationMethod = configurationFactory.getClass().getMethod(
					"getConfiguration", parameterTypes);
			config = (Configuration) getConfigurationMethod.invoke(configurationFactory,
					packageName, confFileUrl.toURI(), middlewareClassLoader);
		} catch (NoSuchMethodException noSuchMethodException) {
			Class[] parameterTypes = new Class[4];
			parameterTypes[0] = LoggerContext.class;
			parameterTypes[1] = String.class;
			parameterTypes[2] = URI.class;
			parameterTypes[3] = ClassLoader.class;
			Method getConfigurationMethod = configurationFactory.getClass().getMethod(
					"getConfiguration", parameterTypes);
			config = (Configuration) getConfigurationMethod.invoke(configurationFactory,
					context, packageName, confFileUrl.toURI(), middlewareClassLoader);
		}
		if (config == null) {
			throw new RuntimeException("No log4j2 configuration are found.");
		}
		for (Map.Entry entry : getProperties().entrySet()) {
			//from Map<String,String>
			config.getProperties().put((String) entry.getKey(), (String) entry.getValue());
		}

		for (Map.Entry entry : System.getProperties().entrySet()) {
			//from Map<String,String>
			config.getProperties().put((String) entry.getKey(), (String) entry.getValue());
		}

		context.start(config);

		return new AbstractLoggerMiddlewareFactory(getLoggingType()) {

			private ConcurrentMap<String, org.apache.logging.slf4j.Log4jLogger> loggerMap =
					new ConcurrentHashMap<>();

			@Override
			public Logger setLevel(String loggerName, MiddlewareLogLevel logLevel) {
				org.apache.logging.slf4j.Log4jLogger log4jLoggerAdapter = (org.apache.logging.slf4j.Log4jLogger) this
						.getLogger(loggerName);
				final String key = Logger.ROOT_LOGGER_NAME.equals(loggerName) ? LogManager.ROOT_LOGGER_NAME
						: loggerName;
				org.apache.logging.log4j.core.Logger log4j2Logger = context.getLogger(key);
				//level
				org.apache.logging.log4j.Level log4j2Level = this.toLog4j2Level(logLevel);
				log4j2Logger.setLevel(log4j2Level);
				return log4jLoggerAdapter;
			}

			@Override
            //使用门面框架 slf4j 返回logger对象
			public org.slf4j.Logger getLogger(String name) {
				final String key = Logger.ROOT_LOGGER_NAME.equals(name) ? LogManager.ROOT_LOGGER_NAME
						: name;
				org.apache.logging.log4j.core.Logger log4jLogger = context.getLogger(key);
				Log4jLogger oldInst = this.loggerMap.get(key);
				if (oldInst != null) {
					return oldInst;
				}
				Log4jLogger newInst = new Log4jLogger(log4jLogger, key);
				oldInst = this.loggerMap.putIfAbsent(key, newInst);
				return oldInst == null ? newInst : oldInst;
			}

			private org.apache.logging.log4j.Level toLog4j2Level(MiddlewareLogLevel logLevel) {
				if (logLevel == null) {
					throw new IllegalStateException(
							"MiddlewareLogLevel is NULL when adapter to log4j2.");
				}
				switch (logLevel) {
				case TRACE:
					return Level.TRACE;
				case DEBUG:
					return Level.DEBUG;
				case INFO:
					return Level.INFO;
				case WARN:
					return Level.WARN;
				case ERROR:
					return Level.ERROR;
				default:
					throw new IllegalStateException(logLevel
							+ " is unknown when adapter to log4j2.");
				}
			}
		};
	} catch (Throwable e) {
		throw new IllegalStateException("Log4j2 loggerMiddlewareFactory build error!", e);
	}
}

当然这个方案也有其缺陷，loggerContext对象增加了对应的内存消耗也就增加了。简单统计了下，每增加一个采用日志隔离框架的模块，内存使用增加5~10kb，一定程度可忽略不计。

总结

整体而言，这个方案还是利远大于弊的，极大的提升了类似于中间件等组件在应用中的排查效率，而对于业务组也是一样，日志中也不会混入大量的于业务无关的日志内容，对双方来说都能提高不少效率。

关注我们

酷家乐质量效能团队热衷于技术的成长和分享，几乎每个月都会举办技术分享活动（海星日），每半年举办一次技术专题竞赛分享（火星日），并将优秀内容写成技术文章。

我们尽可能保障分享到社区的内容，是我们用心编写、精心挑选的优质文章。如果您想更全面地阅读我们的文章，请您关注我们的微信公众号"酷家乐技术质量"。