React: Improving the component logging/debugging experience

[bvaughn]

Backstory

DevTools re-renders function components that use hooks in order to build up metadata to display in the selected element panel. This may cause confusion, since these re-renders will trigger breakpoints and cause unexpected console logging (see this comment). We avoid unnecessary re-renders by caching data (see PR 289) but even so this is likely to be a point of confusion.

Solution

It would be nice if the shallow re-rendering done by DevTools were less observable (e.g. console logs were suppressed to avoid cluttering the console). Breakpoints would still be hit, but that seems like a less common use case.

While we are considering logging, we might also consider if there are additional improvements that could be made, e.g.

1. Add a new section to the Components tree that shows the most recently logged messages for a given component.
2. Add an option to coalesce render-time logs into a single message that's printed at commit (or error) time to make debug logging easier to read. (Perhaps we could use console.group to also indicate the nested structure of these logs.)

The proposals below address both (a) collecting per-component logging info and (b) temporarily disabling console logging while re-rendering for inspection purposes.

API Proposals

1: Modify built-in console methods

DevTools could spy on the built-in console methods and disable the pass-through functionality when re-rendering.

Pros

• Requires no effort / code changes for developers to opt in and benefit from this.
• "Just works" for advanced methods like console.group and console.table.

• "Just works" for third party libraries that may not even be React-specific.

  Cons

• Feels questionable to modify native browser APIs.

2: Add React.log and React.info API

React will be adding two new logging methods in the upcoming v16.9 release- React.warn and React.error (see #15170). These methods decorate console.warn and console.error and append the current component stack to any logged messages. We could extend this pattern and add additional log and info methods. These APIs could be extended by DevTools as needed.

Pros

• Does not require mutating global APIs.

  Cons

• Requires code changes to opt-in.

• Would not cover (or would be a hassle to cover) all console methods (e.g. group)
• Would not work for third party components or non-React utility code.

3: Add React.debug(callback) API

React could add a new debug API that accepts a callback for general debug operations (most commonly console logging, but also potentially breakpoints or other things).

Pros

• Works with breakpoints.
• Covers more complex use cases (e.g. pushing to an array for debug purposes).

• Single method rather than mirroring (or spying on) multiple console APIs.

  Cons

• Requires code changes to opt-in.

• Requires more boilerplate for simple logging use cases.

[bvaughn]

I think my personal preference, after a little consideration, is the third option- React.debug(callback)

[sompylasar]

I think the proposal tries to fight with the call side-effects (logging, hitting breakpoints) but does not address the original problem that DevTools is solving, which is "DevTools re-renders function components that use hooks in order to __build up metadata to display in the selected element panel.__" – why doesn't React expose getting this required metadata as an API, so it forces DevTools to use workarounds to gather hooks information (call the components and thus trigger their call side-effects)?

[bvaughn]

why doesn't React expose getting this required metadata as an API, so it forces DevTools to use workarounds to gather hooks information

There are two reasons for this design:

• DevTools needs a lot more information than React does. For example, it's useful for DevTools to be able to identify and display "custom hooks" (functions with names that start with "use" that call other hooks). Identifying custom hooks relies on the relatively "expensive" operation of parsing the call stack.
• Even for built in hooks, we would not want to add additional overhead to React for every component that uses hooks just to support the uncommon case of displaying hooks values for a component selected in DevTools at some point in time.

For what it's worth, I agree with the general sentiment that it's _unfortunate_ (and a bit awkward) that DevTools needs to shallow render a component to read hooks values. I think it's probably still the right trade off though, given the above considerations.

[sebmarkbage]

@sompylasar Fixing that also doesn't fix the other issue. React recalls functions multiple times during DEV mode and in concurrent mode can rebase and call the function multiple times for a single render. The contract is that we can call the function as much as we want without side-effects.

[bvaughn]

I think the original DevTools behavior that felt particularly broken was that we polled the component once a second. So it felt like there was an infinite loop. Now that we cache the results and only invalidate when the component is updated, it will "feel" more inline with React's normal rendering flow.

[sompylasar]

React recalls functions multiple times during DEV mode and in concurrent mode can rebase and call the function multiple times for a single render. The contract is that we can call the function as much as we want without side-effects.

This is somewhat expected because this is not a part of debugging, it's a part of the program being debugged. Ideally a debugger does not alter the behavior of the program being debugged, and that is what I am concerned about with renders being called more than usual when DevTools is present.

[davidmccabe]

I don't think you should try to conceal that you're calling the function extra times -- this is just going to lead to major confusion when somebody has a side-effect in their function. And debugging is exactly the time that they're going to do that, because they're putting in temporary hacks to figure out what's going on.

[bvaughn]

this is just going to lead to major confusion when somebody has a side-effect in their function.

Shallow rendering a component should _not_ trigger any side effects¹. Those should be in useEffect / useLayoutEffect (which DevTools would not execute).

¹ - Technically calling console.log _is a side effect_ but I think it's also a bit of a special case.

[sebmarkbage]

I don't think most people on this thread will have context on debugging a Concurrent Mode heavy app. Out-of-order logs can be distracting from the "true logic" of the app rather than helping surfacing it. I don't think it works to be principled here.

[sebmarkbage]

@bvaughn For React.debug(callback) and the use case of building up a tree-based, commit-time log, when would we call it?

If we call it during the render, we still need to instrument console.log.

If we call it during the commit phase, after we've built up a set of these, the values that it closes over can have changed/mutated by the time we get there which would be confusing. Also, break points would no longer have the render function in scope so we couldn't inspect anything there.

[bvaughn]

If we call it during the render, we still need to instrument console.log.

Good point. I was primarily thinking of being able to disable it during shallow render- but if we wanted to collect logs for commit timing, you're right that we would also need to spy on the native console methods.

[sompylasar]

this is just going to lead to major confusion when somebody has a side-effect in their function.

Shallow rendering a component should _not_ trigger any side effects1. Those should be in useEffect / useLayoutEffect (which DevTools would not execute).

1 - Technically calling console.log _is a side effect_ but I think it's also a bit of a special case.

Yeah, we add side effects like debugger; (or, more importantly, browser breakpoint, without changing the code) and console.log (or browser logpoint, which should also not be forgotten, there is such in Chrome DevTools) to hook into React workflow. If there was a different way to do that, ideally without changing the source code, and ideally seeing the component stack instead of the React internals fiber work-loop stack, we'd use that I guess.

[bvaughn]

I like the idea of React.debug (maybe combined with spying on console methods if we want the commit time coalescing behavior) the most because it would cover more types of side effects- including breakpoints.

[sompylasar]

I like the idea of React.debug (maybe combined with spying on console methods if we want the commit time coalescing behavior) the most because it would cover more types of side effects- including breakpoints.

Could you please add a code example how would you use it? The part of changing the source code is what would throw me off from using it.

[bvaughn]

People already change source code to add things like console.log or any number of other debugging tools. The only exception is adding a debug breakpoint in the browser (which, anecdotally, I also often do after adding a console.log earlier).

function ExampleComponent(props) {
  React.debug(() => {
    // This callback would not be called when DevTools re-renders the component
    // Or when strict mode's debug side effects double render happens
    // Or in production mode
    console.log("ExampleComponent called with", props);
    debugger;
  });
  return <div>...</div>;
}

[trueadm]

React.debug would fit in nicely too if Chrome ever exposed an API for reverting side-effects (similar to what they have in their dev tools console for eager evaluation).

[sompylasar]

People already change source code to add things like console.log or any number of other debugging tools. The only exception is adding a debug breakpoint in the browser (which, anecdotally, I also often do after adding a console.log earlier).

With the addition of logpoints into the browser this may start happening less often. We have too little data about real usage, so we extrapolate debugging patterns of few people to debugging patterns of a larger community. As before, I'd recommend surfacing this problem to more people and gathering insights how they use the browser DevTools and the built-in features versus modifying the code of components while debugging, and what would they prefer to do if React + React DevTools were smarter in surfacing the right data for debugging (like, in my case, dependencies of hooks and their diffs/what exactly changed would be much appreciated).

[bvaughn]

Surfacing to more people and gathering feedback is the reason I created this GitHub issue rather than just posting in an internal thread 😄 but I think we may still end up making some educated guesses about APIs for this, since we're dealing with a lot of new APIs and tools.

[sompylasar]

_I wish github had inline replies so this does not derail the thread._

function ExampleComponent(props) {
  React.debug(() => {
    // This callback would not be called when DevTools re-renders the component
    // Or when strict mode's debug side effects double render happens
    // Or in production mode
    console.log("ExampleComponent called with", props);
    debugger;
  });
  return <div>...</div>;
}

This makes sense, but as the production components are never that simple, there are multiple hooks involved, and the rendering is conditional, and you need more than one of such output during a debugging session, and you need to add more debugpoints as you find out more details in runtime, the look of the code before/after and developer experience adding such debugpoints might be way more hairy than the above simplest case.

[bvaughn]

I rarely add (or see) more than one debug point or group of console.log statements per component. I don't think it would require too much effort to group these within one or few React.debug calls. My gut tells me that it's not as complicated as you're suggesting.

[sompylasar]

I rarely add (or see) more than one debug point or group of console.log statements per component.

This, again, is highly dependent on specific debugging patterns and the components being debugged. You also may not see them because they do not get committed to source control, they happen while debugging. 🙂 I wonder if anyone does debugging workshops and collects data and insights about web debugging patterns and experiences.

[eps1lon]

It seems like server-side-rendering is ignored so far in this proposal. While leveraging react-devtools (and browser APIs) is definitely viable for client side rendering, it is simply not available on the server.

The component stack should be added to these debug/log/warn/error messages within react not by react-devtools. This guarantees a similar experience for server and client-side debugging.

I'd like to see option 2 implemented with the re-introduction of React.warn and React.error.