diff --git a/index.js b/index.js index 6d011d7..d2ea048 100644 --- a/index.js +++ b/index.js @@ -166,6 +166,9 @@ async function register (server, options) { const childBindings = getChildBindings(request) request.logger = logger.child(childBindings) } + + const responseTime = (info.completed !== undefined ? info.completed : info.responded) - info.received + request.logger.info( { payload: options.logPayload ? request.payload : undefined, @@ -175,9 +178,9 @@ async function register (server, options) { // has the effect of setting it or "leaving it as it was" if it was already added via child bindings req: shouldLogRequestStart(request) ? undefined : request, res: request.raw.res, - responseTime: (info.completed !== undefined ? info.completed : info.responded) - info.received + responseTime }, - 'request completed' + `[response] ${request.method} ${request.path} ${request.raw.res.statusCode} (${responseTime}ms)` ) } }) diff --git a/test.js b/test.js index aa3d5f0..80f83da 100644 --- a/test.js +++ b/test.js @@ -155,7 +155,7 @@ experiment('logs each request', () => { await registerWithSink(server, 'info', data => { expect(data.req.id).to.exists() expect(data.res.statusCode).to.equal(200) - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/get \/something 200 \(\d*ms\)/) expect(data.responseTime).to.be.at.least(0) done() }) @@ -185,7 +185,7 @@ experiment('logs each request', () => { await registerWithSink(server, 'info', data => { expect(data.res.statusCode).to.equal(200) - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/ 200 \(\d*ms\)/) expect(data.responseTime).to.be.at.least(10) done() }) @@ -214,7 +214,7 @@ experiment('logs each request', () => { await registerWithSink(server, 'info', data => { expect(data.res.statusCode).to.equal(200) - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/ 200 \(\d*ms\)/) expect(data.responseTime) .to.be.a.number() .greaterThan(0) @@ -247,7 +247,7 @@ experiment('logs each request', () => { }) await registerWithSink(server, 'info', (data, enc, cb) => { expect(data.res.statusCode).to.equal(200) - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/ 200 \(\d*ms\)/) cb() done() }) @@ -277,7 +277,7 @@ experiment('logs each request', () => { } else { expect(data.res.statusCode).to.equal(500) expect(data.level).to.equal(30) - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/get \/ 500 \(\d*ms\)/) done() } count++ @@ -329,7 +329,7 @@ experiment('logs each request', () => { expect(data.msg).to.equal('hello logger') } else { expect(data.res.statusCode).to.equal(200) - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/get \/ 200 \(\d*ms\)/) done() } count++ @@ -386,7 +386,7 @@ experiment('logs each request', () => { await registerWithSink(server, 'info', data => { expect(data.res.statusCode).to.equal(200) - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/ 200 \(\d*ms\)/) done() }) @@ -935,7 +935,7 @@ experiment('options.logRequestStart', () => { }) const stream = sink(data => { - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/) expect(data.req).to.be.an.object() expect(data.req.id).to.exists() expect(data.res).to.be.an.object() @@ -962,7 +962,7 @@ experiment('options.logRequestStart', () => { }) const stream = sink(data => { - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/) expect(data.req).to.be.an.object() expect(data.req.id).to.exists() expect(data.res).to.be.an.object() @@ -1033,13 +1033,13 @@ experiment('options.logRequestStart', () => { const stream = sink((data, enc, cb) => { if (count === 0) { expect(data.req.url).to.endWith('/ignored') - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/ignored 200 \(\d*ms\)/) } else if (count === 1) { expect(data.req.url).to.endWith('/foo') expect(data.msg).to.equal('request start') } else { expect(data.req.url).to.endWith('/foo') - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/foo 200 \(\d*ms\)/) done() } count++ @@ -1083,7 +1083,7 @@ experiment('options.logRequestStart', () => { expect(data.req).to.be.an.object() expect(data.res).to.be.undefined() } else { - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/) expect(data.req).to.be.an.object() expect(data.res).to.be.an.object() done() @@ -1119,7 +1119,7 @@ experiment('options.logRequestStart', () => { expect(data.res).to.be.undefined() expect(data.requestId).to.equal('request1234') } else { - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/) expect(data.req).to.be.undefined() expect(data.res).to.be.an.object() expect(data.requestId).to.equal('request1234') @@ -1153,7 +1153,7 @@ experiment('options.logRequestComplete', () => { }) const stream = sink(data => { - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/) expect(data.req).to.be.an.object() expect(data.req.id).to.exists() expect(data.res).to.be.an.object() @@ -1180,7 +1180,7 @@ experiment('options.logRequestComplete', () => { }) const stream = sink(data => { - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/something 200 \(\d*ms\)/) expect(data.req).to.be.an.object() expect(data.req.id).to.exists() expect(data.res).to.be.an.object() @@ -1258,7 +1258,7 @@ experiment('options.logRequestComplete', () => { }) const stream = sink((data, enc, cb) => { expect(data.req.url).to.endWith('/foo') - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] get \/foo 200 \(\d*ms\)/) done() }) const logger = require('pino')(stream) @@ -1740,7 +1740,7 @@ experiment('ignore response logs for paths in ignorePaths', () => { }) const stream = sink(data => { expect(data.req.url).to.endWith('/foo') - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] put \/foo 404 \(\d*ms\)/) resolver() }) const logger = require('pino')(stream) @@ -1777,7 +1777,7 @@ experiment('ignore response logs for tags in ignoreTags', () => { }) const stream = sink(data => { expect(data.req.url).to.endWith('/foo') - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] put \/foo 404 \(\d*ms\)/) resolver() }) const logger = require('pino')(stream) @@ -1814,7 +1814,7 @@ experiment('ignore response logs with ignoreFunc', () => { }) const stream = sink(data => { expect(data.req.url).to.endWith('/foo') - expect(data.msg).to.equal('request completed') + expect(data.msg).to.match(/\[response\] put \/foo 404 \(\d*ms\)/) resolver() }) const logger = require('pino')(stream)