Skip to content

Commit

Permalink
Log the request duration
Browse files Browse the repository at this point in the history
  • Loading branch information
@kurayama
Pedro Branco authored and kurayama committed Jan 12, 2017
1 parent 6394701 commit 45f7149
Show file tree
Hide file tree
Showing 2 changed files with 100 additions and 44 deletions.
5 changes: 5 additions & 0 deletions src/index.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,7 @@ module.exports = function logger(request, log) {

function apply(target, caller, args) {
const id = uuid();
const startTime = Date.now();

return target.apply(undefined, args)
.on('complete', function(response) {
Expand All @@ -31,6 +32,7 @@ module.exports = function logger(request, log) {
}

log({
duration: Date.now() - startTime,
id,
response: {
body: response.body,
Expand All @@ -42,6 +44,7 @@ module.exports = function logger(request, log) {
}, this);
}).on('error', function(error) {
log({
duration: Date.now() - startTime,
error,
headers: clone(this.headers),
id,
Expand All @@ -51,6 +54,7 @@ module.exports = function logger(request, log) {
}, this);
}).on('redirect', function() {
log({
duration: Date.now() - startTime,
id,
response: {
headers: clone(this.response.headers),
Expand Down Expand Up @@ -79,6 +83,7 @@ module.exports = function logger(request, log) {
}

log({
duration: Date.now() - startTime,
id,
response: {
headers: clone(response.headers),
Expand Down
139 changes: 95 additions & 44 deletions test/index.test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -96,15 +96,16 @@ describe('request-logger', () => {
nock(url).get('/').reply(200, 'foo');

client(url).on('complete', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
id: log.calls.mostRecent().args[0].id,
response: {
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
});
}));

done();
});
Expand All @@ -117,15 +118,63 @@ describe('request-logger', () => {
nock(url).get('/').reply(200, 'foo');

client(url, () => {}).on('complete', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
response: {
body: 'foo',
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
});
}));

done();
});
});

it('should log the request `duration`', done => {
const log = jasmine.createSpy();
const client = requestLogger(request, log);

spyOn(Date, 'now').and.returnValue(0);

nock(url).get('/').reply(200, 'foo');

client(url, () => {}).on('complete', () => {
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: 0,
response: {
body: 'foo',
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
}));

done();
});
});

it('should log the elapsed time as `duration`', done => {
const log = jasmine.createSpy();
const client = requestLogger(request, log);

nock(url).get('/').delay(500).reply(200, 'foo');

client(url, () => {}).on('complete', () => {
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
response: {
body: 'foo',
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
}));
expect(log.calls.mostRecent().args[0].duration).not.toBeLessThan(500);

done();
});
Expand All @@ -138,7 +187,8 @@ describe('request-logger', () => {
nock(url).get('/').replyWithError('foo');

client(url).on('error', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
error: log.calls.mostRecent().args[0].error,
headers: {
host: 'foo.bar'
Expand All @@ -147,7 +197,7 @@ describe('request-logger', () => {
method: 'GET',
type: 'error',
uri: 'http://foo.bar/'
});
}));

done();
});
Expand All @@ -161,7 +211,8 @@ describe('request-logger', () => {
nock(url).get('/').reply(302, undefined, { Location: redirectUrl });

client(url).on('redirect', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
response: {
headers: {
location: redirectUrl
Expand All @@ -170,7 +221,7 @@ describe('request-logger', () => {
},
type: 'redirect',
uri: redirectUrl
});
}));

done();
});
Expand Down Expand Up @@ -227,14 +278,15 @@ describe('request-logger', () => {
nock(url).get('/').reply(200);

client(url).on('response', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
response: {
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
});
}));

done();
});
Expand All @@ -247,14 +299,15 @@ describe('request-logger', () => {
nock(url).get('/').reply(200, 'foo');

client(url).on('response', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
response: {
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
});
}));

done();
});
Expand All @@ -267,14 +320,14 @@ describe('request-logger', () => {
nock(url).get('/').reply(200);

client(url, () => {}).on('response', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
headers: {
host: 'foo.bar'
},
method: 'GET',
type: 'request',
uri: 'http://foo.bar/'
});
}));

done();
});
Expand Down Expand Up @@ -351,15 +404,15 @@ describe('request-logger', () => {
nock(url)[method]('/').reply(200, 'foo');

client[verb](url).on('complete', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
id: expect.any(String),
response: {
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
});
expect(log.calls.mostRecent().args[0].id).toBeDefined();
}));

done();
});
Expand All @@ -372,16 +425,17 @@ describe('request-logger', () => {
nock(url)[method]('/').reply(200, 'foo');

client[verb](url, () => {}).on('complete', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
id: expect.any(String),
response: {
body: 'foo',
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
});
expect(log.calls.mostRecent().args[0].id).toBeDefined();
}));

done();
});
Expand All @@ -394,16 +448,14 @@ describe('request-logger', () => {
nock(url)[method]('/').replyWithError('foo');

client[verb](url).on('error', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
error: new Error('foo'),
headers: {
host: 'foo.bar'
},
id: expect.any(String),
method: expect.any(String),
type: 'error',
uri: 'http://foo.bar/'
});
expect(log.calls.mostRecent().args[0].method).toBeDefined();
expect(log.calls.mostRecent().args[0].id).toBeDefined();
}));

done();
});
Expand All @@ -418,16 +470,18 @@ describe('request-logger', () => {
nock(url)[method]('/').reply(302, undefined, { Location: redirectUrl });

client[verb](url).on('redirect', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
id: expect.any(String),
response: {
headers: {
location: redirectUrl
}
},
statusCode: 302
},
type: 'redirect',
uri: redirectUrl
});
expect(log.calls.mostRecent().args[0].id).toBeDefined();
}));

done();
});
Expand All @@ -448,7 +502,6 @@ describe('request-logger', () => {
type: 'request',
uri: 'http://foo.bar/'
});

expect(log.calls.mostRecent().args[0].id).toBeDefined();
expect(log.calls.mostRecent().args[0].method).toBeDefined();
}).on('response', () => {
Expand All @@ -474,7 +527,6 @@ describe('request-logger', () => {
type: 'request',
uri: 'http://foo.bar/'
});

expect(log.calls.mostRecent().args[0].id).toBeDefined();
expect(log.calls.mostRecent().args[0].method).toBeDefined();
}).on('response', () => {
Expand All @@ -491,14 +543,16 @@ describe('request-logger', () => {
nock(url)[method]('/').reply(200);

client[verb](url).on('response', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
duration: expect.any(Number),
id: expect.any(String),
response: {
headers: {}
headers: {},
statusCode: 200
},
type: 'response',
uri: 'http://foo.bar/'
});
expect(log.calls.mostRecent().args[0].id).toBeDefined();
}));

done();
});
Expand All @@ -511,15 +565,12 @@ describe('request-logger', () => {
nock(url)[method]('/').reply(200);

client[verb](url, () => {}).on('response', () => {
expect(log.calls.mostRecent().args[0]).toMatchObject({
headers: {
host: 'foo.bar'
},
expect(log.calls.mostRecent().args[0]).toEqual(expect.objectContaining({
id: expect.any(String),
method: expect.any(String),
type: 'request',
uri: 'http://foo.bar/'
});
expect(log.calls.mostRecent().args[0].id).toBeDefined();
expect(log.calls.mostRecent().args[0].method).toBeDefined();
}));

done();
});
Expand Down

0 comments on commit 45f7149

Please sign in to comment.