阅读 45

Java Util Log

Java Util Log

从需求的角度出发, 渐进的理解 Java Util Log 源码

基于 JDK 1.8 源码

Java Util tutorial: tutorials.jenkov.com/java-loggin…

在 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 , FileHandlerSocketHandler 等. handler 需要保证一条 LogRecord 在多线程的情况下能够完整输出, 不会被其他线程扰乱.

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

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