Request-scoped logging in Node.js and Express at Oizom

When an API call fails with a 500 in production, I want one id from the response and, behind it, every log line that request wrote, in order. At Oizom every request gets a context id, every function logs through context.log, and the logs of a request are only kept when it fails or the frontend asks for them.

I'm Panth, and I lead the software team at Oizom, where our devices send tens of thousands of air-quality readings to the cloud every minute. This post is how that logging works in our Node.js and Express backends, with the code. Hosted logging services can collect all of this, but none of them group logs by request out of the box, and running a separate service per request is not an option.

The problem

A client makes a request and the API answers with a 500. To debug it you would normally try to recreate the bug, probably by logging in to the frontend as that user. The faster route is to keep the logs of every request that answered 500, keyed by its requestId, and read them.

The idea

1. Every time a request comes in, generate a UUID and include it in the response headers. Whenever anything fails, the API sends a requestId that the client can show, in a sandbox view or similar.
2. Create a context object (with requestId as context.id) that includes a method context.log, which works like console.log.
3. When creating the context, ensure there is an implementation of context.log where you can access context.id. This allows you to group the logs by requestId effectively.

Solution

My libraries @panth977/functions and @panth977/routes do this out of the box.

Create Context

// Create Context like following
app.get('/v1/user/:userId', function (req, res) {
    const id = null; // either set id, to string or leave it null for auto generate UUID
    DefaultContext.Builder.forTask(id, async function (context, done) {
        res.on("finish", done);
        context.log('My task started!');
        const user = await getUser({context, input: req.params}); // pass context to all the functions, for access to context.log
        res.send(user);
        context.log('My task completed!');
    });
});
// OR
// use @panth977/routes api to skip the process of creating functions!
export const GET_USER = ROUTES.Http.build([WebsiteAuthValidator], 'get', '/v2/user/{userId}', {
    request: ROUTES.z.HttpRequest({path: getUser.input}),
    response: ROUTES.z.HttpResponse({body: getUser.output}),
    async func({context, path}) {
        context.log('My route started!');
        const user = await getUser({context, input: path}); // pass context to all the functions, for access to context.log
        context.log('My route completed!');
        return {body: user};
    }
})

Make every function take context

That way every function can use context.log.

const getUser = FUNCTIONS.AsyncFunction.build({
    input: z.object({userId: z.coerce.number()}),
    output: z.object({name: z.string(), ...}).nullable(),
    async func({context, input}) {
        context.log('Getting user', input);
        const [user] = pg.query(`SELECT * FROM users WHERE id = ? LIMIT 1`, [input.userId]);
        context.log('Found user', user);
        return user ?? null;
    }
});

Capture context.log

Every call to context.log runs your subscribed callback.

const unsub = DefaultContext.onLog(function (context, args) {
    console.log(context.id, ...args);
    // send the log to socket 
    // store to database
    // write to a file!
});
// incase you like to unsubscribe!
unsub();

By default, context.log doesn't write to the console at all, so add console.log in the callback if you want it.

How we use it at Oizom

At Oizom our devices send calibrated air-quality data to the cloud, tens of thousands of entries every minute, and clients read their live data through our APIs. With that many requests, debugging anything in production by reading a shared log stream was close to impossible.

What I wanted

1. Keep logs only for failed requests, so successful ones don't clutter the logs database.
2. A way to list the request IDs made by user from the website, user from third-party APIs, device from the device itself, and system-{type} for any internal system calls like cron jobs, reports, alerts, etc.
3. The full logs for any one request ID.

What I built

1. Define a log payload

    type log = {
        ids: string[];
        msg: string;
        ts: number;
        line: number;
    }

Many logs belong to the same ID, so why can one log belong to many IDs? Most logs do have a single ID, context.id. Multiple IDs are there for filtering: the same log line can be found by request, by user, by organisation or by login session. More on that below.

1. A secure socket app with three channels:

   1. /send_log - every server sends its logs through this channel.
   2. /stream_all_logs - streams all logs in real time as the servers send them.
   3. /stream_logs - streams only the logs that match its room (one room per id).

2. A service that listens to /stream_all_logs and stores every log. For us that is Cassandra, self-hosted in a container, with a ttl of a few weeks.
   

    CREATE TABLE logs.logs_v2 (
      id text,
      ids set<text>,
      ts bigint,
      msg text,
      line bigint,
      PRIMARY KEY ((id), ts)
    ) WITH CLUSTERING ORDER BY (ts ASC) AND ...

1. A service with an HTTP GET endpoint /fetch_logs that reads logs by id from Cassandra, ordered, with limit/offset (Cassandra has token-based pagination built in).

2. A small frontend with two modes: [ real-time , database ]

   1. A text box for the id and a submit button.
   2. Depending on the mode, it connects to the socket /stream_logs or fetches from /fetch_logs, with a "fetch next" button for more.
   3. Each log has an expand button that shows all its ids, which link to the other ids that share the log.

3. That is the logging system. The core is in the backend. Every time a context is created:

   1. It gets a logs state.
   2. Every context.log entry goes into that state.
   3. On an error, or when something needs to be kept, we set .importance = true.
   4. On dispose, if .importance === true, all the logs are streamed to /send_log.

    type Logs = {
        logs: { ids: string[]; msg: string; ts: number; line: number }[];
        important: boolean;
    };
    const LogsStateKey = FUNCTIONS.DefaultContextState.CreateKey<Logs>({
        label: 'Logs',
        scope: 'global',
    });
    const stringifyLogs = LOGS.createStringifyLogger({ forEachLine: false });
    // exposing this function for set the importance level.
    // this determines wether logs should be sent to socket or not!
    export function needToSendLogsToSocket(context: Pick<FUNCTIONS.Context, 'useState'>) {
        const state = context.useState(LogsStateKey).get();
        if (!state) return;
        state.important = true;
    }
    // exposing this function for more versatile use. (link different ids to same log)
    export function logToSocket(
        context: Pick<FUNCTIONS.Context, 'useState'>,
        { ids, line, ts }: { ids: string[]; ts?: number; line?: number },
        ...args: any[]
    ) {
        const state = context.useState(LogsStateKey).get();
        if (!state) return;
        state.logs.push({
            ids: ids,
            msg: stringifyLogs(null, args),
            ts: ts ?? Date.now(),
            line: line ?? state.logs.length,
        });
    }
    // set a state on context
    FUNCTIONS.DefaultContext.onCreate(function (context) {
        context.useState(LogsStateKey).set({ logs: [], important: false });
    });
    // store all the logs in the state
    FUNCTIONS.DefaultContext.onLog(function (context, args) {
        // every context.log will be mapped to 
        // ids=[context.id] 
        // so single id for all the context.log 
        logToSocket(context, { ids: [context.id] }, ...args);
    });
    // at end, check if it is important, and stream them to socket.
    FUNCTIONS.DefaultContext.onDispose(async function (context) {
        try {
            const state = context.useState(LogsStateKey).get();
            if (!state.important) return;
            for (const log of state.logs) socket.send(JSON.stringify(log));
        } catch (err) {
            console.error('Socket Log Error:', err);
        }
    });

1. Whenever a user logs in from the website, a third party, a device or a system-{type}, the login session gets its own UUID in the auth token.
2. Every request goes through an auth check. That is where I work out what kind of login it is and which categories the request belongs to.

    const WebsiteAuthValidator = ROUTES.Middleware.build({
        request: ROUTES.z.MiddlewareRequest({
            headers: z.object({}).passthrough(),
        }),
        response: ROUTES.z.MiddlewareResponse({
            headers: z.object({}).passthrough(),
        }),
        async func({ context, headers }) {
            // frontend wants to store logs!
            if (headers['x-store-logs'] === 'true') needToSendLogsToSocket(context);
            const decoded = ...; // decode the token from headers.
            if (decoded.mode === 'client') throw createHttpError.Unauthorized('This is not a client Api, You only have access to client APIs');
            const ids = [context.id];
            if (decoded.mode === 'system') {
                if (decoded.id) ids.push(`Core:User:System:${decoded.id}`);
            } else {
                ids.push(`Core:User:${decoded.userId}`);
                ids.push(`Core:User:Org:${decoded.orgId}`);
                if (decoded.id) ids.push(`Core:User:${decoded.userId}:${decoded.id}`);
            }
            const { req } = context.useState(ExpressStateKey).get();
            logToSocket(context, { ids }, req.method, req.path);
            context.useState(DecodedStateKey).set(decoded);
            if (headers['x-store-logs'] === 'true') return { headers: { 'x-request-id': context.id } };
            return {};
        },
    })

This way, when you get logs for id = Core:User:2141, you see a list of all the API calls made by this user. Each log includes a list of other relevant ids, and one of them will be context.id. That way, you can get the requestId, and by fetching the logs of that requestId, you get the complete logs for that specific API call.

1. When a request fails, we keep its logs.
   

   const onError: ExpressHandler.onError = function ({ context, error: err }) {
     if (createHttpError.isHttpError(err)) {
       return { 
         body: err.message,
         headers: { 'x-request-id': context.id, ...(error.headers ?? {}) },
         status: err.statusCode
       };
     }
     if (context) {
       const { req } = context.useState(ExpressHandler.ExpressStateKey).get();
       // log the request, could be helpfull for recreating error, in debugging.
       context.log(
         'Req::',
         JSON.stringify({ method: req.method, path: req.params, query: req.query, body: req.body, headers: req.headers }, null, '\t'),
       );
       context.log('Err While Req:', err);
       console.error('500 Error at:', context.id);
       // set the importance.
       needToSendLogsToSocket(context);
     } else {
       // nothing we can do further!
       console.error('Err:', err);
     }
     return { 
       body: 'Something went wrong!', 
       headers: { 'x-request-id': context.id }, 
       statusCode: 500 
     };
   };
   const v2 = ExpressHandler.serve({ bundle: ExposedRoutes, onError });
   app.use(v2);
   

The log viewer

I built the viewer with AI's help: I designed the system and let AI write the boring parts. Here it is:

Later I needed a list of every email sent to one address, or every SMS sent to one phone number. All it took was a new template for id. Each of those logs carries the requestId, so you can see which request sent the email.

Each log shows 4 things:

1. A toggle button to see other linked ids
2. The line number of the log
3. The ts in local time
4. The msg, which is the log message.

The extra ids are links, so you can jump from a user to a request to an email while reading.

---

If you build something like this, build it yourself rather than buying it: the ids you will want to filter by are specific to your system.

How do you find the logs of one failed request in production today?