1

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?

0

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.