setBindings() does not overwrite existing bindings

[deanhaleem]

Hello!

While using setBindings() and referring to the docs comment in the types, I expected it to at least overwrite existing fields. However, it ends up duplicating the field in the log.

Is this the intended behavior? Based on this unit test, I didn't think it was the desired behavior. But since bindings() uses JSON.parse(), the unit test doesn't catch that pino.chindings includes duplicate keys.

Steps to reproduce

const pino = require('pino')

const logger = pino({ name: 'basicTest', level: 'info', base: { foo: 'bar' } })

logger.info('Hello World')

logger.setBindings({ foo: 'baz' })

logger.info('Hello World')

Running this outputs:

{"level":30,"time":1651029373867,"foo":"bar","name":"basicTest","msg":"Hello World"}
{"level":30,"time":1651029373867,"foo":"bar","name":"basicTest","foo":"baz","msg":"Hello World"}

Notice the duplicate foo field.

[mcollina]

This was a design choice for performance reasons . I don't see us changing this, would you like to send a PR to the did to clarify?

[deanhaleem]

@mcollina Sure I can. Question though about the performance. I'm not trying to challenge that there are performance issues, but jw what constitutes as not performant enough at least for pino.

TLDR: the fix I had in mind uses JSON.parse + JSON.stringify + String.substring if we want to at least get rid of logging duplicate fields.

• When chindings has 1000 fields, those operations take about 3ms.
• Calling setBindings() before every log 1000 times took about 8ms longer. (old code: 1393ms, new code 1401ms)
• New code is much faster when duplicate fields are present as getting rid of them means a smaller string to stream.

So given that, even though chindings having 1000 fields, or calling setBindings() before every log is prob unrealistic, is 3ms-8ms too valuable to give up? This of course is only if someone is using setBindings() specifically.

---

I believe the fix is just using JSON.parse() in setBindings() like it's used in bindings(). Something like:

const chindings = asChindings(this, newBindings)
//this[chindingsSym] = chindings // old code
const dedupedChindings = JSON.stringify(JSON.parse(`{${chindings.substring(1)}}`));
this[chindingsSym] = ',' + dedupedChindings.substring(1, dedupedChindings.length-1)

Testing those lines, it takes about 3ms if the string has >1000 fields. 5ms if >10,000. 30 ms if >100,000. And that's including some string concatenation that wouldn't normally be done in setBindings().

const start = performance.now();

let chindings = ',"foo":"bar","name":"basicTest","0":"bar0"';
for (let i = 0; i < 10000; i++) {
  chindings += `,"${i}":"test"`
}
const dedupedChindings = JSON.stringify(JSON.parse(`{${chindings.substring(1)}}`));
const chindingsSym = ',' + dedupedChindings.substring(1, dedupedChindings.length-1)

const end = performance.now();

Testing the reproduction steps I wrote in the issue description, the new code was taking about 8ms longer when running 10 iterations of logging 1000 times, with each log getting progressively bigger. But when we start putting in duplicate fields of course, the newer code is much faster because the actual string it streams is a lot smaller of course:

const logger = pino({ name: 'basicTest', level: 'info', base: { foo: 'bar' } })

// old code 1393.1250248998404ms
// new code 1401.6106416999362ms
let total = 0;
for (let j = 0; j < 10; j++) {
    const childLogger = logger.child({})
    const start = performance.now();
    for (let i = 0; i < 10000; i++) {
        childLogger.info('Hello World')

        childLogger.setBindings({ [i]: `bar${i}` })
        
        childLogger.info('Hello World')
    }
    const end = performance.now();
    total += (end - start)
}
console.log(`Took average of ${total / 10} milliseconds`)

[jsumners]

Resolved by #1419.

[github-actions]

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.