[
https://issues.apache.org/jira/browse/LOG4J2-3018?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17285062#comment-17285062
]
Ralph Goers commented on LOG4J2-3018:
-------------------------------------
Almost everything looks correct. Almost.
First we see Default being started followed by DefaultError, implying that log
records have arrived for those routes. However, I don't see a "Now writing to"
message for Default. But we can see it was written to as we next see the
rolling message at midnight followed by the message indicating the file was
compressed. Then we see the "Now writing to" message for Default for today's
date.
Next we see two new RollingFileAppenders being created. The Database appender
logs the "Now writing to" messge with the correct date for both appenders.
Finally we see something logged to DefaultError but with the wrong date. I am
at a loss to explain why it took 13 minutes from the time the
RollingFileAppender was created until it opened the output stream, but the fact
that it calculated the time on the 15th and didn't open the file until the 16th
explains why the date is wrong. However, it is notable that only Weblogic
messages appear during that 13 minute gap.
The next log event to that file should force a rollover.
{code:java}
2021-02-15 23:47:56,034 [ACTIVE] ExecuteThread: '5' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG Starting RollingFileManager
/mastars/log/Default_%d{yyyy-MM-dd}.log.gz
2021-02-15 23:47:56,069 [ACTIVE] ExecuteThread: '5' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG Starting RollingFileManager
/mastars/log/DefaultError_%d{yyyy-MM-dd}.log.gz
2021-02-16 00:00:00,419 [ACTIVE] ExecuteThread: '0' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG Rolling
/mastars/log/Default_2021-02-15.log
2021-02-16 00:00:00,423 [ACTIVE] ExecuteThread: '0' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG RollingFileManager executing
async GzCompressAction[/mastars/log/Default_2021-02-15.log to
/mastars/log/Default_2021-02-15.log.gz, deleteSource=true]
2021-02-16 00:00:00,426 [ACTIVE] ExecuteThread: '0' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG Now writing to
/mastars/log/Default_2021-02-16.log at 2021-02-16T00:00:00.426-0500
2021-02-16 00:00:10,603 [ACTIVE] ExecuteThread: '9' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG Starting RollingFileManager
/mastars/log/Database_%d{yyyy-MM-dd}.log.gz
2021-02-16 00:00:10,607 [ACTIVE] ExecuteThread: '9' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG Now writing to
/mastars/log/Database_2021-02-16.log at 2021-02-16T00:00:10.607-0500
2021-02-16 00:00:10,628 [ACTIVE] ExecuteThread: '9' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG Starting RollingFileManager
/mastars/log/DatabaseError_%d{yyyy-MM-dd}.log.gz
2021-02-16 00:00:11,041 [ACTIVE] ExecuteThread: '9' for queue:
'weblogic.kernel.Default (self-tuning)' DEBUG Now writing to
/mastars/log/DatabaseError_2021-02-16.log at 2021-02-16T00:00:11.041-0500
2021-02-16 00:00:11,128 Thread-39 DEBUG Now writing to
/mastars/log/DefaultError_2021-02-15.log at 2021-02-16T00:00:11.128-0500{code}
I should point out that with the way I believe you have the appenders
configured they will only be created when a log event arrives that matches the
Route. So these may or may not be instantiated when your server first starts.
If you want to guarantee that they start at server startup then declare the
RollingFileAppenders outside the RoutingAppender as in the example below.
{code:java}
<RollingFile name="Rolling-xxxxInfo"
filePattern="${LOG_PATH}/xxxx_%d{yyyy-MM-dd}.log.gz" >
<LevelRangeFilter minLevel="INFO" maxLevel="INFO" onMatch="ACCEPT"
onMismatch="DENY" />
<PatternLayout pattern="${LOG_PATTERN}" />
<Policies>
<TimeBasedTriggeringPolicy interval="1" modulate="true" />
</Policies>
</RollingFile>
<Routing name="DEBUG">
<Routes pattern="$${ctx:ServiceName}">
<Route key="xxxx" ref="Rolling-xxxxInfo"/>
<Route key="yyyy" ref="Rolling-yyyyInfo"/>
<Route ref="Rolling-DefaultInfo"/>
</Routes>
</Routing>{code}
I should note that in the log4j2.xml attached to this issue I didn't see a
default route being declared, so any log event that doesn't have a matching
Route will be ignored by the RoutingAppender.
> Rollover log file at midnight not working
> -----------------------------------------
>
> Key: LOG4J2-3018
> URL: https://issues.apache.org/jira/browse/LOG4J2-3018
> Project: Log4j 2
> Issue Type: Bug
> Reporter: Rambabu Bikumandla
> Priority: Blocker
> Labels: log4j2.xml, routing
> Attachments: gz_onBothOldNewFile.log, log4j2.xml, log4j2.xml
>
>
> Hi Team,
> I am migrating my project from log4j1.x to log4j2.11.2 version, while
> migration am seeing below issue could you please provide solution on it.
> *Log4j2 version :*
> *log4j-slf4j-impl-2.11.2*
> *log4j-1.2-api-2.11.2*
> *log4j-1.2-core-2.11.2*
> Issue: log files are not roll out every day midnight with new file name, it
> still writing it to old logs for some hours then switching to new logs.
> Below my log4j2.xml config.
> <Routing name="DEBUG">
> <Routes pattern="$${ctx:ServiceName}">
> <Route key="ConsuerManager">
> <RollingFile name="Rolling-${ctx:ServiceName}"
> {color:#ff0000}*fileName="/app/log/Consumer_${date:yyyy-MM-dd}.log*{color}"
> *{color:#ff0000}filePattern="/app/log/Consumer_%d\{yyyy-MM-dd}.log{color}*"
> append="true">
> <LevelRangeFilter minLevel="INFO" maxLevel="DEBUG" onMatch="ACCEPT"
> onMismatch="DENY" />
> <PatternLayout pattern="${LOG_PATTERN}" />
> <Policies>
> <TimeBasedTriggeringPo licy interval="1" modulate="true" />
> </Policies>
> </RollingFile>
> </Route>
> <Route key="AppProvider">
> <RollingFile name="Rolling-${ctx:ServiceName}"
> fileName="/app/log/Provider_${date:yyyy-MM-dd}.log"
> filePattern="/app/log/Provider_%d\{yyyy-MM-dd}.log" append="true">
> <LevelRangeFilter minLevel="INFO" maxLevel="DEBUG" onMatch="ACCEPT"
> onMismatch="DENY" />
> <PatternLayout pattern="${LOG_PATTERN}" />
> <Policies>
> <TimeBasedTriggeringPolicy interval="1" modulate="true" />
> </Policies></RollingFile></Route>
> </Routes>
> </Routing>
> *Sample Logs: consumer_2021-02-08.log - It should contain only Feb-08 but we
> are seeing Feb-09 also*
> [Feb/08/21 18:18:37] INFO com.app.apptest.Database.DbRequest - approval
> status of the myno: 125478412 Is ::W
> [Feb/08/21 18:18:37] INFO
> com.myapp.servicecore.ejb.monitor.AppTestsEJBMonitor
> [Feb/08/21 18:18:37] INFO
> com.myapp.servicecore.ejb.monitor.AppTestsEJBMonitor
> [Feb/08/21 18:18:37] INFO com.bi.myapp.consumer.utils.ConsumerHelper -
> conditional status for the myno ::4857154 is :: false
> [Feb/08/21 18:18:37] INFO com.app.apptest.Database.Database - Database
> initialized
> [Feb/08/21 18:18:37] INFO com.app.apptest.MyManagement.Database - Database
> initialized
> [Feb/08/21 18:18:38] INFO com.app.apptest.Database.DbTtion - mynoId :123456
> mynoID :45678
> [Feb/08/21 18:18:38] INFO com.bi.persistent.process.DBProcess - db is
> ::org.apache.db.oracle.DBCommandOracle@516c36a0
> [Feb/08/21 18:18:38] INFO com.bi.persistent.process.DBProcess - db is
> ::org.apache.db.oracle.DBCommandOracle@4ee951e2
> [{color:#FF0000}Feb/08/21 18:18:38{color}] INFO
> com.bi.myapp.restclients.CircuitImpactClient - constructor: Using environment
> Test to get URL info
> ..
> ..
> {color:#FF0000}[Feb/09/21 12:37:43{color}] INFO com.bi.myapp.util.Client -
> connectToId: Trying to connect to mail server;
> [Feb/09/21 12:37:44] INFO com.bi.myapp.util.Client - connectToId:
> Successfully connected to .
> [Feb/09/21 12:37:45] INFO com.bi.myapp.util.Client - readMails: There are 0
> messages to be processed
> [Feb/09/21 12:37:45] INFO com.bi.myapp.util.Client - readMails: Number of
> unread messages still in the
> [Feb/09/21 12:37:45] INFO
> com.myapp.servicecore.ejb.monitor.AppTestsEJBMonitor - updateLock invoked at
> 12:37:45 PM GMT took 3 milliseconds to execute.
> [Feb/09/21 12:37:45] INFO com.bi.myapp.scheduler.EmailReaderScheduler -
> ~
> "consumer_2021-02-08.log" [readonly] 6327556L, 273633483C
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
