Logging - have binding and persistence logs to own files - but also main log

As part of Pulling data from a really big JSON string I found out how to create individual logs (using the zwave binding page).

So I put in some logging for mysql and http just for giggles. I have then set to debug and they’re happily writing to their own files.

But they also seem to be writing to the main openhab log. How can I leave mysql info messages in openhab.log and keeping the debug level detail in the mysql.log?

Unless you changed this line:

<logger name="org.openhab" level="INFO"/>

everything in openhab.log should be at the INFO level.

If you created your own log appender and logger entry for mysql and http then you shouldn’t be seeing any of the logs from these bindings in your openhab.log file at all.

Hmm,

Still set to
<logger name="org.openhab" level="INFO"/>

And yet in the openhab.log
2016-07-26 08:24:48.622 [DEBUG] [.p.m.i.MysqlPersistenceService] - mySQL: query: INSERT INTO Item72 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;
2016-07-26 08:24:48.624 [DEBUG] [.p.m.i.MysqlPersistenceService] - mySQL query: item is br_master_temperature
2016-07-26 08:24:48.626 [DEBUG] [.p.m.i.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item72 WHERE TIME>‘2016-07-26 00:00:00’ ORDER BY Time ASC
2016-07-26 08:24:48.628 [DEBUG] [.p.m.i.MysqlPersistenceService] - mySQL: query returned 10 rows in 3ms
2016-07-26 08:24:48.651 [DEBUG] [.p.m.i.MysqlPersistenceService] - mySQL query: item is br_master_temperature
2016-07-26 08:24:48.653 [DEBUG] [.p.m.i.MysqlPersistenceService] - mySQL: query:SELECT Time, Value FROM Item72 WHERE TIME>‘2016-07-26 00:00:00’ ORDER BY Time ASC
2016-07-26 08:24:48.657 [DEBUG] [.p.m.i.MysqlPersistenceService] - mySQL: query returned 10 rows in 4ms

Not sure if I can post the entire logback.xml…but here goes.

        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
                <encoder>
                        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}] - %msg%n</pattern>
                </encoder>
        </appender>

        <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>${openhab.logdir:-logs}/openhab.log</file>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                        <!-- weekly rollover and archiving -->
                        <fileNamePattern>${openhab.logdir:-logs}/openhab-%d{yyyy-ww}.log.zip</fileNamePattern>
                        <!-- maximum number of archive files to keep -->
                        <maxHistory>30</maxHistory>
                </rollingPolicy>
                <encoder>
                        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}] - %msg%n</pattern>
                </encoder>
        </appender>

        <appender name="EVENTFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>${openhab.logdir:-logs}/events.log</file>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                        <!-- weekly rollover and archiving -->
                        <fileNamePattern>${openhab.logdir:-logs}/events-%d{yyyy-ww}.log.zip</fileNamePattern>
                        <!-- maximum number of archive files to keep -->
                        <maxHistory>30</maxHistory>
                </rollingPolicy>
                <encoder>
                        <pattern>%d{yyyy-MM-dd HH:mm:ss} - %msg%n</pattern>
                </encoder>
        </appender>

        <logger name="runtime.busevents" level="INFO" additivity="false">
                <appender-ref ref="EVENTFILE" />
                <appender-ref ref="STDOUT" />
        </logger>

        <logger name="org.openhab" level="INFO"/>

        <!-- this class gives an irrelevant warning at startup -->
        <logger name="org.atmosphere.cpr.AtmosphereFramework" level="ERROR" />

        <!-- temporary workaround for https://github.com/openhab/jmdns/issues/12 -->
        <logger name="javax.jmdns" level="OFF"/>

        <!-- temporary workaround for https://bugs.eclipse.org/bugs/show_bug.cgi?id=402750 -->
        <logger name="OSGi" level="OFF" />

        <!-- temporary workaround to circumvent error messages with any obvious effect -->
        <logger name="org.atmosphere.cpr.AtmosphereFramework" level="OFF" />
        <logger name="org.atmosphere.cpr.DefaultAnnotationProcessor" level="OFF" />

        <!-- Z WAVE Logger -->
        <appender name="ZWAVEFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
           <file>${openhab.logdir:-logs}/zwave.log</file>
           <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
              <!-- weekly rollover and archiving -->
              <fileNamePattern>${openhab.logdir:-logs}/zwave-%d{yyyy-ww}.log.zip</fileNamePattern>
              <!-- keep 30 days' worth of history -->
              <maxHistory>30</maxHistory>
           </rollingPolicy>
           <encoder>
             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}:%-4line]- %msg%n</pattern>
           </encoder>
        </appender>
        <!-- Change DEBUG->TRACE for even more detailed logging -->
        <logger name="org.openhab.binding.zwave" level="INFO" additivity="false">
           <appender-ref ref="ZWAVEFILE" />
        </logger>

        <!-- HTTP Binding Logger -->
        <appender name="HTTPFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
           <file>${openhab.logdir:-logs}/http.log</file>
           <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
              <!-- weekly rollover and archiving -->
              <fileNamePattern>${openhab.logdir:-logs}/http-%d{yyyy-ww}.log.zip</fileNamePattern>
              <!-- keep 30 days' worth of history -->
              <maxHistory>30</maxHistory>
           </rollingPolicy>
           <encoder>
             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}:%-4line]- %msg%n</pattern>
           </encoder>
        </appender>
        <!-- Change DEBUG->TRACE for even more detailed logging -->
        <logger name="org.openhab.binding.http" level="DEBUG" additvity="false">
                <appender-ref ref="HTTPFILE" />
        </logger>

        <!-- SQL Binding Logger -->
        <appender name="MYSQLFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
           <file>${openhab.logdir:-logs}/mysql.log</file>
           <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
              <!-- weekly rollover and archiving -->
              <fileNamePattern>${openhab.logdir:-logs}/mysql-%d{yyyy-ww}.log.zip</fileNamePattern>
              <!-- keep 30 days' worth of history -->
              <maxHistory>30</maxHistory>
           </rollingPolicy>
           <encoder>
             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}:%-4line]- %msg%n</pattern>
           </encoder>
        </appender>
        <!-- Change DEBUG->TRACE for even more detailed logging -->
        <logger name="org.openhab.persistence.mysql" level="DEBUG" additvity="false">
                <appender-ref ref="MYSQLFILE" />
        </logger>

        <root level="WARN">
                <appender-ref ref="FILE" />
                <appender-ref ref="STDOUT" />
        </root>

</configuration>

OK, try moving the appenders to before ALL of the loggers. Think logback sets the loggers up as it parses the XML file. So when it parses the org.openhab logger it doesn’t know about the MYSQLFILE appender yet so it tells those classes to use that logger. Then later it learns about MYSQLFILE appender and it adds that appender instead of replaces it.

I could be completely off base here on how it works but I know when I use other appenders for debugging I always put the appenders first and then the loggers.

I also put the loggers for my special classes before the org.openhab logger so that might make a difference too.

Tried that, didn’t seem to have any effect. Also I tried making it look a little like the events one by adding the stdout, but that had no effect etither.

Still getting all the logging in openhab.log and the specific log.

Here is my logback.xml file to see if you can find any other differences. When I uncomment the Nest or Zwave loggers all those logs only go to that file.

<configuration scan="true">

        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
                <encoder>
                        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}] - %msg%n</pattern>
                </encoder>
        </appender>

        <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>${openhab.logdir:-logs}/openhab.log</file>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                        <!-- weekly rollover and archiving -->
                        <fileNamePattern>${openhab.logdir:-logs}/openhab-%d{yyyy-ww}.log.zip</fileNamePattern>
                        <!-- maximum number of archive files to keep -->
                        <maxHistory>30</maxHistory>
                </rollingPolicy>
                <encoder>
                        <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}] - %msg%n %nopex</pattern>
                </encoder>
        </appender>

        <appender name="EVENTFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
                <file>${openhab.logdir:-logs}/events.log</file>
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                        <!-- weekly rollover and archiving -->
                        <fileNamePattern>${openhab.logdir:-logs}/events-%d{yyyy-ww}.log.zip</fileNamePattern>
                        <!-- maximum number of archive files to keep -->
                        <maxHistory>30</maxHistory>
                </rollingPolicy>
                <encoder>
                        <pattern>%d{yyyy-MM-dd HH:mm:ss} - %msg%n</pattern>
                </encoder>
        </appender>

        <appender name="ZWAVEFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>${openhab.logdir:-logs}/zwave.log</file>
            <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                <fileNamePattern>logs/zwave-%d{yyyy-ww}.log.zip</fileNamePattern>
                <maxHistory>30</maxHistory>
            </rollingPolicy>
            <encoder>
                <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}:%-4line]- %msg%n</pattern>
            </encoder>
        </appender>

        <appender name="NESTFILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>${openhab.logdir:-logs}/nest.log</file>
            <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                <fileNamePattern>logs/nest-%d{yyyy-ww}.log.zip</fileNamePattern>
                <maxHistory>30</maxHistory>
            </rollingPolicy>
            <encoder>
                <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] [%-30.30logger{36}:%-4line]- %msg%n</pattern>
            </encoder>
        </appender>

        <!-- Change DEBUG->TRACE for even more detailed logging -->

          <logger name="org.openhab.binding.zwave" level="INFO" additivity="false">
            <appender-ref ref="ZWAVEFILE" />
          </logger>

   <!--     <logger name="org.openhab.binding.nest" level="TRACE" additivity="false">
            <appender-ref ref="NESTFILE" />
        </logger> -->

        <!--<logger name="runtime.busevents" level="ERROR" additivity="false">
                <appender-ref ref="EVENTFILE" />
                <appender-ref ref="STDOUT" />
        </logger>-->

        <!-- <logger name="org.openhab.persistence.mapdb" level="DEBUG" /> -->

        <logger name="org.openhab" level="INFO"/>

        <!-- this class gives an irrelevant warning at startup -->
        <logger name="org.atmosphere.cpr.AtmosphereFramework" level="ERROR" />

        <!-- temporary workaround for https://github.com/openhab/jmdns/issues/12 -->
        <logger name="javax.jmdns" level="OFF"/>

        <!-- temporary workaround for https://bugs.eclipse.org/bugs/show_bug.cgi?id=402750 -->
        <logger name="OSGi" level="OFF" />

        <!-- temporary workaround to circumvent error messages with any obvious effect -->
        <logger name="org.atmosphere.cpr.AtmosphereFramework" level="OFF" />
        <logger name="org.atmosphere.cpr.DefaultAnnotationProcessor" level="OFF" />
        <!--<logger name="org.openhab.binding.zwave" level="TRACE"/> -->
        <!--<logger name="org.openhab.io.transport.mqtt" level="TRACE"/> -->
        <logger name="org.eclipse.jetty.io.nio" level="ERROR"/>

        <root level="WARN">
                <appender-ref ref="FILE" />
                <appender-ref ref="STDOUT" />
        </root>

</configuration>

Well I followed yours, and swapped the definitions to the top, and allocations to the definitions to the bottom…but didn’t’ seem to have an effect for me. Doesn’t matter…I’ve quietened up the mysql which I had set to debug and that makes it manageable.