Re: [Log4cplus-devel] few logging issues

[Václav Z. <vha...@gm...>]

On 05/01/2012 08:15 PM, Jeremy C. Reed wrote:
> 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
I have never seen such behaviour. You are the first one reporting this.
I have no idea why it could be happening.

>
> 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
There is no inter-process synchronization for console output. In theory,
it should be possible to implement it using lock file.

>
> 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
Yes, this has been reported and it should be fixed on trunk and upcoming
1.1.0 for FileAppender and RollingFileAppender. DailyRollingFileAppender
still has issues with synchronization between multiple processes.

>[...]

-- 
VZ