在看原书第六章之前，一直觉得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 LifecycleListeners
lifecycle.fireLifecycleEvent(BEFORE_START_EVENT, null);
started = true;
try {
// Start our subordinate components, if any
if ((loader != null) && (loader instanceof Lifecycle))
((Lifecycle) loader).start();
// Start our child containers, if any
Container 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 any
if (pipeline instanceof Lifecycle)
((Lifecycle) pipeline).start();
// Notify our interested LifecycleListeners
lifecycle.fireLifecycleEvent(START_EVENT, null);
}
catch (Exception e) {
e.printStackTrace();
}
// Notify our interested LifecycleListeners
lifecycle.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 LifecycleListeners
lifecycle.fireLifecycleEvent(BEFORE_STOP_EVENT, null);
lifecycle.fireLifecycleEvent(STOP_EVENT, null);
started = false;
try {
// Stop the Valves in our pipeline (including the basic), if any
if (pipeline instanceof Lifecycle) {
((Lifecycle) pipeline).stop();
}
// Stop our child containers, if any
Container 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 LifecycleListeners
lifecycle.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_stop
Process 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();
@Override
public 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 Thread
super.start();
worker.start();
}
@Override
public 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 interruption
super.stop();
// interrupt the worker thread so that it can terminate. Note that the interruption can be consumed
// by sub-appenders
worker.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 message
if (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();
}
}
@Override
protected 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 started
while (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线程的理解是
- 在某一时段内，记日志的IO操作针对的是同一个日志文件，如果多线程同时争抢这个文件资源的话，不加锁会导致写入的内容混乱、损坏，加锁的话又丢失了并发的意义。
- 应用程序的日志应该是有顺序的，多线程同时消费日志消息的话，由于操作系统调度和线程执行顺序的不确定性，可能导致数据的写入顺序错乱，影响我们分析日志。
同理，使用单例AsyncAppender对象也是类似原因。但是具体是否有多实例这个情况，这里就暂时不深究了。
通过本章的内容，我们了解了Tomcat是怎么记日志的，它默认采用同步IO的形式来记日志，当然有有异步IO供你选择。下一章，我们来研究下Tomcat中载入器的实现方式，看看它是怎么自定义类加载机制的。
源码分享
https://gitee.com/huo-ming-lu/HowTomcatWorks
原书中代码没有bug，我仅仅格式化了一下代码
