Java Util Log

Java Util Log

从需求的角度出发, 渐进的理解 Java Util Log 源码
基于 JDK 1.8 源码
Java Util tutorial: http://tutorials.jenkov.com/java-logging/index.html

在 JUL 中有以下主要对象

• Logger 面向用户获取日志的接口
• LoggerManager 负责管理所有 logger
• Handler 负责最终日志的输出, 例如 ConsoleHandler 输出到终端, FileHandler 输出到文件
• Formatter 用于格式化日志内容, 例如添加时间戳, 输出包名等
• Level 日志级别

最简单的日志方式莫过于使用 System.out.println("debug log"); 的方式来输出调试信息.

Logger logger = Logger.getLogger("TestLogger-" + random.nextInt());
logger.log(Level.INFO, "This is a test log.");

Logger

Logger 的创建

每个 Logger 对象在创建的时候都需要一个名称, 这个名称主要用在 logging.properties 中, 针对不同日志设置不同的输出级别, 实现日志信息的过滤. 也可以指定 handler, 来输出到不同的文件中去. 对于没有上述需要的, 通常的做法是使用当前类的名称作为 logger name.

Logger logger = Logger.getLogger(JavaUtilLog.class.getName());

例如在 Web 服务中, HTTP 请求日志的级别设置为 Level.INFO, 应用程序的日志级别设置为 Level.WARNING, 数据库的日志级别设置为 Level.SEVERE. 将应用程序的日志输出到 app.log 文件中.

// In Java code
Logger rstLogger = Logger.getLogger("LOG_REQUEST");
Logger dbLogger = Logger.getLogger("LOG_DATABASE");
Logger appLogger = Logger.getLogger("LOG_APP");

############################################################
#   Custom Logging Configuration File
#   -Djava.util.logging.config.file=applogging.properties

LOG_REQUEST.level= INFO
LOG_DATABASE.level= SEVERE
LOG_APP.level= WARNING
LOG_APP.handlers = java.util.logging.FileHandler

java.util.logging.FileHandler.pattern = app.log
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter

额外提一点, 如果需要将 HTTP 请求的日志输出到 request.log 文件中, 如何实现呢? JUL 其实是不支持这种需求的, 不过可以通过继承 FileHandler 实现一个 RequestFileHandler 然后添加到配置文件中.

日志的输出

Logger 中会构建一个 LogRecord 对象来包装日志内容, 之后遍历所有可用的 handler, 调用 Handler.publish(LogRecord record) 由 handler 负责写入操作.

日志内容的原子性

Logger 日志输出的相关函数中都没有使用 synchronized 或其他锁, 在多个线程都获得同一个 logger 对象时, 同时在写日志, 它时如何保证线程安全的, 换句话说如何保证多条日志信息不会互相影响, 每一条日志都能完整的输出?

public void log(Level level, String msg) {
  // 日志过滤
  if (!isLoggable(level)) {
    return;
  }
  LogRecord lr = new LogRecord(level, msg);
  doLog(lr);
}

private void doLog(LogRecord lr) {
  // 填充 LogRecord
  lr.setLoggerName(name);
  // 此处 final 是为了线程安全考虑
  final Logger.LoggerBundle lb = getEffectiveLoggerBundle();
  final ResourceBundle bundle = lb.userBundle;
  final String ebname = lb.resourceBundleName;
  if (ebname != null && bundle != null) {
    lr.setResourceBundleName(ebname);
    lr.setResourceBundle(bundle);
  }
  log(lr);
}

public void log(LogRecord record) {
  // ...
  // 查找可用的 handler
  // 如果当前 logger 上没有挂载 handler, 则去父logger上查找
  Logger logger = this;
  while (logger != null) {
    final Handler[] loggerHandlers = isSystemLogger
        ? logger.accessCheckedHandlers()
        : logger.getHandlers();

    for (Handler handler : loggerHandlers) {
      handler.publish(record);
    }

    final boolean useParentHdls = isSystemLogger
        ? logger.config.useParentHandlers
        : logger.getUseParentHandlers();

    if (!useParentHdls) {
      break;
    }

    logger = isSystemLogger ? logger.parent : logger.getParent();
  }
}

通过代码可以看出来, LogRecord 是作为一个原子集, 在 Logger 中填充好日志相关的信息, 然后将它对象传递给 handler, 由 handler 来保证一个 LogRecord 能够完整的输出.

handler 线程安全

Logger 上 handler 的添加和删除操作都没有加锁, 如何保证在遍历 handler 时, 当前 handler 的数量保持不变? 例如线程A正在遍历 handler 来输出日志, 线程B此时删除了中间某个 handler, 如何避免线程A抛出 java.util.ConcurrentModificationException 的异常

handler 存储在 Logger.ConfigurationData 类中, 它是一个 CopyOnWriteArrayList 的 List 对象, 所以 Logger.addHandler() 和 Logger.removeHandler() 可以保持线程安全. 在遍历 handler 输出日志时, 会返回一个 Handler[], 这个数组不是 CopyOnWriteArrayList 中实际存储的数组的包装引用, 而是重新拷贝了一份. 所以线程B的删除操作不会影响到线程A.

LogManager

LogManager 主要负责所有 Logger 的创建, 管理和销毁. LogManager 的构造函数是 private, LogManager 中定了一个全局的对象, 后续所有的操作其实都是在操作这一个对象.

Logger 的创建

Logger.getLogger() 实际调用的是 LogManager.demandLogger() 方法. 首先查找是否已经存在名称是 name 的 logger, 如果不存在则创建一个新的 logger 加入到 logger 列表.

Logger demandLogger(String name, String resourceBundleName, Class<?> caller) {
  Logger result = getLogger(name);
  if (result == null) {
    Logger newLogger = new Logger(name, resourceBundleName, caller, this, false);
    do {
      if (addLogger(newLogger)) {
        return newLogger;
      }

      // 因为方法中并没有任何的加锁操作, 所以在判断完 result == null 之后, addLogger 之前
      // 可能有其他的线程已经添加了同名的 logger, 我们这里的 addLogger 将会返回 false,
      // 所以在 addLogger 返回 false 之后我们需要调用 getLogger 尝试获取那个同名的 logger.
      //
      // 既然已经有其他线程已经创建并添加了同名的 logger, 为什么 getLogger 会有可能返回 null呢?
      // 因为 LogManager 在管理 logger 时使用的是弱引用(WeakReference), 如果那个已经添加的 logger
      // 没有被强引用, 在 addLogger 返回 false 之后 JVM 恰好执行了一个 GC 操作, 那个没有强引用的
      // logger 会被系统回收掉, 所以 getLogger 得到的是一个 null. 这就是这里 do-while 存在的意义.
      result = getLogger(name);
    } while (result == null);
  }
  return result;
}

Logger 的生命周期

LogManager 上有一个 userContext 的成员变量, 所有的 logger 实际都在保存在这个变量上. namedLoggers 的 value 实际是一个 logger 的弱引用.

// class LogManager {
private final LoggerContext userContext = new LoggerContext();
class LoggerContext {
    // Table of named Loggers that maps names to Loggers.
    private final ConcurrentHashMap<String,LoggerWeakRef> namedLoggers =
            new ConcurrentHashMap<>();
}

final class LoggerWeakRef extends WeakReference<Logger> {
  private String name;  // for namedLoggers cleanup
  private LogManager.LogNode node;       // for loggerRef cleanup
  private WeakReference<Logger> parentRef;  // for kids cleanup
  private boolean disposed = false;         // avoid calling dispose twice

  LoggerWeakRef(Logger logger) {
    super(logger, loggerRefQueue);
    name = logger.getName();
  }

  void dispose() {
    // ...
  }
}

对于弱引用通常会有这几个疑问:

1. 如何知道一个 logger 已经被回收了?
2. logger 被回收之后, 清理工作什么时候进行?
3. logger 上绑定的 handler 什么时候关闭?

如果一个 logger 对象已经被回收了, LogManager 并不能第一时间知道, 而是在每次调用 getLogger() 和 addLogger() 的时候才知道的, 而这两个方法是在 demandLogger() 被调用.

LogManager.demandLogger() 实际调用的是 LoggerContext.findLogger(String) 方法. LogManager.addLogger() 实际调用的是 LoggerContext.addLocalLogger(Logger, boolean) 方法.

// class LoggerContext {
Logger findLogger(String name) {

  // ...

  synchronized (this) {
    // 确保这个 context 已经初始化过了.
    ensureInitialized();
    LogManager.LoggerWeakRef ref = namedLoggers.get(name);
    if (ref == null) {
      // 在 LoggerWeakRef.dispose() 方法中清理 namedLoggers
      // 此处不需要清理
      return null;
    }
    logger = ref.get();
    if (logger == null) {
      // namedLoggers 中保存的弱引用 logger 已经被 GC 回收了
      // 此时调用 LoggerWeakRef.dispose() 执行清理操作.
      ref.dispose();
    }
    return logger;
  }
}

synchronized boolean addLocalLogger(Logger logger, boolean addDefaultLoggersIfNeeded) {

  // ...

  LogManager.LoggerWeakRef ref = namedLoggers.get(name);
  if (ref != null) {
    if (ref.get() == null) {
      // It's possible that the Logger was GC'ed after a
      // drainLoggerRefQueueBounded() call above so allow
      // a new one to be registered.
      ref.dispose();
    } else {
      // We already have a registered logger with the given name.
      return false;
    }
  }

  // ...

}

handler 只由 Logger 对象持有, 当 logger 对象销毁后 handler 并未关闭. LogManager 的构造函数中注册了一个 JVM 退出的钩子, 最终调用 LogManager.resetLogger(Logger) 来执行 handler 的清理操作. 如果在代码中给某个 logger 添加了自定义的 handler, 记得保持这个 handler 的强应用, 并在合适的时候手动调用 Handler.close() 关闭它.

// class LogManager {
private LogManager(Void checked) {
  // Add a shutdown hook to close the global handlers.
  try {
    Runtime.getRuntime().addShutdownHook(new Cleaner());
  } catch (IllegalStateException e) {
    // If the VM is already shutting down,
    // We do not need to register shutdownHook.
  }
}

private void resetLogger(java.util.logging.Logger logger) {
  // Close all the Logger's handlers.
  Handler[] targets = logger.getHandlers();
  for (int i = 0; i < targets.length; i++) {
    Handler h = targets[i];
    logger.removeHandler(h);
    try {
      h.close();
    } catch (Exception ex) {
      // Problems closing a handler?  Keep going...
    }
  }
  
  // ...

}

handler

handler 负责将 logger 传递过来的 LogRecord 输出到具体的介质中. JDK 默认提供了 ConsoleHandler , FileHandler 和 SocketHandler 等. handler 需要保证一条 LogRecord 在多线程的情况下能够完整输出, 不会被其他线程扰乱.

handler 是由 logger 调用过来的, 所以不能在 handler 中调用 logger, 这样会造成调用死循环, 导致栈溢出.

handler 会持有一个类型为 ErrorManager 的成员变量, handler 中任何有需要写日志的地方, 通过它来输出.