Feature request: Custom object to logger.X() calls

[thernstig]

Caveat: I am not completely confident of the best API for this feature request, or if it even is a good one, but that is something to figure out.

Problem

We are writing code that sometimes have to log "normal" logs and sometimes what we call "audit" logs. Audit logs is a common concept to keep an "auditing trial" of user actions, actions that are often seen as more important. Consider when a user changes password, we want to log that this user changes password but with some additional details. In an HTTP based application, these details could be the HTTP response status code, the logged in user (usually found on req.session.username or similar.

Today we do something like this early in the HTTP routes, using Express:

  app.use((req, res, next) => {
    req.loggerAudit = log4js.getLogger('audit');
    req.loggerAudit.addContext('req', req);
    req.loggerAudit.addContext('res', res);
    next();
  });

This works ok, as we in each HTTP route can now use:

req.loggerAudit.info(`User logged out. User IP: ${req.ip}`);

The actual appender looks something like:

        layout: {
          type: 'pattern',
          pattern:
            '[%d{ISO8601_WITH_TZ_OFFSET}] [%p] %c - %m%x{auditInformation}',
          tokens: {
            auditInformation(logEvent) {
              // This gets data from the req/res like const { req, res, username } = logEvent.context;
              const auditInfo = getAuditInformation(logEvent);
              return formatAuditInformation(auditInfo);
            },
          },
        },

This is not ideal, since we have added the logger on the req object we have to pass that around even to all functions that need to write audit logs.

Solution

I'd want to add context to each loggerAudit .info() call as loggerAudit.info(obj, 'string'); and have it enforced that this particular logger always require an object as the first parameter. We could then use loggerAudit.info(req, 'string) to add a context at invocation, instead of once early.

Another idea would be to already in the const foo = getLogger('something', { type: 'audit' }) call specify that this logger is "special" requiring extra information when doing a foo.info(req, 'something something') call.

Alternatives

An alternative to this would actually be to tagged template lterals in some sense to achieve this, together with TypeScript enforcing it. Or even a custom ESLint rule that any getLogger('audit') (with specific name or the extra `{ type: 'audit' } would require a named tagged template with the last parameter to it being of a certain shape.

To be honest, when I write this it feels impossible to programmatically fix this just with JavaScript i.e. that it will require TypeScript as well.

Additional context

One additional problem we have in our current solution is that we do something like:

        res.send();
        req.loggerAudit.info(`Unknown user. Logout from ${req.ip}`);

res.send() always have to come before req.loggerAudit. since otherwise res.status or even the content-length header (to log the amount of bytes sent) are not populated until .sent() is called. I would have wished log4js could "postpone" the logging until some data has been populated e.g. by awaiting a promise or something. It would require some parts to be async though, but that defeats the logic of having logger calls being done instantly when called. It also introduces a problem with what timestamp the logging call should get. But it is a real problem for us even today where the above solution of calling the logging after res.send() solves it, albeit not nicely.

Aside

I am not in the best shape today so I hope this did not end up a mess 😆