skip to Main Content

I’ve encountered some very strange behavior. I have a bigger project, but for demonstration purposes the following simple Next.JS application would suffice, I think.

Steps to reproduce:

  1. Create a simple Next.JS project:

    npx create-next-app my-next-app --ts

  2. Add following 2 files to the project:

// ./componens/logs.ts

export function createLogger(options: { name: string }) {
  const logIdObj = { logId: 0 };
  function vivify(o: { logId: number }) {
    let n = 0;
    Object.defineProperty(o, 'logId', {
      get: () => {
        console.warn(`Getting logId for logger ${options.name}: ${n}`);
        return n;
      },
      set: (v: number) => {
        console.warn(`Setting logId for logger ${options.name}: ${v}`);
        n = v;
      },
    });
  }
  vivify(logIdObj);

  return (message: string) => {
    logIdObj.logId += 1;
    console.log(`${logIdObj.logId}. ${message}`);
  };
}
// ./componens/Chat.tsx

import { useEffect } from 'react';
import { createLogger } from './logs';

const log = createLogger({ name: 'Chat' });

export default function Chat(): JSX.Element {
  log('render');

  useEffect(() => {
    log('useEffect');
  }, []);

  return <div>Some content</div>;
}
  1. Modify the main page file ./pages/index.tsx like this:
import type { NextPage } from 'next'
import Chat from '../components/Chat'

const Home: NextPage = () => {
  return <>
      <Chat />
      <h1>Welcome</h1>
    </>
}

export default Home
  1. Run the project in development mode:
    npm run dev

  2. Open the browser, navigate to localhost:3000 and look what you’ll get in console:

enter image description here

As you can see in ./componens/logs.ts the access to the logId property of logIdObj object was intentionaly wrapped in getter-setter interceptors to log any kind of access to it, but according to logs value was changed without having been accessed.

Here is my environment:

Distributor ID: Debian
Description:    Debian GNU/Linux 10 (buster)
Release:        10
Codename:       buster
node: v14.17.0
npm: 7.22.0

and my package.json:

{
  "name": "my-next-app",
  "version": "0.1.0",
  "private": true,
  "scripts": {
    "dev": "next dev",
    "build": "next build",
    "start": "next start",
    "lint": "next lint"
  },
  "dependencies": {
    "next": "11.1.2",
    "react": "17.0.2",
    "react-dom": "17.0.2"
  },
  "devDependencies": {
    "@types/react": "17.0.30",
    "eslint": "7.32.0",
    "eslint-config-next": "11.1.2",
    "typescript": "4.4.4"
  }
}

I guess it might be related somehow to the internal Next.JS logic, but it should not work like this anyway.

As always, any help would be appreciated.


Update:

Though first reply (thanks to Ben) gave no clear answer to the reason of the issue, it gave a clue on what might be wrong. So I have modified ./componens/logs.ts like this:

const allLogs = [] as { message: string, logId: number, time: number }[];
if (typeof window !== 'undefined') {
  // @ts-ignore
  window.allLogs = allLogs;
}

export function createLogger(options: { name: string }) {
  let logId = 0;

  return (message: string) => {
    logId += 1;
    allLogs.push({ message, logId, time: Date.now() });
    console.log(`${logId}. ${message}`);
  };
}

Now my results look like this:
enter image description here

Now we can clearly see, that rendering happened actually two times and console.log() doesn’t always produce actual logs. Still, It’s not clear why.

Any explanations?

2

Answers


  1. Chosen as BEST ANSWER

    The actual reason was a specific behavior of React in StrictMode:

    Starting with React 17, React automatically modifies the console methods like console.log() to silence the logs in the second call to lifecycle functions. However, it may cause undesired behavior in certain cases...

    For further explanations see https://reactjs.org/docs/strict-mode.html#detecting-unexpected-side-effects


  2. You’re right. If you change:

    set: (v: number) => {        
      console.log(`Setting logId for logger ${options.name}: ${v}`);
      n = v;
    },
    

    to

    set: (v: number) => {        
      alert(`Setting logId for logger ${options.name}: ${v}`);
      n = v;
    },
    

    you’ll see that the setter is, of course, getting called.

    I don’t have an answer for the underlying why – it might be a bug worth raising as an issue in the Next repo, or at least someone might be able to explain why.

    Login or Signup to reply.
Please signup or login to give your own answer.
Back To Top
Search