diff --git a/docs/api.md b/docs/api.md index 41565b809..314e26d15 100644 --- a/docs/api.md +++ b/docs/api.md @@ -662,9 +662,6 @@ By default, `pino.destination` will use `process.stdout.fd` (1) as the file desc A `pino.destination` instance can also be used to reopen closed files (for example, for some log rotation scenarios), see [Reopening log files](/docs/help.md#reopening). -On AWS Lambda we recommend to call `destination.flushSync()` at the end -of each function execution to avoid losing data. - * See [`destination` parameter](#destination) * See [`sonic-boom` ⇗](https://github.com/mcollina/sonic-boom) * See [Reopening log files](/docs/help.md#reopening) @@ -707,13 +704,14 @@ or create an exit listener function. The `finalLogger` is a specialist logger that synchronously flushes on every write. This is important to guarantee final log writes, -both when using `pino.destination` or `pino.extreme` targets. +both when using `pino.extreme` target. Since final log writes cannot be guaranteed with normal Node.js streams, if the `destination` parameter of the `logger` supplied to `pino.final` -is a Node.js stream `pino.final` will throw. It's highly recommended -for both performance and safety to use `pino.destination`/`pino.extreme` -destinations. +is a Node.js stream `pino.final` will throw. + +The use of `pino.final` with `pino.destination` is not needed, as +`pino.destination` writes things synchronously. #### `pino.final(logger, handler) => Function` diff --git a/lib/tools.js b/lib/tools.js index a553c877e..c297f109b 100644 --- a/lib/tools.js +++ b/lib/tools.js @@ -21,11 +21,6 @@ const { streamSym } = require('./symbols') -// FIXME we need to check if we are using AWS Lambda -// because we cannot use pino.destination/Sonic Boom -// there, as data might get lost during freeze -const isAWSLambda = !!process.env.LAMBDA_TASK_ROOT - function noop () {} function genLog (z) { @@ -267,8 +262,8 @@ function hasBeenTampered (stream) { return stream.write !== stream.constructor.prototype.write } -function buildSafeSonicBoom (dest, buffer = 0) { - const stream = new SonicBoom(dest, buffer) +function buildSafeSonicBoom (dest, buffer = 0, sync = true) { + const stream = new SonicBoom(dest, buffer, sync) stream.on('error', filterBrokenPipe) return stream @@ -311,7 +306,7 @@ function createArgsNormalizer (defaultOptions) { const { enabled, prettyPrint, prettifier, messageKey } = opts if (enabled === false) opts.level = 'silent' stream = stream || process.stdout - if (stream === process.stdout && stream.fd >= 0 && !isAWSLambda && !hasBeenTampered(stream)) { + if (stream === process.stdout && stream.fd >= 0 && !hasBeenTampered(stream)) { stream = buildSafeSonicBoom(stream.fd) } if (prettyPrint) { diff --git a/package.json b/package.json index f5099f5f3..3f76941ba 100644 --- a/package.json +++ b/package.json @@ -69,7 +69,7 @@ "fresh-require": "^1.0.3", "log": "^1.4.0", "loglevel": "^1.6.1", - "pino-pretty": "^2.2.4", + "pino-pretty": "^2.4.0", "pre-commit": "^1.2.2", "proxyquire": "^2.1.0", "qodaa": "^1.0.1", @@ -79,17 +79,17 @@ "steed": "^1.1.3", "tap": "^12.1.0", "tape": "^4.9.0", - "through2": "^2.0.5", + "through2": "^3.0.0", "winston": "^3.1.0" }, "dependencies": { "fast-json-parse": "^1.0.3", - "fast-redact": "^1.4.0", + "fast-redact": "^1.4.2", "fast-safe-stringify": "^2.0.6", - "flatstr": "^1.0.5", + "flatstr": "^1.0.9", "pino-std-serializers": "^2.3.0", "pump": "^3.0.0", "quick-format-unescaped": "^3.0.0", - "sonic-boom": "^0.6.3" + "sonic-boom": "^0.7.1" } } diff --git a/pino.js b/pino.js index 0600ca1da..072d1e8d3 100644 --- a/pino.js +++ b/pino.js @@ -119,8 +119,8 @@ function pino (...args) { return instance } -pino.extreme = (dest = process.stdout.fd) => buildSafeSonicBoom(dest, 4096) -pino.destination = (dest = process.stdout.fd) => buildSafeSonicBoom(dest) +pino.extreme = (dest = process.stdout.fd) => buildSafeSonicBoom(dest, 4096, false) +pino.destination = (dest = process.stdout.fd) => buildSafeSonicBoom(dest, 0, true) pino.final = final pino.levels = mappings() diff --git a/test/exit.test.js b/test/exit.test.js new file mode 100644 index 000000000..fe7542a32 --- /dev/null +++ b/test/exit.test.js @@ -0,0 +1,53 @@ +'use strict' + +const { test } = require('tap') +const { join } = require('path') +const execa = require('execa') +const writer = require('flush-write-stream') +const { once } = require('./helper') + +// https://github.com/pinojs/pino/issues/542 +test('pino.destination log everything when calling process.exit(0)', async ({ isNot }) => { + var actual = '' + const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'destination-exit.js')]) + + child.stdout.pipe(writer((s, enc, cb) => { + actual += s + cb() + })) + + await once(child, 'close') + + isNot(actual.match(/hello/), null) + isNot(actual.match(/world/), null) +}) + +test('pino.extreme does not log everything when calling process.exit(0)', async ({ is }) => { + var actual = '' + const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'extreme-exit.js')]) + + child.stdout.pipe(writer((s, enc, cb) => { + actual += s + cb() + })) + + await once(child, 'close') + + is(actual.match(/hello/), null) + is(actual.match(/world/), null) +}) + +test('pino.extreme logs everything when calling flushSync', async ({ isNot }) => { + var actual = '' + const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'extreme-flush-exit.js')]) + + child.stdout.pipe(writer((s, enc, cb) => { + actual += s + cb() + })) + + await once(child, 'close') + + isNot(actual.match(/hello/), null) + isNot(actual.match(/world/), null) +}) diff --git a/test/final.test.js b/test/final.test.js index 7daeba521..abceb5380 100644 --- a/test/final.test.js +++ b/test/final.test.js @@ -24,13 +24,13 @@ test('throws if the supplied handler is not a function', async ({ throws }) => { }, Error('if supplied, the handler parameter should be a function')) }) -test('throws if not supplied logger with pino.destination or pino.extreme instance', async ({ throws, doesNotThrow }) => { +test('throws if not supplied logger with pino.extreme instance', async ({ throws, doesNotThrow }) => { throws(() => { pino.final(pino(fs.createWriteStream('/dev/null')), () => {}) }, Error('final requires a stream that has a flushSync method, such as pino.destination and pino.extreme')) doesNotThrow(() => { - pino.final(pino(pino.destination()), () => {}) + pino.final(pino(pino.extreme()), () => {}) }) doesNotThrow(() => { @@ -39,10 +39,22 @@ test('throws if not supplied logger with pino.destination or pino.extreme instan }) test('returns an exit listener function', async ({ is }) => { - is(typeof pino.final(pino(pino.destination()), () => {}), 'function') + is(typeof pino.final(pino(pino.extreme()), () => {}), 'function') }) test('listener function immediately sync flushes when fired', async ({ pass, fail }) => { + const dest = pino.extreme('/dev/null') + var passed = false + dest.flushSync = () => { + passed = true + pass('flushSync called') + } + pino.final(pino(dest), () => {})() + await sleep(10) + if (passed === false) fail('flushSync not called') +}) + +test('listener function immediately sync flushes when fired (pino.destination)', async ({ pass, fail }) => { const dest = pino.destination('/dev/null') var passed = false dest.flushSync = () => { @@ -55,14 +67,14 @@ test('listener function immediately sync flushes when fired', async ({ pass, fai }) test('swallows the non-ready error', async ({ doesNotThrow }) => { - const dest = pino.destination('/dev/null') + const dest = pino.extreme('/dev/null') doesNotThrow(() => { pino.final(pino(dest), () => {})() }) }) test('listener function triggers handler function parameter', async ({ pass, fail }) => { - const dest = pino.destination('/dev/null') + const dest = pino.extreme('/dev/null') var passed = false pino.final(pino(dest), () => { passed = true @@ -73,14 +85,14 @@ test('listener function triggers handler function parameter', async ({ pass, fai }) test('passes any error to the handler', async ({ is }) => { - const dest = pino.destination('/dev/null') + const dest = pino.extreme('/dev/null') pino.final(pino(dest), (err) => { is(err.message, 'test') })(Error('test')) }) test('passes a specialized final logger instance', async ({ is, isNot, error }) => { - const dest = pino.destination('/dev/null') + const dest = pino.extreme('/dev/null') const logger = pino(dest) pino.final(logger, (err, finalLogger) => { error(err) @@ -104,7 +116,7 @@ test('passes a specialized final logger instance', async ({ is, isNot, error }) }) test('returns a specialized final logger instance if no handler is passed', async ({ is, isNot }) => { - const dest = pino.destination('/dev/null') + const dest = pino.extreme('/dev/null') const logger = pino(dest) const finalLogger = pino.final(logger) is(typeof finalLogger.trace, 'function') @@ -126,7 +138,7 @@ test('returns a specialized final logger instance if no handler is passed', asyn }) test('final logger instances synchronously flush after a log method call', async ({ pass, fail, error }) => { - const dest = pino.destination('/dev/null') + const dest = pino.extreme('/dev/null') const logger = pino(dest) var passed = false var count = 0 @@ -146,7 +158,7 @@ test('final logger instances synchronously flush after a log method call', async }) test('also instruments custom log methods', async ({ pass, fail, error }) => { - const dest = pino.destination('/dev/null') + const dest = pino.extreme('/dev/null') const logger = pino({ customLevels: { foo: 35 diff --git a/test/fixtures/destination-exit.js b/test/fixtures/destination-exit.js new file mode 100644 index 000000000..c14ab07f0 --- /dev/null +++ b/test/fixtures/destination-exit.js @@ -0,0 +1,8 @@ +global.process = { __proto__: process, pid: 123456 } +Date.now = function () { return 1459875739796 } +require('os').hostname = function () { return 'abcdefghijklmnopqr' } +var pino = require(require.resolve('./../../')) +var logger = pino({}, pino.destination(1)) +logger.info('hello') +logger.info('world') +process.exit(0) diff --git a/test/fixtures/extreme-exit.js b/test/fixtures/extreme-exit.js new file mode 100644 index 000000000..a90cc67c9 --- /dev/null +++ b/test/fixtures/extreme-exit.js @@ -0,0 +1,9 @@ +global.process = { __proto__: process, pid: 123456 } +Date.now = function () { return 1459875739796 } +require('os').hostname = function () { return 'abcdefghijklmnopqr' } +var pino = require(require.resolve('./../../')) +var dest = pino.extreme(1) +var logger = pino({}, dest) +logger.info('hello') +logger.info('world') +process.exit(0) diff --git a/test/fixtures/extreme-flush-exit.js b/test/fixtures/extreme-flush-exit.js new file mode 100644 index 000000000..3abf7e0ec --- /dev/null +++ b/test/fixtures/extreme-flush-exit.js @@ -0,0 +1,10 @@ +global.process = { __proto__: process, pid: 123456 } +Date.now = function () { return 1459875739796 } +require('os').hostname = function () { return 'abcdefghijklmnopqr' } +var pino = require(require.resolve('./../../')) +var dest = pino.extreme(1) +var logger = pino({}, dest) +logger.info('hello') +logger.info('world') +dest.flushSync() +process.exit(0) diff --git a/test/stdout-protection.test.js b/test/stdout-protection.test.js index 963dba2dd..1a9778526 100644 --- a/test/stdout-protection.test.js +++ b/test/stdout-protection.test.js @@ -1,34 +1,11 @@ 'use strict' const { test } = require('tap') -const pino = require('..') -const { symbols } = pino const { join } = require('path') const { fork } = require('child_process') const { once } = require('./helper') const writer = require('flush-write-stream') -test('do not use SonicBoom on AWS Lambda', async (t) => { - // hack, we are on lambda now - process.env.LAMBDA_TASK_ROOT = __dirname - - // we need to clear the cache - delete require.cache[require.resolve('../')] - delete require.cache[require.resolve('../lib/tools.js')] - const pino = require('..') - - // restore in the next tick - process.nextTick(() => { - delete process.env.LAMBDA_TASK_ROOT - }) - - const logger = pino() - - // this test verifies that the default constructor of pino - // does not use SonicBoom on lambda by default - t.equal(logger[symbols.streamSym], process.stdout) -}) - test('do not use SonicBoom is someone tampered with process.stdout.write', async ({ isNot }) => { var actual = '' const child = fork(join(__dirname, 'fixtures', 'stdout-hack-protection.js'), { silent: true })