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.

On Condition

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

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

And look at the level as well:

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

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

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

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

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

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

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

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

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

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

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