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 中任何有需要写日志的地方, 通过它来输出.

©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 194,491评论 5赞 459
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 81,856评论 2赞 371
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 141,745评论 0赞 319
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 52,196评论 1赞 263
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 61,073评论 4赞 355
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 46,112评论 1赞 272
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 36,531评论 3赞 381
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 35,215评论 0赞 253
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 39,485评论 1赞 290
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 34,578评论 2赞 309
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 36,356评论 1赞 326
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 32,215评论 3赞 312
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 37,583评论 3赞 299
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 28,898评论 0赞 17
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,174评论 1赞 250
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 41,497评论 2赞 341
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 40,697评论 2赞 335