diff --git a/lib/proto.js b/lib/proto.js index 5f9237992..239aef52d 100644 --- a/lib/proto.js +++ b/lib/proto.js @@ -195,6 +195,7 @@ function write (_obj, msg, num) { const responseKey = this[responseKeySym] const messageKey = this[messageKeySym] const mixinMergeStrategy = this[mixinMergeStrategySym] || defaultMixinMergeStrategy + const future = this[futureSym] let obj if (_obj === undefined || _obj === null) { @@ -205,9 +206,13 @@ function write (_obj, msg, num) { msg = _obj.message } } else if (_obj.method && _obj.headers && _obj.socket) { - obj = { [requestKey]: _obj } + if (future.skipUnconditionalStdSerializers) { + obj = { [requestKey]: _obj } + } } else if (typeof _obj.setHeader === 'function') { - obj = { [responseKey]: _obj } + if (future.skipUnconditionalStdSerializers) { + obj = { [responseKey]: _obj } + } } else { obj = _obj if (msg === undefined && _obj[messageKey] === undefined && _obj[errorKey]) { diff --git a/lib/symbols.js b/lib/symbols.js index 0c8dbf665..d41b926ff 100644 --- a/lib/symbols.js +++ b/lib/symbols.js @@ -25,12 +25,12 @@ const endSym = Symbol('pino.end') const formatOptsSym = Symbol('pino.formatOpts') const messageKeySym = Symbol('pino.messageKey') const errorKeySym = Symbol('pino.errorKey') +const requestKeySym = Symbol('pino.requestKey') +const responseKeySym = Symbol('pino.responseKey') const nestedKeySym = Symbol('pino.nestedKey') const nestedKeyStrSym = Symbol('pino.nestedKeyStr') const mixinMergeStrategySym = Symbol('pino.mixinMergeStrategy') const msgPrefixSym = Symbol('pino.msgPrefix') -const responseKeySym = Symbol('pino.responseKey') -const requestKeySym = Symbol('pino.requestKey') const futureSym = Symbol('pino.future') const wildcardFirstSym = Symbol('pino.wildcardFirst') @@ -65,8 +65,8 @@ module.exports = { formatOptsSym, messageKeySym, errorKeySym, - responseKeySym, requestKeySym, + responseKeySym, nestedKeySym, wildcardFirstSym, needsMetadataGsym, diff --git a/lib/tools.js b/lib/tools.js index 74746677a..ce84e2415 100644 --- a/lib/tools.js +++ b/lib/tools.js @@ -3,6 +3,7 @@ /* eslint no-prototype-builtins: 0 */ const format = require('quick-format-unescaped') +const { mapHttpRequest, mapHttpResponse } = require('pino-std-serializers') const SonicBoom = require('sonic-boom') const onExit = require('on-exit-leak-free') const { @@ -23,10 +24,12 @@ const { requestKeySym, responseKeySym, nestedKeyStrSym, - msgPrefixSym + msgPrefixSym, + futureSym } = require('./symbols') const { isMainThread } = require('worker_threads') const transport = require('./transport') +const { warning } = require('./deprecations') function noop () { } @@ -41,6 +44,16 @@ function genLog (level, hook) { function LOG (o, ...n) { if (typeof o === 'object') { let msg = o + if (!this[futureSym].skipUnconditionalStdSerializers) { + warning.PINODEP010() + if (o !== null) { + if (o.method && o.headers && o.socket) { + o = mapHttpRequest(o) + } else if (typeof o.setHeader === 'function') { + o = mapHttpResponse(o) + } + } + } let formatParams if (msg === null && n.length === 0) { formatParams = [null] @@ -128,9 +141,9 @@ function asJson (obj, msg, num, time) { value = serializers[key](value) } else if (key === errorKey && serializers.err) { value = serializers.err(value) - } else if (key === requestKey && serializers.req) { + } else if (key === requestKey && serializers.req && this[futureSym].skipUnconditionalStdSerializers) { value = serializers.req(value) - } else if (key === responseKey && serializers.res) { + } else if (key === responseKey && serializers.res && this[futureSym].skipUnconditionalStdSerializers) { value = serializers.res(value) } @@ -316,7 +329,7 @@ function createArgsNormalizer (defaultOptions) { stream = transport({ caller, ...opts.transport, levels: customLevels }) } opts = Object.assign({}, defaultOptions, opts) - opts.serializers = Object.assign({}, defaultOptions.serializers, opts.serializers) + opts.formatters = Object.assign({}, defaultOptions.formatters, opts.formatters) if (opts.prettyPrint) { diff --git a/pino.js b/pino.js index c3ded444b..3f6c49604 100644 --- a/pino.js +++ b/pino.js @@ -53,9 +53,7 @@ const { const { epochTime, nullTime } = time const { pid } = process const hostname = os.hostname() -const defaultErrorSerializer = stdSerializers.err -const defaultRequestSerializer = stdSerializers.req -const defaultResponseSerializer = stdSerializers.res + const defaultOptions = { level: 'info', levelComparison: SORTING_ORDER.ASC, @@ -67,11 +65,6 @@ const defaultOptions = { nestedKey: null, enabled: true, base: { pid, hostname }, - serializers: Object.assign(Object.create(null), { - err: defaultErrorSerializer, - req: defaultRequestSerializer, - res: defaultResponseSerializer - }), formatters: Object.assign(Object.create(null), { bindings (bindings) { return bindings @@ -95,8 +88,6 @@ const defaultOptions = { const normalize = createArgsNormalizer(defaultOptions) -const serializers = Object.assign(Object.create(null), stdSerializers) - function pino (...args) { const instance = {} const { opts, stream } = normalize(instance, caller(), ...args) @@ -110,8 +101,8 @@ function pino (...args) { timestamp, messageKey, errorKey, - requestKey, responseKey, + requestKey, nestedKey, base, name, @@ -130,7 +121,13 @@ function pino (...args) { future } = opts - const futureSafe = Object.assign(Object.create(null), defaultFuture, future) + // future is made immutable, as it impacts other settings + const futureSafe = Object.freeze(Object.assign(Object.create(null), defaultFuture, future)) + + const defaultSerializers = futureSafe.skipUnconditionalStdSerializers + ? { err: stdSerializers.err, req: stdSerializers.req, res: stdSerializers.res } + : { err: stdSerializers.err } + const serializersSafe = Object.assign(Object.create(null), defaultSerializers, serializers) const stringifySafe = configure({ maximumDepth: depthLimit, @@ -153,7 +150,7 @@ function pino (...args) { const end = '}' + (crlf ? '\r\n' : '\n') const coreChindings = asChindings.bind(null, { [chindingsSym]: '', - [serializersSym]: serializers, + [serializersSym]: serializersSafe, [stringifiersSym]: stringifiers, [stringifySym]: stringify, [stringifySafeSym]: stringifySafe, @@ -202,12 +199,12 @@ function pino (...args) { [formatOptsSym]: formatOpts, [messageKeySym]: messageKey, [errorKeySym]: errorKey, - [requestKeySym]: requestKey, [responseKeySym]: responseKey, + [requestKeySym]: requestKey, [nestedKeySym]: nestedKey, // protect against injection [nestedKeyStrSym]: nestedKey ? `,${JSON.stringify(nestedKey)}:{` : '', - [serializersSym]: serializers, + [serializersSym]: serializersSafe, [mixinSym]: mixin, [mixinMergeStrategySym]: mixinMergeStrategy, [chindingsSym]: chindings, @@ -216,7 +213,7 @@ function pino (...args) { silent: noop, onChild, [msgPrefixSym]: msgPrefix, - [futureSym]: Object.freeze(futureSafe) // future is set immutable to each Pino top-instance, as it affects behavior of other settings + [futureSym]: futureSafe }) Object.setPrototypeOf(instance, proto()) @@ -243,7 +240,7 @@ module.exports.transport = require('./lib/transport') module.exports.multistream = require('./lib/multistream') module.exports.levels = mappings() -module.exports.stdSerializers = serializers +module.exports.stdSerializers = Object.assign(Object.create(null), stdSerializers) module.exports.stdTimeFunctions = Object.assign({}, time) module.exports.symbols = symbols module.exports.version = version diff --git a/test/http.test.js b/test/http.test.js index d01cf86d3..2b342a1db 100644 --- a/test/http.test.js +++ b/test/http.test.js @@ -83,41 +83,79 @@ test('http request support via serializer', async ({ ok, same, error, teardown } server.close() }) -test('http request support via serializer (avoids stdSerializers)', async ({ error, equal, match }) => { - let originalReq - const instance = pino({ - requestKey: 'myRequest', - serializers: { - req: (req) => { - equal(req, originalReq) - return req.arbitraryProperty +test('http request support via serializer (avoids stdSerializers)', async ({ test }) => { + test('current behavior in major-version 9', async ({ equal, not, error }) => { + let originalReq + const instance = pino({ + serializers: { + req: (req) => { + // original request object is already replaced by pino.stdSerializers.req + not(req, originalReq) + equal(req.arbitraryProperty, undefined) + return req + } } - } - }, sink((chunk, _enc) => { - match(chunk, { - pid, - hostname, - level: 30, - msg: 'my request', - myRequest: originalReq.arbitraryProperty + }, sink()) + + const server = http.createServer(function (req, res) { + originalReq = req + req.arbitraryProperty = Math.random() + + instance.info(req, 'my response') + res.end('hello') }) - })) - const server = http.createServer(function (req, res) { - originalReq = req - req.arbitraryProperty = Math.random() + server.unref() + server.listen() + const err = await once(server, 'listening') + error(err) - instance.info(req, 'my request') - res.end('hello') + const res = await once(http.get('http://localhost:' + server.address().port), 'response') + res.resume() + server.close() }) - server.unref() - server.listen() - const err = await once(server, 'listening') - error(err) - const res = await once(http.get('http://localhost:' + server.address().port), 'response') - res.resume() - server.close() + test('future behavior', async ({ error, equal, match }) => { + const resultOfSerialization = Math.random() + let originalReq + const instance = pino({ + requestKey: 'myRequest', + serializers: { + req: (req) => { + equal(req, originalReq) + equal(req.arbitraryProperty, originalReq.arbitraryProperty) + return resultOfSerialization + } + }, + future: { + skipUnconditionalStdSerializers: true + } + }, sink((chunk, _enc) => { + match(chunk, { + pid, + hostname, + level: 30, + msg: 'my request', + myRequest: resultOfSerialization + }) + })) + + const server = http.createServer(function (req, res) { + originalReq = req + req.arbitraryProperty = Math.random() + + instance.info(req, 'my request') + res.end('hello') + }) + server.unref() + server.listen() + const err = await once(server, 'listening') + error(err) + + const res = await once(http.get('http://localhost:' + server.address().port), 'response') + res.resume() + server.close() + }) }) // skipped because request connection is deprecated since v13, and request socket is always available @@ -237,42 +275,79 @@ test('http response support via a serializer', async ({ ok, same, error, teardow server.close() }) -test('http response support via serializer (avoids stdSerializers)', async ({ match, equal, error }) => { - let originalRes - const instance = pino({ - responseKey: 'myResponse', - serializers: { - res: (res) => { - equal(res, originalRes) - return res.arbitraryProperty +test('http response support via serializer (avoids stdSerializers)', async ({ test }) => { + test('current behavior in major-version 9', async ({ equal, not, error }) => { + let originalRes + const instance = pino({ + serializers: { + res: (res) => { + // original response object is already replaced by pino.stdSerializers.res + not(res, originalRes) + equal(res.arbitraryProperty, undefined) + return res + } } - } - }, sink((chunk, _enc) => { - match(chunk, { - pid, - hostname, - level: 30, - msg: 'my response', - myResponse: originalRes.arbitraryProperty + }, sink()) + + const server = http.createServer(function (_req, res) { + originalRes = res + res.arbitraryProperty = Math.random() + + instance.info(res, 'my response') + res.end('hello') }) - })) - const server = http.createServer(function (_req, res) { - originalRes = res - res.arbitraryProperty = Math.random() + server.unref() + server.listen() + const err = await once(server, 'listening') + error(err) - instance.info(res, 'my response') - res.end('hello') + const res = await once(http.get('http://localhost:' + server.address().port), 'response') + res.resume() + server.close() }) + test('future behavior', async ({ match, equal, error }) => { + const resultOfSerialization = Math.random() + let originalRes + const instance = pino({ + responseKey: 'myResponseKey', + serializers: { + res: (res) => { + equal(res, originalRes) + equal(res.arbitraryProperty, originalRes.arbitraryProperty) + return resultOfSerialization + } + }, + future: { + skipUnconditionalStdSerializers: true + } + }, sink((chunk, _enc) => { + match(chunk, { + pid, + hostname, + level: 30, + msg: 'my response', + myResponseKey: resultOfSerialization + }) + })) - server.unref() - server.listen() - const err = await once(server, 'listening') - error(err) + const server = http.createServer(function (_req, res) { + originalRes = res + res.arbitraryProperty = Math.random() - const res = await once(http.get('http://localhost:' + server.address().port), 'response') - res.resume() - server.close() + instance.info(res, 'my response') + res.end('hello') + }) + + server.unref() + server.listen() + const err = await once(server, 'listening') + error(err) + + const res = await once(http.get('http://localhost:' + server.address().port), 'response') + res.resume() + server.close() + }) }) test('http request support via serializer in a child', async ({ ok, same, error, teardown }) => { diff --git a/test/serializers.test.js b/test/serializers.test.js index 986fa4a08..a26aca07a 100644 --- a/test/serializers.test.js +++ b/test/serializers.test.js @@ -115,35 +115,63 @@ test('child does not overwrite parent serializers', async ({ equal }) => { equal((await o2).test, 'child') }) -test('Symbol.for(\'pino.serializers\')', async ({ equal, same, not }) => { - const stream = sink() - const expected = Object.assign({ - err: stdSerializers.err, - req: stdSerializers.req, - res: stdSerializers.res - }, parentSerializers) - const parent = pino({ serializers: parentSerializers }, stream) - const child = parent.child({ a: 'property' }) - - same(parent[Symbol.for('pino.serializers')], expected) - same(child[Symbol.for('pino.serializers')], expected) - equal(parent[Symbol.for('pino.serializers')], child[Symbol.for('pino.serializers')]) +test('Symbol.for(\'pino.serializers\')', async ({ test }) => { + test('current behavior in major-version 9', async ({ equal, same, not }) => { + const stream = sink() + const expected = Object.assign({ + err: stdSerializers.err + }, parentSerializers) + const parent = pino({ serializers: parentSerializers }, stream) + const child = parent.child({ a: 'property' }) + + same(parent[Symbol.for('pino.serializers')], expected) + same(child[Symbol.for('pino.serializers')], expected) + equal(parent[Symbol.for('pino.serializers')], child[Symbol.for('pino.serializers')]) + + const child2 = parent.child({}, { + serializers: { + a + } + }) - const child2 = parent.child({}, { - serializers: { - a + function a () { + return 'hello' } + + not(child2[Symbol.for('pino.serializers')], parentSerializers) + equal(child2[Symbol.for('pino.serializers')].a, a) + equal(child2[Symbol.for('pino.serializers')].test, parentSerializers.test) }) + test('future behavior', async ({ equal, same, not }) => { + const stream = sink() + const expected = Object.assign({ + err: stdSerializers.err, + req: stdSerializers.req, + res: stdSerializers.res + }, parentSerializers) + const future = { skipUnconditionalStdSerializers: true } + const parent = pino({ serializers: parentSerializers, future }, stream) + const child = parent.child({ a: 'property' }) + + same(parent[Symbol.for('pino.serializers')], expected) + same(child[Symbol.for('pino.serializers')], expected) + equal(parent[Symbol.for('pino.serializers')], child[Symbol.for('pino.serializers')]) + + const child2 = parent.child({}, { + serializers: { + a + } + }) - function a () { - return 'hello' - } + function a () { + return 'hello' + } - not(child2[Symbol.for('pino.serializers')], parentSerializers) - equal(child2[Symbol.for('pino.serializers')].a, a) - equal(child2[Symbol.for('pino.serializers')].test, parentSerializers.test) + not(child2[Symbol.for('pino.serializers')], parentSerializers) + equal(child2[Symbol.for('pino.serializers')].a, a) + equal(child2[Symbol.for('pino.serializers')].test, parentSerializers.test) + }) }) - test('children inherit parent serializers', async ({ equal }) => { const stream = sink() const parent = pino({ serializers: parentSerializers }, stream) @@ -155,37 +183,71 @@ test('children inherit parent serializers', async ({ equal }) => { }) test('children inherit parent Symbol serializers', async ({ equal, same, not }) => { - const stream = sink() - const symbolSerializers = { - [Symbol.for('b')]: b - } - const expected = Object.assign({ - err: stdSerializers.err, - req: stdSerializers.req, - res: stdSerializers.res - }, symbolSerializers) - const parent = pino({ serializers: symbolSerializers }, stream) + test('current behavior in major-version 9', async ({ equal, same, not }) => { + const stream = sink() + const symbolSerializers = { + [Symbol.for('b')]: b + } + const expected = Object.assign({ + err: stdSerializers.err + }, symbolSerializers) + const parent = pino({ serializers: symbolSerializers }, stream) - same(parent[Symbol.for('pino.serializers')], expected) + same(parent[Symbol.for('pino.serializers')], expected) - const child = parent.child({}, { - serializers: { - [Symbol.for('a')]: a, - a + const child = parent.child({}, { + serializers: { + [Symbol.for('a')]: a, + a + } + }) + + function a () { + return 'hello' } + + function b () { + return 'world' + } + + same(child[Symbol.for('pino.serializers')].a, a) + same(child[Symbol.for('pino.serializers')][Symbol.for('b')], b) + same(child[Symbol.for('pino.serializers')][Symbol.for('a')], a) }) + test('future behavior', async ({ equal, same, not }) => { + const stream = sink() + const symbolSerializers = { + [Symbol.for('b')]: b + } + const expected = Object.assign({ + err: stdSerializers.err, + req: stdSerializers.req, + res: stdSerializers.res + }, symbolSerializers) + const future = { skipUnconditionalStdSerializers: true } + const parent = pino({ serializers: symbolSerializers, future }, stream) + + same(parent[Symbol.for('pino.serializers')], expected) + + const child = parent.child({}, { + serializers: { + [Symbol.for('a')]: a, + a + } + }) - function a () { - return 'hello' - } + function a () { + return 'hello' + } - function b () { - return 'world' - } + function b () { + return 'world' + } - same(child[Symbol.for('pino.serializers')].a, a) - same(child[Symbol.for('pino.serializers')][Symbol.for('b')], b) - same(child[Symbol.for('pino.serializers')][Symbol.for('a')], a) + same(child[Symbol.for('pino.serializers')].a, a) + same(child[Symbol.for('pino.serializers')][Symbol.for('b')], b) + same(child[Symbol.for('pino.serializers')][Symbol.for('a')], a) + }) }) test('children serializers get called', async ({ equal }) => {