[Log4cplus-devel] few logging issues

[Jeremy C. R. <re...@re...>]

The BIND 10 suite uses log4cplus. We have multiple processes running 
that use a centralized logging configuration. Our use of log4cplus is 
wide-spread through our code. But mostly abstracted as our own library 
with code at
http://git.bind10.isc.org/~jreed/gitweb/gitweb.cgi?p=bind10/.git;a=tree;f=src/lib/log

(By the way, we have a nice feature where we have a unique log message 
for every use that has a corresponding longer description that is 
available in our documentation.)

A few problems we have include:

1) stderr output sometimes has Ctrl-@ characters included in the output. 
I have only seen this on our MacOS system and can't reproduce it, but it 
happens frequently.

An example:

2012-01-25 03:58:52.408 DEBUG [b10-cmdctl.cmdctl] CMDCTL_STARTED cmdctl 
is listening for connections on 127.0.0.1:8080
2012-01-25 03:58:52.429 012-01-25 03:58:52.428^@IINFO ^@^@^@ ^@ 
[^@^@b10-xfrout.xfrouttats-httpd^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@] 
^@^@XFROUT_NEW_CONFIG Update xfrout 
configuration^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@
^@2012-01-25 03:58:52.429 INFO  [b10-xfrout.xfrout] 
XFROUT_NEW_CONFIG_DONE Update xfrout configuration done
2012-01-25 03:59:07.946 INFO  [b10-xfrin.xfrin] 
XFRIN_XFR_TRANSFER_STARTED IXFR transfer of zone example/IN started

Anyone see CTRL-@? (Note that you probably can't see it unless you 
convert it to something visible. I piped the saved output through cat 
-v.)  (The rest of the corruption in that output is probably due to poit 
#2 below.)

Our BIND 10 specific ticket about this is at 
http://bind10.isc.org/ticket/1629

2) Often we have log output that is mixed when sent to console (stdout 
or stderr). For example, the following line:

2012-02-22 11:20:33.287 DEBUG2012-02-22 11:20:33.287 DEBUG [b10-auth.auth] AUTH_DNS_SERVICES_CREATED DNS services created

was logged as different entries but ended up interspersed. We have seen 
this on multiple different operating systems.

I see the new fileappender UseLockFile. Is there any similar feature so 
different processes (using same log4cplus setup) won't write their log 
output to console at the same time?

Our BIND 10 specific ticket about this is at 
http://bind10.isc.org/ticket/1704

3) Old rotated logs continue to be open and written to. fstat shows it 
clearly. The problem is mostly understood. Multiple processes (all using 
log4cplus) are writing to the same rotated log file. One process noticed 
file needs to be rotated, so files are renamed. Other processes continue 
to have the file handle open (now with an old name with number at 
end) and start logging to it (starting from an empty file?). Later it 
may reach our max file size configuration and be rotated too.

I haven't tried the fileappender's UseLockFile, but maybe it handles 
this rotation problem also. Any suggestions on this?

Our BIND 10 specific ticket about this is at 
http://bind10.isc.org/ticket/1896

Thank you for log4cplus. If you have any suggestions on how we can 
better use it, please let us know.

Jeremy C. Reed