Dynamic Log Control for Log Libraries

This post is part 2 of the Dynamic Logging series and describes how to implement dynamic logging with several popular logging libraries.

Please first read part 1 at Dynamic Serverless Log Control which explains the technique of dynamic log control and how it works.

Controlling Various Loggers

This post describes the code required to implement dynamic log control for several popular and suitable logging libraries.

• SenseLogs
• Debug
• Bunyan
• Pino
• Winston
• Python

When selecting your logging library, here are several important factets it should exhibit:

• An API to change the logging level. Ideally this should not be a numeric level but an arbitrary set of levels that can be enabled and disabled at will.
• Extremely small and fast and a good match for serverless.
• Close to zero cost for logging APIs that are disabled for output.
• Ability to capture the stack for any logging request.
• Rich context of request and system information. Ideally the library should support global context and per-API context.

Controlling SenseLogs

Here is a sample of how to use SenseLogs which is an extremely fast logger with built in support to respond to the LOG_FILTER, LOG_OVERRIDE and LOG_SAMPLE environment variables. No extra glue code is required.

You can also access these code snippets via GitHub gists at: Dynamic Log Control Gist

import SenseLogs from 'senselogs'

let log = new SenseLogs()

exports.handler = async (event, context) => {
    //  This will be emitted if LOG_FILTER contains 'debug' as a log level
    log.debug('Hello world')
    //  EMF metrics can also be dynamically controlled
    log.metrics('metrics', 'AcmeRockets/CriticalLaunchFailure', {explosion: 1})
}

The SenseLogs logging library is available from GitHub SenseLogs or NPM SenseLogs.

Controlling Debug

Here is a sample of how to use the Debug logger.

The Debug logger is a more primitive logger and is restricted to a single log level at a time.

import Debug from 'debug'

let {LOG_FILTER, LOG_OVERRIDE, LOG_SAMPLE} = process.env

if (LOG_OVERRIDE != null) {
    let [expire, level] = LOG_OVERRIDE.split(':')
    if (level && Date.now() < expire) {
        LOG_FILTER = level
    }
}
let sample = 0, sampleRate, sampleLevel
if (LOG_SAMPLE != null) {
    [sampleRate, sampleLevel] = LOG_SAMPLE.split(':')
}

Debug.enable(LOG_FILTER)

exports.handler = async (event, context) => {
    if (sampleRate && (sample++ % (100 / sampleRate)) == 0) {
        debug.enable(sampleLevel)
    }
    Debug('debug')('Debug message')
}

Controlling Bunyan

Here is a sample of how to use the Bunyan logger.

import Bunyan from 'bunyan'

let {LOG_FILTER, LOG_OVERRIDE, LOG_SAMPLE} = process.env

if (LOG_OVERRIDE != null) {
    let [expire, level] = LOG_OVERRIDE.split(':')
    if (level && Date.now() < expire) {
        LOG_FILTER = level
    }
}
let sample = 0, sampleRate, sampleLevel
if (LOG_SAMPLE != null) {
    [sampleRate, sampleLevel] = LOG_SAMPLE.split(':')
}

const bunyan = Bunyan.createLogger({name: 'bunyan', level: LOG_FILTER})

exports.handler = async (event, context) => {
    if (sampleRate && (sample++ % (100 / sampleRate)) == 0) {
        bunyan.level = sampleLevel
    }
    bunyan.debug('Debug message')
}

Controlling Pino

Here is a sample of how to use the Pino general purpose logger to respond to these environment variables in a Lambda function.

import Pino from 'pino'

let {LOG_FILTER, LOG_OVERRIDE, LOG_SAMPLE} = process.env

if (LOG_OVERRIDE != null) {
    let [expire, level] = LOG_OVERRIDE.split(':')
    if (level && Date.now() < expire) {
        LOG_FILTER = level
    }
}
let sample = 0, sampleRate, sampleLevel
if (LOG_SAMPLE != null) {
    [sampleRate, sampleLevel] = LOG_SAMPLE.split(':')
}

const pino = Pino({name: 'pino', level: LOG_FILTER})

exports.handler = async (event, context) => {
    if (sampleRate && (sample++ % (100 / sampleRate)) == 0) {
        pino.level = sampleLevel
    }
    pino.debug('Debug message')
}

Controlling Python

Here is a sample of how to use this technique with Python.

The stock Python logger supports only numeric log levels.

import os
import logging
from datetime import datetime

LOG_FILTER = os.environ.get('LOG_FILTER')
LOG_OVERRIDE = os.environ.get('LOG_OVERRIDE')
LOG_SAMPLE = os.environ.get('LOG_SAMPLE')

sample = 0
sampleRate = 0
sampleLevel = None

if LOG_SAMPLE != None:
    sampleRate, sampleLevel = LOG_SAMPLE.split(':')

if LOG_OVERRIDE != None:
    when, level = LOG_OVERRIDE.split(':')
    if level and int(datetime.today().timestamp()) < int(when):
        LOG_FILTER = level

logging.basicConfig(level = int(LOG_FILTER))
log = logging.getLogger()

def lambda_handler(event, context):
    sample = sample + 1
    if sampleRate and (sample % (100 / sampleRate)) == 0:
        log.setLevel(int(sampleLevel))

    log.info("Hello World")
    return 'done'

Controlling Winston

Here is a sample of how to use the Winston logger.

import Winston from 'winston'

let {LOG_FILTER, LOG_OVERRIDE, LOG_SAMPLE} = process.env

if (LOG_OVERRIDE != null) {
    let [expire, level] = LOG_OVERRIDE.split(':')
    if (level && Date.now() < expire) {
        LOG_FILTER = level
    }
}
let sample = 0, sampleRate, sampleLevel
if (LOG_SAMPLE != null) {
    [sampleRate, sampleLevel] = LOG_SAMPLE.split(':')
}

const winston = Winston.createLogger({
    level: LOG_FILTER,
    transports: [new Winston.transports.Console()],
})

exports.handler = async (event, context) => {
    if (sampleRate && (sample++ % (100 / sampleRate)) == 0) {
        winston.transports[0].level = sampleLevel
    }
    winston.debug('Debug message')
}

Links

• SenseLogs
• Observability without the cost
• SenseDeep Quick Tour
• SenseDeep App