整透 tomcat logging
2019-07-18 本文已影响99人
zh_harry
该篇文章源于一年前的一个问题,线上报出来的错误如下文所示
21-Jul-2017 10:15:51.521 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service Catalina
21-Jul-2017 10:15:51.521 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.0.30
21-Jul-2017 10:15:51.544 INFO [search.17usoft.com-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive /usr/local/tomcat/webapps/app_name.war
21-Jul-2017 10:17:07.417 INFO [search.17usoft.com-startStop-1] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive /usr/local/tomcat/webapps/app_name.war has finished in 75,870 ms
21-Jul-2017 10:17:07.420 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-apr-7573"]
21-Jul-2017 10:17:07.431 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 75932 ms
21-Jul-2017 13:19:53.368 INFO [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.startup.HostConfig.undeploy Undeploying context [/app_namec]
21-Jul-2017 13:19:58.405 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [app_name] registered the JDBC driver [com.alibaba.druid.proxy.DruidDriver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
21-Jul-2017 13:19:58.405 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesJdbc The web application [app_name] registered the JDBC driver [com.mysql.jdbc.Driver] but failed to unregister it when the web application was stopped. To prevent a memory leak, the JDBC Driver has been forcibly unregistered.
21-Jul-2017 13:19:58.424 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesThreads The web application [app_name] appears to have started a thread named [logback-1] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
Jul 25 16:36:17 xdl-44-58 dockerd: time="2017-07-25T16:36:17.659425231+08:00" level=warning msg="Not using native diff for ov
解决方案
http://grails.1312388.n4.nabble.com/Deployment-problems-td4628710.html。
在应用的WEB-INF下加如下日志，即可在该文件中打出详细日志
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 = ${catalina.base}/logs
org.apache.juli.FileHandler.prefix = error-debug.
java.util.logging.ConsoleHandler.level = FINE
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
当时为了解决问题，而没有深究为什么？
这篇文章主要从tomcat logging原理出发，研究为什么在 catalina.out 中未出现该日志。
我们都知道tomcat 的webapp是通过classloader 来实现每个应用之间的隔离，所以它内部的日志是重写了public class ClassLoaderLogManager extends LogManager
The internal logging for Apache Tomcat uses JULI, a packaged renamed fork of [Apache Commons Logging](https://commons.apache.org/logging) that is hard-coded to use the `java.util.logging` framework. This ensures that Tomcat's internal logging and any web application logging will remain independent, even if a web application uses Apache Commons Logging.
To configure Tomcat to use an alternative logging framework for its internal logging, follow the instructions provided by the alternative logging framework for redirecting logging for applications that use `java.util.logging`. Keep in mind that the alternative logging framework will need to be capable of working in an environment where different loggers with the same name may exist in different class loaders.
注意，在tomcat 启动时需要用-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager来 指定日志的实现，否则日志记录还会使用jdk自带的LogManager.
tomcat startup.sh启动脚本已经帮我们实现了该功能，但如果我们用jsvc或ide来启动时，需要注意
Apache Tomcat has its own implementation of several key elements of java.util.logging API. This implementation is called JULI. The key component there is a custom LogManager implementation, that is aware of different web applications running on Tomcat (and their different class loaders). It supports private per-application logging configurations. It is also notified by Tomcat when a web application is unloaded from memory, so that the references to its classes can be cleared, preventing memory leaks.
This java.util.logging implementation is enabled by providing certain system properties when starting Java. The Apache Tomcat startup scripts do this for you, but if you are using different tools to run Tomcat (such as jsvc, or running Tomcat from within an IDE), you should take care of them by yourself.
关于配置文件
Globally. That is usually done in the ${catalina.base}/conf/logging.properties file. The file is specified by the java.util.logging.config.file System property which is set by the startup scripts. If it is not readable or is not configured, the default is to use the ${java.home}/lib/logging.properties file in the JRE.
In the web application. The file will be WEB-INF/classes/logging.properties
通过上文描述日志通过classloader来区别对待应用日志，补充一下tomcat classloader结构
https://tomcat.apache.org/tomcat-8.5-doc/class-loader-howto.html
通过代码测试我们发现，实际结构如下
classoader.png
由于ExtClassloader的parent为bootstrap 为c语言实现，故这里打印为null,实际上应该是bootstrap的parent为null。
/**
* Map containing the classloader information, keyed per classloader. A
* weak hashmap is used to ensure no classloader reference is leaked from
* application redeployment.
*/
protected final Map<ClassLoader, ClassLoaderLogInfo> classLoaderLoggers =
new WeakHashMap<>(); // Guarded by this
对应结构存储于该对象中，key为classloader 对象
Value对应以下结构
protected static final class ClassLoaderLogInfo {
/**
* root node of loggerName tree
*这里通过tree和map两个结构来实现handler的映射关系，笔者认为是为提高检索性能，以空间换时间 。
*/
final LogNode rootNode;
final Map<String, Logger> loggers = new ConcurrentHashMap<>();
final Map<String, Handler> handlers = new HashMap<>();
final Properties props = new Properties();
ClassLoaderLogInfo(final LogNode rootNode) {
this.rootNode = rootNode;
}
}
该方法是通过classloader来读取配置文件从而实例化ClassLoaderLogInfo的过程。
可见tomcat 区别对待每一个classloader实例.首先如果是webappclassloader 则先读应用下的logging.properties配置文件，如果没有读到,则用parent classloader对就的ClassloaderLogInfo对象
if (is == null) {
// Retrieve the root logger of the parent classloader instead
ClassLoader current = classLoader.getParent();
ClassLoaderLogInfo info = null;
while (current != null && info == null) {
info = getClassLoaderInfo(current);
current = current.getParent();
}
if (info != null) {
localRootLogger.setParent(info.rootNode.logger);
}
}
/**
* Read configuration for the specified classloader.
*
* @param classLoader The classloader
* @throws IOException Error reading configuration
*/
protected synchronized void readConfiguration(ClassLoader classLoader)
throws IOException {
//@harry read configuration
InputStream is = null;
// Special case for URL classloaders which are used in containers:
// only look in the local repositories to avoid redefining loggers 20 times
try {
System.err.println(classLoader.getClass().getName());
if (classLoader instanceof WebappProperties) {
if (((WebappProperties) classLoader).hasLoggingConfig()) {
is = classLoader.getResourceAsStream("logging.properties");
}
} else if (classLoader instanceof URLClassLoader) {
//tomcat 的/config/logging.properties配置文件
URL logConfig = ((URLClassLoader)classLoader).findResource("logging.properties");
if(null != logConfig) {
if(Boolean.getBoolean(DEBUG_PROPERTY))
System.err.println(getClass().getName()
+ ".readConfiguration(): "
+ "Found logging.properties at "
+ logConfig);
is = classLoader.getResourceAsStream("logging.properties");
} else {
if(Boolean.getBoolean(DEBUG_PROPERTY))
System.err.println(getClass().getName()
+ ".readConfiguration(): "
+ "Found no logging.properties");
}
}
} catch (AccessControlException ace) {
// No permission to configure logging in context
// Log and carry on
ClassLoaderLogInfo info = classLoaderLoggers.get(ClassLoader.getSystemClassLoader());
if (info != null) {
Logger log = info.loggers.get("");
if (log != null) {
Permission perm = ace.getPermission();
if (perm instanceof FilePermission && perm.getActions().equals("read")) {
log.warning("Reading " + perm.getName() + " is not permitted. See \"per context logging\" in the default catalina.policy file.");
}
else {
log.warning("Reading logging.properties is not permitted in some context. See \"per context logging\" in the default catalina.policy file.");
log.warning("Original error was: " + ace.getMessage());
}
}
}
}
if ((is == null) && (classLoader == ClassLoader.getSystemClassLoader())) {
//如果tomcat_home/config/logging.properties没有找到，则使用java.util.logging.config.file 对应的配置文件 默认在jdk中
String configFileStr = System.getProperty("java.util.logging.config.file");
if (configFileStr != null) {
try {
is = new FileInputStream(replace(configFileStr));
} catch (IOException e) {
System.err.println("Configuration error");
e.printStackTrace();
}
}
// Try the default JVM configuration
if (is == null) {
File defaultFile = new File(new File(System.getProperty("java.home"),
isJava9 ? "conf" : "lib"),
"logging.properties");
try {
is = new FileInputStream(defaultFile);
} catch (IOException e) {
System.err.println("Configuration error");
e.printStackTrace();
}
}
}
Logger localRootLogger = new RootLogger();
if (is == null) {
//如果是webappclassloader 未找到，则使用parent 的classloader的classloader info对象
// Retrieve the root logger of the parent classloader instead
ClassLoader current = classLoader.getParent();
ClassLoaderLogInfo info = null;
while (current != null && info == null) {
info = getClassLoaderInfo(current);
current = current.getParent();
}
if (info != null) {
localRootLogger.setParent(info.rootNode.logger);
}
}
//@harry init class loader info
//add root log node
ClassLoaderLogInfo info =
new ClassLoaderLogInfo(new LogNode(null, localRootLogger));
//@harry classloader loggers is global variable
// info is root logger info
classLoaderLoggers.put(classLoader, info);
if (is != null) {
//@harry init handler instance for classloader
readConfiguration(is, classLoader);
}
try {
// Use a ThreadLocal to work around
// https://bugs.openjdk.java.net/browse/JDK-8195096
addingLocalRootLogger.set(Boolean.TRUE);
//@harry add root logger
addLogger(localRootLogger);
} finally {
addingLocalRootLogger.set(Boolean.FALSE);
}
}
由此可见，文中开篇的问题并不是tomcat 打不出详细日志，而是可能因为配置文件配置问题打到了其他日志里。
我们具体看tomcat 官方的配置文件
第一行表示当前tomcat 可以使用的所有handler对象实例
handlers = 1catalina.org.apache.juli.FileHandler, \
2localhost.org.apache.juli.FileHandler, \
3manager.org.apache.juli.FileHandler, \
java.util.logging.ConsoleHandler
第二行表示默认的 root logger 对应的appender 如果不设置为全部，代码见下文注释
.handlers = 1catalina.org.apache.juli.FileHandler, java.util.logging.ConsoleHandler
############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
表示每个hander对应的日志打印策略，级别format 及对应的日志文件路径等
############################################################
1catalina.org.apache.juli.FileHandler.level = FINE
1catalina.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
1catalina.org.apache.juli.FileHandler.prefix = catalina.
1catalina.org.apache.juli.FileHandler.maxDays = 90
1catalina.org.apache.juli.FileHandler.encoding = UTF-8
2localhost.org.apache.juli.FileHandler.level = FINE
2localhost.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
2localhost.org.apache.juli.FileHandler.prefix = localhost.
2localhost.org.apache.juli.FileHandler.maxDays = 90
2localhost.org.apache.juli.FileHandler.encoding = UTF-8
3manager.org.apache.juli.FileHandler.level = FINE
3manager.org.apache.juli.FileHandler.directory = ${catalina.base}/logs
3manager.org.apache.juli.FileHandler.prefix = manager.
3manager.org.apache.juli.FileHandler.bufferSize = 16384
3manager.org.apache.juli.FileHandler.maxDays = 90
3manager.org.apache.juli.FileHandler.encoding = UTF-8
java.util.logging.ConsoleHandler.level = FINE
java.util.logging.ConsoleHandler.formatter = java.util.logging.OneLineFormatter
java.util.logging.ConsoleHandler.encoding = UTF-8
############################################################
# Facility specific properties.
# Provides extra control for each logger.
下边默认配置每个 logger对应的handlers
这里的前缀对应 log = LogFactory.getLog(Bootstrap.class);传过来的类名， tomcat 会对类名进一步转换 见下文代码片断
############################################################
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].handlers = \
2localhost.org.apache.juli.FileHandler
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].handlers = \
3manager.org.apache.juli.FileHandler
logging name代码片断
/**
* @return the abbreviated name of this container for logging messages
*/
@Override
public String getLogName() {
if (logName != null) {
return logName;
}
String loggerName = null;
Container current = this;
while (current != null) {
String name = current.getName();
if ((name == null) || (name.equals(""))) {
name = "/";
} else if (name.startsWith("##")) {
name = "/" + name;
}
loggerName = "[" + name + "]"
+ ((loggerName != null) ? ("." + loggerName) : "");
current = current.getParent();
}
logName = ContainerBase.class.getName() + "." + loggerName;
return logName;
}
不设置默认handler取全部代码片断
try {
this.prefix.set(prefix);
Handler handler = (Handler) classLoader.loadClass(
handlerClassName).getConstructor().newInstance();
// The specification strongly implies all configuration should be done
// during the creation of the handler object.
// This includes setting level, filter, formatter and encoding.
this.prefix.set(null);
info.handlers.put(handlerName, handler);
//root为空，则遍历过程中的所有hander都加入到rootLogger中
if (rootHandlers == null) {
localRootLogger.addHandler(handler);
}
} catch (Exception e) {
// Report error
System.err.println("Handler error");
e.printStackTrace();
}
根据class full name构造logger tree
递归调用
Logger.getLogger(className)-->demandLogger-->addLogger(newLogger)-->Logger.getLogger(className)
直到root .为止.
/**
* Add the specified logger to the classloader local configuration.
*
* @param logger The logger to be added
* @see java.util.logging.Logger getLogger recursion
*/
@Override
public synchronized boolean addLogger(final Logger logger) {
final String loggerName = logger.getName();
ClassLoader classLoader =
Thread.currentThread().getContextClassLoader();
ClassLoaderLogInfo info = getClassLoaderInfo(classLoader);
if (info.loggers.containsKey(loggerName)) {
return false;
}
info.loggers.put(loggerName, logger);
// Apply initial level for new logger
final String levelString = getProperty(loggerName + ".level");
if (levelString != null) {
try {
AccessController.doPrivileged(new PrivilegedAction<Void>() {
@Override
public Void run() {
logger.setLevel(Level.parse(levelString.trim()));
return null;
}
});
} catch (IllegalArgumentException e) {
// Leave level set to null
}
}
// Always instantiate parent loggers so that
// we can control log categories even during runtime
int dotIndex = loggerName.lastIndexOf('.');
if (dotIndex >= 0) {
final String parentName = loggerName.substring(0, dotIndex);
//@harry get parent log name recursion
//org.apache.catalina.startup
//org.apache.catalina
//org.apache
//org
Logger.getLogger(parentName);
}
//org
//org.apache
//org.apache.catalina
//org.apache.catalina.startup
// Find associated node
LogNode node = info.rootNode.findNode(loggerName);
node.logger = logger;
// Set parent logger
Logger parentLogger = node.findParentLogger();
if (parentLogger != null) {
doSetParentLogger(logger, parentLogger);
}
// Tell children we are their new parent
node.setParentLogger(logger);
// Add associated handlers, if any are defined using the .handlers property.
// In this case, handlers of the parent logger(s) will not be used
//@harry read .handler config
String handlers = getProperty(loggerName + ".handlers");
if (handlers != null) {
//@harry without use parent if exist handler
logger.setUseParentHandlers(false);
StringTokenizer tok = new StringTokenizer(handlers, ",");
while (tok.hasMoreTokens()) {
String handlerName = (tok.nextToken().trim());
Handler handler = null;
ClassLoader current = classLoader;
while (current != null) {
info = classLoaderLoggers.get(current);
if (info != null) {
//@harry read from handlers config
handler = info.handlers.get(handlerName);
if (handler != null) {
break;
}
}
current = current.getParent();
}
if (handler != null) {
logger.addHandler(handler);
}
}
}
// Parse useParentHandlers to set if the logger should delegate to its parent.
// Unlike java.util.logging, the default is to not delegate if a list of handlers
// has been specified for the logger.
String useParentHandlersString = getProperty(loggerName + ".useParentHandlers");
if (Boolean.parseBoolean(useParentHandlersString)) {
logger.setUseParentHandlers(true);
}
return true;
}
综上可见，tomcat 日志如果配置正确不需要webapp/WEB-INF/logging.properties也可以打印全部日志。
有可能因为 tomcat server.xml配置问题或者logging.properties的配置问题导致日志文件没有打到catalina.out而已。
由于篇幅原因，具体代码细节不再赘述，如果有遇到该类问题，欢迎回复。
