[logback-user] Unsuccessful delete in FixedWindowRollingPolicy causes disk trashing and cpu at 100%

[Carl-Erik Kopseng]

Hi, for some weeks we have observed some really mysterious behavior when
enabling one of our appenders. This appender was configured specially to
use the `FixedWindowRollingPolicy`. What we observed, was that after some
time of debug logging, the CPU would suddenly hit the roof and have at
least one core fully pegged at 100%. Using Jprofiler we found the issue to
be various cases of `logger.debug()` that would be used by this special
appender. Disabling the appender immediately fixed the issue (as we have
`scan=true`)

I debugged this yesterday and found the answer partly in the logs and in
the logback code. This is the line that basically shows the issue:

   if (!file2zip.delete()) {
        addStatus(new WarnStatus("Could not delete [" + nameOfFile2zip
+ "].", this));
    }


The logs were full of this and I also found references to this online. I
documented the entire process and findings in this repo:
https://github.com/fatso83/logback-bug. The repo also contains a minimal
attempt at recreating what I saw on the Windows servers on my local
machine.

I was unable to reproduce this locally, which I kind of need in order to
fix this bug. So, I was just wondering if any of you had any tips? What
could cause the file to be "locked" / prevented from being deleted? Would
it be enough if someone had a read-handle on the file, for instance a log
reader like `glogg <https://glogg.bonnefon.org>`? I made sure to close my
own programs when looking at this, but there are multiple users that look
at these logs.

There is a single JVM running this app.

-- 
Carl-Erik Kopseng
Senior developer
Diffia AS
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20210622/ac064468/attachment.html>