A simple way to keep context in console.log()

This post explains a simple way to enhance the use of console.log() in a nodejs http server, with an example for SvelteKit. Of course one may use dedicated logger tools too.

Nodejs http/tcp servers handle several requests simultaneously. When it comes to logging, it is useful to preprend each log message with an identifier of the current request (requestId, userId or whatever data related to the request).

Let's name this information contextualData.

The obvious and easy way is to pass the contextual data from function to function, so that we can call console.log(contextualData, xxx) from any file in the code.

Simple and easy at the beginning, less simple as the app grows and awful with a huge codebase.

Any other way ?
Indeed, AsyncLocalStorage is a relatively new and unknown Nodejs API that provides exactly what we need : a storage (similar to localStorage in the browser) that lives in the context of the request.

Step 1 : using AsyncLocalStorage

using this API is pretty straightforward. Let's have a look at the exact same documentation example, including my own comments :

import http from 'node:http';

// import AsyncLocalStorage API
import { AsyncLocalStorage } from 'node:async_hooks';

// new instance
const asyncLocalStorage = new AsyncLocalStorage();

// this function shows how to retrieve the context
// and preprend it to console.log() messages
function logWithId(msg) {
  const id = asyncLocalStorage.getStore();
  console.log(`${id !== undefined ? id : '-'}:`, msg);
}

let idSeq = 0; // the contextual data of this example

http.createServer((req, res) => {

  // .run(context, callback) runs the callback and makes 'context' 
  // available when calling .getStore() from inside the callback
  // for this example, idSeq is incremented on each request
  asyncLocalStorage.run(idSeq++, () => {

    // starting from here, contextualData is defined

    logWithId('start');

    // Imagine any chain of async operations here
    setImmediate(() => {
      logWithId('finish');
      res.end();
    });
    // until here
  });
}).listen(8080);

http.get('http://localhost:8080');
http.get('http://localhost:8080');
// Prints:
//   0: start
//   1: start
//   0: finish
//   1: finish

Next step is to rewrite console.log() so that it automatically preprends messages with the context when available.

Step 2 : rewriting console.log()

Let's take an example with a static prefix :

let _log = null // pointer to console.log base function

const setConsolePrefix = (prefix) => {
  // singleton
  if (_log)
    return
  // keep a pointer to the system console.log function
  _log = console.log
  // rewrite console.log function with prefix
  console.log = () => {
    let args = Array.from(arguments)
    if (prefix)
        // insert prefix as the first argument
        args.unshift(prefix)
    // call system console.log function with updated arguments
    _log.apply(console, log, args)
}

// anywhere in the code
setConsolePrefix("Pulp Fiction:")

// later in the code
console.log("It's Zed's") 
console.log("Who's Zed ?")
// prints :
// Pulp Fiction: It's Zed's
// Pulp Fiction: Who's Zed ?

Straightforward too.

Putting things together

Now let's put things together and encapsulate this feature in a Context.js file :

import { AsyncLocalStorage } from "async_hooks"

export const context = new AsyncLocalStorage()

var __log = null
export function setContextualConsole(){

    // singleton
    if (__log)
        return
    __log = console.log

    console.log = function(){

        let args = Array.from(arguments)

        // retrieve a contextual prefix instead of a static prefix
        const contextualPrefix = context.getStore()

        if (contextualPrefix)
            args.unshift(contextualPrefix )

        __log.apply(console, args)
    }    
}

Using in Sveltekit

In Sveltekit, the right place to use it is the handle() function, that is defined in hooks.ts. In our example, the contextual data is the very same seqId as in Nodejs AsyncLocalStorage documentation example :

import {context, setContextualConsole} from 'Context'

// our contextual data
let seqId = 0 

export async function handle({ event, resolve }) {

    seqId++

    // use our new 'context-ready' console.log
    setContextualConsole()

    return await context.run(seqId, async()=>{

        // starting from here, console.log(xxx) prints 'seqId xxx' 

        const response = await resolve(event)

        // until here
        return response
    })
}

Using in nodejs HttpServer

same with a bare nodejs httpServer :

import http from 'node:http'
import {context, setContextualConsole} from './Context.js'

// our contextual data
let seqId = 0

http.createServer((req, res) => {

    seqId++

    // use our 'context-ready' console
    setContextualConsole()

    context.run(seqId, ()=>{

        // context available from here...
        console.log('start')

        // the timeout simulates request processing time
        // so that we get simultaneous requests for this example
        setTimeout(()=>{

            console.log('end')

            // ... to here
            res.end()

            }, 10)
        })

}).listen(80)


http.get('http://localhost')
http.get('http://localhost')

// prints :
// 1 start
// 2 start
// 1 end
// 2 end

That's it !

The contextual data may be an object, an array or any data that needs to be stored during the request handling.

In SvelteKit, my advice is to use this trick only for logging purposes : it should not replace event.locals.