Tomcat 下多个 war 包部署引发 log 4j 组件异常分析

背景

一个简单的列表查询应用，使用了 Log4jConfigListener 监听器，但是客户现场是一个 Tomcat 下同时部署多个应用的方式使用该 war 包的，虽然本地部署都没问题，但是现场却一直启动失败，Catalina.log 日志中只有一行报错信息：

org.apache.catalina.core.StandardContext.startInternal One or more listeners failed to start. Full details will be found in the appropriate container log file

看不到任何异常堆栈日志。

排查过程

最麻烦的是看不到异常堆栈日志，而应用日志显示应用刚启动又停止了，所以第一步就是打印出异常日志。

Tomcat 使用的是 logging 日志框架，所以需要提供 logging.properties 文件。所以先准备一个日志配置文件放入应用的类路径下，内容如下：

handlers = org.apache.juli.FileHandler, java.util.logging.ConsoleHandler
############################################################
Handler specific properties.
Describes specific configuration info for Handlers.
############################################################
org.apache.juli.FileHandler.level = FINE
org.apache.juli.FileHandler.directory = …/logs
org.apache.juli.FileHandler.prefix = error-debug.
java.util.logging.ConsoleHandler.level = FINE
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter

症结

添加日志配置后，重启 Tomcat 此时 catalian.log 日志中出现了异常信息：

SEVERE: Exception sending context initialized event to listener instance of class [org.springframework.web.util.Log4jConfigListener]
java.lang.IllegalStateException: Web app root system property already set to different value: 'webapp.root' = [/opt/apache-tomcat-8.5.20/webapps/xxx/] instead of [/opt/apache-tomcat-8.5.20/webapps/xxx/] - Choose unique values for the 'webAppRootKey' context-param in your web.xml files!
        at org.springframework.web.util.WebUtils.setWebAppRootSystemProperty(WebUtils.java:162)
        at org.springframework.web.util.Log4jWebConfigurer.initLogging(Log4jWebConfigurer.java:119)
        at org.springframework.web.util.Log4jConfigListener.contextInitialized(Log4jConfigListener.java:49)
        at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4745)
        at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5207)
        at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
        at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:752)
        at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:728)
        at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
        at org.apache.catalina.startup.HostConfig.deployWAR(HostConfig.java:988)
        at org.apache.catalina.startup.HostConfig$DeployWar.run(HostConfig.java:1860)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

根源是 Log4jConfigListener 配置监听器启动异常导致应用启动失败，而这个异常根源是两个 war 包应用中都没有配置 webAppRootKey 参数。

解决办法

单独为在每个项目 web.xml 中配置各自的该参数：

<context-param>
		<param-name>webAppRootKey</param-name>
		<param-value>xxx.root</param-value>
	</context-param>

延伸思考

延伸思考一 ：这个 webAppRootKey 配置的作用是什么呢，为什么多项目部署时都不配会导致 Log4jConfigListener 监听器启动失败呢？

webAppRootKey 是指项目部署的路径的 key ，Spring 提供了默认值为 webapp.root ，作为系统环境变量，运行过程中通过 System.getProperty("webapp.root") 来动态获项目的运行路径，该路径为项目部署根路径。

跟踪了一下 Log4jConfigListener 源码，找到了根源。

它的 initLogging 方法需要使用项目部署根目录以便确定 log4j 配置文件的绝对路径，由于是一个 Tomcat 启动后是作为一个 JVM 实例运行的，所有的系统参数都是共享的，如果不同的项目都使用了 Log4jConfigListener 它们会找各自应用的配置文件，并且限制了系统变量获取到的根目录不能相同。

initLogging 方法：

setWebAppRootSystemProperty 方法：

这里一旦报错，就会抛出异常，导致该 Linstener 启动失败，进而该应用启动失败。

延伸思考二：Tomcat 的日志配置文件的作用，为什么明明有异常，而且是 Serve 最高级别的，为什么没有显示在容器的启动日志中呢？

跟了下 Tomcat 的源码看到部分 logging 的过程，以前编译过 Tomcat 源码，本地有源码跟踪环境。

首先，在 Eclipse 中全局搜索异常信息 “Exception sending context initialized event to listener instance of class” ，发现他是在一个本地化配置文件 LocalStrings.properties 中定义的，内容为：

standardContext.listenerStart=Exception sending context initialized event to listener instance of class {0}

这里只是配置日志格式，占位符处是输出具体 Linstener 名称的，继续找引用该配置的地方，全局搜索 “ standardContext.listenerStart ” 找到调用者：

继续看它是怎么用的，日志打印方法：

这里的水还是不浅的，最终找到 getLogger 是一个 org.apache.juli.logging.Log 接口，只有一个实现类 DirectJDKLog ，它承担了 Tomcat 的日志工作。

这里有一个疑问：Tomcat 配置 conf 目录下的 logging.properties 和 某一应用类路径下同时都具有 logging.properties ，那么 Tomcat 是以哪个为主的？Tomcat 的 conf 中的日志配置级别应该是能输出异常的为什么没有呢？

没搜到结果，改天研究下。