logback.xml in /etc/opentsdb ignored

[kylebrandt]

I have the following in /etc/opentsdb/logback.xml, but I get INFO messages /var/log/opentsdb/opentsdb-ny-tsdb03.ds.stackexchange.com-opentsdb.out

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <!--<jmxConfigurator/>-->
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>
        %d{ISO8601} %-5level [%thread] %logger{0}: %msg%n
      </pattern>
    </encoder>
  </appender>

  <appender name="CYCLIC" class="ch.qos.logback.core.read.CyclicBufferAppender">
    <MaxSize>1024</MaxSize>
  </appender>

  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>/var/log/opentsdb/opentsdb.log</file>
    <append>true</append>

    <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
      <fileNamePattern>/var/log/opentsdb/opentsdb.log.%i</fileNamePattern>
      <minIndex>1</minIndex>
      <maxIndex>3</maxIndex>
    </rollingPolicy>

    <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
      <maxFileSize>128MB</maxFileSize>
    </triggeringPolicy>

    <!-- encoders are assigned the type
         ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} %-5level [%logger{0}.%M] - %msg%n</pattern>
    </encoder>
  </appender>

  <logger name="org.apache.zookeeper" level="WARN"/>
  <logger name="org.hbase.async" level="WARN"/>
  <logger name="com.stumbleupon.async" level="WARN"/>
  <root level="WARN">
    <appender-ref ref="STDOUT"/>
    <appender-ref ref="CYCLIC"/>
    <appender-ref ref="FILE"/>
  </root>
</configuration>

[oozie]

I was unable to reproduce this undesired behavior with 2.0 or 2.1RC with your logback.xml, in both cases the logger works as expected:

14:13:00.195 INFO  [ConnectionManager.handleUpstream] - [id: 0xc48f0735, /192.168.1.64:60855 :> /192.168.1.67:4242] CLOSED
14:31:56.626 INFO  [TSDB.shutdown] - Flushing compaction queue
#            vvvv--- note that INFO will continue to be recorded before new config is re-read
14:31:56.639 INFO  [CompactionQueue.flush] - Flushing all old outstanding rows out of 2341 rows
14:31:56.786 INFO  [HBaseClient.removeClientFromCache] - Lost connection with the .META. region
14:32:02.979 WARN  [PluginLoader.loadPlugins] - Unable to locate any plugins of the type: net.opentsdb.tsd.HttpSerializer

...
[ no log for healthy queries ]
...

14:33:02.901 ERROR [HttpQuery.logError] - [id: 0xa88d0745, /192.168.1.64:60914 => /192.168.1.67:4242] Internal Server Error on /api/query?start=1w-ago&m=min:24h-min:myme
ric&no_annotations=1
net.opentsdb.uid.NoSuchUniqueName: No such name for 'metrics': 'mymeric'
        at net.opentsdb.uid.UniqueId$1GetIdCB.call(UniqueId.java:281) ~[tsdb-2.1.0RC1.jar:60d9b78]
        at net.opentsdb.uid.UniqueId$1GetIdCB.call(UniqueId.java:278) ~[tsdb-2.1.0RC1.jar:60d9b78]
        at com.stumbleupon.async.Deferred.doCall(Deferred.java:1278) ~[suasync-1.4.0.jar:fe17b98]
        at com.stumbleupon.async.Deferred.addCallbacks(Deferred.java:688) ~[suasync-1.4.0.jar:fe17b98]

Has TSDB been restarted since the config update?

[manolama]

Sounds like it could be picking up the wrong logback file. It can be pretty finicky. Can you look for alternate logback.xml files and check your classpath to see if it was scooped up somewhere else?

[kylebrandt]

Don't think that is the case. /etc/opentsdb/logback.xml is the only logback.xml on the system.

root     18357  521  1.5 17583104 2074140 pts/0 Sl  16:32   4:36 java -DLOG_FILE_PREFIX=/var/log/opentsdb/opentsdb-ny-tsdb03.ds.stackexchange.com- -enableassertions -enablesystemassertions -Xmx6000m -XX:OnOutOfMemoryError=/usr/share/opentsdb/tools/opentsdb_restart.py -classpath /usr/share/opentsdb/*.jar:/usr/share/opentsdb:/usr/share/opentsdb/bin:/usr/share/opentsdb/lib/asynchbase-1.6.0.jar:/usr/share/opentsdb/lib/guava-18.0.jar:/usr/share/opentsdb/lib/jackson-annotations-2.4.3.jar:/usr/share/opentsdb/lib/jackson-core-2.4.3.jar:/usr/share/opentsdb/lib/jackson-databind-2.4.3.jar:/usr/share/opentsdb/lib/log4j-over-slf4j-1.7.7.jar:/usr/share/opentsdb/lib/logback-classic-1.0.13.jar:/usr/share/opentsdb/lib/logback-core-1.0.13.jar:/usr/share/opentsdb/lib/netty-3.9.4.Final.jar:/usr/share/opentsdb/lib/protobuf-java-2.5.0.jar:/usr/share/opentsdb/lib/slf4j-api-1.7.7.jar:/usr/share/opentsdb/lib/suasync-1.4.0.jar:/usr/share/opentsdb/lib/tsdb-2.1.0RC1.jar:/usr/share/opentsdb/lib/zookeeper-3.3.6.jar:/usr/share/opentsdb/etc/opentsdb net.opentsdb.tools.TSDMain --config=/etc/opentsdb/opentsdb.conf

[manolama]

Yep, classpath issue. Your CP has /usr/share/opentsdb/etc/opentsdb specified so if you dump the logback in there it will be picked up. Or change that path in the cp.

Was this from one of the package installs? We should fix the script in that case.

[kylebrandt]

Yes this was an RPM generated via OpenTSDB's make script. I had moved the logback.xml as a workaround, but would be nice to have it right again.

On Sun, Apr 19, 2015 at 10:21 PM, Chris Larsen notifications@github.com wrote:

Yep, classpath issue. Your CP has /usr/share/opentsdb/etc/opentsdb specified so if you dump the logback in there it will be picked up. Or change that path in the cp.

Was this from one of the package installs? We should fix the script in that case.

— Reply to this email directly or view it on GitHub https://github.com/OpenTSDB/opentsdb/issues/443#issuecomment-94341360.

[johann8384]

The two are conditionally symlinked in the RPM spec, perhaps this is an issue with an upgrade?

if [ $1 -eq 1 ]; then
  # we're installing the first version of this package
  ln -s %{_datarootdir}/opentsdb/etc/opentsdb /etc/opentsdb
  ln -s %{_datarootdir}/opentsdb/etc/init.d/opentsdb /etc/init.d/opentsdb
fi