Logback log level change not working

Question

I'm using an application called Apache Drill that uses logback for logging. I'm trying to edit it's shipped logback.xml configuration file to output debugging messages.

Here is the file, untouched

<?xml version="1.0" encoding="UTF-8" ?>
<!--
 Licensed to the Apache Software Foundation (ASF) under one or more
 contributor license agreements.  See the NOTICE file distributed with
 this work for additional information regarding copyright ownership.
 The ASF licenses this file to You under the Apache License, Version 2.0
 (the "License"); you may not use this file except in compliance with
 the License.  You may obtain a copy of the License at

     http://www.apache.org/licenses/LICENSE-2.0

 Unless required by applicable law or agreed to in writing, software
 distributed under the License is distributed on an "AS IS" BASIS,
 WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 See the License for the specific language governing permissions and
 limitations under the License.
-->
<configuration>
  <!--  <appender name="SOCKET"
    class="de.huxhorn.lilith.logback.appender.ClassicMultiplexSocketAppender">
    <Compressing>true</Compressing>
    <ReconnectionDelay>10000</ReconnectionDelay>
    <IncludeCallerData>true</IncludeCallerData>
    <RemoteHosts>${LILITH_HOSTNAME:-localhost}</RemoteHosts>
  </appender>
   -->

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

    <appender name="QUERY" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>${log.query.path}</file>
      <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
        <fileNamePattern>${log.query.path}.%i</fileNamePattern>
        <minIndex>1</minIndex>
        <maxIndex>10</maxIndex>
      </rollingPolicy>

      <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
        <maxFileSize>100MB</maxFileSize>
      </triggeringPolicy>
      <encoder>
        <pattern>%msg%n</pattern>
      </encoder>
    </appender>


    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
      <file>${log.path}</file>
      <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
        <fileNamePattern>${log.path}.%i</fileNamePattern>
        <minIndex>1</minIndex>
        <maxIndex>10</maxIndex>
      </rollingPolicy>

      <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
        <maxFileSize>100MB</maxFileSize>
      </triggeringPolicy>
      <encoder>
        <pattern>%date{ISO8601} [%thread] %-5level %logger{36} - %msg%n</pattern>
      </encoder>
    </appender>


  <logger name="org.apache.drill" additivity="false">
    <level value="info" />
    <appender-ref ref="FILE" />
  </logger>

  <logger name="query.logger" additivity="false">
    <level value="info" />
    <appender-ref ref="QUERY" />
    <!--     <appender-ref ref="SOCKET" /> -->
  </logger>

  <!-- 
  <logger name="org.apache.drill" additivity="false">
    <level value="debug" />
    <appender-ref ref="SOCKET" />
  </logger>
   -->

  <root>
    <level value="error" />
    <appender-ref ref="STDOUT" />
  </root>

</configuration>

All I did afterwards was editing

<logger name="org.apache.drill" additivity="false">
  <level value="info" />
  <appender-ref ref="FILE" />
</logger>

to be

<logger name="org.apache.drill" additivity="false">
  <level value="debug" />
  <appender-ref ref="FILE" />
</logger>

And absolutely nothing changed ! This is the java command used to start the application (Search for -cp /home/gelbana/drillv11/conf, the logback.xml file is located in the conf directory)

/usr/java/jdk1.8.0_112/bin/java -Xms10G -Xmx10G -XX:MaxDirectMemorySize=230G -XX:ReservedCodeCacheSize=1G -Ddrill.exec.enable-epoll=false -XX:MaxPermSize=512M -Djava.io.tmpdir=/home/gelbana/drillv11/tmp -Ddrill.memory.debug.allocator=true -XX:+CMSClassUnloadingEnabled -XX:+UseG1GC -Dlog.path=/home/gelbana/drillv11/log/drillbit.log -Dlog.query.path=/home/gelbana/drillv11/log/drillbit_queries.json -cp /home/gelbana/drillv11/conf:/home/gelbana/drillv11/jars/*:/home/gelbana/drillv11/jars/ext/*:/home/gelbana/drillv11/jars/3rdparty/*:/home/gelbana/drillv11/jars/classb/* org.apache.drill.exec.server.Drillbit

The drillbit.out file has the following lines at the beginning

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/home/gelbana/drillv11/jars/3rdparty/slf4j-simple-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/gelbana/drillv11/jars/classb/logback-classic-1.0.13.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.SimpleLoggerFactory]

I tried changing all levels to DEBUG, ALL but still, nothing changed. I can't find a single DBEUG in the logs.

Answer 1

The changes you made should work. I made the same change and ran a drillbit and I can see debug logs in drillbit.log. For example:

DEBUG o.a.drill.exec.server.StartupOptions - Parsing arguments.

The drillbit.out file should tell you something about how Logback configured itself. Have a look at that file, specifically the entries which relate to LoggerContext for example:

Found resource [logback.xml] at ...

Resource [logback.xml] occurs multiple times on the classpath

And you'll likely find that Logback relveals the answer via it's own logging.