Mutation of log inputs - (un)expected?

[CharliW90]

Hi there - not sure whether the behaviour is intended or not, so I wanted to check my understanding and the intentions here before even looking at a solution or PR.

I've noticed that inside setting up Pino (in my case, using a mixin) changes made to the 'log' that has been passed into our logger mutate the input - that is to say that if I pass a custom error object into my logger.error() and then my mixin performs a destructive / altering action on that object, it mutates the original. Example of some code to better explain:

logger.js (snippet):

...
  const logger = pino({
    mixin(obj, num) {
      if(obj.code && obj.message && num === 50){
        errCode = obj.code;
        errMsg = obj.message;
        obj.code = 500
        obj.message = "Ooops, should this be allowed to happen..."
        return {msg: `${errCode}: ${errMsg}`}
      } else {
        if(obj.message){
          return { msg: obj.message}
        } else {
          return { msg: obj.msg}
        }
      }
    },
  },transports)
...

lookupGuild.js (snippet):

...
  const error = {code: 404, message: 'No guild found for that ID'}

  logger.error(error)
  logger.info(error)
....

OUTPUT:

[16:12:29.167] ERROR: 404: No guild found for that ID
    code: 500
    message: "Ooops, this shouldn't be allowed to happen..."
[16:12:29.167] INFO: Ooops, should this be allowed to happen...
    code: 500
    message: "Ooops, should this be allowed to happen..."

my error object that was passed into the logger has been mutated - I wouldn't expect this to happen... I only came across this because I am trying to get all of my different log levels to look the way I wanted, and as such I was comparing them side-by-side with like-for-like inputs. In particular the issue I came across was that in my pino transport for errors I had set it to ignore: 'code,message' because these would be handled by the mixin, but then I realised if either of the code or message were missing then the if() statement would be falsy, and I would see no evidence of code or message - so I didn't want to blanket ignore them on all error transports, and instead wanted to remove them from the error object inside that same if() statement, so what I implemented was:

  if(obj.code && obj.message && num === 50){
      errCode = obj.code;
      errMsg = obj.message;
      delete obj.code
      delete obj.message
      return {msg: `${errCode}: ${errMsg}`}
    }

with the intention of only tidying up the output when those two values had been moved to the msg key. It certainly worked, but a little too well, and my error object now had neither code nor message (which caused later catch() blocks in my code to fail)

Is it expected behaviour to mutate the input, or should this be avoided?

[emmyakin]

Is it expected behaviour to mutate the input, or should this be avoided?

Hi, to be clear, the pino mixin API is not mutating the log object, you are adding logic to mutate the log object

the mixin api seems like it is only intended to return a new base object, for which the log object will be merged with.

[CharliW90]

I'm not entirely sure that that is accurate - as far as I understand it I am providing a callback function (the mixin) to be applied to the log, but I am not in control of the arguments passed into the mixin. I would expect the arguments passed in to not be the same object in memory, as this mutates the input.

so yes, I am defining the logic to apply to the parameters in the mixin, but I am not defining the arguments to pass into this mixin function. writing code in the callback function in an attempt to avoid mutation doesn't work, because ultimately pino looks at obj, I can't provide it with a new obj to look at instead, so using copy or deepcopy to try to avoid mutation doesn't work because pino is looking at the original obj

I still feel like mutation of input is not expected behaviour... if I console.log(myVariable) I would never expect myVariable to change, regardless of what backend logic might be applied to the logging.

[emmyakin]

Uhm, this is fairly a programming language thing (a gotcha in js), non-primitives object, array, ... are passed by references.

https://flexiple.com/javascript/javascript-pass-by-reference-or-value

Yes, you do not control the arguments, but you are mutating the referenced arguments,

const objRef = {
  a: 1,
};

function mixin(obj) {
  obj.a = 'changed the value';
}

console.log(objRef); // { a: 1 }

mixin(objRef);

console.log(objRef); // { a: 'changed the value' }

P.S use of console.log is also not ideal to prove this, as console.log is not synchronous, and the first call, could happen after mixin is called, but generally works

[CharliW90]

Okay, sorry, I don't think you're understanding my point. I fully understand 'why' it's happening, I am not confused by that at all. My issue is that (I believe) it should not be. If we take a step back, and ignore the fact that the mixin is defined by the user, we still find ourselves with the issue that a variable passed into the logger is having its value changed. IMO this would never be expected behaviour. Regardless of what the logger might be configured to do, it is my understanding that we should never have:

const variable = "a";
// variable === "a"; truthy
logger.info(variable);
// variable === "a"; falsy

In software development we want to avoid unexpected behaviours, and a key thing we want to avoid is input mutation. Both of these are things I learned very early on, which is why I'm surprised to see it in such a popular tool, and hence wanting to check that I'm not misunderstanding why pino allows for input mutation.

I can't think of a simpler way to put it - there is no situation I can think of where we would WANT our logging to mutate what we log - almost by definition the logger is supposed to be showing us what the item is. For it to then change without us knowing is problematic - if I see "a" in the console, I'm going to believe that variable === a, and yet the logger has changed it.

Now I understand also that mixin is user-defined, and as such the user remains in control of what happens - my issue is that it appears to me that the mixin wants to perform mutation in place, and as such it is out of the user's control to avoid input mutation, and instead needs to be handled by pino.

What this essentially means, from my perspective, is that prior to performing ANY logic on the values passed into a logger, a deep copy should be made of them and this should be what everything else works from. I'm a little baffled that that isn't happening anyway. But ultimately, as I said before, the user is not in control of what gets passed into the mixin function as positional arguments, and the first one IMO should be a copy of the user's input.

[jsumners]

This is working as intended and documented https://getpino.io/#/docs/api?id=mixin-function

Pino is a performance first logger. Object cloning is expensive and avoided.

[CharliW90]

Thank you for explaining @jsumners :) that's understandable.

[emmyakin]

Apologies @CharliW90 I misunderstood and missed your question, thanks for clarifying

[github-actions[bot]]

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.