diff --git a/CHANGES.md b/CHANGES.md index 4104d42..9fed3fd 100644 --- a/CHANGES.md +++ b/CHANGES.md @@ -2,6 +2,8 @@ ## bunyan 0.11.2 (not yet released) +- [issue #30] Robust handling of 'req' field without a 'headers' subfield + in `bunyan` CLI. - [issue #31] Pull the TRACE, DEBUG, et al defines from `bunyan -c "..."` filtering code. This was added in v0.11.1, but has a significant adverse affect. diff --git a/TODO.md b/TODO.md index fbfa5c1..bec3056 100644 --- a/TODO.md +++ b/TODO.md @@ -2,7 +2,7 @@ - move custom keys out to 'x' ? What about req, res? Compat issues there? Bunyan CLI would have to deal with both for a while. Just a change in record.v from 0 to 1. -- [Yunong] buffered writes to increase speed: +- buffered writes to increase speed: - I'd start with a tools/timeoutput.js for some numbers to compare before/after. Sustained high output to a file. - perhaps this would be a "buffered: true" option on the stream object diff --git a/bin/bunyan b/bin/bunyan index 27ea668..7b04608 100755 --- a/bin/bunyan +++ b/bin/bunyan @@ -570,10 +570,13 @@ function emitRecord(rec, line, opts, stylize) { if (rec.req) { var headers = rec.req.headers; - details.push(indent(format("%s %s HTTP/1.1\n%s", rec.req.method, + details.push(indent(format("%s %s HTTP/1.1%s", rec.req.method, rec.req.url, - Object.keys(headers).map( - function (h) { return h + ': ' + headers[h]; }).join('\n')))); + (headers + ? '\n' + Object.keys(headers).map( + function (h) { return h + ': ' + headers[h]; }).join('\n') + : '') + ))); } delete rec.req; diff --git a/test/cli.test.js b/test/cli.test.js index b4b61ab..6a7e65d 100644 --- a/test/cli.test.js +++ b/test/cli.test.js @@ -276,15 +276,43 @@ test('multiple --conditions', function (t) { // // One of the records in corpus/withreq.log has a 'req' // field with no 'headers'. Ditto for the 'res' field. -//test('robust req handling', function (t) { -// XXX -// var expect = [ -// '{"hi": "there"}\n' -// ].join(''); -// exec(BUNYAN + ' corpus/withreq.log', function (err, stdout, stderr) { -// t.ok(false, "boom XXX") -// t.error(err); -// t.equal(stdout, expect); -// t.end(); -// }); -//}); +test('robust req handling', function (t) { + var expect = [ + '[2012-08-08T10:25:47.636Z] DEBUG: amon-master/12859 on 9724a190-27b6-4fd8-830b-a574f839c67d: headAgentProbes respond (req_id=cce79d15-ffc2-487c-a4e4-e940bdaac31e, route=HeadAgentProbes, contentMD5=11FxOYiYfpMxmANj4kGJzg==)', + '[2012-08-08T10:25:47.637Z] INFO: amon-master/12859 on 9724a190-27b6-4fd8-830b-a574f839c67d: HeadAgentProbes handled: 200 (req_id=cce79d15-ffc2-487c-a4e4-e940bdaac31e, 3ms, audit=true, remoteAddress=10.2.207.2, remotePort=50394, secure=false, _audit=true)', + ' HEAD /agentprobes?agent=ccf92af9-0b24-46b6-ab60-65095fdd3037 HTTP/1.1', + ' accept: application/json', + ' content-type: application/json', + ' host: 10.2.207.16', + ' connection: keep-alive', + ' --', + ' HTTP/1.1 200 OK', + ' content-md5: 11FxOYiYfpMxmANj4kGJzg==', + ' access-control-allow-origin: *', + ' access-control-allow-headers: Accept, Accept-Version, Content-Length, Content-MD5, Content-Type, Date, X-Api-Version', + ' access-control-allow-methods: HEAD', + ' access-control-expose-headers: X-Api-Version, X-Request-Id, X-Response-Time', + ' connection: Keep-Alive', + ' date: Wed, 08 Aug 2012 10:25:47 GMT', + ' server: Amon Master/1.0.0', + ' x-request-id: cce79d15-ffc2-487c-a4e4-e940bdaac31e', + ' x-response-time: 3', + ' --', + ' route: {', + ' "name": "HeadAgentProbes",', + ' "version": false', + ' }', + '[2012-08-08T10:25:47.637Z] INFO: amon-master/12859 on 9724a190-27b6-4fd8-830b-a574f839c67d: HeadAgentProbes handled: 200 (req_id=cce79d15-ffc2-487c-a4e4-e940bdaac31e, 3ms, audit=true, remoteAddress=10.2.207.2, remotePort=50394, secure=false, _audit=true)', + ' HEAD /agentprobes?agent=ccf92af9-0b24-46b6-ab60-65095fdd3037 HTTP/1.1', + ' --', + ' route: {', + ' "name": "HeadAgentProbes",', + ' "version": false', + ' }' + ].join('\n') + '\n'; + exec(BUNYAN + ' corpus/withreq.log', function (err, stdout, stderr) { + t.error(err); + t.equal(stdout, expect); + t.end(); + }); +}); diff --git a/test/corpus/withreq.log b/test/corpus/withreq.log new file mode 100644 index 0000000..e5ece7a --- /dev/null +++ b/test/corpus/withreq.log @@ -0,0 +1,3 @@ +{"name":"amon-master","hostname":"9724a190-27b6-4fd8-830b-a574f839c67d","pid":12859,"route":"HeadAgentProbes","req_id":"cce79d15-ffc2-487c-a4e4-e940bdaac31e","level":20,"contentMD5":"11FxOYiYfpMxmANj4kGJzg==","msg":"headAgentProbes respond","time":"2012-08-08T10:25:47.636Z","v":0} +{"name":"amon-master","hostname":"9724a190-27b6-4fd8-830b-a574f839c67d","pid":12859,"audit":true,"level":30,"remoteAddress":"10.2.207.2","remotePort":50394,"req_id":"cce79d15-ffc2-487c-a4e4-e940bdaac31e","req":{"method":"HEAD","url":"/agentprobes?agent=ccf92af9-0b24-46b6-ab60-65095fdd3037","headers":{"accept":"application/json","content-type":"application/json","host":"10.2.207.16","connection":"keep-alive"},"httpVersion":"1.1","trailers":{},"version":"*"},"res":{"statusCode":200,"headers":{"content-md5":"11FxOYiYfpMxmANj4kGJzg==","access-control-allow-origin":"*","access-control-allow-headers":"Accept, Accept-Version, Content-Length, Content-MD5, Content-Type, Date, X-Api-Version","access-control-allow-methods":"HEAD","access-control-expose-headers":"X-Api-Version, X-Request-Id, X-Response-Time","connection":"Keep-Alive","date":"Wed, 08 Aug 2012 10:25:47 GMT","server":"Amon Master/1.0.0","x-request-id":"cce79d15-ffc2-487c-a4e4-e940bdaac31e","x-response-time":3},"trailer":false},"route":{"name":"HeadAgentProbes","version":false},"latency":3,"secure":false,"_audit":true,"msg":"HeadAgentProbes handled: 200","time":"2012-08-08T10:25:47.637Z","v":0} +{"name":"amon-master","hostname":"9724a190-27b6-4fd8-830b-a574f839c67d","pid":12859,"audit":true,"level":30,"remoteAddress":"10.2.207.2","remotePort":50394,"req_id":"cce79d15-ffc2-487c-a4e4-e940bdaac31e","req":{"method":"HEAD","url":"/agentprobes?agent=ccf92af9-0b24-46b6-ab60-65095fdd3037","httpVersion":"1.1","trailers":{},"version":"*"},"res":{"statusCode":200,"trailer":false},"route":{"name":"HeadAgentProbes","version":false},"latency":3,"secure":false,"_audit":true,"msg":"HeadAgentProbes handled: 200","time":"2012-08-08T10:25:47.637Z","v":0}