Conditional Logging

No matter how fast your logging is, it’s always faster not to log a statement at all. Blindsight does its best to allow the system to not log as much as it makes it possible to log.

Blindsight has conditional logging on two levels; on the logger itself, and on the method. Conditional logging has access to the level and to the LoggerState available to the logger, but does not have access to individual statements.

Conditional logging is just as fast as adding a guard conditional wrapper around SLF4J statements and far more flexible. It provides the obvious use cases of “never” logging and logging based on given feature flags, and also allows for less intuitive use cases, such as time-limited logging conditions or JVM conditions that limit logging in response to high CPU or memory pressure.

Note

You should use Condition.never when disabling logging, as it will allow Blindsight to do some additional optimization, particularly with flow logging. Because conditions run through a logical AND, using Condition.never will return a “no-op” logger which will always return false and produce no output, and adding additional conditions afterwards has no effect.

On Condition

All loggers have an withCondition method that takes a Condition. You can look at a marker from the logger state:

val fooMarker              = MarkerFactory.getMarker("FOO")
val markerCondition        = Condition((stateMarkers: Markers) => stateMarkers.contains(fooMarker))
val conditionalOnFooMarker = logger.withCondition(markerCondition)

And look at the level as well:

val levelMarkerCondition = Condition((level, markers) =>
  (level.compareTo(Level.DEBUG) >= 0) && markers.contains(fooMarker)
)
val conditionalOnLevelAndMarker = logger.withCondition(levelMarkerCondition)

And you can also pass through anything that returns a boolean and it will take it as a call by name.

def booleanCondition: Boolean = sys.props("java.version").startsWith("1.8")
val conditionalLogger         = logger.withCondition(booleanCondition)
conditionalLogger.info("Only logs when condition is true")

Conditions will be stacked with a boolean AND:

def anotherCondition: Boolean = sys.props.get("user.home").isDefined
val bothConditionsLogger      = conditionalLogger.withCondition(anotherCondition)
bothConditionsLogger.info("Only logs when both conditions are true")

The conditions are not exposed from the logger, and clients should not peek under the hood.

When

By contrast, when is used on methods, rather than the logger, and provides a block that is executed only when the condition is true:

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

This is useful when constructing and executing a logging statement is expensive in itself, and allows for finer grained control.

You can, of course, partially apply when to return a function:

val infoFunction = logger.info.when(1 == 1)(_)
infoFunction(info => info("when true"))

It is generally easier to pass a conditional logger around rather than a logging function.

Conditional with Tracer Bullet

Conditional logging is very useful in conjunction with tracer-bullet logging, where you set a marker that is using a turbofilter with OnMatch=ACCEPT:

<turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
  <Name>TRACER_FILTER</Name>
  <Marker>TRACER</Marker>
  <OnMatch>ACCEPT</OnMatch>
</turboFilter> 

This means that you can bypass the logging system’s levels, and be sure that logging at a TRACE level will cause a logging event to be generated, even if the logger level is set to INFO.

val tracerMarker = org.slf4j.MarkerFactory.getMarker("TRACER")
val traceCondition = Condition(request.getQueryString("trace").nonEmpty)
val traceBulletLogger = logger.withCondition(traceCondition).withMarker(tracerMarker)
traceBulletLogger.trace("trace statement written even if loglevel is INFO!")

Conditional on Circuit Breaker

You can rate limit your logging, or manage logging with a circuit breaker, so that error messages are suppressed when the circuit breaker is open.

val operationLogger = logger.withCondition(isCircuitBreakerClosed)
operationLogger.error("Only errors when circuit breaker is closed")

Conditional on Feature Flag

Feature Flag systems allow you to turn on and off features in the application at runtime, in response to complex inputs. Commercial feature flag systems like Launch Darkly allow you to target feature flags to specific users.

implicit val request: Request = Request(user = "thisuser")

// Define feature flag method in context of a request...
def userFeatureFlag(implicit request: Request): Boolean = isUserDebugFlagOn(request)

// the logger will debug if level=DEBUG and feature flag is enabled for user.
val userLogger = logger.withCondition(userFeatureFlag)
userLogger.debug("user debug request", request.user)

Note that this is just an example – in production, you should organize your feature flags so that they’re only exposed from one place and the call out to the flag system is under the hood.

By combining conditionals with feature flags, you can use targeted diagnostic logging to show debug statements in production only for a specific user, without impacting logging for the entire application as a whole.

Conditional on Time

Conditional logging can also be used for time and date limited logging statements. This can be a more flexible way of dealing and rollouts, where we can say “log verbose debugging statements for the next ten minutes” or “suppress logging completely from 10 pm to 8 am.”

This works best with a Deadline:

import scala.concurrent.duration._
var debugDeadline: Deadline = Deadline.now

def debugActiveFor(newDuration: FiniteDuration) = {
  debugDeadline = newDuration.fromNow
}

// Enable from REST API or admin command
debugActiveFor(30.seconds)

// Run until deadline is met.
logger.debug.when(debugDeadline.hasTimeLeft()) { debug =>
  debug("Logging debug information while there is time left")
}

For periodic scheduling, you can use CronScheduler in conjunction with an AtomicBoolean. You can use ScheduledExecutorService, but be aware that ScheduledExecutorService is not good at handling a periodic schedule as it can suffer from extended drift, especially when system time is corrected.

To use CronScheduler, first define a periodic scheduler in Java:

public class Periodic {
    private final CronScheduler cron = CronScheduler.create(Duration.ofMinutes(1));

    public void schedule(Duration duration, CronTask cronTask) {
        cron.scheduleAtFixedRateSkippingToLatest(0, duration.toMinutes(), TimeUnit.MINUTES, cronTask);
    }

    public void shutdown() {
        try {
            cron.shutdownNow();
            cron.awaitTermination(1, TimeUnit.MINUTES);
        } catch (InterruptedException e) {
            // do nothing
        }
    }
}

Then access it from Scala:

import java.util.concurrent.atomic.AtomicBoolean

val latch    = new AtomicBoolean()
val periodic = new Periodic()
periodic.schedule(
  java.time.Duration.ofMinutes(1),
  new CronTask {
    override def run(scheduledRunTimeMillis: Long): Unit = latch.set(true)
  }
)

logger.debug.when(latch.getAndSet(false)) { debug => debug("Only run once per minute max") }
periodic.shutdown() // on app shutdown

The key to using logging in conjunction with a periodic conditional schedule is that you always log on an operation, and can alter the periodic schedule at runtime, without restarting the service. By doing this, you are turning up the observability of an operation for a specific period, as opposed to simply running a logging statement on a periodic basis.

Conditional on Memory Pressure

Using conditional logging is preferable to using call-by-name semantics in expensive logging statements. Call-by-name arguments still create short lived objects that take up memory in a thread local allocation buffer and cause memory churn:

“You get all of these funny downstream costs that you don’t even think about. In terms of the allocation, it’s still quick. If the objects die very quickly, there’s zero cost to collect them, so that’s true. That’s what garbage collection people have been telling you all the time, ”Go, don’t worry about it. Just create objects. It’s free to collect them.“ It may be free to collect them, but quick times a large number does equal slow. If you have high creation rates, it’s not free to create. It may be free to collect, but it’s not free to create at the higher rate.”

– Kirk Pepperdine, The Trouble with Memory

Using when will at least create only one function block, rather than many of them.

If you are concerned about the costs of logging overall and are using JDK 11, you can create a condition that returns false in cases of high JVM memory pressure, ideally through a JEP 331 enabled sampler like heapsampler – if that’s not available, you can use JFR event streaming as a feedback mechanism, so you can check the TLAB allocation rates.

logger.info.when(isLowPressure) { info =>
  val expensiveResult = createLotsOfObjects()
  info("many statements, much memory pressure {}", expensiveResult)
}

If you are on a pre-11 JVM, you can still provide a feedback mechanism to reduce memory pressure. For example, you can run Yourkit as a Java Agent and enable object counting. This is low-overhead and can be run in production, but requires some extra work to close the loop.

The source code for this page can be found here.