logback autoscan is not working intermittently in k8s pod

8/10/2021

Intermittently facing issue related to logback where it is not generating logs as per the latest logger levels configured even though ConfigMap gets updated successfully.

I was just updating logger level for io.kubernetes.client.extended.leaderelection.LeaderElector from debug to error and vice versa.

logback.xml is as below:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 second" debug="true">

    <property scope="context" name="APP_INSTANCE" value="${APP_INSTANCE}" />
    <property scope="context" name="NODE_NAME" value="${NODE_NAME}" />
    <property scope="context" name="HOSTNAME" value="${HOSTNAME}" />

    <property name="DEFAULT_PATTERN" value="%d{ISO8601} [%thread] %-5level %logger{36} - %msg%n" />

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
      <encoder>
        <pattern>${DEFAULT_PATTERN}</pattern>
      </encoder>
    </appender>

  <appender name="SOCKET" class="ch.qos.logback.classic.net.SocketAppender">
      <remoteHost>consolidated-logging</remoteHost>
      <port>5644</port>
      <reconnectionDelay>10000</reconnectionDelay>
  </appender>

  <appender name="GRPCv2" class="com.logging.appenders.GrpcStreamAppenderV2">
      <host>consolidated-logging</host>
      <port>5644</port>
      <instanceInfo>${APP_INSTANCE}</instanceInfo>
  </appender>

  <appender name="GRPC" class="com.logging.appenders.GrpcStreamAppender">
      <remoteHost>consolidated-logging</remoteHost>
      <port>5644</port>
      <instanceInfo>${APP_INSTANCE}</instanceInfo>
  </appender>

  <appender name="ASYNC" class="com.logging.appenders.AsynchAppender">
      <appender-ref ref="STDOUT" />
      <appender-ref ref="GRPCv2" />
  </appender>

  <!-- Configure Loggers -->
  <!-- 3rd party Loggers-->
  <logger name="com.danga" level="warn" />
  <logger name="com.google" level="info"/>
  <logger name="com.springsource" level="error" />
  <logger name="httpclient.wire" level="warn" />
  <logger name="net.rubyeye.xmemcached" level="info"/>
  <logger name="org" level="warn"/>
  <logger name="org.apache.activemq.transport.InactivityMonitor" level="warn" />
  <logger name="org.apache.commons.httpclient" level="warn" />
  <logger name="org.eclipse" level="warn" />
  <logger name="org.springframework" level="warn" />
  <logger name="org.springframework.osgi.extensions.annotation.ServiceReferenceDependencyBeanFactoryPostProcessor" level="error" />
  <logger name="sun.rmi.tranrsport.tcp" level="warn" />
  <logger name="org.jdiameter.client.impl.transport.tcp.TCPTransportClient" level="off"/>

  <!-- QPS Loggers -->
  <logger name="ch.qos.logback" level="trace"/>
  <logger name="io.etcd.jetcd" level="error"/>
  <logger name="io.grpc" level="error"/>
  <logger name="io.kubernetes.client.extended.leaderelection.LeaderElector" level="error"/>
  <logger name="policy.engine" level="debug"/>
  <logger name="transaction.log" level="info"/>

  <!-- Configure default Loggers -->
  <root level="trace">
    <appender-ref ref="ASYNC" />
  </root>

versions: logback-classic, logback-core 1.2.3, slf4j-api 1.7.28

As per ls -la pod output, symbolic links too get modified properly on pod(but pod logs do not indicate autoScan getting triggered even after this point)

root@rest-ep-85597b67b7-7dwjz:/etc/logback# ls -la
total 12
drwxrwxrwx 3 root root 4096 Aug 10 05:40 .
drwxr-xr-x 1 root root 4096 Aug 10 05:07 ..
drwxr-xr-x 2 root root 4096 Aug 10 05:40 ..2021_08_10_05_40_05.423996728
lrwxrwxrwx 1 root root   31 Aug 10 05:40 ..data -> ..2021_08_10_05_40_05.423996728
lrwxrwxrwx 1 root root   18 Aug 10 05:06 logback.xml -> ..data/logback.xml
root@rest-ep-85597b67b7-7dwjz:/etc/logback#

Heap dump shows that lastModifiedList in ConfigurationWatchList does not get modified to represent the latest timestamp when log level was updated. Can this be because of symbolic link or something else ?

Also found below details from link but not sure if this is what really happening

In short, when a configuration file changes, it will be automatically reloaded but only after several logger invocations and after a delay determined by the scanning period.

-- Kedar
java
kubernetes
logging

0 Answers