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:

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

And look at the level as well:

sourceval 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.

sourcedef 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:

sourcedef 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:

sourcelogger.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:

sourceval 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.

sourceval 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.

sourceimplicit 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:

sourceimport 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:

sourcepublic 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:

sourceimport 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 can reduce memory churn. If you are concerned about the costs of logging, you can create a condition that returns false in cases of high JVM memory pressure.

sourcelogger.info.when(isLowPressure) { info =>
  val expensiveResult = createLotsOfObjects()
  info("many statements, much memory pressure {}", expensiveResult)
}
The source code for this page can be found here.