Issue Type: Bug Bug
Affects Versions: 1.0.13
Assignee: Logback dev list
Components: logback-core
Created: 02/Jul/13 11:49 PM
Description:

Our app is a java app with multiple jvms involved. That is, the main java app starts other java apps as sub-processes by launching them via java's ProcessBuilder. All java apps here use the same logback.xml and log info to the same log file, $

{THE_LOG_DIR}/hhss-%d{yyyy-MM-dd-HH-mm}.%i.log.zip.

Here is the logback.xml used:

<configuration debug="false" scan="true">
<property name="THE_LOG_DIR" value="C:/ProgramData/HH/SS/LOG"/>
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${THE_LOG_DIR}

/hhss-%d

{yyyy-MM-dd-HH-mm}

.%i.log.zip</fileNamePattern>
<maxHistory>30</maxHistory>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>5MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
</rollingPolicy>
<encoder>
<pattern>%d

{dd MMM yyyy HH:mm:ss.SSS}

%X

{process}

[%thread] %-5level %logger

{36}

- %msg%n</pattern>
</encoder>
</appender>
<root level="debug">
<appender-ref ref="FILE"/>
</root>

</configuration>

The test case is divided into 3 steps:

1). First tested the simplest case where the main app had no any java sub-process. In this(single jvm) case, the zip file was created with no problem and the original to-be-zipped (or unzipped)files were deleted. that's what is expected;

2). Let the main app start just one java sub-process. In this (2-jvm) case, both apps kept logging info to the same log file. It was found that the logging data was not heavy, and almost all unzipped files were removed after the compression but there were some left behind;

3). The main java app started all java sub-processes (totally 6) and some of them logged info heavily to the same log file. As you can see from the logback.xml above, the rotation and zip compression occurred every minute. In this (multi-jvm)case, the zip files were created by logback with no problem, but almost all the unzipped files were left behind.

So the item 2). and 3). are not what we expect. why did it happen? I checked the relevant class, ch.qos.logback.core.rolling.helper.Compressor and found the method zipCompress(...) indeed has a deletion operation over the old unzipped files,

if (!file2zip.delete())

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

but in a multi-jvm environment (maybe a multi-threading env has the same issue), it was found that the deletion cannot be happened. Why? Here is my explanation.

1). The compression process is asynchronous (via AsynchronousCompressor.java). The various jvms might hold the file's handle to log info to the same log file alternatively. If a jvm is not the owner of the file handle at the zip compression time, then it might not have privileges to delete the unzipped file because it is being held by another jvm. If no SecurityManager is set, then the File.delete() only returns a boolean false, nothing else;
2). Tn the method zipCompress(...), the above piece of code is called only after the zip compression is successfully done. It implies when the zip compression is only done by a jvm, then the deletion is executed by the same jvm. It didn't consider a special case: due to the compression's asynchronous feature, a jvm can do the zip compression, and another jvm can do the deletion operation immediately after the zip compression. I indeed found such case in our testing: before the main java app did the zip compression, it was found that the zip file was already created by another jvm. In this case, the current code didn't handle it right, I think(still in the method of zipCompress(...))

if (zippedFile.exists())

{ addStatus(new WarnStatus("The target compressed file named [" + nameOfZippedFile + "] exist already.", this)); return; }

It did not do any thing, and then quit. since the jvm which zipped the file didn't get the file handle at the time, the jvm can also not delete the unzipped file. the file was left behind. The more the jvm are, the more unzipped files are left behind.

A possible solution to fix it is simple - adding a few lines to the block,

if (zippedFile.exists())
{
addStatus(new WarnStatus("The target compressed file named [" + nameOfZippedFile + "] exist already.", this));
try
{
Path path = FileSystems.getDefault().getPath(nameOfFile2zip);
while(!Files.deleteIfExists(path))

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

}
catch (Exception e)

{ addStatus(new WarnStatus("Could not delete [" + nameOfFile2zip + "].", this)); }
catch (Throwable t)
{ addStatus(new WarnStatus("Could not delete [" + nameOfFile2zip + "].", this)); }

return;
}

That is, even the zip file is found existing (it might be created by another jvm), the current jvm should still delete the unzipped file since it own the file handle at the time.

I have tested the change in the case 3). where all java jvms (6 jvms)share the same logback.xml and log to the same log file. it worked as expected.

Environment:

OS: windows 2008 server R2 (64 bits)
java version: jse 1.7.0_21

Project: logback
Labels: none
Priority: Major Major
Reporter: Mike J
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira