log to file on SBCL looses last two log messages about log4cl

[7max]

Can you evaluate the following forms and paste the output?

(log:config)

(list
   (find :bordeaux-threads *features*)
   log4cl-impl::*watcher-thread*
   (slot-value (log4cl-impl::current-hierarchy) 
               'log4cl-impl::watch-tokens)      
   (log4cl-impl::effective-appenders log4cl-impl:*root-logger*))

[avodonosov]

done, see here: http://paste.lisp.org/display/130667

[7max]

A few things to try

1. Does this workaround fix it?

(log:config :daily log-file :immediate-flush)

If above workaround does not work, something is really strange going on. Can you then do (trace finish-output) and issue some log statements, there should be calls to finish-output on the log file after every log statement.. They look like so in my Slime

0: (FINISH-OUTPUT #<SB-SYS:FD-STREAM for "file /home/max/projects/lisp/log4cl/tests/file.txt" {108635DAF3}>)

Note you will also be getting them for console stream too.

If above work workaround does work, can you do the following two experiments:

2 Check that hierarchy watcher is in fact doing its thing.

(trace log4cl-impl::watch-token-check)

... there should be a bunch of output in *inferior-lisp* buffer showing that its being called every second, the argument being the file appender

(untrace) to remove it

3 Verify finish-output gets called

1. Reconfigure to remove console-appender, with just file (log:config :sane :daily log-file)
2. (trace finish-output)
3. Do a loop issuing a bunch of log statements in a loop like so (dotimes (i 2000) (log:info "iteration ~d" i))

There should be (finish-output) for the log file, either in REPL, or in the *inferior-lisp* (from the watcher thread auto-flushing)..

You need to adjust the number of log messages in the loop, so that outputting them takes longer then 2-3 seconds, so that autoflusher thread has a chance to run...

If there are no FINISH-OUTPUT shown in *inferior-lisp* something is definitely screwed up with log4cl logic

If FINISH-OUTPUT do show up, but it still seems like last few messages are getting buffered, how do you test it? do you "tail -f" the log file? Also what is the filesystem.

[avodonosov]

The workaround helps. I am not performing the remaining experiments, because the reason is obvious: my program exits and the hierarchy watcher do not have chance to flush the log statements issued during the last 1 second.

(Note, the issue is only with two last log statements, and the key point that the program exits after it's work is done).

[avodonosov]

Maybe :auto-flush should be the default? I do not remember that I had such issues with log4j. Either they do autoflush, or set Runtime.addShutdownHook, but shutdown hooks are not guaranteed to execute if JVM crashes, so autoflush seems more reliable.

[7max]

Ok I seem to understand the problem now, if your program does (exit) before autoflusher had a chance to run, then FINISH-OUTPUT probably never gets called.

The reason autoflush is not default like with Log4J, is that I feel Log4CL default setting is better solution then Log4J with immediateFlush turned off.. It gives almost the same performance as Log4J, but unlike it ensures that there is no stale statements in the log file older then log4cl-impl::*hierarchy-watcher-heartbeat* seconds.. Obviously with exception of the corner case we had just discovered, of a program exiting before that time.

Since Lisp is generally used with long-running processes, I'd like to keep the default that provides best performance, and try to fix the process exiting special case.

[avodonosov]

Well, it's a questionable solution, but I do not insist (I just use :immediate-flush in my config). Feel free to close the issue.

Some ideas:
Maybe a function like log:flush may be added to the public API which ensures everything is written?
One could add it in the end of his MAIN function (in unwind-protect).

Also, maybe instead of looping with 1 second interval, some wait/signal scheme will be more reliable and, hopefully, will have the same performance. I mean bordeaux-threads:condition-wait, bordeaux-threads:condition-notify.

[7max]

I'd like to also point out, that log file switch at midnight happens when log statement is issued, and the current day is different from the day when previous log statement was issued.

For the short-running script program, it will be unlikely that program runs exactly at midnight and issues two log statements on different days, so log switch will not happen..

You can fix it by giving adding the %Y%m%d to the file name, which will use timestamp in the current log file name, althought this makes it difficult to tail -f the current log file, as you need to figure out the current one.

I think its possible to fix it, by checking the file modification time when we first open the file, and checking if we need to rename the log file at that time, so I'll try to fix this in the next version.

[avodonosov]

Thanks for the info, I already had some suspicions about this. But it didn't bothered me too much.

[7max]

I like the public API idea, will likely be called log:flush-all-appeders

[7max]

LOG4CL:FLUSH-ALL-APPENDERS API added in version v1.1.0.

Under SBCL it is called from EXIT-HOOKS