Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
PanAeon opened this issue Mar 20, 2020 · 12 comments · May be fixed by #1938 or #2473
Open

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

PanAeon opened this issue Mar 20, 2020 · 12 comments · May be fixed by #1938 or #2473

Comments

@PanAeon
Copy link

PanAeon commented Mar 20, 2020

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
Copy link

I have the same question.

@EveX1
Copy link

EveX1 commented Nov 15, 2020

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
Copy link

trekze commented Mar 21, 2021

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
Copy link

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
Copy link

clintonb commented Jul 12, 2021

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
Copy link

chunghha commented Aug 5, 2021

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
Copy link

tlylt commented Apr 17, 2022

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 wbt pinned this issue Apr 28, 2022
@wbt
Copy link
Contributor

wbt commented Apr 28, 2022

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
Copy link

AasishP commented Apr 22, 2023

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
Copy link

heyask commented Apr 27, 2023

Still having shallow copy issue.

@synthmusic
Copy link

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
Copy link

kzunino commented May 18, 2024

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 

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment