How to use Restify's RequestLogger?

Question

RequestLogger

Sets up a child bunyan logger with the current request id filled in, along with any other parameters you define.

server.use(restify.requestLogger());

Registering the plugin does not log requests.

Yellowgreen

Answer 1

RequestLogger plugin does not log each request. It extends the .log property of the req:

The advantage to doing this is that each restify req instance has a new bunyan instance log on it where the request id is automatically injected in, so you can easily correlate your high-throughput logs together.

You have to register your own logger first, e.g.

var restify = require('restify'),
    bunyan = require('bunyan'),
    // Create a logger.
    log = bunyan.createLogger({name: 'showtime'}),
    server;

// Register logger.
server = restify.createServer({
    log: log
});

// Extend logger using the plugin.
server.use(restify.requestLogger());

// Use req.log property as a regular instance of bunyan logger.
server.use(function (req, res, next) {
    req.log.info('TEST');
    next();
});

server.get('/ping', function (req, res, next) {
    res.send('pong');
    next();
});

server.listen(8080);

Making a few requests to the /ping endpoint will produce the following logs:

{"name":"showtime","hostname":"localhost.localdomain","pid":6446,"req_id":"3c734e70-81de-11e4-bc58-e3e7254ff287","level":30,"msg":"TEST","time":"2014-12-12T09:07:02.488Z","v":0}
{"name":"showtime","hostname":"localhost.localdomain","pid":6446,"req_id":"3d6bdf40-81de-11e4-bc58-e3e7254ff287","level":30,"msg":"TEST","time":"2014-12-12T09:07:04.116Z","v":0}
{"name":"showtime","hostname":"localhost.localdomain","pid":6446,"req_id":"3df47030-81de-11e4-bc58-e3e7254ff287","level":30,"msg":"TEST","time":"2014-12-12T09:07:05.011Z","v":0}

Notice the "req_id" property.

The equivalent requests without the requestLogger code

server.use(restify.requestLogger({
    log: log,
    serializers: restify.bunyan.serializers
}));

will produce the following logs:

{"name":"showtime","hostname":"localhost.localdomain","pid":6448,"level":30,"msg":"TEST","time":"2014-12-12T09:07:23.099Z","v":0}
{"name":"showtime","hostname":"localhost.localdomain","pid":6448,"level":30,"msg":"TEST","time":"2014-12-12T09:07:24.527Z","v":0}
{"name":"showtime","hostname":"localhost.localdomain","pid":6448,"level":30,"msg":"TEST","time":"2014-12-12T09:07:24.674Z","v":0}

If your intention is to log every single request, then ditch

server.use(function (req, res, next) {
    req.log.info('TEST');
    next();
});

in favour of:

server.on('after', restify.auditLogger({
    log: log
}));

This will produce logs:

{"name":"showtime","hostname":"localhost.localdomain","pid":6451,"audit":true,"level":30,"remoteAddress":"192.168.100.1","remotePort":58986,"req_id":"00093110-81df-11e4-981e-e3d13800c8bf","req":{"method":"GET","url":"/ping","headers":{"user-agent":"curl/7.37.1","host":"192.168.100.100:8080","accept":"*/*"},"httpVersion":"1.1","trailers":{},"version":"*","timers":{"bunyan":378,"handler-1":3044}},"res":{"statusCode":200,"headers":{"content-type":"application/json","content-length":6},"trailer":false},"latency":6,"_audit":true,"msg":"handled: 200","time":"2014-12-12T09:12:30.629Z","v":0}
{"name":"showtime","hostname":"localhost.localdomain","pid":6451,"audit":true,"level":30,"remoteAddress":"192.168.100.1","remotePort":58989,"req_id":"2b2fcac0-81df-11e4-981e-e3d13800c8bf","req":{"method":"GET","url":"/ping","headers":{"user-agent":"curl/7.37.1","host":"192.168.100.100:8080","accept":"*/*"},"httpVersion":"1.1","trailers":{},"version":"*","timers":{"bunyan":105,"handler-1":607}},"res":{"statusCode":200,"headers":{"content-type":"application/json","content-length":6},"trailer":false},"latency":1,"_audit":true,"msg":"handled: 200","time":"2014-12-12T09:13:43.021Z","v":0}
{"name":"showtime","hostname":"localhost.localdomain","pid":6451,"audit":true,"level":30,"remoteAddress":"192.168.100.1","remotePort":58990,"req_id":"2b6532a0-81df-11e4-981e-e3d13800c8bf","req":{"method":"GET","url":"/ping","headers":{"user-agent":"curl/7.37.1","host":"192.168.100.100:8080","accept":"*/*"},"httpVersion":"1.1","trailers":{},"version":"*","timers":{"bunyan":7067,"handler-1":677}},"res":{"statusCode":200,"headers":{"content-type":"application/json","content-length":6},"trailer":false},"latency":8,"_audit":true,"msg":"handled: 200","time":"2014-12-12T09:13:43.371Z","v":0}

Yellowgreen

@vanduc1102 I prefer to give some time before accepting my own answers. Seeing there have been no other answers, I will accept my own. – Yellowgreen