I got this weird issue that log4cl output duplicate logs in thread functions when running as script:
#!/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")
Output:
$ ./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
I'm using SBCL 2.4.1, and log4cl is the latest from quicklisp. I also tested log4cl from https://github.com/sharplispers/log4cl and got the same issue.
It appears that the log duplication only occurs in thread functions.
However, if load the file into SBCL REPL, there is no duplication:
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
Could someone tell me is it a bug of log4cl, or am I missing something?