Logback appender not matching package, logging to console instead

Question

One of my appenders is logging to console instead of to a file. I have a couple of applications with logback perfectly working, one of them with more than ten appenders. I'm now configuring a new one just the same way, but I just can't seem to make it work.

<!-- General -->
<appender name="MAIN_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${log.folder}/main.log</file>
    <encoder>
        <pattern>%d{"yyyy-MM-dd HH:mm:ss,SSS zzz"}, level="%le", %n%caller{2}, message="%msg" %n</pattern>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${log.folder}/main.log.%d</fileNamePattern>
    </rollingPolicy>
</appender>

<logger name="com.mycompany.crawler" level="INFO" additivity="false">
    <appender-ref ref="MAIN_APPENDER"/>
</logger>

<root level="INFO">
    <appender-ref ref="MAIN_APPENDER"/>
</root>

<!-- Requests to Google Maps API -->
<appender name="GOOGLE_MAPS_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${log.folder}/maps-requests.log</file>
    <encoder>
        <pattern>%d{"yyyy-MM-dd HH:mm:ss,SSS zzz"}, level="%le", %n%caller{2}, message="%msg" %n</pattern>
    </encoder>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <fileNamePattern>${log.folder}/maps-requests.log.%d</fileNamePattern>
    </rollingPolicy>
</appender>

<logger name="com.google.maps" level="DEBUG" additivity="false">
    <appender-ref ref="GOOGLE_MAPS_APPENDER"/>
</logger>

Is this second GOOGLE_MAPS_APPENDER what is not working. It logs to the console instead of to the file maps-requests.log. Messages in the console look like:

Dec 06, 2016 12:53:29 PM com.google.maps.OkHttpRequestHandler handle
INFO: Request: https://maps.googleapis.com/maps/api/place/details/json?key=xxxxxxxxxx&placeid=yyyyyy&language=ar
Dec 06, 2016 12:53:31 PM com.google.maps.OkHttpRequestHandler handle
INFO: Request: https://maps.googleapis.com/maps/api/place/details/json?key=xxxxxxxxxx&placeid=yyyyyy&language=de

To my understanding those lines should be matched by the appender. I've also tried with com.google.maps.OkHttpRequestHandler, but same result. I can also confirm that the class OkHttpRequestHandler is writing to a log, not directly to console:

LOG.log(Level.INFO, "Request: {0}", hostName + url);

When I launch the application with maven, it says that the appender is correctly matched:

13:13:33,524 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
13:13:33,525 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [GOOGLE_MAPS_APPENDER]
13:13:33,525 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
13:13:33,527 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@480870659 - No compression will be used
13:13:33,527 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy@480870659 - Will use the pattern D://code//google-maps-middleware//target/log/maps-requests.log.%d for the active file
13:13:33,528 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'D://code//google-maps-middleware//target/log/maps-requests.log.%d'.
13:13:33,528 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
13:13:33,529 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Tue Dec 06 12:44:14 CET 2016
13:13:33,530 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[GOOGLE_MAPS_APPENDER] - Active log file name: D:\\code\\google-maps-middleware\\target/log/maps-requests.log
13:13:33,530 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[GOOGLE_MAPS_APPENDER] - File property is set to [D:\\code\\google-maps-middleware\\target/log/maps-requests.log]
13:13:33,531 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.google.maps] to DEBUG
13:13:33,531 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [com.google.maps] to false
13:13:33,531 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [GOOGLE_MAPS_APPENDER] to Logger[com.google.maps]
13:13:33,531 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
13:13:33,533 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@7009d85c - Registering current configuration as safe fallback point

I would think that the problem is that the class OkHttpRequestHandler is external to my application, but I am using this same schema in another application to match Hibernate packages and it works. What am I missing?

score 0 · Answer 1 · edited May 23 '17 at 12:24

0

The problem is that OkHttpRequestHandler uses java.util.logging instead of slf4j.

The solution was just to bind it as described in this answer.

edited May 23 '17 at 12:24

Community

1
1

answered Dec 06 '16 at 15:22

user3748908

885
2
9
26

And google-map-service changed from JUL to SLF4J [recently](https://github.com/googlemaps/google-maps-services-java/pull/186). You can follow up with the next release. – tan9 Dec 06 '16 at 15:27

Logback appender not matching package, logging to console instead

1 Answers1