logging – Tona Consulting

A customer of mine got sometimes the following exception in his catalina.out log.

ERROR in ch.qos.logback.core.joran.spi.Interpreter@23:25 - RuntimeException in Action for tag [rollingPolicy] java.lang.IndexOutOfBoundsException: No group 1
at java.lang.IndexOutOfBoundsException: No group 1
at at java.util.regex.Matcher.group(Matcher.java:470)
at at ch.qos.logback.core.rolling.helper.FileFilterUtil.extractCounter(FileFilterUtil.java:109)
at at ch.qos.logback.core.rolling.helper.FileFilterUtil.findHighestCounter(FileFilterUtil.java:93)
at at ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP.computeCurrentPeriodsHighestCounterValue(SizeAndTimeBasedFNATP.java:65)
at at ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP.start(SizeAndTimeBasedFNATP.java:49)
at at ch.qos.logback.core.rolling.TimeBasedRollingPolicy.start(TimeBasedRollingPolicy.java:87)
at at ch.qos.logback.core.joran.action.NestedComplexPropertyIA.end(NestedComplexPropertyIA.java:167)
at at ch.qos.logback.core.joran.spi.Interpreter.callEndAction(Interpreter.java:318)
at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:197)
at at ch.qos.logback.core.joran.spi.Interpreter.endElement(Interpreter.java:183)
at at ch.qos.logback.core.joran.spi.EventPlayer.play(EventPlayer.java:62)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:147)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:133)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:96)
at at ch.qos.logback.core.joran.GenericConfigurator.doConfigure(GenericConfigurator.java:55)
at at ch.qos.logback.classic.util.ContextInitializer.configureByResource(ContextInitializer.java:75)
at at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:148)
at at org.slf4j.impl.StaticLoggerBinder.init(StaticLoggerBinder.java:84)
at at org.slf4j.impl.StaticLoggerBinder.(StaticLoggerBinder.java:54)
at at org.slf4j.LoggerFactory.bind(LoggerFactory.java:121)
at at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:111)
at at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:268)
at at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:241)
at at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:156)
at at org.apache.commons.logging.impl.SLF4JLogFactory.getInstance(SLF4JLogFactory.java:132)
at at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:645)
at at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:184)
at at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:47)
at at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:3972)
at at org.apache.catalina.core.StandardContext.start(StandardContext.java:4467)
at at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:791)
at at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771)
at at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:546)
at at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1041)
at at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:964)
at at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:502)
at at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1277)
at at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:321)
at at org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:119)
at at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053)
at at org.apache.catalina.core.StandardHost.start(StandardHost.java:785)
at at org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045)
at at org.apache.catalina.core.StandardEngine.start(StandardEngine.java:443)
at at org.apache.catalina.core.StandardService.start(StandardService.java:519)
at at org.apache.catalina.core.StandardServer.start(StandardServer.java:710)
at at org.apache.catalina.startup.Catalina.start(Catalina.java:581)

Turns out the problem was with his logback.xml configuration file –

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${env.PANORAMA_HOME}/var/log/panorama-sl.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <!-- daily rollover -->
        <fileNamePattern>${env.PANORAMA_HOME}/var/log/panorama-sl.%d{yyyy-MM-dd}.log.gz</fileNamePattern>
                                         
        <timeBasedFileNamingAndTriggeringPolicy   class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- or whenever the file size reaches 100MB -->
            <maxFileSize>100MB</maxFileSize>
       </timeBasedFileNamingAndTriggeringPolicy>
    <!-- keep 10 files worth of history -->
        <maxHistory>10</maxHistory>
    </rollingPolicy>
               
    <Append>true</Append>
    <encoder>
        <!-- default ISO date format enables lexical sorting of dates -->
        <pattern>%-30.-30(%date %level) [%-50.-50thread] %logger{25} %msg%n</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>ALL</level>
    </filter>
</appender>

Since sometimes the log file size was bigger than 100MB, QOS needed to roll the log file – but couldn’t, since the log file format didn’t include a counter. The correct configuration is:

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${env.PANORAMA_HOME}/var/log/panorama-sl.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <!-- daily rollover -->
        <fileNamePattern>${env.PANORAMA_HOME}/var/log/panorama-sl.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
                                         
        <timeBasedFileNamingAndTriggeringPolicy   class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- or whenever the file size reaches 100MB -->
            <maxFileSize>100MB</maxFileSize>
       </timeBasedFileNamingAndTriggeringPolicy>
    <!-- keep 10 files worth of history -->
        <maxHistory>10</maxHistory>
    </rollingPolicy>
               
    <Append>true</Append>
    <encoder>
        <!-- default ISO date format enables lexical sorting of dates -->
        <pattern>%-30.-30(%date %level) [%-50.-50thread] %logger{25} %msg%n</pattern>
    </encoder>
    <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        <level>ALL</level>
    </filter>
</appender>