LogLevel output doesn't show when running in a test about loglevel

[pimterry]

Hard to say I'm afraid! What happens if you put a console.log(...) and logger.log(...) calls outside the test, e.g. just after the enableAll() call?

I suspect what's happening is that something else in your test stack is patching the console methods, but loglevel is capturing them early on (when setLevel or enableAll is called) and that's causing issues. We've seen similar issues from React itself in the past (#171).

What happens if you put logger.enableAll() inside the test, just before you call logger.debug? If that fix this then this is definitely caused by something patching console.log itself during the tests, and not expecting anybody to still have a reference to the previous value.

[JESii]

Thanks much… I’ll give that a whirl when I’m back in the office! Have a great day! Jon Seidel, CMC®

…

On Aug 26, 2022, at 7:47 AM, Tim Perry ***@***.***> wrote: Hard to say I'm afraid! What happens if you put a console.log(...) and logger.log(...) calls outside the test, e.g. just after the enableAll() call? I suspect what's happening is that something else in your test stack is patching the console methods, but loglevel is capturing them early on (when setLevel or enableAll is called) and that's causing issues. We've seen similar issues from React itself in the past (#171 <#171>). What happens if you put logger.enableAll() inside the test, just before you call logger.debug? If that fix this then this is definitely caused by something patching console.log itself during the tests, and not expecting anybody to still have a reference to the previous value. — Reply to this email directly, view it on GitHub <#177 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAADZUJTGM5A7FTSOHOTJDV3DKIFANCNFSM57UPNO4Q>. You are receiving this because you authored the thread.

[JESii]

Thanks @pimterry. Tried what you suggested:
(1) adding console/logger calls after enableAll() outside the test - no luck (e.g., console.log => display; logger.log => no display.
(2) moving enableAll() and the console/logger calls inside the test - no luck

• I went through the setupTests.js file (testingLibrary) and tried some Jest config options (e.g., --silent=false) - no luck
• I also modified setupTests.js to see if I could trap any of the "CDE" messages that I was outputting from logLevel with the following:

const originalConsoleLog = console.log;
...
   global.console.log = (...args) => {
     if (args[0].match(/CDE/)) {
       alert('console.log: ' + args[0] + 'FIXUP');
     } else {
       originalConsoleLog(args);
    }

And did this for all the console options (log, warn, error, info, debug, trace)

Seems as if by the time it got to the test code, the logLevel stuff was all MIA.

So... unless you have any more ideas, I guess I'll just have to add console.logs as needed during tests rather than reusing the existing log calls. <sigh>

[pimterry]

Hard to say! I would suggest debugging inside loglevel's code in your environment (it's very very short, this is a tiny library) and trying to work out why console.log in your code isn't the same value as console[methodName] when methodName is 'log' here.

Effectively, all loglevel does is run:

logger[methodName] = console[methodName].bind(console);

for each log level that's enabled. It's nothing especially complicated, and it should work in any standard JS environment anywhere.

My best guess is that Jest is doing something very weird to globals, because it does all sorts of non-standard things like that which break libraries like this in different ways all the time (this is a widespread problem: https://twitter.com/matteocollina/status/1453029660925861901). If you can trace it down though, you might be able to work around it, or at least produce a clear bug the Jest team can fix.

[JESii]

Thanks, Tim... I'll work on that.

[JESii]

Well... that's interesting, and looks to be a work-around.
I tried all the console.xxx options and found that Jest does display console.warn and console.error messages and doesn't fail the test in either case. I get a lot of unneeded stack trace info, but at least I get my console display from logger.warn.

  console.log
    DefaultLayoutNoPeriods.test.js/enableAll/console

      at src/layouts/DefaultLayoutNoPeriods.test.js:21:11

  console.warn
    DefaultLayoutNoPeriods/warn [
      {
        entity: 'XXX-entity',
        displayName: 'XXX-Display',
        ribbonName: 'XXX-Ribbon'
      }
    ]

      20 |   logger.debug('DefaultLayoutNoPeriods/debug', state.entitiesList);
      21 |   logger.info('DefaultLayoutNoPeriods/info', state.entitiesList);
    > 22 |   logger.warn('DefaultLayoutNoPeriods/warn', state.entitiesList);
         |          ^
      23 |   logger.error('DefaultLayoutNoPeriods/error', state.entitiesList);
      24 |   return (
      25 |     <>

      at DefaultLayoutNoPeriods (src/layouts/DefaultLayoutNoPeriods.js:22:10)
      at renderWithHooks (node_modules/react-dom/cjs/react-dom.development.js:14985:18)
      at mountIndeterminateComponent (node_modules/react-dom/cjs/react-dom.development.js:17811:13)
      at beginWork (node_modules/react-dom/cjs/react-dom.development.js:19049:16)
      at beginWork$1 (node_modules/react-dom/cjs/react-dom.development.js:23940:14)
      at performUnitOfWork (node_modules/react-dom/cjs/react-dom.development.js:22779:12)
      at workLoopSync (node_modules/react-dom/cjs/react-dom.development.js:22707:5)

  console.error
    DefaultLayoutNoPeriods/error [
      {
        entity: 'XXX-entity',
        displayName: 'XXX-Display',
        ribbonName: 'XXX-Ribbon'
      }
    ]

      21 |   logger.info('DefaultLayoutNoPeriods/info', state.entitiesList);
      22 |   logger.warn('DefaultLayoutNoPeriods/warn', state.entitiesList);
    > 23 |   logger.error('DefaultLayoutNoPeriods/error', state.entitiesList);
         |          ^
      24 |   return (
      25 |     <>
      26 |       <StyledHeader>

      at DefaultLayoutNoPeriods (src/layouts/DefaultLayoutNoPeriods.js:23:10)
      at renderWithHooks (node_modules/react-dom/cjs/react-dom.development.js:14985:18)
      at mountIndeterminateComponent (node_modules/react-dom/cjs/react-dom.development.js:17811:13)
      at beginWork (node_modules/react-dom/cjs/react-dom.development.js:19049:16)
      at beginWork$1 (node_modules/react-dom/cjs/react-dom.development.js:23940:14)
      at performUnitOfWork (node_modules/react-dom/cjs/react-dom.development.js:22779:12)
      at workLoopSync (node_modules/react-dom/cjs/react-dom.development.js:22707:5)

  console.log
    <body>
      <div>
        <div>
          Hello World
        </div>
      </div>
    </body>

      at debug (node_modules/@testing-library/react/dist/pure.js:107:13)

[JESii]

And the unexpected nicety is that these show up in-line with other output from the test, as opposed to being separated out at the very start of the test.

[pimterry]

Have you reported this to the Jest team? It seems like Jest is clearly doing its own custom handling of log output, and so I feel like they'll be more help here.

[JESii]

Good idea; thanks for all your help on this!