hermes icon indicating copy to clipboard operation
hermes copied to clipboard

Strange hermes debug jumps and var state #23820

Open mgscreativa opened this issue 2 years ago • 13 comments

Minimal reproducible example

https://github.com/mgscreativa/heremes-test-expo-go

Summary

I’m using hermes debugging working, but the debugger behaviour is really strange. My workspace is as follows:

  • Linux Mint 21.2
  • WebStorm 2023.1.4
  • Using expo sdk v49 (49.0.6)
  • Expo Go on iPhone 12 Pro Max and iOS 16.5.1

For testing hermes debugging I have created a complete new and clean app with npx create-expo-app@latest --template tabs, I have also uploaded the app to GitHub here GitHub - mgscreativa/heremes-test-expo-go: heremes-test-expo-go 1

Accessing chrome debugger by pressing j in terminal I can see the hermes instance running and also can browse the project files and set some breakpoints in code but the debugger behaviour is really strange, ie:

  • Defined variables displays undefined when already defined in code
  • Watched vars already defined in code, sometimes display undefined as values and sometimes displays their actual values

I have tested the same result in:

  • Linux with expo go in Android 13 device, iOS iPhone XS Max, and Android emulator API 33
  • Macos Android 13 device, iOS iPhone XS Max

Have attached a two videos showing the process I’m following

Linux, Android Emu API 33

Peek 2023-08-04 12-16

Linux, iOS expo go

Peek 2023-08-04 12-21ios

Production code project

In this third video I'm showing the behaviour I get using a more complex project that I'm working on. I'll describe the strange behaviour:

  • The debugger jumps directly to the code at line 58 without stopping on first breakpoint at line 52!
  • Strangely, it jumps to line 64 but that line should not be executed as it's an else statement that was not hit by the condition of the if statement at line 58
  • After hitting the Resume button, the code jumps to line 52 and it doesn't hit line 58 anymore
  • Sometimes after hitting the Resume button the app crashes

Peek 2023-08-04 12-53-3

What Am I doing wrong? Should I configure anything else?

PS: Flipper 0.210.0 has the same behavior, tested on macos

Environment

expo-env-info 1.0.5 environment info: System: OS: Linux 5.15 Linux Mint 21.2 (Victoria) Shell: 5.1.16 - /bin/bash Binaries: Node: 16.13.1 - ~/.nvm/versions/node/v16.13.1/bin/node Yarn: 1.22.19 - ~/.nvm/versions/node/v16.13.1/bin/yarn npm: 9.8.1 - ~/.nvm/versions/node/v16.13.1/bin/npm Watchman: 20230430.125247.0 - /usr/local/bin/watchman SDKs: Android SDK: API Levels: 33 Build Tools: 30.0.3, 33.0.0 System Images: android-30 | Google APIs Intel x86 Atom, android-30 | Google Play Intel x86_64 Atom, android-32 | Google APIs Intel x86_64 Atom, android-33 | Google APIs Intel x86_64 Atom npmPackages: expo: ~49.0.5 => 49.0.6 react: 18.2.0 => 18.2.0 react-dom: 18.2.0 => 18.2.0 react-native: 0.72.3 => 0.72.3 react-native-web: ~0.19.6 => 0.19.7 npmGlobalPackages: eas-cli: 3.18.3 expo-cli: 6.3.10 Expo Workflow: managed

mgscreativa avatar Aug 08 '23 17:08 mgscreativa

Bump... any comments from devs?

mgscreativa avatar Aug 10 '23 21:08 mgscreativa

Hi, it is very difficult for us to debug something with complex dependencies. Can this be reproduced with a bare RN application?

tmikov avatar Aug 10 '23 23:08 tmikov

@tmikov cool! will create a bare RN test repo and check this issue in iOS and Android and let you know

mgscreativa avatar Aug 11 '23 11:08 mgscreativa

Did you open the debugger after making various code changes? If so, I think at least the breakpoints being set in different locations (and the code stopping on different parts) is due to an issue with Debugger.scriptParsed issue.

@tmikov Basically what's happening is that on every change (during a HMR session), the new bundle is parsed as new script. When the debugger connects, it receives all versions of the same bundle in the wrong order (from new to old) and possibly confusing the debugger a bit here.

Breakpoints in general are handled client-side on the debugger right now. Chrome devtools is trying to match the breakpoints by source map, and with the bug I just described, might result in some weird behavior.

I tested this issue a bit on the expo/expo repository, you can see a test PR to prevent this exact use case here. But, this PR probably breaks some things, that's why we probably aren't going to merge it.

Hope this helps!

byCedric avatar Aug 14 '23 14:08 byCedric

@byCedric that's an interesting case, thanks for sharing. It's true that right now a quick reload after making an edit does simply start running the new JS bundle alongside the old one (as opposed to a full reload that restarts the JS VM with just the updated code), but that should still be usable in theory.

I believe the most common way Chrome Dev Tools sets breakpoints is via setBreakpointByURL, which specifies where to set a breakpoint by file name (as opposed to using the ID that scriptParsed uses to identify source/maps), and will end up triggering multiple breakpoints when there are multiple copies of the script running simultaneously. This should still be able to report accurate locations when pausing, as the specific pause location (and corresponding source/map that should be used) is indicated by ID, rather than URL, allowing Chrome Dev Tools to display the correct one of the multiple versions of the script being run.

If your PR does improve pause locations, perhaps there's either a bug in scriptID management, or a different sequence of events is playing out than what I described.

Either way, I'd be curious to know if the code reloading issue is what @mgscreativa is running into, and if they're able to repro in the plain RN setup.

mattbfb avatar Aug 14 '23 15:08 mattbfb

@mattbfb I'll do some more testing on my end as well. But, here is a short overview from what I can see through the Protocol Monitor (Chrome DevTools experiment, but very useful).

Sorry in advance for the longer comment, but I think it's good to go into details here. Here is a JSON dump of all events listed below (in chronological order from oldest > newest) events in case you want to investigate yourself.

Breakpoint.setBreakpointByUrl is just referring to the bundled code, and thus resolved from sourcemap prettified code to the bundle (which is client side AFAIK)

image

In some cases, chrome devtools seems to not resolve the code properly. In the screenshot below, you can see the devtools trying to bind to "line 9, col 4", which is incorrect if you compare it with the actual bundled script executed (also the original source code btw). Not sure why this happens, or if this is a race condition from parsing sourcemaps and eagerly setting breakpoints.

image

One of the reasons why I think some unexpected behavior is related to these different script instances can be seen here. Besides the setBreakpointByURL, there is also Debugger.getPossibleBreakpoints (which is currently unimplemented - but invoked by devtools to find non-bindable code).

The screenshot below shows that it's asking for "script 3" and "script 4", while the HMR session has 9 already. But, since that was sent as first Debugger.scriptParsed event, I think the devtools is overwriting those script versions in later scriptParsed events (such as the script 4 & 3 events)

image
Here is script 9 image
Here is script 4 image
Here is script 3 image

All of this was tested in a default template Expo app (yarn create expo ./test-devtools - to try it yourself).

byCedric avatar Aug 14 '23 21:08 byCedric

@mattbfb I've been able to reproduce the behavior I described above with the React Native Community CLI too. Here is the full JSON dump of the debugger.

Here is script 10 image
Here is script 3 image

Eventually, the different script IDs lead up to two breakpoints being bound. One in "script 10", at a wrong location, and one in "script 3" at the correct location for the outdated script.

Breakpoint at script 3, good location but outdated code image
Breakpoint at script 10, good code, but wrong location image

byCedric avatar Aug 15 '23 20:08 byCedric

@byCedric thanks for that investigation with such thorough documentation!

I'll follow your steps and try to repro locally as well. I'm curious to learn more about a few things:

  1. If old versions of code are still running simultaneously with new code (e.g. if a breakpoint is set at an unusual point in old versions of the code, will it ever be hit?).
  2. If Chrome is displaying the latest version of the code. It does have some logic to match based on file name and choose the latest, but perhaps they're being sent in an order that confuses it, or it just doesn't handle them correctly in quick succession.
  3. Why the mid-line breakpoint expressions are showing in the screenshots. We don't answer Debugger.getPossibleBreakpoints today, but the screenshots have the breakpoint markers mid-line, showing the possible breakpoint locations as if that message was answered.

mattbfb avatar Aug 18 '23 12:08 mattbfb

@mattbfb No problem, happy to help.

  1. AFAIK, breakpoints are still binding, but to the wrong locations. This is equal to randomly binding breakpoints, resulting in some of these being hit and pausing the app in an unexpected position. Once hit, the bundle code is displayed and then paused on something usually at the top of the bundle.

  2. Chrome DevTools have something they call computeNonBreakableLines, which seems to be using the sourcemap as a reference. I'm not entirely sure how the source maps are handled within Chrome DevTools, but that might indeed affect this logic.

  3. The computeNonBreakableLines seems to try to map the source code to actual bundled code. If it doesn't have a match, it considers the breakpoint "unbindable". This makes sense for empty lines, which seems to be the only scenario where Chrome DevTools marks lines as unbindable. But, all of this still happens client side.

Hope this helps! I can also hop on a call if needed (I'm in the RN Discord).

byCedric avatar Aug 21 '23 12:08 byCedric

Thanks a lot @byCedric and @mattbfb for taking the time to review this! No step debugging is not debugging at all...

mgscreativa avatar Aug 21 '23 13:08 mgscreativa

My experience with the topic above: https://github.com/expo/expo/issues/24273

robozb avatar Sep 05 '23 18:09 robozb

@mgscreativa, I don't know that we're actually making progress here. Were you ever able to reproduce using a bare RN app?

Also, I don't think you answered this question from @byCedric: "Did you open the debugger after making various code changes?"

We need a good set of repro in order for us to root cause the issue. Right now we don't have it.

@byCedric I'm not 100% sure the issue you talked about is causing this reported issue. But I landed a fix for Hermes CDP to make sure the scriptParsed ordering is always maintained: https://github.com/facebook/hermes/commit/f6aed0e0fe1e106fe22a65e701e35246515f0900

dannysu avatar Nov 10 '23 02:11 dannysu

@mgscreativa, I don't know that we're actually making progress here. Were you ever able to reproduce using a bare RN app?

Also, I don't think you answered this question from @byCedric: "Did you open the debugger after making various code changes?"

We need a good set of repro in order for us to root cause the issue. Right now we don't have it.

@byCedric I'm not 100% sure the issue you talked about is causing this reported issue. But I landed a fix for Hermes CDP to make sure the scriptParsed ordering is always maintained: f6aed0e

Good day, i have the same issue. Are you think that the problem is gone away with this fix?

dariovr1 avatar Nov 10 '23 08:11 dariovr1