LogLevel output doesn't show when running in a test

[JESii]

First off, thanks for this module -- been using it for some time now and it really works great!

However, when I'm testing a module that has a logger, any output logged by the logger is MIA, while logs created via simple console.log appear just fine. I'm using: Loglevel 1.8.0 React TestingLibrary 11.2.6 MacOS BigSur 11.6.8

Here's my logger component:

/* eslint-disable func-names */
import * as log from 'loglevel';

// Log levels are: trace/debug/info/warn/error
const loggerLevel = process.env.REACT_APP_LOG_LEVEL || 'info';

const originalFactory = log.methodFactory;
/* eslint-disable-next-line no-import-assign */
log.methodFactory = function (methodName, logLevel, loggerName) {
  const rawMethod = originalFactory(methodName, logLevel, loggerName);

  return function (...args) {
    const messages = [`CDE ${new Date().toISOString()}: `];
    const elements = Object.getOwnPropertyNames(args[0]);
    for (let i = 0; i < elements.length; i++) {
      const elementName = elements[i];
      const elementValue = args[0][elements[i]];
      messages.push(`${elementName}:`);
      switch (typeof elementValue) {
        case 'string':
          messages.push(`'${elementValue}'`);
          break;
        case 'number':
        case 'boolean':
          messages.push(elementValue);
          break;
        case 'undefined':
          messages.push('undefined');
          break;
        case 'null':
          messages.push('null');
          break;
        default:
          messages.push(elementValue);
      }
    }
    rawMethod.apply(undefined, messages); /* eslint-disable-line */
  };
};
log.setLevel(loggerLevel); // Be sure to call setLevel method in order to apply plugin
log.noConflict();

export default log;

Here's some sample code; notice that I'm using logger.enableAll() and confirming that the legLevel is as expected (0) in the component under test. Test module:

import React from 'react';
import {MockedProvider} from '@apollo/client/testing';

import DefaultLayoutNoPeriods from './DefaultLayoutNoPeriods';
import {render, act, getByText} from '../utils/testHelpers';
import {mockGetClientNames, mockGetPeriods} from '../graphql/mocks';
import {AppProvider} from '../context/AppContext';
import EntityRibbon from '../components/EntityRibbon';
import logger from '../logger';

logger.enableAll();

const TestComponent = () => {
  return <div>Hello World</div>;
};
const mocks = [mockGetClientNames, mockGetPeriods, mockGetClientNames];
describe('DefaultLayoutNoPeriods', () => {

  // This test works and displays the expected 'Hello World'
  it('displays "Hello World" with TestComponent', async () => {
    const {container, debug} = await render(
      <AppProvider>
        <MockedProvider mocks={mocks} addtypename={false}>
          <TestComponent />
        </MockedProvider>
      </AppProvider>
    );

    await act(async () => {
      await new Promise(resolve => setTimeout(resolve, 0));
    });
    debug();
    const homeElement = await getByText(container, 'Hello World');
    expect(homeElement).toBeInTheDocument();
  });

  // This test fails; any logger.debug output is lost, but
  // console.log() output is displayed in the test output
  it('displays "Portfolio" with EntityRibbon', async () => {
    const {container, debug} = await render(
      <AppProvider>
        <MockedProvider mocks={mocks} addtypename={false}>
          <EntityRibbon />
        </MockedProvider>
      </AppProvider>
    );

    await act(async () => {
      await new Promise(resolve => setTimeout(resolve, 0));
    });
    debug();
    const homeElement = await getByText(container, 'Portfolio');
    expect(homeElement).toBeInTheDocument();
  });
});

Here are relevant snippets from the EntityRibbon component:

import React, {useContext} from 'react';
import * as R from 'ramda';
import {Menu} from 'antd';
import styled from '@emotion/styled';

import logger from '../../logger';
import {AppContext} from '../../context/AppContext';
import {client} from '../../graphql/queries/client';
import {setNewEntity} from '../../utils/utilHelpers';
import COLORS from '../../theme/colors';

const EntityRibbon = () => {
  const {state, dispatch} = useContext(AppContext);

  const entitiesList = state.entitiesList;
  console.log('EntityRibbon/getLevel', logger.getLevel());
  logger.debug({
    method: 'entityRibbon/logger',
    entitiesList: state.entitiesList,
    selectedEntityId: state.selectedEntityId,
    selectedPortfolioId: state.selectedPortfolioId
  });
  console.log({
    method: 'entityRibbon/console.log',
    entitiesList: state.entitiesList,
    selectedEntityId: state.selectedEntityId,
    selectedPortfolioId: state.selectedPortfolioId
  });
...
};

export default EntityRibbon;

And here's the test output showing the problem:

    EntityRibbon/getLevel 0

      at EntityRibbon (src/components/EntityRibbon/index.js:61:11)

  console.log
    {
      method: 'entityRibbon/console.log',
      entitiesList: [
        {
          entity: 'XXXX',
          displayName: 'XXXX',
          ribbonName: 'XXXX'
        }
      ],
      selectedEntityId: 'XXXX',
      selectedPortfolioId: 'XXXX'
    }

In normal operation, these logs display perfectly fine!

[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 (https://github.com/pimterry/loglevel/issues/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 https://github.com/pimterry/loglevel/issues/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 https://github.com/pimterry/loglevel/issues/177#issuecomment-1228587913, 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!

[AllenAttuned]

Any progress on this? I'm experiencing this with Jest v29.7.0 and LogLevel v1.8.1.

[AllenAttuned]

I looked in Jest's issue list and found one solution that seems to work in https://github.com/jestjs/jest/issues/687

• https://github.com/jestjs/jest/issues/687#issuecomment-370080590

It involves mapping the console.xxx methods to the LogLevel counterparts. This works fine for my team's use case.

// Jest setupTests.js
import log from 'loglevel';

log.info = console.info;
log.debug = console.debug;
log.trace = console.trace;
log.error = console.error;
log.warn = console.warn;

Also, I tried invoking log.noConflict() in the setupTest.js and my logger module, but that didn't seem to have any effect. The solution above is probably the way to go.