[
https://issues.apache.org/jira/browse/LOG4J2-1906?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16147401#comment-16147401
]
Antonio Tarricone edited comment on LOG4J2-1906 at 8/30/17 3:12 PM:
--------------------------------------------------------------------
I've the same trouble.
Below log4j configuration used:
{code:java}
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="trace" monitorInterval="30">
<Appenders>
<RollingFile name="RollingFile"
filePattern="rollingfile.%d{yyyy-MM-dd-HH-mm}.log">
<PatternLayout pattern="%d{DEFAULT} [%level] [%c]
%msg%n" />
<Policies>
<TimeBasedTriggeringPolicy />
</Policies>
<DirectWriteRolloverStrategy />
</RollingFile>
</Appenders>
<Loggers>
<Root level="trace">
<AppenderRef ref="RollingFile" />
</Root>
</Loggers>
</Configuration>
{code}
and the sample code:
{code:java}
package log4j2test;
import java.io.IOException;
import java.io.InputStream;
import java.util.Date;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.config.ConfigurationSource;
import org.apache.logging.log4j.core.config.Configurator;
public class Main {
public static void main(String[] args) throws IOException,
InterruptedException {
InputStream inputStream = null;
try {
inputStream = Main.class.getResourceAsStream("test.xml");
ConfigurationSource configurationSource = new
ConfigurationSource(inputStream);
Configurator.initialize(null, configurationSource);
Logger logger = LogManager.getRootLogger();
for (int i = 0; i < 18; i++) {
System.out.println(new Date());
logger.trace("This is a test!");
Thread.sleep(5000);
}
} finally {
if (inputStream != null) {
inputStream.close();
}
}
}
}
{code}
>From log4j log, you can see:
{code:java}
2017-08-30 17:02:59,295 main DEBUG Now writing to
rollingfile.2017-08-30-17-02.log at 2017-08-30T17:02:59.294+0200
2017-08-30 17:03:04,306 main DEBUG Now writing to
rollingfile.2017-08-30-17-02.log at 2017-08-30T17:03:04.305+0200
2017-08-30 17:04:04,343 main DEBUG Now writing to
rollingfile.2017-08-30-17-03.log at 2017-08-30T17:04:04.343+0200
{code}
Below the content of rollingfile.2017-08-30-17-02.log:
{code:java}
2017-08-30 17:02:59,292 [TRACE] [] This is a test!
2017-08-30 17:03:04,297 [TRACE] [] This is a test!
2017-08-30 17:03:09,310 [TRACE] [] This is a test!
2017-08-30 17:03:14,311 [TRACE] [] This is a test!
2017-08-30 17:03:19,315 [TRACE] [] This is a test!
2017-08-30 17:03:24,315 [TRACE] [] This is a test!
2017-08-30 17:03:29,316 [TRACE] [] This is a test!
2017-08-30 17:03:34,316 [TRACE] [] This is a test!
2017-08-30 17:03:39,318 [TRACE] [] This is a test!
2017-08-30 17:03:44,318 [TRACE] [] This is a test!
2017-08-30 17:03:49,319 [TRACE] [] This is a test!
2017-08-30 17:03:54,323 [TRACE] [] This is a test!
2017-08-30 17:03:59,324 [TRACE] [] This is a test!
{code}
and the content of rollingfile.2017-08-30-17-03.log:
{code:java}
2017-08-30 17:04:04,325 [TRACE] [] This is a test!
2017-08-30 17:04:09,348 [TRACE] [] This is a test!
2017-08-30 17:04:14,348 [TRACE] [] This is a test!
2017-08-30 17:04:19,349 [TRACE] [] This is a test!
2017-08-30 17:04:24,350 [TRACE] [] This is a test!
{code}
It's the same with version 2.9.
was (Author: fabriziolxxiii):
I've the same trouble.
Below log4j configuration used:
{{<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="trace" monitorInterval="30">
<Appenders>
<RollingFile name="RollingFile"
filePattern="rollingfile.%d{yyyy-MM-dd-HH-mm}.log">
<PatternLayout pattern="%d{DEFAULT} [%level] [%c]
%msg%n" />
<Policies>
<TimeBasedTriggeringPolicy />
</Policies>
<DirectWriteRolloverStrategy />
</RollingFile>
</Appenders>
<Loggers>
<Root level="trace">
<AppenderRef ref="RollingFile" />
</Root>
</Loggers>
</Configuration>}}
and the sample code:
{{package log4j2test;
import java.io.IOException;
import java.io.InputStream;
import java.util.Date;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.config.ConfigurationSource;
import org.apache.logging.log4j.core.config.Configurator;
public class Main {
public static void main(String[] args) throws IOException,
InterruptedException {
InputStream inputStream = null;
try {
inputStream = Main.class.getResourceAsStream("test.xml");
ConfigurationSource configurationSource = new
ConfigurationSource(inputStream);
Configurator.initialize(null, configurationSource);
Logger logger = LogManager.getRootLogger();
for (int i = 0; i < 18; i++) {
System.out.println(new Date());
logger.trace("This is a test!");
Thread.sleep(5000);
}
} finally {
if (inputStream != null) {
inputStream.close();
}
}
}
}}}
>From log4j log, you can see:
{{2017-08-30 17:02:59,295 main DEBUG Now writing to
rollingfile.2017-08-30-17-02.log at 2017-08-30T17:02:59.294+0200
2017-08-30 17:03:04,306 main DEBUG Now writing to
rollingfile.2017-08-30-17-02.log at 2017-08-30T17:03:04.305+0200
2017-08-30 17:04:04,343 main DEBUG Now writing to
rollingfile.2017-08-30-17-03.log at 2017-08-30T17:04:04.343+0200
}}
Below the content of rollingfile.2017-08-30-17-02.log:
{{2017-08-30 17:02:59,292 [TRACE] [] This is a test!
2017-08-30 17:03:04,297 [TRACE] [] This is a test!
2017-08-30 17:03:09,310 [TRACE] [] This is a test!
2017-08-30 17:03:14,311 [TRACE] [] This is a test!
2017-08-30 17:03:19,315 [TRACE] [] This is a test!
2017-08-30 17:03:24,315 [TRACE] [] This is a test!
2017-08-30 17:03:29,316 [TRACE] [] This is a test!
2017-08-30 17:03:34,316 [TRACE] [] This is a test!
2017-08-30 17:03:39,318 [TRACE] [] This is a test!
2017-08-30 17:03:44,318 [TRACE] [] This is a test!
2017-08-30 17:03:49,319 [TRACE] [] This is a test!
2017-08-30 17:03:54,323 [TRACE] [] This is a test!
2017-08-30 17:03:59,324 [TRACE] [] This is a test!
}}
and teh content of rollingfile.2017-08-30-17-03.log:
{{2017-08-30 17:04:04,325 [TRACE] [] This is a test!
2017-08-30 17:04:09,348 [TRACE] [] This is a test!
2017-08-30 17:04:14,348 [TRACE] [] This is a test!
2017-08-30 17:04:19,349 [TRACE] [] This is a test!
2017-08-30 17:04:24,350 [TRACE] [] This is a test!
}}
It's the same with version 2.9.
> DirectWriteRolloverStrategy not properly creating files
> -------------------------------------------------------
>
> Key: LOG4J2-1906
> URL: https://issues.apache.org/jira/browse/LOG4J2-1906
> Project: Log4j 2
> Issue Type: Bug
> Affects Versions: 2.8.2
> Reporter: João Santos
> Assignee: Ralph Goers
>
> The DirectWriteRolloverStrategy is not properly determining the filename of
> the new log file after the rollover happens.
> With the following configuration:
> {noformat}
> <RollingFile name="ApplicationLog"
> filePattern="application.log.%d{yyyy-MM-dd-HH-mm}">
> <PatternLayout>
> <Pattern>%m%n</Pattern>
> </PatternLayout>
> <Policies>
> <TimeBasedTriggeringPolicy />
> <SizeBasedTriggeringPolicy />
> </Policies>
> <DirectWriteRolloverStrategy />
> </RollingFile>
> {noformat}
> What is happening is, for instance:
> - application starts at 09h35m30s
> - at instant 09h35m55s a new log is written the rollover is set to happen at
> 09h36m00s, log line is written to application.log.2017-05-10-09-35 - OK
> - at instant 09h36m05s a new log is written and the rollover is triggered,
> after the rollover logs are written to application.log.2017-05-10-09-35 - Not
> OK
> - at instant 09h37m05s a new log is written and the rollover is triggered,
> after the rollover logs are written to application.log.2017-05-10-09-36 - Not
> OK
> This seems to be happening because
> DirectWriteRolloverStrategy.getCurrentFileName (when being called from
> createFileAfterRollover) is calling the PatternProcessor.formatFileName and
> telling it to use the currentTime. However, currentFileTime is zero, and it
> will fallback to the prevFileTime to determine the filename, which is wrong
> as it will be one minute before current time.
> It should probably either use the nextFileTime (while debugging I could see
> that it was set to the correct time, the minute I expect the file to
> rollover), or use the System time.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
