log4cl在SBCL多线程脚本中输出重复日志，是否为Bug或使用问题？

问题现象 #

在SBCL 2.4.1环境中使用最新版Log4CL时，出现以下异常：

• 将代码作为SBCL脚本运行时，线程函数内的日志会重复输出，每条日志打印两次
• 但将代码加载到SBCL REPL中运行时，日志输出正常，无重复现象
• 仅线程执行的代码段出现重复日志，主线程日志无此问题

原代码示例 #

#!/usr/bin/sbcl --script

(require :asdf)
(require :log4cl)

(log:config :debug)

(log:info "begin")

(defun worker ()
  (let ((name (sb-thread:thread-name sb-thread:*current-thread*)))
    (log:info "~a started" name)
    (log:debug "~a ~a" name (sb-ext:get-time-of-day))
    (log:info "~a stoped" name)))

(loop for thread in (loop for i below 2
                          collect (sb-thread:make-thread
                                   'worker
                                   :name (format nil "worker-~a" i)
                                   :arguments nil))
      do (sb-thread:join-thread thread))

(log:info "done")

脚本运行重复日志输出 #

$ ./foo.lisp
 <INFO> [17:40:25] cl-user foo.lisp () - begin
 <INFO> [17:40:25] cl-user foo.lisp (worker) - worker-0 started
 <INFO> [17:40:25] cl-user foo.lisp (worker) - worker-0 started
 <INFO> [17:40:25] cl-user foo.lisp (worker) - worker-1 started
 <INFO> [17:40:25] cl-user foo.lisp (worker) - worker-1 started
<DEBUG> [17:40:25] cl-user foo.lisp (worker) - worker-0 1713346825
<DEBUG> [17:40:25] cl-user foo.lisp (worker) - worker-0 1713346825
<DEBUG> [17:40:25] cl-user foo.lisp (worker) - worker-1 1713346825
<DEBUG> [17:40:25] cl-user foo.lisp (worker) - worker-1 1713346825
 <INFO> [17:40:25] cl-user foo.lisp (worker) - worker-0 stoped
 <INFO> [17:40:25] cl-user foo.lisp (worker) - worker-0 stoped
 <INFO> [17:40:25] cl-user foo.lisp (worker) - worker-1 stoped
 <INFO> [17:40:25] cl-user foo.lisp (worker) - worker-1 stoped
 <INFO> [17:40:25] cl-user foo.lisp () - done

REPL加载正常输出 #

sbcl --noinform --no-userinit
* (load "foo.lisp")
 <INFO> [17:48:36] cl-user foo.lisp () - begin
 <INFO> [17:48:36] cl-user foo.lisp (worker) - worker-0 started
 <INFO> [17:48:36] cl-user foo.lisp (worker) - worker-1 started
<DEBUG> [17:48:36] cl-user foo.lisp (worker) - worker-1 1713347316
 <INFO> [17:48:36] cl-user foo.lisp (worker) - worker-1 stoped
<DEBUG> [17:48:36] cl-user foo.lisp (worker) - worker-0 1713347316
 <INFO> [17:48:36] cl-user foo.lisp (worker) - worker-0 stoped
 <INFO> [17:48:36] cl-user foo.lisp () - done
T

问题原因 #

这是SBCL脚本模式与Log4CL初始化逻辑的兼容性问题：

• SBCL脚本模式下，(require :log4cl)会初始化一次默认控制台appender
• 当新线程创建时，脚本环境的特性会触发Log4CL内部的初始化逻辑再次执行，导致同一个控制台appender被重复注册
• 每条日志会被多个相同的appender输出，最终造成重复打印

REPL模式下不存在此问题，因为REPL环境是单初始化流程，appender仅被注册一次。

解决方案 #

显式管理Log4CL的appender，在配置日志前清除所有默认appender，再手动添加一次控制台appender，避免重复注册：

修改后的代码 #

#!/usr/bin/sbcl --script

(require :asdf)
(require :log4cl)

// 清除所有已存在的appender，避免重复注册
(log:remove-all-appenders)
// 手动添加控制台appender到根日志器
(log:add-appender (log:console-appender) log:*root-logger*)

(log:config :debug)

(log:info "begin")

(defun worker ()
  (let ((name (sb-thread:thread-name sb-thread:*current-thread*)))
    (log:info "~a started" name)
    (log:debug "~a ~a" name (sb-ext:get-time-of-day))
    (log:info "~a stoped" name)))

(loop for thread in (loop for i below 2
                          collect (sb-thread:make-thread
                                   'worker
                                   :name (format nil "worker-~a" i)
                                   :arguments nil))
      do (sb-thread:join-thread thread))

(log:info "done")

验证效果 #

运行修改后的脚本，日志输出不再重复，与REPL模式下表现一致：

$ ./foo.lisp
 <INFO> [xx:xx:xx] cl-user foo.lisp () - begin
 <INFO> [xx:xx:xx] cl-user foo.lisp (worker) - worker-0 started
 <INFO> [xx:xx:xx] cl-user foo.lisp (worker) - worker-1 started
<DEBUG> [xx:xx:xx] cl-user foo.lisp (worker) - worker-0 171xxxxxxx
 <INFO> [xx:xx:xx] cl-user foo.lisp (worker) - worker-0 stoped
<DEBUG> [xx:xx:xx] cl-user foo.lisp (worker) - worker-1 171xxxxxxx
 <INFO> [xx:xx:xx] cl-user foo.lisp (worker) - worker-1 stoped
 <INFO> [xx:xx:xx] cl-user foo.lisp () - done

内容的提问来源于stack exchange，提问作者xiepan