You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@logging.apache.org by Steffen Offermann <st...@aixigo.de> on 2019/04/30 06:26:43 UTC

RollingRandomAccessFileAppender does not wait for compression to complete on LogContext.stop()

Hi, guys!

We are having problems with Log4j because it apparently does not wait for currently running asynchronous operations to finish when the log system is being stopped/shut down.

We use LoggerContext.stop() with a timeout of 60 seconds. According to the documentation of LoggerContext.stop() this should block until the log file compression completes:

 >     * Log4j can start threads to perform certain actions like file rollovers, calling this method with a positive timeout will
 >     * block until the rollover thread is done.

Unfortunately that does not seem to be the case, and it leads to incomplete (and hence unusable) log files in production.

Are there any plans on fixing this, or are there any known workarounds?

Thanks,
    Steffen

-- 
aixigo AG - financial solutions & technology
Karl-Friedrich-Straße 68, 52072 Aachen, Germany
fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de

Amtsgericht Aachen - HRB 8057
Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch

Re: RollingRandomAccessFileAppender does not wait for compression to complete on LogContext.stop()

Posted by Carter Kozak <ck...@ckozak.net>.
Hi Steffen,

I've seen this occur in two scenarios:
1. The JVM is stopped in an unexpected way (e.g. process killed, system loses power, Runtime.halt) while files roll
2. Compressing files takes long enough in a shutdown hook that the JVM is forcefully killed by a service wrapper (resulting in the first case)

Unfortunately there's not a great deal we can do in these cases, though using the default configuration, the plain text rolled file should exist next to the partial compressed file. It should only be deleted after compression completes.

-ck

On Thu, May 2, 2019, at 09:17, Steffen Offermann wrote:
> Update: I have been trying to reproduce the issue myself for a while (it has been reported by another team), and I can't get it to fail. So it MIGHT be false alarm. I need to investigate some more ...
> 
> On 02.05.19 11:43, Steffen Offermann wrote:
> > I think I didn't make this clear: we stop the log system before the process exits - and hence the JVM shuts down. So the problem occurs when the JVM shuts down while the compression is still being 
> > executed.
> > 
> > Regards,
> > Steffen
> > 
> > On 02.05.19 11:33, Steffen Offermann wrote:
> >>
> >> Hi, Remko!
> >>
> >> I'm afraid that's very difficult to do, as the problem is apparently caused by a race condition. The test would have to make sure that the log file compression has already started and is still being 
> >> executed when the log system is being shut down.
> >>
> >> But from what I can see when I look at the sources, it's quite obvious that there is mechanism implemented that waits for the compression to finish before the log system is shut down.
> >>
> >> Regards,
> >> Steffen
> >>
> >>
> >> On 30.04.19 23:45, Remko Popma wrote:
> >>> Can you provide a unit test or minimal project that reproduces the problem?
> >>>
> >>> On Tue, Apr 30, 2019 at 3:26 PM Steffen Offermann <
> >>> steffen.offermann@aixigo.de> wrote:
> >>>
> >>>> Hi, guys!
> >>>>
> >>>> We are having problems with Log4j because it apparently does not wait for
> >>>> currently running asynchronous operations to finish when the log system is
> >>>> being stopped/shut down.
> >>>>
> >>>> We use LoggerContext.stop() with a timeout of 60 seconds. According to the
> >>>> documentation of LoggerContext.stop() this should block until the log file
> >>>> compression completes:
> >>>>
> >>>> > * Log4j can start threads to perform certain actions like file
> >>>> rollovers, calling this method with a positive timeout will
> >>>> > * block until the rollover thread is done.
> >>>>
> >>>> Unfortunately that does not seem to be the case, and it leads to
> >>>> incomplete (and hence unusable) log files in production.
> >>>>
> >>>> Are there any plans on fixing this, or are there any known workarounds?
> >>>>
> >>>> Thanks,
> >>>> Steffen
> >>>>
> >>>> -- 
> >>>> aixigo AG - financial solutions & technology
> >>>> Karl-Friedrich-Straße 68, 52072 Aachen, Germany
> >>>> fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
> >>>> eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de
> >>>>
> >>>> Amtsgericht Aachen - HRB 8057
> >>>> Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
> >>>> Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch
> >>>>
> >>>
> >>
> >>
> > 
> > 
> 
> 
> -- 
> aixigo AG - financial solutions & technology
> Karl-Friedrich-Straße 68, 52072 Aachen, Germany
> fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
> eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de
> 
> Amtsgericht Aachen - HRB 8057
> Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
> Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch
>

Re: RollingRandomAccessFileAppender does not wait for compression to complete on LogContext.stop()

Posted by Steffen Offermann <st...@aixigo.de>.
Update: I have been trying to reproduce the issue myself for a while (it has been reported by another team), and I can't get it to fail. So it MIGHT be false alarm. I need to investigate some more ...

On 02.05.19 11:43, Steffen Offermann wrote:
> I think I didn't make this clear: we stop the log system before the process exits - and hence the JVM shuts down. So the problem occurs when the JVM shuts down while the compression is still being 
> executed.
> 
> Regards,
>    Steffen
> 
> On 02.05.19 11:33, Steffen Offermann wrote:
>>
>> Hi, Remko!
>>
>> I'm afraid that's very difficult to do, as the problem is apparently caused by a race condition. The test would have to make sure that the log file compression has already started and is still being 
>> executed when the log system is being shut down.
>>
>> But from what I can see when I look at the sources, it's quite obvious that there is mechanism implemented that waits for the compression to finish before the log system is shut down.
>>
>> Regards,
>>    Steffen
>>
>>
>> On 30.04.19 23:45, Remko Popma wrote:
>>> Can you provide a unit test or minimal project that reproduces the problem?
>>>
>>> On Tue, Apr 30, 2019 at 3:26 PM Steffen Offermann <
>>> steffen.offermann@aixigo.de> wrote:
>>>
>>>> Hi, guys!
>>>>
>>>> We are having problems with Log4j because it apparently does not wait for
>>>> currently running asynchronous operations to finish when the log system is
>>>> being stopped/shut down.
>>>>
>>>> We use LoggerContext.stop() with a timeout of 60 seconds. According to the
>>>> documentation of LoggerContext.stop() this should block until the log file
>>>> compression completes:
>>>>
>>>>   >     * Log4j can start threads to perform certain actions like file
>>>> rollovers, calling this method with a positive timeout will
>>>>   >     * block until the rollover thread is done.
>>>>
>>>> Unfortunately that does not seem to be the case, and it leads to
>>>> incomplete (and hence unusable) log files in production.
>>>>
>>>> Are there any plans on fixing this, or are there any known workarounds?
>>>>
>>>> Thanks,
>>>>      Steffen
>>>>
>>>> -- 
>>>> aixigo AG - financial solutions & technology
>>>> Karl-Friedrich-Straße 68, 52072 Aachen, Germany
>>>> fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
>>>> eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de
>>>>
>>>> Amtsgericht Aachen - HRB 8057
>>>> Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
>>>> Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch
>>>>
>>>
>>
>>
> 
> 


-- 
aixigo AG - financial solutions & technology
Karl-Friedrich-Straße 68, 52072 Aachen, Germany
fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de

Amtsgericht Aachen - HRB 8057
Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch

Re: RollingRandomAccessFileAppender does not wait for compression to complete on LogContext.stop()

Posted by Steffen Offermann <st...@aixigo.de>.
I think I didn't make this clear: we stop the log system before the process exits - and hence the JVM shuts down. So the problem occurs when the JVM shuts down while the compression is still being 
executed.

Regards,
   Steffen

On 02.05.19 11:33, Steffen Offermann wrote:
> 
> Hi, Remko!
> 
> I'm afraid that's very difficult to do, as the problem is apparently caused by a race condition. The test would have to make sure that the log file compression has already started and is still being 
> executed when the log system is being shut down.
> 
> But from what I can see when I look at the sources, it's quite obvious that there is mechanism implemented that waits for the compression to finish before the log system is shut down.
> 
> Regards,
>    Steffen
> 
> 
> On 30.04.19 23:45, Remko Popma wrote:
>> Can you provide a unit test or minimal project that reproduces the problem?
>>
>> On Tue, Apr 30, 2019 at 3:26 PM Steffen Offermann <
>> steffen.offermann@aixigo.de> wrote:
>>
>>> Hi, guys!
>>>
>>> We are having problems with Log4j because it apparently does not wait for
>>> currently running asynchronous operations to finish when the log system is
>>> being stopped/shut down.
>>>
>>> We use LoggerContext.stop() with a timeout of 60 seconds. According to the
>>> documentation of LoggerContext.stop() this should block until the log file
>>> compression completes:
>>>
>>>   >     * Log4j can start threads to perform certain actions like file
>>> rollovers, calling this method with a positive timeout will
>>>   >     * block until the rollover thread is done.
>>>
>>> Unfortunately that does not seem to be the case, and it leads to
>>> incomplete (and hence unusable) log files in production.
>>>
>>> Are there any plans on fixing this, or are there any known workarounds?
>>>
>>> Thanks,
>>>      Steffen
>>>
>>> -- 
>>> aixigo AG - financial solutions & technology
>>> Karl-Friedrich-Straße 68, 52072 Aachen, Germany
>>> fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
>>> eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de
>>>
>>> Amtsgericht Aachen - HRB 8057
>>> Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
>>> Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch
>>>
>>
> 
> 


-- 
aixigo AG - financial solutions & technology
Karl-Friedrich-Straße 68, 52072 Aachen, Germany
fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de

Amtsgericht Aachen - HRB 8057
Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch

Re: RollingRandomAccessFileAppender does not wait for compression to complete on LogContext.stop()

Posted by Steffen Offermann <st...@aixigo.de>.
Hi, Remko!

I'm afraid that's very difficult to do, as the problem is apparently caused by a race condition. The test would have to make sure that the log file compression has already started and is still being 
executed when the log system is being shut down.

But from what I can see when I look at the sources, it's quite obvious that there is mechanism implemented that waits for the compression to finish before the log system is shut down.

Regards,
   Steffen


On 30.04.19 23:45, Remko Popma wrote:
> Can you provide a unit test or minimal project that reproduces the problem?
> 
> On Tue, Apr 30, 2019 at 3:26 PM Steffen Offermann <
> steffen.offermann@aixigo.de> wrote:
> 
>> Hi, guys!
>>
>> We are having problems with Log4j because it apparently does not wait for
>> currently running asynchronous operations to finish when the log system is
>> being stopped/shut down.
>>
>> We use LoggerContext.stop() with a timeout of 60 seconds. According to the
>> documentation of LoggerContext.stop() this should block until the log file
>> compression completes:
>>
>>   >     * Log4j can start threads to perform certain actions like file
>> rollovers, calling this method with a positive timeout will
>>   >     * block until the rollover thread is done.
>>
>> Unfortunately that does not seem to be the case, and it leads to
>> incomplete (and hence unusable) log files in production.
>>
>> Are there any plans on fixing this, or are there any known workarounds?
>>
>> Thanks,
>>      Steffen
>>
>> --
>> aixigo AG - financial solutions & technology
>> Karl-Friedrich-Straße 68, 52072 Aachen, Germany
>> fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
>> eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de
>>
>> Amtsgericht Aachen - HRB 8057
>> Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
>> Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch
>>
> 


-- 
aixigo AG - financial solutions & technology
Karl-Friedrich-Straße 68, 52072 Aachen, Germany
fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de

Amtsgericht Aachen - HRB 8057
Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch

Re: RollingRandomAccessFileAppender does not wait for compression to complete on LogContext.stop()

Posted by Remko Popma <re...@gmail.com>.
Can you provide a unit test or minimal project that reproduces the problem?

On Tue, Apr 30, 2019 at 3:26 PM Steffen Offermann <
steffen.offermann@aixigo.de> wrote:

> Hi, guys!
>
> We are having problems with Log4j because it apparently does not wait for
> currently running asynchronous operations to finish when the log system is
> being stopped/shut down.
>
> We use LoggerContext.stop() with a timeout of 60 seconds. According to the
> documentation of LoggerContext.stop() this should block until the log file
> compression completes:
>
>  >     * Log4j can start threads to perform certain actions like file
> rollovers, calling this method with a positive timeout will
>  >     * block until the rollover thread is done.
>
> Unfortunately that does not seem to be the case, and it leads to
> incomplete (and hence unusable) log files in production.
>
> Are there any plans on fixing this, or are there any known workarounds?
>
> Thanks,
>     Steffen
>
> --
> aixigo AG - financial solutions & technology
> Karl-Friedrich-Straße 68, 52072 Aachen, Germany
> fon: +49 (0)241 559709-65, fax: +49 (0)241 559709-99
> eMail: steffen.offermann@aixigo.de, web: http://www.aixigo.de
>
> Amtsgericht Aachen - HRB 8057
> Vorstand: Erich Borsch, Christian Friedrich, Tobias Haustein
> Vors. des Aufsichtsrates: Prof. Dr. Rüdiger von Nitzsch
>