My problem is now down to finding out how logback (or the java app) can hold *two* file handles for the same file. I managed to verify that having the file open in another process, like glogg, when the rollover happened was enough to trigger the issue. Using Process Explorer from SysInternals or the Resource Monitor would show the file handle being used by both processes and after closing the other process. Once the other process was closed, another logging statement would then again trigger the rollover and delete the file (*usually*): [image: Skjermbilde 2021-06-23 kl. 00.56.54.png][image: Skjermbilde 2021-06-23 kl. 00.50.34.png] The problem is that sometimes this situation arose: [image: Skjermbilde 2021-06-23 kl. 00.15.44.png] There are three file handles, of which two belong to the java process. Killing the external process this time did nothing, as the java process itself prevented itself from deleting the file. I am not sure how this can happen? This is the real issue here. Either it is one thread holding two references or two threads holding one each. Trying to find out how to see which code/class/instance owns these file handles is a problem of its own <https://stackoverflow.com/questions/68091703/find-out-which-class-instance-holds-a-reference-to-an-open-file>. If you have any tips on how I can find out, please give me a tip - not rocking the OQL :) Seeing that I am able to verify the issue quite easily on the server (lowering the file size for rollover to 50KB and opening the file in a log viewer) makes me optimistic that I should be able to verify it locally, as well. I think one fix for this issue is to simply try and truncate the file on failing to delete, as writing obviously works. That would get rid of the entire "recompress entire log file on each log statement" behavior it currently displays, without any immediate downsides, AFAIK. tir. 22. jun. 2021 kl. 17:28 skrev Carl-Erik Kopseng <carlerik@diffia.com>:
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
-- Carl-Erik Kopseng Senior developer Diffia AS m: +47 400 65 078 <+4740065078> a: StartupLab, Gaustadalléen 21, 0349, Oslo, Norway <https://maps.google.com/?q=Gaustadall%C3%A9en+21,+0349,+Oslo,+norway&entry=gmail&source=g> <https://www.facebook.com/diffia/> <https://www.linkedin.com/company/10602313/>
