Missing log entries with log4j log rotation

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Missing log entries with log4j log rotation

Shawn Heisey-2
There appear to be large blocks of time missing in my solr logfiles
created with slf4j->log4j and rotated using the log4j config:

End of solr.log.1: INFO  - 2014-10-31 12:52:25.073;
Start of solr.log: INFO  - 2014-11-01 02:27:27.404;

End of solr.log.2: INFO  - 2014-10-29 06:30:32.661;
Start of solr.log.1: INFO  - 2014-10-30 07:01:34.241;

Queries happen at a fairly constant low level and updates happen once a
minute, so I know for sure that there is activity during the missing
blocks of time.  I need to investigate a problem that occurred during
the time that is not logged, which means I have nothing to investigate.

This is the log4j configuration that I'm using:

http://apaste.info/9vC

These are the logging jars that I have in jetty's lib/ext:

-rw-r--r-- 1 ncindex ncindex  16515 Apr 11  2014 jcl-over-slf4j-1.7.6.jar
-rw-r--r-- 1 ncindex ncindex   4959 Apr 11  2014 jul-to-slf4j-1.7.6.jar
-rw-r--r-- 1 ncindex ncindex 489883 Apr 11  2014 log4j-1.2.17.jar
-rw-r--r-- 1 ncindex ncindex  28688 Apr 11  2014 slf4j-api-1.7.6.jar
-rw-r--r-- 1 ncindex ncindex   8869 Apr 11  2014 slf4j-log4j12-1.7.6.jar

Is this a bug, or have I done something wrong in my config?  Should I be
putting this on the log4j mailing list instead of here?  My best guess
about how this is happening is that an entire logfile is getting deleted
during rotation.

Thanks,
Shawn

Reply | Threaded
Open this post in threaded view
|

Re: Missing log entries with log4j log rotation

Shawn Heisey-2
On 11/1/2014 11:45 AM, Shawn Heisey wrote:
> Is this a bug, or have I done something wrong in my config?  Should I be
> putting this on the log4j mailing list instead of here?  My best guess
> about how this is happening is that an entire logfile is getting deleted
> during rotation.

I did find this blog post describing a similar problem with a different
Appender:

http://vivekagarwal.wordpress.com/2008/02/09/missing-log4j-log-files-with-dailyrollingfileappender-when-they-should-roll-over/

I'm not running on Windows, I'm on Linux, which normally does not have
problems with renaming files even when they are open.

My logfiles where I redirect stdout and stderr from Jetty don't show
anything related, and I don't see anything like the error mentioned in
any of the surviving logfiles from log4j.

Thanks,
Shawn

Reply | Threaded
Open this post in threaded view
|

Re: Missing log entries with log4j log rotation

Shawn Heisey-2
In reply to this post by Shawn Heisey-2
On 11/1/2014 11:45 AM, Shawn Heisey wrote:
> There appear to be large blocks of time missing in my solr logfiles
> created with slf4j->log4j and rotated using the log4j config:
>
> End of solr.log.1: INFO  - 2014-10-31 12:52:25.073;
> Start of solr.log: INFO  - 2014-11-01 02:27:27.404;
>
> End of solr.log.2: INFO  - 2014-10-29 06:30:32.661;
> Start of solr.log.1: INFO  - 2014-10-30 07:01:34.241;

The more I thought about this problem, the more convinced I became that
the issue had to be in log4j, since log4j is responsible for writing and
rotating the logs.

I posted the question on the log4j mailing list, and the response
basically said "If this is a bug in log4j 1.x, it's not going to get
fixed.  Upgrade to 2.x."  We do something similar ourselves when a new
major version gets minted, so I can't really complain about that.

I was able to get information on what jar changes would be required for
such an upgrade, but from what I can tell, log4j2 does not support a
property-based configuration file, it must be XML.  There are no
conversion tools for version 2... the only conversion tool I found would
convert log4j.properties into an XML config for version 1.x, which looks
very different from a version 2 XML config.  There do not appear to be
any examples of a RollingFileAppender based config for log4j2.

It won't be a relevant upgrade test if I can't configure the new version
in the same way as the old version, and because I can't find any
examples to work from, I'm going to have to experiment with the config.

If we choose to upgrade the project to log4j 2.1, upgrading the logging
might prove tricky for some end users.  If we do the upgrade right, they
would have the option of continuing to use their existing logging setup,
which might be losing logs like mine.

Thanks,
Shawn

Reply | Threaded
Open this post in threaded view
|

Re: Missing log entries with log4j log rotation

Michael Sokolov-3
In reply to this post by Shawn Heisey-2
Shawn this is really weird -- we run log4j in lots of installations and
have never seen an issue like this.

I wonder if you might be running some other log rotation software (like
logrotate) that is somehow getting in the way or conflicting?

-Mike

On 11/01/2014 01:45 PM, Shawn Heisey wrote:

> There appear to be large blocks of time missing in my solr logfiles
> created with slf4j->log4j and rotated using the log4j config:
>
> End of solr.log.1: INFO  - 2014-10-31 12:52:25.073;
> Start of solr.log: INFO  - 2014-11-01 02:27:27.404;
>
> End of solr.log.2: INFO  - 2014-10-29 06:30:32.661;
> Start of solr.log.1: INFO  - 2014-10-30 07:01:34.241;
>
> Queries happen at a fairly constant low level and updates happen once a
> minute, so I know for sure that there is activity during the missing
> blocks of time.  I need to investigate a problem that occurred during
> the time that is not logged, which means I have nothing to investigate.
>
> This is the log4j configuration that I'm using:
>
> http://apaste.info/9vC
>
> These are the logging jars that I have in jetty's lib/ext:
>
> -rw-r--r-- 1 ncindex ncindex  16515 Apr 11  2014 jcl-over-slf4j-1.7.6.jar
> -rw-r--r-- 1 ncindex ncindex   4959 Apr 11  2014 jul-to-slf4j-1.7.6.jar
> -rw-r--r-- 1 ncindex ncindex 489883 Apr 11  2014 log4j-1.2.17.jar
> -rw-r--r-- 1 ncindex ncindex  28688 Apr 11  2014 slf4j-api-1.7.6.jar
> -rw-r--r-- 1 ncindex ncindex   8869 Apr 11  2014 slf4j-log4j12-1.7.6.jar
>
> Is this a bug, or have I done something wrong in my config?  Should I be
> putting this on the log4j mailing list instead of here?  My best guess
> about how this is happening is that an entire logfile is getting deleted
> during rotation.
>
> Thanks,
> Shawn
>

Reply | Threaded
Open this post in threaded view
|

Re: Missing log entries with log4j log rotation

Shawn Heisey-2
On 11/4/2014 7:45 AM, Michael Sokolov wrote:
> Shawn this is really weird -- we run log4j in lots of installations
> and have never seen an issue like this.
>
> I wonder if you might be running some other log rotation software
> (like logrotate) that is somehow getting in the way or conflicting?

I did not configure logrotate for my solr logs.  The Solr/Jetty
combination is the only thing on the system that ever writes to those
directories.  I occasionally look at them manually, usually with less or
grep.

[root@idxa1 ~]# ls -ald /etc/logrotate*
-rw-r--r--  1 root root  662 Aug 29  2007 /etc/logrotate.conf
drwxr-xr-x. 2 root root 4096 Apr 11  2014 /etc/logrotate.d
[root@idxa1 ~]# grep -r solr /etc/logrotate*
[root@idxa1 ~]#

I have upgraded jetty, slf4j, and log4j beyond the versions included
with the original download for the Solr version that I'm using, which is
4.7.2.  The versions I'm using for slf4j and log4j are the same versions
that are included in the 4.9 download, though.

Thanks,
Shawn