[Winston logger] Filename displayed in stdout when using Winston logger is wrong

[cisum-la]

🐛 Bug Report

[Winston logger] Filename and linenumber displayed in stdout when using Winston logger is wrong
(node_modules/winston/lib/winston/transports/console.js:79 is displayed instead of filename:line_number where the winston logger is called. e.g. tests/index2.test.js:7)

To Reproduce

Steps to reproduce the behavior:

1. Use winston logger for logging
2. Run jest test for multiple test files which use winston logger
3. Notice in stdout wrong file name is displayed.

NOTES: The behavior is correct when using console logging but incorrect when using winston logging. I noticed that there is snapshot test - which also exhibits this incorrect behavior (added as part of https://github.com/facebook/jest/pull/8021/files).

Also, it appears that the issue only happens when we use winston with jest. Winston by itself when used with node works well. I think there is some issue with jest-console package when we use Winston e.g. below code: https://github.com/facebook/jest/blob/e740de246b3a5ef4a7692f2f58bf8223323e4daf/packages/jest-console/src/getConsoleOutput.ts#L18

Seems to return console.log node_modules/winston/lib/winston/transports/console.js:79 always whenever winston is used (it works as expected when using console logging)

Actual behavior

Wrong filename and line number is displayed
console.log node_modules/winston/lib/winston/transports/console.js:79

Expected behavior

Exact filename and line number where logger is called is displayed e.g.
console.log tests/index2.test.js:15

` ● Console

console.log __tests__/index2.test.js:7
  Console - I logged something too
console.log node_modules/winston/lib/winston/transports/console.js:79
  {"message":"Winston - I logged something too","level":"info"}

console.log __tests__/index2.test.js:15
  Console - I logged something before failure
console.log node_modules/winston/lib/winston/transports/console.js:79
  {"message":"Winston - I logged something before failure","level":"info"}`

Link to repl or repo (highly encouraged)

GitHub repo for Winston logging issue

Run npx envinfo --preset jest

Paste the results here:

npx: installed 1 in 2.209s

  System:
    OS: macOS 10.14.5
    CPU: (8) x64 Intel(R) Core(TM) i7-4770HQ CPU @ 2.20GHz
  Binaries:
    Node: 8.16.0 - ~/.nvm/versions/node/v8.16.0/bin/node
    Yarn: 1.13.0 - /usr/local/bin/yarn
    npm: 6.4.1 - ~/.nvm/versions/node/v8.16.0/bin/npm
  npmPackages:
    jest: 24.8.0 => 24.8.0

[SimenB]

Right now we make an assumption that you want to know which line directly triggered the logging. It might make sense to walk up the stack until we're out of node_modules (if we never leave it, fallback to the current behavior). Or maybe we could give you the current one PLUS from user code if it exists outside of node_modules? Not sure what would be best signal to noise ratio here.

@thymikee @jeysal thoughts?

[cisum-la]

thanks for your quick response @SimenB , i wanted to provide some more context around the issue:

1. I agree it does appear that Winston, does ultimately seem to write to console in below line referred above
   https://github.com/winstonjs/winston/blob/15c9653e4eeae1c76875603a722e11db9a6556bd/lib/winston/transports/console.js#L79
   and that's why the 'origin' stays the same as Jest captures the line where console was used as above.

2. Recently jest-junit added console log capturing console support jest-community/jest-junit#45, so we wanted to utilize that feature. It turned out that we were using an older version of Winston (3.0.0-rc4) and due to that we weren't getting the console logs in junit.xml. Also, with Winston (3.0.0-rc4) jest ConsoleBuffer wasn't able to capture it's logs.

3. When we upgraded to Winston 3.2.1 latest version - then jest ConsoleBuffer was able to capture the winston logs and we saw the logs in junit.xml as well, but this time we ran into the above issue wherein the 'origin' property value is same for all logs.

4. So a way where in we are able to display correct filename:linenumber when using jest + winston and also preserve the ability of jest-junit(junit.xml) to show the logs in the case of jest+winston would be great.

[saurabhdes]

One suggestion if we are not able to fix above issue is to have a jest flag (e.g. --shortConsoleOutput or something similar) that only outputs the message value - not the Filename:Linenumber or log type. This flag can be useful when someone is using Winston logger. This doesn't solve the issue listed above, but at least prevents the output of redundant data (same console.js and line number getting printed). Please let me know your opinion - if it makes sense then i can investigate more and come up with a PR.

[jeysal]

It might make sense to walk up the stack until we're out of node_modules

I'm not excited about node_modules detection magic TBH. It doesn't work with Yarn PnP. It also doesn't help in cases (logging or something else) where users have their own utils that are not helpful to show here.
Compensating these problems would require even more magic (1. detecting modules resolved by PnP, 2. also excluding utils?\/, ...)

We could have something like stackTraceIgnorePatterns (not just for console, I think this problem exists for other stack traces as well), but I'm not sure whether that's worth it or just extremely overkill.

[PabloLION]

Any update / workaround on this?
I'm thinking to use the maybe with mock function we can still show the real stack trace?

[github-actions]

This issue is stale because it has been open for 1 year with no activity. Remove stale label or comment or this will be closed in 30 days.

[github-actions]

This issue was closed because it has been stalled for 30 days with no activity. Please open a new issue if the issue is still relevant, linking to this one.

[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.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.