runtime icon indicating copy to clipboard operation
runtime copied to clipboard

[wasm][debugger] Random test failure due to a possible race in startup

Open radical opened this issue 3 years ago • 3 comments

Failure:

[xUnit.net 00:39:52.49]     DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged [FAIL]
  Failed DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged [10 ms]
  Error Message:
   : Expected Ok result but got [Result: IsOk: False, IsErr: True, Value: , Error: {
  "result": {
    "type": "object",
    "subtype": "error",
    "className": "TypeError",
    "description": "TypeError: Cannot read properties of undefined (reading 'BINDING')\n    at invoke_static_method (http://localhost:9400/debugger-driver.html:25:65)\n    at <anonymous>:1:35007\n    at mono_wasm_runtime_ready (http://localhost:9400/dotnet.js:3:6539)\n    at sc (http://localhost:9400/dotnet.js:3:106750)\n    at async Qa (http://localhost:9400/dotnet.js:3:104967)",
    "objectId": "-8087959768314858508.1.9"
  },
  "exceptionDetails": {
    "exceptionId": 1,
    "text": "Uncaught",
    "lineNumber": 24,
    "columnNumber": 64,
    "scriptId": "3",
    "stackTrace": {
      "callFrames": [
        {
          "functionName": "invoke_static_method",
          "scriptId": "3",
          "url": "http://localhost:9400/debugger-driver.html",
          "lineNumber": 24,
          "columnNumber": 64
        },
        {
          "functionName": "",
          "scriptId": "60",
          "url": "",
          "lineNumber": 0,
          "columnNumber": 35006
        },
        {
          "functionName": "mono_wasm_runtime_ready",
          "scriptId": "6",
          "url": "http://localhost:9400/dotnet.js",
          "lineNumber": 2,
          "columnNumber": 6538
        },
        {
          "functionName": "sc",
          "scriptId": "6",
          "url": "http://localhost:9400/dotnet.js",
          "lineNumber": 2,
          "columnNumber": 106749
        }
      ]
    },
    "exception": {
      "type": "object",
      "subtype": "error",
      "className": "TypeError",
      "description": "TypeError: Cannot read properties of undefined (reading 'BINDING')\n    at invoke_static_method (http://localhost:9400/debugger-driver.html:25:65)\n    at <anonymous>:1:35007\n    at mono_wasm_runtime_ready (http://localhost:9400/dotnet.js:3:6539)\n    at sc (http://localhost:9400/dotnet.js:3:106750)\n    at async Qa (http://localhost:9400/dotnet.js:3:104967)",
      "objectId": "-8087959768314858508.1.10"
    }
  }
} ]
Expected: True
Actual:   False
  Stack Trace:
     at DebuggerTests.TestExtensions.AssertOk(Result res, String prefix) in /_/src/mono/wasm/debugger/DebuggerTestSuite/TestExtensions.cs:line 12
   at DebuggerTests.DebuggerTestBase.LoadAssemblyAndTestHotReload(String asm_file, String pdb_file, String asm_file_hot_reload, String class_name, String method_name) in /_/src/mono/wasm/debugger/DebuggerTestSuite/DebuggerTestBase.cs:line 1444
   at DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged() in /_/src/mono/wasm/debugger/DebuggerTestSuite/HotReloadTests.cs:line 39
--- End of stack trace from previous location ---

I think this is because https://github.com/dotnet/runtime/blob/e43e31527db9f1a2dde3095a1651279b272c8c09/src/mono/wasm/debugger/tests/debugger-test/debugger-main.js#L24 .. in ..

https://github.com/dotnet/runtime/blob/e43e31527db9f1a2dde3095a1651279b272c8c09/src/mono/wasm/debugger/tests/debugger-test/debugger-main.js#L9-L25

.. can run after the test starts running which is once Mono.runtimeReady is received from the proxy.

IIUC, mono_wasm_runtime_ready() gets called before createDotnetRuntime returns, which would create a race, because in response to the Mono.runtimeReady message, the test would start to execute, and can call invoke_static_method which would access the as-yet-uninitialized App.runtime.

I might have this wrong, in which case please do explain what I got wrong :)

cc @pavelsavara @thaystg

radical avatar Aug 07 '22 06:08 radical

Tagging subscribers to 'arch-wasm': @lewing See info in area-owners.md if you want to be subscribed.

Issue Details

Failure:

[xUnit.net 00:39:52.49]     DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged [FAIL]
  Failed DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged [10 ms]
  Error Message:
   : Expected Ok result but got [Result: IsOk: False, IsErr: True, Value: , Error: {
  "result": {
    "type": "object",
    "subtype": "error",
    "className": "TypeError",
    "description": "TypeError: Cannot read properties of undefined (reading 'BINDING')\n    at invoke_static_method (http://localhost:9400/debugger-driver.html:25:65)\n    at <anonymous>:1:35007\n    at mono_wasm_runtime_ready (http://localhost:9400/dotnet.js:3:6539)\n    at sc (http://localhost:9400/dotnet.js:3:106750)\n    at async Qa (http://localhost:9400/dotnet.js:3:104967)",
    "objectId": "-8087959768314858508.1.9"
  },
  "exceptionDetails": {
    "exceptionId": 1,
    "text": "Uncaught",
    "lineNumber": 24,
    "columnNumber": 64,
    "scriptId": "3",
    "stackTrace": {
      "callFrames": [
        {
          "functionName": "invoke_static_method",
          "scriptId": "3",
          "url": "http://localhost:9400/debugger-driver.html",
          "lineNumber": 24,
          "columnNumber": 64
        },
        {
          "functionName": "",
          "scriptId": "60",
          "url": "",
          "lineNumber": 0,
          "columnNumber": 35006
        },
        {
          "functionName": "mono_wasm_runtime_ready",
          "scriptId": "6",
          "url": "http://localhost:9400/dotnet.js",
          "lineNumber": 2,
          "columnNumber": 6538
        },
        {
          "functionName": "sc",
          "scriptId": "6",
          "url": "http://localhost:9400/dotnet.js",
          "lineNumber": 2,
          "columnNumber": 106749
        }
      ]
    },
    "exception": {
      "type": "object",
      "subtype": "error",
      "className": "TypeError",
      "description": "TypeError: Cannot read properties of undefined (reading 'BINDING')\n    at invoke_static_method (http://localhost:9400/debugger-driver.html:25:65)\n    at <anonymous>:1:35007\n    at mono_wasm_runtime_ready (http://localhost:9400/dotnet.js:3:6539)\n    at sc (http://localhost:9400/dotnet.js:3:106750)\n    at async Qa (http://localhost:9400/dotnet.js:3:104967)",
      "objectId": "-8087959768314858508.1.10"
    }
  }
} ]
Expected: True
Actual:   False
  Stack Trace:
     at DebuggerTests.TestExtensions.AssertOk(Result res, String prefix) in /_/src/mono/wasm/debugger/DebuggerTestSuite/TestExtensions.cs:line 12
   at DebuggerTests.DebuggerTestBase.LoadAssemblyAndTestHotReload(String asm_file, String pdb_file, String asm_file_hot_reload, String class_name, String method_name) in /_/src/mono/wasm/debugger/DebuggerTestSuite/DebuggerTestBase.cs:line 1444
   at DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged() in /_/src/mono/wasm/debugger/DebuggerTestSuite/HotReloadTests.cs:line 39
--- End of stack trace from previous location ---

I think this is because https://github.com/dotnet/runtime/blob/e43e31527db9f1a2dde3095a1651279b272c8c09/src/mono/wasm/debugger/tests/debugger-test/debugger-main.js#L24 .. in ..

https://github.com/dotnet/runtime/blob/e43e31527db9f1a2dde3095a1651279b272c8c09/src/mono/wasm/debugger/tests/debugger-test/debugger-main.js#L9-L25

.. can run after the test starts running which is once Mono.runtimeReady is received from the proxy.

IIUC, mono_wasm_runtime_ready() gets called before createDotnetRuntime returns, which would create a race, because in response to the Mono.runtimeReady message, the test would start to execute, and can call invoke_static_method which would access the as-yet-uninitialized App.runtime.

I might have this wrong, in which case please do explain what I got wrong :)

cc @pavelsavara @thaystg

Author: radical
Assignees: -
Labels:

arch-wasm, blocking-clean-ci, area-Debugger-mono, test-failure

Milestone: 7.0.0

msftbot[bot] avatar Aug 07 '22 06:08 msftbot[bot]

Tagging subscribers to this area: @thaystg See info in area-owners.md if you want to be subscribed.

Issue Details

Failure:

[xUnit.net 00:39:52.49]     DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged [FAIL]
  Failed DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged [10 ms]
  Error Message:
   : Expected Ok result but got [Result: IsOk: False, IsErr: True, Value: , Error: {
  "result": {
    "type": "object",
    "subtype": "error",
    "className": "TypeError",
    "description": "TypeError: Cannot read properties of undefined (reading 'BINDING')\n    at invoke_static_method (http://localhost:9400/debugger-driver.html:25:65)\n    at <anonymous>:1:35007\n    at mono_wasm_runtime_ready (http://localhost:9400/dotnet.js:3:6539)\n    at sc (http://localhost:9400/dotnet.js:3:106750)\n    at async Qa (http://localhost:9400/dotnet.js:3:104967)",
    "objectId": "-8087959768314858508.1.9"
  },
  "exceptionDetails": {
    "exceptionId": 1,
    "text": "Uncaught",
    "lineNumber": 24,
    "columnNumber": 64,
    "scriptId": "3",
    "stackTrace": {
      "callFrames": [
        {
          "functionName": "invoke_static_method",
          "scriptId": "3",
          "url": "http://localhost:9400/debugger-driver.html",
          "lineNumber": 24,
          "columnNumber": 64
        },
        {
          "functionName": "",
          "scriptId": "60",
          "url": "",
          "lineNumber": 0,
          "columnNumber": 35006
        },
        {
          "functionName": "mono_wasm_runtime_ready",
          "scriptId": "6",
          "url": "http://localhost:9400/dotnet.js",
          "lineNumber": 2,
          "columnNumber": 6538
        },
        {
          "functionName": "sc",
          "scriptId": "6",
          "url": "http://localhost:9400/dotnet.js",
          "lineNumber": 2,
          "columnNumber": 106749
        }
      ]
    },
    "exception": {
      "type": "object",
      "subtype": "error",
      "className": "TypeError",
      "description": "TypeError: Cannot read properties of undefined (reading 'BINDING')\n    at invoke_static_method (http://localhost:9400/debugger-driver.html:25:65)\n    at <anonymous>:1:35007\n    at mono_wasm_runtime_ready (http://localhost:9400/dotnet.js:3:6539)\n    at sc (http://localhost:9400/dotnet.js:3:106750)\n    at async Qa (http://localhost:9400/dotnet.js:3:104967)",
      "objectId": "-8087959768314858508.1.10"
    }
  }
} ]
Expected: True
Actual:   False
  Stack Trace:
     at DebuggerTests.TestExtensions.AssertOk(Result res, String prefix) in /_/src/mono/wasm/debugger/DebuggerTestSuite/TestExtensions.cs:line 12
   at DebuggerTests.DebuggerTestBase.LoadAssemblyAndTestHotReload(String asm_file, String pdb_file, String asm_file_hot_reload, String class_name, String method_name) in /_/src/mono/wasm/debugger/DebuggerTestSuite/DebuggerTestBase.cs:line 1444
   at DebuggerTests.HotReloadTests.DebugHotReloadMethodUnchanged() in /_/src/mono/wasm/debugger/DebuggerTestSuite/HotReloadTests.cs:line 39
--- End of stack trace from previous location ---

I think this is because https://github.com/dotnet/runtime/blob/e43e31527db9f1a2dde3095a1651279b272c8c09/src/mono/wasm/debugger/tests/debugger-test/debugger-main.js#L24 .. in ..

https://github.com/dotnet/runtime/blob/e43e31527db9f1a2dde3095a1651279b272c8c09/src/mono/wasm/debugger/tests/debugger-test/debugger-main.js#L9-L25

.. can run after the test starts running which is once Mono.runtimeReady is received from the proxy.

IIUC, mono_wasm_runtime_ready() gets called before createDotnetRuntime returns, which would create a race, because in response to the Mono.runtimeReady message, the test would start to execute, and can call invoke_static_method which would access the as-yet-uninitialized App.runtime.

I might have this wrong, in which case please do explain what I got wrong :)

cc @pavelsavara @thaystg

Author: radical
Assignees: -
Labels:

arch-wasm, blocking-clean-ci, area-Debugger-mono, test-failure

Milestone: 7.0.0

msftbot[bot] avatar Aug 07 '22 06:08 msftbot[bot]

I was able to artificially reproduce this by calling moving App.runtime = runtime; App.init(); to run after a timeout.

radical avatar Aug 07 '22 06:08 radical

we are synchronizing 2 processes here.

  1. The normal unix dotnet+debug-proxy +xunit
  2. the wasm app running inside mono_wasm_runtime_ready is the synchronization helper necessary to make the process 1) wait

@radical said "mono_wasm_runtime_ready indicates that the runtime is ready, but not that the app is ready.. " and we need both. I will think about some consistent fix. Moving App.runtime = runtime into callback is possible, but I'm not sure yet if the best thing.

pavelsavara avatar Aug 08 '22 07:08 pavelsavara

Having an event/message that indicates "app is ready", and having "app is ready" as formal thing would be helpful.

As a workaround, I can add a special message for this in debugger-main.js's App.init, and make the tests wait for that. or even just add a tiny delay after we get runtime ready.

radical avatar Aug 08 '22 07:08 radical

The mono_wasm_runtime_ready is currently called by runtime in non-blazor startup sequence https://github.com/dotnet/runtime/blob/0c5ca95fec9b6e2cc5e757ad36d0b094f81a59a6/src/mono/wasm/runtime/startup.ts#L297

And blazor calls it here https://github.com/dotnet/aspnetcore/blob/55616fa5b272d6d957d20059a681a68901807486/src/Components/Web.JS/src/Platform/Mono/MonoPlatform.ts#L483

Both environments don't have applications ready at that point. Only the runtime is mostly ready.

pavelsavara avatar Aug 08 '22 08:08 pavelsavara

cc @maraf

pavelsavara avatar Aug 08 '22 10:08 pavelsavara