Dynamic Logging with Conditions

02 May 2021 • logging

This is going to be a quick blog post about dynamic logging – changing the logging behavior of the application while it's still running without recompiling.

The code is available at https://github.com/wsargent/blindsight-groovy.

Dynamic logging is important for diagnostic purposes, when you want to investigate a particular bug, and for bandwidth purposes, when you want to stop a particular logging message spamming you. I've talked a bit about enabling targeted logging using feature flags and conditions, but this does require some extra set up, and there are simpler solutions.

Blindsight has the notion of conditional logging built in using Condition

val clogger = logger.withCondition(condition)

or on the statement itself:

logger.info.when(condition) { info => info("log") }

A condition has to return Boolean but is intentionally left open so that anything can be a condition. This means that we can tie a condition to a JSR 223 script.

In this example, we'll use Groovy to evaluate a condition and return a boolean.

So. We run the program. While the program is running, we edit the Groovy script. The code will reload the script as soon as the file's last modification date is changed, and we can turn on and off individual logging statements at run time.

Here's the example program:

object Main {

  val logger: Logger = LoggerFactory.getLogger(getClass)
  val cm = new ConditionManager(Paths.get("src/main/groovy/condition.groovy"), "groovy")

  def main(args: Array[String]): Unit = {
    // Run from a loop
    while (true) {
      logInfo()
      logDebug()
      logInfoSpecial()
      logDebugSpecial()

      Thread.sleep(1000L)
    }
  }

  def logInfo(): Unit = {
    logger.info.when(cm.condition()) { info =>
      info("Logging at a info level")
    }
  }

  def logInfoSpecial(): Unit = {
    logger.info.when(cm.condition()) { info =>
      info("Logging at a info level from special method")
    }
  }

  def logDebugSpecial(): Unit = {
    logger.debug.when(cm.condition()) { debug =>
      debug("Logging at a debug level from special method")
    }
  }

  def logDebug(): Unit = {
    logger.debug.when(cm.condition()) { debug =>
      debug("Logging at a debug level")
    }
  }
}

One of the things we get for free in Scala is source code location access using SourceCode.
When we log using cm.condition(), the enclosing method and file name is compiled into the code using macros, so the code really looks like this:

def logDebugSpecial(): Unit = {
  // condition(enclosing =`"com.tersesystems.blindsight.groovy.Main.logInfoSpecial")
  logger.debug.when(cm.condition()) { debug =>
    debug("Logging at a debug level from special method")
  }
}

From there, we can expose that Enclosing to the script:

import com.tersesystems.blindsight.Markers
import org.slf4j.event.Level
import sourcecode.Enclosing
import sourcecode.File

boolean evaluate(Level level, Markers markers, Enclosing enclosing, File file) {
    var enc = enclosing.value()
    
    // We like this debug message so we want it to show up
    if (enc == "com.tersesystems.blindsight.groovy.Main.logDebugSpecial") {
        return true;
    }

    // We don't like this info message
    if (enc == "com.tersesystems.blindsight.groovy.Main.logInfoSpecial") {
        return false;
    }

    // Otherwise we'll just use info level.
    return (level.toInt() >= Level.INFO.toInt())
}

So the end result is that you can turn off or on logging on a method basis, without touching Logback, having to write a special filter, or integrating with feature flags. For example, we flip com.tersesystems.blindsight.groovy.Main.logInfoSpecial to return true instead of false and you can see it pop up at 19086:

18031 INFO  c.t.blindsight.groovy.Main$ - Logging at a info level
18033 DEBUG c.t.blindsight.groovy.Main$ - Logging at a debug level from special method
19085 INFO  c.t.blindsight.groovy.Main$ - Logging at a info level
19086 INFO  c.t.blindsight.groovy.Main$ - Logging at a info level from special method
19087 DEBUG c.t.blindsight.groovy.Main$ - Logging at a debug level from special method
20089 INFO  c.t.blindsight.groovy.Main$ - Logging at a info level
20091 INFO  c.t.blindsight.groovy.Main$ - Logging at a info level from special method
20092 DEBUG c.t.blindsight.groovy.Main$ - Logging at a debug level from special method

Because this is a full on Groovy script, you can also add arbitrary logic into it, for example sampling, adding temporal logic, calling out to system properties and environment variables, and even call System.exit(). This level of power does mean that it's a security risk, but you can use a different scripting language like Tweakflow that gives the application more power over execution.

Also note that this is an intentionally trivial example for the purposes of demonstration, and a condition source may come from any text-base stream, so Redis, Consul KV, or ctlstore all work as places where you can store conditions.