request/response serializers behave incorrectly for auditLogger plugin and Bunyan logger

[carycodes]

• Used appropriate template for the issue type
• Searched both open and closed issues for duplicates of this issue
• Title adequately and concisely reflects the feature or the bug

Restify Version: 11.1.0
Node.js Version: Problem is verified in both 20.8.1 and 14.19.1. Probably exists in all versions.

Expected behaviour

• By default, audit logger will use serializers that only print a common subset of req and res fields.
• If a customer serializer is provided, it will be used.

Actual behaviour

For some configurations, particularly with Bunyan as the logger, the entirety of req and res is unconditionally printed out.

Repro case

Consider the following example:

import restify from "restify";
import pino from "pino";
import bunyan from "bunyan";

// (1) log instantiation
//const logger = pino({ name: "pino-log" });
const logger = bunyan.createLogger({ name: "bunyan-log" });

const server = restify.createServer({
  name: "myapp",
  log: logger, // (2) server log instance
});

server.on(
  "after",
  restify.plugins.auditLogger({
    log: logger, // (3) audit log instance
    event: "after",
  })
);

server.get("/echo/:name", function (req, res, next) {
  res.send(req.params);
  return next();
});

server.listen(8080, function () {
  console.log("%s listening at %s", server.name, server.url);
});

A) As currently configured, this example will incorrectly log the entirety of req/res.

B) If the logger is changed from Bunyan to Pino at (1), the example appears to work correctly.

C) If the server logger is removed at (2), the audit logger appears to work correctly.

Cause

Points (A) and (B) from above are caused by the code in lib/plugins/audit.js around lines 293 to 295. That code was written with Pino in mind, and the Pino child function takes options in the second parameter. Bunyan appears to take options in the first parameter, so this code does not work correctly with Bunyan.

Note that this breaks audit logging with Bunyan even if you don't pass in custom serializers, because internally the default ones are passed to the child logger in the same way.

Additional reference:

• Bunyan requires settings in the first parameter: https://github.com/trentm/node-bunyan/blob/5c2258ecb1d33ba34bd7fbd6167e33023dc06e40/lib/bunyan.js#L686
• This bug appears to originate here: 0a8cf83

For point (C), I am not sure why removing the server level logger fixes the issue, but one key observation here is from audit.js at line 288. If a logger exists on the request object, that one takes precedence, and any logger that was explicitly passed into the audit logger is silently ignored. That doesn't seem right. This is especially weird since the audit logger function explicitly requires a log object to be specified, even in cases where it will be ignored.

It is strange to me that opts.log would not take precedence, but this change (528ecbc) seems to indicate that was at least a conscious decision. if that is intentional, the log field of auditLogger options should not be mandatory.

Are you willing and able to fix this?

Probably yes, but this is not a straight-forward fix. There are design decisions to be made. I would want to make sure there was agreement on how this should be fixed first.

Should restify attempt to automatically detect and adapt to different logger APIs? Should audit logger require calling code to pass in a fully formed child logger rather than making one itself? Should restify explicitly only support Pino?

And for the loggers, is it correct that a server/request level logger takes precedence over an explicitly passed logger when the auditLogger plugin is created? If that is correct, then the log parameter should not be mandatory.

For my own usage, I have used the patch-package library to modify audit.js so that the serializers field is passed in the first parameter when creating a child logger. I only use Bunyan, so this is fine for me. It is obviously not a suitable fix for restify generally.

[jybleau]

@carycodes ran into the same annoying issue. Excellent explanation.
When not giving a log param (2), Restify seems to create a default pino log instance at req.log. The problem is that is has nothing to do with the auditLogger plugin log params; for instance, if you set multiple streams they will be unknown by the default pino req.log instance.

Your solution to apply a patch to get the old behaviour is correct. I'll try the same.

Otherwise you have to explicitly pass custom serializers to the bunyan.createLogger(...) call. But that does not use the default serializers and they're not even exposed.

I'm not sure this project is properly maintain anymore, sadly, last PR merged last summer.