深入剖析Tomcat(七) 日志记录器

在看原书第六章之前，一直觉得Tomcat记日志的架构可能是个“有点东西”的东西。在看了第六章之后呢，额… 就这？不甘心的我又翻了翻logback与新版tomcat的源码，额…，日志架构原来也没那么神秘。本篇文章先过一遍原书内容，然后再说一下我看了其他日志框架后的见解。

《深入剖析Tomcat》这本书中的代码是基于Tomcat4的，它的日志架构非常简单，对日志记录器只定义了一个接口 org.apache.catalina.Logger ,只要实现了这个接口的类都可以作为日志记录器，Tomcat4内部提供了三种实现 SystemOutLogger、SystemErrLogger、FileLogger 他们都在 org.apache.catalina.logger 包下。基于日志记录器的共性，Tomcat4提供了LoggerBase这个抽象类，上面三种日志记录器都继承了LoggerBase类。

日志记录器的UML图

Logger接口

Logger接口定义了五种日志级别：FATAL、ERROR、WARNING、INFORMATION、DEBUG，并提供了getVerbosity()与setVerbosity()来获取与修改日志级别。

Logger接口定义了好几种log方法来记录日志，其中后两个方法允许传参日志级别，只有当前日志记录器的日志级别数字大于等于传参的话，才会记录日志。

LoggerBase类

这个抽象类编写了日志记录器的一些公共代码。它实现了Logger接口，并将其中大多数方法都实现了，仅仅保留了 void log(String message); 方法作为抽象方法，其他重载的log方法最终都会调用此方法，具体对日志怎么处理就看子类如何实现此方法了。

public abstract class LoggerBase implements Logger {//关联的容器protected Container container = null;protected int debug = 0;// 该日志记录器的描述protected static final String info = "org.apache.catalina.logger.LoggerBase/1.0";// 属性值变化监听 辅助类，用于监听属性值的变化，并通知与此组件绑定的监听器protected PropertyChangeSupport support = new PropertyChangeSupport(this);// 日记级别protected int verbosity = ERROR;// =================== getter  setter 方法 ==================public Container getContainer() {return (container);}public void setContainer(Container container) {Container oldContainer = this.container;this.container = container;// 属性值发生了变化，通知监听器support.firePropertyChange("container", oldContainer, this.container);}public int getDebug() {return (this.debug);}public void setDebug(int debug) {this.debug = debug;}public String getInfo() {return (info);}public int getVerbosity() {return (this.verbosity);}public void setVerbosity(int verbosity) {this.verbosity = verbosity;}public void setVerbosityLevel(String verbosity) {if ("FATAL".equalsIgnoreCase(verbosity)) this.verbosity = FATAL;else if ("ERROR".equalsIgnoreCase(verbosity)) this.verbosity = ERROR;else if ("WARNING".equalsIgnoreCase(verbosity)) this.verbosity = WARNING;else if ("INFORMATION".equalsIgnoreCase(verbosity)) this.verbosity = INFORMATION;else if ("DEBUG".equalsIgnoreCase(verbosity)) this.verbosity = DEBUG;}// ================== Public Methods ====================// 为此组件添加一个属性监听器public void addPropertyChangeListener(PropertyChangeListener listener) {support.addPropertyChangeListener(listener);}// 记录日志public abstract void log(String msg);public void log(Exception exception, String msg) {log(msg, exception);}public void log(String msg, Throwable throwable) {CharArrayWriter buf = new CharArrayWriter();PrintWriter writer = new PrintWriter(buf);writer.println(msg);throwable.printStackTrace(writer);Throwable rootCause = null;if (throwable instanceof LifecycleException) rootCause = ((LifecycleException) throwable).getThrowable();else if (throwable instanceof ServletException) rootCause = ((ServletException) throwable).getRootCause();if (rootCause != null) {writer.println("----- Root Cause -----");rootCause.printStackTrace(writer);}log(buf.toString());}// 只有当该组件的日志级别数字大于参数的话，才记日志。也就是说过滤掉低级别的日志public void log(String message, int verbosity) {if (this.verbosity >= verbosity) {log(message);} }public void log(String message, Throwable throwable, int verbosity) {if (this.verbosity >= verbosity) {log(message, throwable);}}// 移除一个属性监听器public void removePropertyChangeListener(PropertyChangeListener listener) {support.removePropertyChangeListener(listener);}}

接下来的几个日志记录器的类就是对log方法的具体实现了，有的是将日志直接打印到控制台上，有的是写入到文件中。

SystemOutLogger类

这个类的实现就是调用 System.out.println 方法，将日志打印到控制台上。

package org.apache.catalina.logger;public class SystemOutLogger extends LoggerBase {// 该日志记录器的描述protected static final String info = "org.apache.catalina.logger.SystemOutLogger/1.0";public void log(String msg) {System.out.println(msg);}}

SystemErrLogger类

这个类的实现就是调用 System.err.println 方法，将日志打印到控制台上。看清了这个是 err 不是 out 了。

package org.apache.catalina.logger;public class SystemErrLogger extends LoggerBase {// 该日志记录器的描述protected static final String info = "org.apache.catalina.logger.SystemErrLogger/1.0";public void log(String msg) {System.err.println(msg);}}

FileLogger类

这个类是将日志记录到文件中，相比于前两个类来说，要复杂一点。本类实现了Lifecycle接口，但是相关方法的实现并没有什么内容，所以下面的代码展示省略了这些方法。

该类定义了日志文件的所在文件夹、文件名前后缀，并可以设置是否记录日志时间等。日志文件按照日期来区分，当日期发生改变时，会改变 date 及 writer 的属性值，将其切换到新的日志文件上。

public class FileLogger extends LoggerBase implements Lifecycle {// 当前正打开的日志文件对应的日期字符串，如果没有打开的日志文件则为空字符串private String date = "";// 日志文件的所在文件夹private String directory = "logs";// 该日志记录器的描述protected static final String info = "org.apache.catalina.logger.FileLogger/1.0";// 生命周期事件 辅助类protected LifecycleSupport lifecycle = new LifecycleSupport(this);// 日志文件的文件名前缀private String prefix = "catalina.";private StringManager sm = StringManager.getManager(Constants.Package);// 组件是否启动了private boolean started = false;// 日志文件的文件名后缀private String suffix = ".log";// 记录的消息中是否应该有日期/时间戳?private boolean timestamp = false;// 当前正在记日志的PrintWriter，切换日志文件时 该对象也会切换private PrintWriter writer = null;// ------------- getter setter 方法省略 ---------// -------------   生命周期相关方法省略   --------/*** 将日志消息写入文件*/public void log(String msg) {// 构建时间戳对象Timestamp ts = new Timestamp(System.currentTimeMillis());String tsString = ts.toString().substring(0, 19);String tsDate = tsString.substring(0, 10);// 如果date发生了变化,则切换日志文件if (!date.equals(tsDate)) {synchronized (this) {if (!date.equals(tsDate)) {// 关闭当前日志文件close();date = tsDate;// 打开新的日志文件open();}}}// 记录日志, 如果需要的话，将时间也加入日志中if (writer != null) {if (timestamp) {writer.println(tsString + " " + msg);} else {writer.println(msg);}}}/*** 关闭当前正打开的文件*/private void close() {if (writer == null) return;writer.flush();writer.close();writer = null;date = "";}/*** 根据date属性，打开新的日志文件*/private void open() {// 如果需要的，先创建logs文件夹File dir = new File(directory);if (!dir.isAbsolute()) {dir = new File(System.getProperty("catalina.base"), directory);}dir.mkdirs();// 打开当前需要写入日志的文件try {String pathname = dir.getAbsolutePath() + File.separator + prefix + date + suffix;writer = new PrintWriter(new FileWriter(pathname, true), true);} catch (IOException e) {writer = null;}}}

SImpleContext类

本章的应用程序代码沿用第六章的代码，为了使用一下日志框架，仅将SimpleContext类做了点改造，嵌入了日志记录器，并在start与stop方法中打印了日志。

下面是该类的部分代码

public class SimpleContext implements Context, Pipeline, Lifecycle {public SimpleContext() {pipeline.setBasic(new SimpleContextValve());}protected HashMap children = new HashMap();private Loader loader = null;private Logger logger = null;protected LifecycleSupport lifecycle = new LifecycleSupport(this);private SimplePipeline pipeline = new SimplePipeline(this);private HashMap servletMappings = new HashMap();protected Mapper mapper = null;protected HashMap mappers = new HashMap();private Container parent = null;protected boolean started = false;public Logger getLogger() {return logger;}public void setLogger(Logger logger) {this.logger = logger;}public synchronized void start() throws LifecycleException {log("starting Context");if (started)throw new LifecycleException("SimpleContext has already started");// Notify our interested LifecycleListenerslifecycle.fireLifecycleEvent(BEFORE_START_EVENT, null);started = true;try {// Start our subordinate components, if anyif ((loader != null) && (loader instanceof Lifecycle))((Lifecycle) loader).start();// Start our child containers, if anyContainer children[] = findChildren();for (int i = 0; i < children.length; i++) {if (children[i] instanceof Lifecycle)((Lifecycle) children[i]).start();}// Start the Valves in our pipeline (including the basic),// if anyif (pipeline instanceof Lifecycle)((Lifecycle) pipeline).start();// Notify our interested LifecycleListenerslifecycle.fireLifecycleEvent(START_EVENT, null);}catch (Exception e) {e.printStackTrace();}// Notify our interested LifecycleListenerslifecycle.fireLifecycleEvent(AFTER_START_EVENT, null);log("Context started");}public void stop() throws LifecycleException {log("stopping Context");if (!started)throw new LifecycleException("SimpleContext has not been started");// Notify our interested LifecycleListenerslifecycle.fireLifecycleEvent(BEFORE_STOP_EVENT, null);lifecycle.fireLifecycleEvent(STOP_EVENT, null);started = false;try {// Stop the Valves in our pipeline (including the basic), if anyif (pipeline instanceof Lifecycle) {((Lifecycle) pipeline).stop();}// Stop our child containers, if anyContainer children[] = findChildren();for (int i = 0; i < children.length; i++) {if (children[i] instanceof Lifecycle)((Lifecycle) children[i]).stop();}if ((loader != null) && (loader instanceof Lifecycle)) {((Lifecycle) loader).stop();}}catch (Exception e) {e.printStackTrace();}// Notify our interested LifecycleListenerslifecycle.fireLifecycleEvent(AFTER_STOP_EVENT, null);log("Context stopped");}private void log(String message) {Logger logger = this.getLogger();if (logger!=null)logger.log(message);}
}

Bootstrap类

启动类的话，相比于上一章的类，就是多创建了一个日志记录器（Logger）并将其绑定到context容器上。

public final class Bootstrap {public static void main(String[] args) {Connector connector = new HttpConnector();Wrapper wrapper1 = new SimpleWrapper();wrapper1.setName("Primitive");wrapper1.setServletClass("PrimitiveServlet");Wrapper wrapper2 = new SimpleWrapper();wrapper2.setName("Modern");wrapper2.setServletClass("ModernServlet");Loader loader = new SimpleLoader();Context context = new SimpleContext();context.addChild(wrapper1);context.addChild(wrapper2);Mapper mapper = new SimpleContextMapper();mapper.setProtocol("http");LifecycleListener listener = new SimpleContextLifecycleListener();((Lifecycle) context).addLifecycleListener(listener);context.addMapper(mapper);context.setLoader(loader);// context.addServletMapping(pattern, name);context.addServletMapping("/Primitive", "Primitive");context.addServletMapping("/Modern", "Modern");// ------ add logger --------System.setProperty("catalina.base", System.getProperty("user.dir"));FileLogger logger = new FileLogger();logger.setPrefix("FileLog_");logger.setSuffix(".txt");logger.setTimestamp(true);logger.setDirectory("webroot");context.setLogger(logger);//---------------------------connector.setContainer(context);try {connector.initialize();((Lifecycle) connector).start();((Lifecycle) context).start();// make the application wait until we press a key.System.in.read();((Lifecycle) context).stop();}catch (Exception e) {e.printStackTrace();}}
}

将Bootstrap启动，并向控制台输入内容使其关闭。

控制台日志

SimpleContextLifecycleListener's event before_start
Starting SimpleLoader
Starting Wrapper Primitive
Starting Wrapper Modern
SimpleContextLifecycleListener's event start
Starting context.
SimpleContextLifecycleListener's event after_start关闭应用
SimpleContextLifecycleListener's event before_stop
SimpleContextLifecycleListener's event stop
Starting context.
Stopping wrapper Primitive
Stopping wrapper Modern
SimpleContextLifecycleListener's event after_stopProcess finished with exit code 0

在webroot目录下多了一个日志文件

文件内容为

2024-05-07 17:03:26 HttpConnector Opening server socket on all host IP addresses
2024-05-07 17:03:26 HttpConnector[8080] Starting background thread
2024-05-07 17:03:26 HttpProcessor[8080][0] Starting background thread
2024-05-07 17:03:26 HttpProcessor[8080][1] Starting background thread
2024-05-07 17:03:26 HttpProcessor[8080][2] Starting background thread
2024-05-07 17:03:26 HttpProcessor[8080][3] Starting background thread
2024-05-07 17:03:26 HttpProcessor[8080][4] Starting background thread
2024-05-07 17:03:26 starting Context
2024-05-07 17:03:26 Context started
2024-05-07 17:03:31 stopping Context
2024-05-07 17:03:31 Context stopped

好，Tomcat4的日志架构就是这样，是不是很简单？另外，有一点需要注意，FileLogger在将日志写入文件的时候，整个IO操作是同步的而不是异步的，这意味着打印日志这个步骤，多多少少会增加程序运行的耗时。那么很自然的我们就会发出疑问：那日志框架发展到现在，应该支持异步了吧？我翻看了一下Tomcat9 juli包下的日志架构与我们目前常用的logback，他们在默认情况下仍然使用的是同步IO，但是使用FileChannel等技术做了优化，减少了耗时；但是它们也都提供了异步IO的日志记录器实现。

上图中的这两个类就是异步记日志的日志记录器，他们的实现方式也很相似，通过一个线程内部类的方式启动一个独立线程；同时外部类拥有一个队列属性，来存放写日志的事件；用户线程负责往队列里放日志事件，独立线程就不停地从队列里取日志事件出来将其写入到文件中。

下面是logback框架下AsyncAppenderBase类的部分代码

public class AsyncAppenderBase<E> extends UnsynchronizedAppenderBase<E> implements AppenderAttachable<E> {AppenderAttachableImpl<E> aai = new AppenderAttachableImpl<E>();BlockingQueue<E> blockingQueue;public static final int DEFAULT_QUEUE_SIZE = 256;int queueSize = DEFAULT_QUEUE_SIZE;int appenderCount = 0;Worker worker = new Worker();@Overridepublic void start() {if (isStarted())return;if (appenderCount == 0) {addError("No attached appenders found.");return;}if (queueSize < 1) {addError("Invalid queue size [" + queueSize + "]");return;}blockingQueue = new ArrayBlockingQueue<E>(queueSize);if (discardingThreshold == UNDEFINED)discardingThreshold = queueSize / 5;addInfo("Setting discardingThreshold to " + discardingThreshold);worker.setDaemon(true);worker.setName("AsyncAppender-Worker-" + getName());// make sure this instance is marked as "started" before staring the worker Threadsuper.start();worker.start();}@Overridepublic void stop() {if (!isStarted())return;// mark this appender as stopped so that Worker can also processPriorToRemoval if it is invoking// aii.appendLoopOnAppenders// and sub-appenders consume the interruptionsuper.stop();// interrupt the worker thread so that it can terminate. Note that the interruption can be consumed// by sub-appendersworker.interrupt();InterruptUtil interruptUtil = new InterruptUtil(context);try {interruptUtil.maskInterruptFlag();worker.join(maxFlushTime);// check to see if the thread ended and if not add a warning messageif (worker.isAlive()) {addWarn("Max queue flush timeout (" + maxFlushTime + " ms) exceeded. Approximately " + blockingQueue.size()+ " queued events were possibly discarded.");} else {addInfo("Queue flush finished successfully within timeout.");}} catch (InterruptedException e) {int remaining = blockingQueue.size();addError("Failed to join worker thread. " + remaining + " queued events may be discarded.", e);} finally {interruptUtil.unmaskInterruptFlag();}}@Overrideprotected void append(E eventObject) {if (isQueueBelowDiscardingThreshold() && isDiscardable(eventObject)) {return;}preprocess(eventObject);put(eventObject);}private void put(E eventObject) {if (neverBlock) {blockingQueue.offer(eventObject);} else {putUninterruptibly(eventObject);}}private void putUninterruptibly(E eventObject) {boolean interrupted = false;try {while (true) {try {blockingQueue.put(eventObject);break;} catch (InterruptedException e) {interrupted = true;}}} finally {if (interrupted) {Thread.currentThread().interrupt();}}}public void addAppender(Appender<E> newAppender) {if (appenderCount == 0) {appenderCount++;addInfo("Attaching appender named [" + newAppender.getName() + "] to AsyncAppender.");aai.addAppender(newAppender);} else {addWarn("One and only one appender may be attached to AsyncAppender.");addWarn("Ignoring additional appender named [" + newAppender.getName() + "]");}}class Worker extends Thread {public void run() {AsyncAppenderBase<E> parent = AsyncAppenderBase.this;AppenderAttachableImpl<E> aai = parent.aai;// loop while the parent is startedwhile (parent.isStarted()) {try {E e = parent.blockingQueue.take();aai.appendLoopOnAppenders(e);} catch (InterruptedException ie) {break;}}addInfo("Worker thread will flush remaining events before exiting. ");for (E e : parent.blockingQueue) {aai.appendLoopOnAppenders(e);parent.blockingQueue.remove(e);}aai.detachAndStopAllAppenders();}}
}

AsyncAppender类继承了AsyncAppenderBase，由上述代码可知，一个AsyncAppender对象只会创建一个Worker线程。而且根据我搜到资料显示，如果应用程序使用了logback框架的话，整个程序中也只会创建一个AsyncAppender对象，即单实例。

这里我对单worker线程的理解是