logger.info({message:...}) modifies original object

[PanAeon]

Problem description:

const data = {'message':'hello'}
logger.log(data)
// now data contains "level":"info"

.info(), and probably other methods modify original object when the object contains 'message' field.
This is unfortunate because a user might be unaware of such behaviour, and can easily overlook this moment, which would lead to hard-to-find problems.

Possible fix:

Leave everything as it is (as user expect to pass config object to the logging method), but clone incoming object.

• winston version - (3.2.1)
• platform: all
• languages: all

[HelloKevinTian]

I have the same question.

[EveX1]

I have the same issue using winston 3.3.3 when logging some custom errors.
I set some level prop to the errors objects and when I use winston to log errors, it change the error.level value to its own value.

Given:

class CustomError extends Error {
    level;
    constructor(message, level) {
        super(message);
        this.level = level
    } 
}

const win = winston.createLogger({
    transports: [
        new winston.transports.Console(),
    ]
});

const error = new CustomError("Wrong level", "fatal");
win.error(error);  // {"level":"error"}
console.log(error.level); // error

If winston should modify the logged value, at least it should NOT modify the logged object.
However it shouldn't modify the value at all.

[trekze]

As the original poster guessed, this caused a very hard-to-find bug for myself. I could never have imagined that the logger I'm using would modify the object I've passed to it, so it was the last place I looked to resolve an issue. Winston should not be doing this!

[clintonb]

I also just discovered this bug. We rely on the data object stored on a Feathers exception to be relayed to the API client. Logging that exception results in data being changed to an empty object.

[clintonb]

I have a fix at #1938 ...but it needs to be updated to handle deep cloning of Error objects and other types. JS is not my primary language, so I am open to ideas here. The quick solution is to use Lodash, or another library, but I'm not sure how open the maintainers are to adding such a dependency.

[chunghha]

I also came across this defect as I get optional "message" property from external API. When "message" returned is empty, this issue disappears so it was nasty to track where my problem is from.

To me, response (res.data) from axios service call modified by winston logger should be fixed ASAP. I see @clintonb PR fixes the issue of data object mutated at least, (the object logged still has the issue though as I use json format). Having this workaround is bad, please help by reviewing the PR and merging it.

const resToLog: any = res.data;
this.loggerService.debug(res.config?.url);
this.loggerService.info(resToLog);
// eslint-disable-next-line @typescript-eslint/no-unused-vars
const { ['level']: _, ['timestamp']: __, ...resToReturn } = resToLog;

[tlylt]

Experience the same thing that the logger.error method modifies the message of the error object directly to pad 3 spaces in front.
So

const error = new Error('No!');
// before
console.log(error.message.length); // 3 - 'No!'
// after
logger.error(error);
console.log(error.message.length); // 6 - '   No!'

[wbt]

Wow - this does seem like something that should be fixed, though it also seems like a fair amount of work to do it well without having a pretty large impact on performance (which is important for a logging library). I think the best strategy here is go through an analysis of the code to find places where that error object getting logged is mutated, and try to split the mutated thing from the original and pass them alongside each other, copying only where really necessary e.g. for passing into other functions that can't take side-by-side parameters. I don't personally have any time budget to do that right now, but am pinning this issue so that folks can be more aware of it, as lack of awareness/expectation of this behavior is a key reason why it's so frustrating.

[AasishP]

I am still facing the same issue on winston version 3.8.2

const data = {
  message: {
    test: "hello",
  },
};

logger.info(data);

// output
// { test: 'hello' }

// expected output
// { message: { test: 'hello' } }

[heyask]

Still having shallow copy issue.

[synthmusic]

I am still facing the same issue on winston version 3.8.2

const data = {
  message: {
    test: "hello",
  },
};

logger.info(data);

// output
// { test: 'hello' }

// expected output
// { message: { test: 'hello' } }

best succinct example! This was my expectation, and spent a bunch of time figuring out the actual behavior, and finding this issue.

Given that changing established behavior might be a significant breaking change, if there were an option in format.json() like ignoreMessage: true, or some such - that would solve the problem - given the docs mentioned it.

[kzunino]

I'm facing a similar issue where the log output seems to append a second JSON object to my log message. It adds an extra {"level":"info"} at the end of the message. This JSON object is correlated to whichever log method I am calling (e.g. logger.info, warn, error, debug)

The interesting thing is that I have this implemented in two apps with identical implementations and package versions. One app outputs correctly to grafana and I can prettify the logs for better readability. The other app outputs the message with that extra JSON object and it breaks the prettify feature in Grafana and makes the logs really unreadable.

  const logBody = {
       level: 'info',
       message: '{"level":"info","message":{"message":"Message received","environment":"development"},"labels":{"level":"info"}}',
       labels: {
            level: 'info',   
  }
}

// send log to Grafana
winston.log(logBody);

// Expected output
{"level":"info","message":{"message":"Message received","environment":"development"},"labels":{"level":"info"}}

// Actual output:
{"level":"info","message":{"message":"Message received","environment":"development"},"labels":{"level":"info"}}, {"level":"info"}   <-- this extra JSON gets appended