From 2a5bdd231a5cf3b2c1231d5b0cc4dc2649da5657 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Wed, 3 May 2017 23:16:14 -0700 Subject: [PATCH] some updated TODOs for 2.x work --- TODO.md | 144 ++++++++++++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 141 insertions(+), 3 deletions(-) diff --git a/TODO.md b/TODO.md index db7c45f..9215525 100644 --- a/TODO.md +++ b/TODO.md @@ -1,12 +1,22 @@ # v2 -- ^C fix. Done in 1.8.9. However, see a recent ticket about ^C/EPIPE issues. - I suspect the uncommited exeunt work will fix that. -- node-exeunt +- Exit handling: + + - make a ticket with notes from "bunyan CLI exit handling" section below + - resolve it with the uncommited changes here + +- figure out how to 'make cutarelease' for 2.x but tag as beta +- comment/grokking of bunyan.js flushing issues at + https://github.com/trentm/node-bunyan/issues/37 would be nice. Even if just a + link to exeunt and some examples. Wiki page? + - respond to Qs here: https://github.com/trentm/node-bunyan/issues/37#issuecomment-282933502 +- consider whether to backport the exit handling work to 1.x??? - `createLogger(, )` changes (#460) - see section below - the dtrace-provider thing (#487) TODO: answer Cody email +- https://github.com/trentm/node-bunyan/issues/398 if easy, perhaps on 1.x + as well - use package.json version for VERSION - use deps - dashdash @@ -19,6 +29,134 @@ - formatters: read up again on `glp master..1.x` - support for customer formatters - for the CLI as well? How? ~/.bunyanrc? +- if doing ~/.bunyanrc, then consider color schemes + + +# bunyan CLI exit handling + +It has some problems currently. + +One basic problem is that our stdout.on('error') handler can call into +drainStdoutAndExit multiple times, leading to the multiple Event Emitters +leak warning, and with a pager we are waiting for the pager to exit. +Why doesn't the pager exit on ^C? Is that a less thing? Perhaps due to our +LESS opts? + + + +Setting up a file to work with: + +```javascript +$ cat lots.js +var bunyan = require('./') +var log = bunyan.createLogger({ + name: 'lots', + streams: [ + { + type: 'file', + path: './lots.log' + } + ] +}); + +N = Math.pow(2, 16); +for (var i = N; i >= 0; i--) { + log.info({i: i}, 'another record'); +} + +$ node lots.js +``` + +## Issue 1: EventEmitter mem leak + +``` +$ node --version +v4.8.0 +$ ./bin/bunyan lots.log | cat +[2017-04-05T01:47:15.899Z] INFO: lots/53218 on danger0.local: another record (i=65536) +[2017-04-05T01:47:15.901Z] INFO: lots/53218 on danger0.local: another record (i=65535) +... +^C # ^C quickly before it is done writing rendered logs +... +[2017-04-05T01:47:16.023Z] INFO: lots/53218 on danger0.local: another record (i=57351) +[2017-04-05T01:47:16.023Z] INFO: lots/53218 +^C(node) warning: possible EventEmitter memory leak detected. 11 drain listeners added. Use emitter.setMaxListeners() to increase limit. +Trace + at Socket.addListener (events.js:239:17) + at Socket.Readable.on (_stream_readable.js:680:33) + at drainStdoutAndExit (/Users/trentm/tm/node-bunyan/bin/bunyan:1116:12) + at Socket. (/Users/trentm/tm/node-bunyan/bin/bunyan:1597:13) + at emitOne (events.js:77:13) + at Socket.emit (events.js:169:7) + at onwriteError (_stream_writable.js:313:10) + at onwrite (_stream_writable.js:331:5) + at WritableState.onwrite (_stream_writable.js:90:5) + at fireErrorCallbacks (net.js:457:13) +``` + +## Issue 2: "write after end" infinite loop with ^C in pager + +Mac. Node v4.8.0. Happens with node 0.10 as well. + +``` +$ ./bin/bunyan lots.log +[2017-04-05T01:47:15.899Z] INFO: lots/53218 on danger0.local: another record (i=65536) +[2017-04-05T01:47:15.901Z] INFO: lots/53218 on danger0.local: another record (i=65535) +[2017-04-05T01:47:15.901Z] INFO: lots/53218 on danger0.local: another record (i=65534) +... +^C +... +[2017-04-05T01:47:15.909Z] INFO: lots/53218 on danger0.local: another record (i=65490) +:[Error: write after end] +[Error: write after end] +[Error: write after end] +[Error: write after end] +[Error: write after end] +(node) warning: possible EventEmitter memory leak detected. 11 drain listeners added. Use emitter.setMaxListeners() to increase limit. +Trace + at Socket.addListener (events.js:239:17) + at Socket.Readable.on (_stream_readable.js:680:33) + at drainStdoutAndExit (/Users/trentm/tm/node-bunyan/bin/bunyan:1116:12) + at Socket. (/Users/trentm/tm/node-bunyan/bin/bunyan:1600:13) + at emitOne (events.js:77:13) + at Socket.emit (events.js:169:7) + at writeAfterEnd (_stream_writable.js:169:10) + at Socket.Writable.write (_stream_writable.js:212:5) + at Socket.write (net.js:645:40) + at emit (/Users/trentm/tm/node-bunyan/bin/bunyan:1097:32) +[Error: write after end] +[Error: write after end] +[Error: write after end] +[Error: write after end] +... # this goes forever until 'q' to quit pager +``` + +With bunyan's internal `_DEBUG`: + +``` +... +[2017-04-05T01:47:15.909Z] INFO: lots/53218 on danger0.local: another record (i=65491) +[2017-04-05T01:47:15.909Z] INFO: lots/53218 on danger0.local: another record (i=65490) +:(bunyan: cleanupAndExit) +(stdout error event: Error: write after end) +[Error: write after end] +(drainStdoutAndExit(1)) +(stdout error event: Error: write after end) +[Error: write after end] +(drainStdoutAndExit(1)) +(stdout error event: Error: write after end) +[Error: write after end] +(drainStdoutAndExit(1)) +(stdout error event: Error: write after end) +[Error: write after end] +... +(drainStdoutAndExit(1)) +(stdout error event: Error: write EPIPE) +(drainStdoutAndExit(0)) +(bunyan: pager exit) +(bunyan: pager exit -> process.exit(1)) +``` + # changes to ctor and log.child to separate fields from config