[logback-user] Logging outage in WebLogic with RollingFileAppender

Roxolid roxolid84 at gmail.com
Wed Apr 17 13:26:03 CEST 2013


Hi Ceki,

ouch, I didn't notice that debug flag! Just copied the configuration file
from the real application we use... Nevertheless, when I changed it,
redeployed and tested again, the only thing I can see in the server's log
is:

13:03:47,487 |-INFO in
ch.qos.logback.classic.jmx.JMXConfigurator(TST-LOGBACK) - onReset() method
called JMXActivator
[ch.qos.logback.classic:Name=TST-LOGBACK,Type=ch.qos.logback.classic.jmx.JMXConfigurator]

When I (re)deploy the app, I can see (as expected) a lot of statements from
Logback during its initialization. However, when I stop/start the
application, nothing like that happens. Looks like logback is not
reinitializing in such case.

Thank you.

Best regards,
rox



On Wed, Apr 17, 2013 at 11:59 AM, ceki <ceki at qos.ch> wrote:

> It very much helps to set <configuration debug="true">  when diagnosing
> logback-related problems. If debug="true" logback might actually tell you
> why it stops logging after app restart. I suspect that the underlying issue
> is caused by jmxConfigurator which probably throws an exception the second
> time it is started in your particular environment.
>
>
>
>
> On 17.04.2013 11:45, Roxolid wrote:
>
>> Hi Ceki,
>>
>> first of all, here is my configuration file, I'm copy-pasting it as we
>> have (is almost identical to the one from all applications we develop
>> now):
>>
>> <?xml version="1.0" encoding="UTF-8"?>
>> <configuration debug="false">
>>      <contextName>TST-LOGBACK</**contextName>
>>      <jmxConfigurator/>
>>
>>      <turboFilter class="ch.qos.logback.classic.**turbo.MarkerFilter">
>>          <Marker>PROFILER</Marker>
>>          <OnMatch>ACCEPT</OnMatch>
>>      </turboFilter>
>>
>>      <property name="AUDIT_LOG_DIR" value="/export/home/oracle/**TESTS/tst"
>> />
>>      <property name="AUDIT_LOG_FILE" value="tst-logback-audit.log" />
>>      <property name="PERF_LOG_DIR" value="/export/home/oracle/**TESTS/tst"
>> />
>>      <property name="PERF_LOG_FILE" value="tst-logback-perf.log" />
>>      <property name="LOG_DIR" value="/export/home/oracle/**TESTS/tst" />
>>      <property name="LOG_FILE" value="tst-logback.log" />
>>      <property name="LOG_FILE_ROLLING" value="tst-logback" />
>>
>>      <appender name="FILE"
>> class="ch.qos.logback.core.**rolling.RollingFileAppender">
>>          <prudent>true</prudent>
>>          <rollingPolicy
>> class="ch.qos.logback.core.**rolling.**TimeBasedRollingPolicy">
>>              <!-- daily rollover with
>> ${LOG_DIR}/${LOG_FILE_ROLLING}**_%d{yyyy-MM-dd}.log -->
>>              <!-- hourly rollover with
>> ${LOG_DIR}/${LOG_FILE_ROLLING}**_%d{yyyy-MM-dd_HH}.log -->
>>              <!-- every minute rollover with
>> ${LOG_DIR}/${LOG_FILE_ROLLING}**_%d{yyyy-MM-dd_HH_mm}.log -->
>>
>> <fileNamePattern>${LOG_DIR}/${**LOG_FILE_ROLLING}_%d{yyyy-MM-**
>> dd_HH}.log</fileNamePattern>
>>              <!-- keep 30 days' worth of history -->
>>              <maxHistory>48</maxHistory>
>>          </rollingPolicy>
>>          <encoder>
>>              <pattern>%date %level [%thread] %logger{10} [%file:%line]
>> %msg%n</pattern>
>>          </encoder>
>>      </appender>
>>
>>      <appender name="AUDIT_FILE" class="ch.qos.logback.core.**
>> FileAppender">
>>          <file>${AUDIT_LOG_DIR}/${**AUDIT_LOG_FILE}</file>
>>          <encoder>
>>              <pattern>%date %level %logger{10} %msg%n</pattern>
>>          </encoder>
>>      </appender>
>>
>>      <appender name="PERF_FILE" class="ch.qos.logback.core.**
>> FileAppender">
>>          <file>${PERF_LOG_DIR}/${PERF_**LOG_FILE}</file>
>>          <encoder>
>>              <pattern>%date [%thread] %logger{10} %msg%n</pattern>
>>          </encoder>
>>      </appender>
>>
>>      <appender name="STDOUT" class="ch.qos.logback.core.**
>> ConsoleAppender">
>>          <encoder>
>>              <pattern>%date %level [%file:%line] %msg</pattern>
>>          </encoder>
>>      </appender>
>>
>>      <logger name="com.oracle.sk.tst" level="trace" additivity="false">
>>          <appender-ref ref="FILE" />
>>      </logger>
>>
>>      <logger name="com.oracle.sk.tst.**logback.TestLogbackServlet"
>> level="info" additivity="false">
>>          <appender-ref ref="FILE" />
>>      </logger>
>>
>>      <logger name="AUDITOR" level="trace" additivity="false">
>>          <appender-ref ref="AUDIT_FILE" />
>>      </logger>
>>
>>      <logger name="PROFILER" level="debug" additivity="false">
>>          <appender-ref ref="PERF_FILE" />
>>      </logger>
>>
>>      <root level="OFF">
>>          <appender-ref ref="FILE" />
>>      </root>
>> </configuration>
>>
>> The prudent flag is there because I had troubles with truncating log
>> files by our test people. They use "cat /dev/null/ >
>> tst-logback_2013-04-17_10.log" to clear the log when they start testing.
>> Without "prudent", application was not able to recover from it and was
>> not logging anymore.
>>
>> Maybe you want to look at complete testing project I use for solving
>> this issue. I try to attach it to this email (don't know if attachments
>> are allowed for this mailing list). And if you wish I can provide you
>> with small (~2 min, ~13MB, FLV) video demostrating the behavior.
>>
>> I did further testing and found one thing - after stopping and starting
>> the app it was not able to recover even after rollover (on my dev
>> machine with the testing project). The report from testing team says
>> that they've seen it recovers when the new log file was rolled out,
>> however now no one can remember if really :-) So I consider this as
>> "not, it didn't recover" - at least I'm not able to prove that.
>>
>> So after all, when I stop/start the app, it will stop logging...
>>
>> Thank you for your help, I really appreciate it.
>>
>> Regards,
>> rox
>>
>> P.S.: BTW, even it has no impact to this issue, just for interest's
>> sake, I think I found why I had lc.reset() in my code - in
>> documentation, the example uses stop(), however the text above mentions
>> reset().
>>
>>
>>
>> On Tue, Apr 16, 2013 at 5:31 PM, ceki <ceki at qos.ch <mailto:ceki at qos.ch>>
>>
>> wrote:
>>
>>
>>     LoggerContext.close() is almost identical to
>>     LoggerContext.reset(). Here is the code:
>>
>>     class LoggerContext ... {
>>
>>        public void stop() {
>>          reset();
>>          fireOnStop();
>>          resetAllListeners();
>>          started = false;
>>        }
>>     }
>>
>>     I don't think calling reset or close should make a difference. You
>>     want to release and close appenders which reset() does.  Could you
>>     post your configuration file?
>>
>>
>>     On 16.04.2013 16:59, Roxolid wrote:
>>
>>         Hi Ceki,
>>
>>         well, half-true in my case... I have that code in my
>>         contextDestroyed(..) method, however, for whatever reason I have
>>         lc.reset() instead of lc.stop there... Will change and test that
>>         once
>>         I'm back to my dev machine. I will let you know then.
>>
>>         Thank you for your help.
>>
>>         Regards,
>>         rox
>>
>>
>>
>>         On Tue, Apr 16, 2013 at 4:01 PM, ceki <ceki at qos.ch
>>         <mailto:ceki at qos.ch> <mailto:ceki at qos.ch <mailto:ceki at qos.ch>>>
>>
>>
>>         wrote:
>>
>>              Hi Rox,
>>
>>              Are you stopping logback when your application is stopped
>>         (and then
>>              started)? The conextDestroyed method of
>>              javax.servlet.____**ServletContextListener is a good place
>>         for invoking
>>              such code:
>>
>>              import javax.servlet.____**ServletContextListener;
>>              import javax.servlet.____**ServletContextEvent;
>>              import org.slf4j.LoggerFactory;
>>              import ch.qos.logback.classic.____**LoggerContext;
>>
>>
>>
>>              public class MyServletContextListener implements
>>
>> ServletContextListener {
>>
>>                 public void contextInitialized(____**ServletContextEvent
>>         sce) {
>>                 }
>>
>>                 public void contextDestroyed(____**ServletContextEvent
>> sce)  {
>>                   LoggerContext lc =
>>                             (LoggerContext)
>>         LoggerFactory.____**getILoggerFactory();
>>
>>
>>                   lc.stop();
>>              }
>>
>>              Please let us know if stopping logback as described above
>>         helps.
>>
>>
>>              On 16.04.2013 15:06, Roxolid wrote:
>>
>>                  Hi all,
>>
>>                  I have a trouble with logback configuration under
>>         WebLogic 12c. My
>>                  application is using RollingFile Appender with
>>                  TimeBasedRollingPolicy
>>                  and the problem is it stops logging every time I stop
>>         and then
>>                  start the
>>                  application through WebLogic Console. However, the
>>         logging is
>>                  back when
>>                  a rollover occurs - in the new file logging continues...
>>
>>                  Has anyone faced such behavior (and knows the solution)?
>>
>>                  Thank you in advance.
>>
>>                  Regards,
>>
>>                  rox
>>
>>
>>
>>
> --
> Ceki
> 65% of statistics are made up on the spot
> ______________________________**_________________
> Logback-user mailing list
> Logback-user at qos.ch
> http://mailman.qos.ch/mailman/**listinfo/logback-user<http://mailman.qos.ch/mailman/listinfo/logback-user>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20130417/5e5807da/attachment.html>


More information about the Logback-user mailing list