Open pavelsavara opened 8 months ago
Tagging subscribers to 'arch-wasm': @lewing See info in area-owners.md if you want to be subscribed.
Author: | pavelsavara |
---|---|
Assignees: | - |
Labels: | `arch-wasm`, `area-VM-threading-mono`, `os-browser` |
Milestone: | 9.0.0 |
cc @kg @BrzVlad
here is one more
[11:01:33] info: [2023-12-17T11:01:33.762Z] [PASS] System.Threading.Tests.MutexTests.OpenExisting(name: "ada314549e444c7da1055fc1741a507e")
[11:01:33] warn: worker sent an error! http://127.0.0.1:38575/_framework/dotnet.native.worker.js:1: Uncaught RuntimeError: operation does not support unaligned accesses
[11:01:33] fail: MONO_WASM: Error
at Qe (http://127.0.0.1:38575/_framework/dotnet.js:3:19749)
at e (http://127.0.0.1:38575/_framework/dotnet.js:3:33736)
at http://127.0.0.1:38575/_framework/dotnet.js:3:33881
[11:01:33] warn: MONO_WASM: mono_wasm_exit failed {}
[11:01:33] fail: [out of order message from the browser]: http://127.0.0.1:38575/_framework/dotnet.native.worker.js 0 Uncaught RuntimeError: operation does not support unaligned accesses
I don't see any atomics in store_local, so the stack trace must be wrong
Ah, if so we'd need to run it under a debugger and hope it will pause there
Perhaps Invalid atomic access index
is related ?
[13:00:09] info: [2023-12-21T13:00:09.376Z] [PASS] System.Threading.Tasks.Sources.Tests.ManualResetValueTaskSourceTests.TaskScheduler_CaptureIfRequested(runContinuationsAsynchronously: False, captureTaskScheduler: True, setBeforeOnCompleted: True)
[13:00:09] warn: worker sent an error! http://127.0.0.1:44357/_framework/dotnet.native.worker.js:1:
Uncaught RangeError: Invalid atomic access index
[13:00:09] fail: MONO_WASM: Error
at Qe (http://127.0.0.1:44357/_framework/dotnet.js:3:19734)
at e (http://127.0.0.1:44357/_framework/dotnet.js:3:33726)
at http://127.0.0.1:44357/_framework/dotnet.js:3:33871
[12:54:20] info: [2023-12-21T12:54:20.235Z] [PASS] Microsoft.Extensions.Logging.Console.Test.JsonConsoleFormatterTests.Log_StateAndScopeContainsSpecialCaseValue_SerializesValueAsExpected(value: 1, expectedJsonValue: "1")
[12:54:20] warn: worker sent an error! http://127.0.0.1:45013/_framework/dotnet.native.worker.js:1: Uncaught RangeError: Invalid atomic access index
[12:54:20] fail: MONO_WASM: Error
at Qe (http://127.0.0.1:45013/_framework/dotnet.js:3:19734)
at e (http://127.0.0.1:45013/_framework/dotnet.js:3:33726)
at http://127.0.0.1:45013/_framework/dotnet.js:3:33871
[12:54:20] info: WASM EXIT 1
@lambdageek any thoughts ?
It's either us or emscripten libc, right?
Maybe we can instrument all our atomic ops with an alignment check?
Another Log
[13:22:55] warn: worker sent an error! http://127.0.0.1:39547/_framework/dotnet.native.worker.js:1: Uncaught RangeError: Invalid atomic access index
[13:22:55] fail: MONO_WASM: Error
at Qe (http://127.0.0.1:39547/_framework/dotnet.js:3:19635)
at e (http://127.0.0.1:39547/_framework/dotnet.js:3:33629)
at http://127.0.0.1:39547/_framework/dotnet.js:3:33774
[13:22:55] info: WASM EXIT 1
I created known error for tracking of Invalid atomic access index
https://github.com/dotnet/runtime/issues/96545
And possibly unrelated ?? memory access out of bounds
https://github.com/dotnet/runtime/issues/96546
For this issue I can't find the build which failed with operation does not support unaligned accesses
anymore 😞
They are 20231219.1
and 20231217.1
on runtime-wasm
If we're getting memory access out of bounds, it could mean that we're doing an atomic on a garbage address. That address would have like a 1/2 or 3/4 chance of being unaligned, and a decent chance of being out of bounds.
yeah, maybe we should try building with asan
Couldn't repro locally with debug builds of the runtime/libraries/tests. Trying a release build (but hopefully still with native symbols).
Update no luck with release builds either.
For the record I'm using:
$ ./build.sh --os browser -c Release /p:MonoWasmBuildVariant=multithread /p:KeepNativeSymbols=true /p:WasmNativeDebugSymbols=true /p:MonoEnableAssertMessages=true
...
$ XUNIT_RANDOM_ORDER_SEED=186041091 XHARNESS_COMMAND="test-browser --no-quit --browser=chrome --web-server-use-cop" ./dotnet.sh build /t:Test /p:RuntimeFlavor=Mono /p:WasmEnableThreads=true -c Release /p:TargetOS=browser /p:TargetArchitecture=wasm /p:KeepNativeSymbols=true /p:WasmNativeDebugSymbols=true /p:MonoEnableAssertMessages=true /p:MonoWasmBuildVariant=multithread src/libraries/System.Threading/tests/System.Threading.Tests.csproj
...
(Also tried Microsoft.Extensions.Logging.Console.Tests.csproj
and System.Net.Http.Json.Functional.Tests.csproj
with a variety of random seeds)
Couldn't repro locally with debug builds of the runtime/libraries/tests. Trying a release build (but hopefully still with native symbols).
Update no luck with release builds either.
For the record I'm using:
$ ./build.sh --os browser -c Release /p:MonoWasmBuildVariant=multithread /p:KeepNativeSymbols=true /p:WasmNativeDebugSymbols=true /p:MonoEnableAssertMessages=true ... $ XUNIT_RANDOM_ORDER_SEED=186041091 XHARNESS_COMMAND="test-browser --no-quit --browser=chrome --web-server-use-cop" ./dotnet.sh build /t:Test /p:RuntimeFlavor=Mono /p:WasmEnableThreads=true -c Release /p:TargetOS=browser /p:TargetArchitecture=wasm /p:KeepNativeSymbols=true /p:WasmNativeDebugSymbols=true /p:MonoEnableAssertMessages=true /p:MonoWasmBuildVariant=multithread src/libraries/System.Threading/tests/System.Threading.Tests.csproj ...
(Also tried
Microsoft.Extensions.Logging.Console.Tests.csproj
andSystem.Net.Http.Json.Functional.Tests.csproj
with a variety of random seeds)
have you tried with -fsanitize=address in the cflags/ldflags when building?
[13:35:56] info: Starting: System.Threading.Tests.dll
[13:36:27] warn: [0x000dc69c-main 13:36:27.947] MONO_WASM: Failed to find loaded WebWorker, this may deadlock. Please increase the pthreadPoolSize. Running threads 17. Loading workers: 8
[13:36:32] fail: [0x061b0040-emsc 13:36:32.808] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[13:36:32] fail: [0x061b0040-emsc 13:36:32.808] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[13:36:32] info: [0x061b0040-emsc 13:36:32.809] MONO_WASM: Dumping web worker info as seen by UI thread, it could be stale:
[13:36:32] info: 00 | 0x061b0040-emsc: isRunning:false isAttached:false isEventLoop:false reuseCount: 40 - pthread-assigned
[13:36:32] fail: [0x061b0040-emsc 13:36:32.810] MONO_WASM: operation does not support unaligned accesses
RuntimeError: operation does not support unaligned accesses
at http://127.0.0.1:38395/_framework/dotnet.native.wasm:wasm-function[779]:0x4c626
at http://127.0.0.1:38395/_framework/dotnet.native.wasm:wasm-function[2752]:0xd3d1b
at http://127.0.0.1:38395/_framework/dotnet.native.wasm:wasm-function[2748]:0xd37f7
at Object.invokeEntryPoint (http://127.0.0.1:38395/_framework/dotnet.native.js:8:69009)
at handleMessage (http://127.0.0.1:38395/_framework/dotnet.native.worker.js:1:2306)
[13:36:32] info: WASM EXIT 1
cc @steveisok @vargaz
Local on my system, with better stack trace I admit this is code I just changed, so it could be me causing it.
Any invalid pointer could lead any lock to cause this. ☹️
fail: [0x042d06b0-pool 10:23:37.263] MONO_WASM: operation does not support unaligned accesses
RuntimeError: operation does not support unaligned accesses
at a_cas.7 (a_cas.7 (http://127.0.0.1:57921/_framework/dotnet.native.wasm:wasm-function[17476]:0x35a5ee))
at __pthread_mutex_trylock (__pthread_mutex_trylock (http://127.0.0.1:57921/_framework/dotnet.native.wasm:wasm-function[17477]:0x35a609))
at mono_os_mutex_trylock.18 (mono_os_mutex_trylock.18 (http://127.0.0.1:57921/_framework/dotnet.native.wasm:wasm-function[8720]:0x1ee1fd))
at mono_coop_mutex_lock.18 (mono_coop_mutex_lock.18 (http://127.0.0.1:57921/_framework/dotnet.native.wasm:wasm-function[8719]:0x1ee19a))
at mono_mem_manager_lock (mono_mem_manager_lock (http://127.0.0.1:57921/_framework/dotnet.native.wasm:wasm-function[8718]:0x1ee176))
Looking at the emscripten implementation, they don't make any effort to ensure alignment of the address they're doing cas on: https://github.com/emscripten-core/emscripten/blob/e0c3ce6d2b3f121abab481e6e79a1a60e2fcd18b/system/lib/libc/musl/src/thread/pthread_mutex_trylock.c#L75
So not only would invalid pointers have a 3/4 or 7/8 chance of hitting this, but you need to make sure any pthread_mutex_t instances are sufficiently aligned as well - if they're static you're relying on the linker to arrange them at aligned offsets (it probably has to for anything to work), and if they're struct members you're relying on the alignment and packing of the struct to not put it at a bad address.
If you're trying to lock an invalid pointer, I would assume that in cases where it doesn't crash like this, it either erroneously wakes instantly because it thinks it just 'locked' garbage memory, or it deadlocks forever waiting on something that isn't a lock?
[21:04:35] fail: [0x050c02f0-long 21:04:35.756] MONO_WASM: operation does not support unaligned accesses
RuntimeError: operation does not support unaligned accesses
at a_cas (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[8517]:0x20eec2)
at __pthread_mutex_trylock (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[8670]:0x21538d)
at lock_thread (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[2758]:0xd6056)
at ves_icall_System_Threading_Thread_GetState_raw (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[2096]:0xb18e9)
at do_icall (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[334]:0x28859)
at do_icall_wrapper (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[263]:0x26009)
at mono_interp_exec_method (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[254]:0x18a3c)
at interp_runtime_invoke (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[293]:0x26c97)
at mono_jit_runtime_invoke (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[3347]:0xfd35a)
at do_runtime_invoke (http://127.0.0.1:44659/_framework/dotnet.native.wasm:wasm-function[2615]:0xcf3ae)
[19:51:30] info: [PASS] System.Threading.Tests.MutexTests.NamedMutex_DisposeWhenLockedRaceTest
[19:51:32] fail: [0x05620040-long 19:51:32.464] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[19:51:32] fail: [0x05620040-long 19:51:32.465] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[19:51:32] info: [0x05620040-long 19:51:32.466] MONO_WASM: Dumping web worker info as seen by UI thread, it could be stale:
[19:51:32] info: 010 | 0x05620040-long: isRunning:false isAttached: true isEventLoop:false reuseCount: 2 - .NET Long Running Task
[19:51:32] fail: [0x05620040-long 19:51:32.467] MONO_WASM: operation does not support unaligned accesses
RuntimeError: operation does not support unaligned accesses
at a_cas (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[8528]:0x20f31e)
at __pthread_mutex_trylock (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[8682]:0x215a4e)
at lock_thread (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[2769]:0xd669d)
at ves_icall_System_Threading_Thread_GetState_raw (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[2107]:0xb1f1a)
at do_icall (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[340]:0x28bb1)
at do_icall_wrapper (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[269]:0x2635f)
at mono_interp_exec_method (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[260]:0x18b4e)
at interp_runtime_invoke (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[299]:0x26fed)
at mono_jit_runtime_invoke (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[3358]:0xfd753)
at do_runtime_invoke (http://127.0.0.1:41171/_framework/dotnet.native.wasm:wasm-function[2626]:0xcf9f5)
[19:51:32] info: WASM EXIT 1
[15:11:26] info: [STRT] System.Threading.Tests.MutexTests.NamedMutex_ThreadExitDisposeRaceTest
[15:11:27] fail: [0x057d0040-back 15:11:27.025] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[15:11:27] fail: [0x057d0040-back 15:11:27.026] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[15:11:27] info: [0x057d0040-back 15:11:27.027] MONO_WASM: Dumping web worker info as seen by UI thread, it could be stale:
[15:11:27] info: 019 | 0x057d0040-back: isRunning:false isAttached:false isEventLoop:false reuseCount: 19 - pthread-assigned
[15:11:27] fail: [0x057d0040-back 15:11:27.054] MONO_WASM: operation does not support unaligned accesses
RuntimeError: operation does not support unaligned accesses
at mono_threads_open_thread_handle (http://127.0.0.1:34685/_framework/dotnet.native.wasm:wasm-function[795]:0x4f9fc)
at mono_thread_attach_internal (http://127.0.0.1:34685/_framework/dotnet.native.wasm:wasm-function[2774]:0xd6f43)
at start_wrapper (http://127.0.0.1:34685/_framework/dotnet.native.wasm:wasm-function[2770]:0xd6a24)
at Object.invokeEntryPoint (http://127.0.0.1:34685/_framework/dotnet.native.js:8:69009)
at handleMessage (http://127.0.0.1:34685/_framework/dotnet.native.worker.js:1:2306)
[15:11:27] info: WASM EXIT 1
[06:20:11] info: [STRT] System.Threading.Tests.MutexTests.NamedMutex_ThreadExitDisposeRaceTest
[06:20:14] fail: [0x01ae9b90-dpty 06:20:14.155] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[06:20:14] fail: [0x01ae9b90-dpty 06:20:14.156] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[06:20:14] info: [0x01ae9b90-dpty 06:20:14.157] MONO_WASM: Dumping web worker info as seen by UI thread, it could be stale:
[06:20:14] info: 001 | 0x01ae9b90-dpty: isRunning: true isAttached: true isEventLoop:false reuseCount: 1 -
[06:20:14] fail: [0x01ae9b90-dpty 06:20:14.188] MONO_WASM: operation does not support unaligned accesses
RuntimeError: operation does not support unaligned accesses
at a_cas (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[8511]:0x20e9a8)
at __pthread_mutex_trylock (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[8665]:0x2150d8)
at lock_thread (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[2763]:0xd630f)
at ves_icall_System_Threading_Thread_GetState_raw (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[2103]:0xb1e7e)
at do_icall (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[336]:0x28a85)
at do_icall_wrapper (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[265]:0x26234)
at mono_interp_exec_method (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[256]:0x18af2)
at interp_runtime_invoke (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[295]:0x26ec2)
at mono_jit_runtime_invoke (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[3342]:0xfcd58)
at do_runtime_invoke (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[2622]:0xcf9b1)
at mono_runtime_invoke_checked (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[2621]:0xcf941)
at ves_icall_InternalInvoke_raw (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[1980]:0xaa473)
at do_icall (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[336]:0x28b1e)
at do_icall_wrapper (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[265]:0x26234)
at mono_interp_exec_method (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[256]:0x18af2)
at interp_entry (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[329]:0x28530)
at interp_entry_static_0 (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[365]:0x29539)
at wasm_native_to_interp_System_Runtime_InteropServices_JavaScript_JSSynchronizationContext_BackgroundJobHandler (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[231]:0x1666f)
at mono_background_exec (http://127.0.0.1:43199/_framework/dotnet.native.wasm:wasm-function[835]:0x50cb8)
at zs (http://127.0.0.1:43199/_framework/dotnet.runtime.js:3:70332)
at callUserCallback (http://127.0.0.1:43199/_framework/dotnet.native.js:8:102608)
at http://127.0.0.1:43199/_framework/dotnet.native.js:8:111163
[06:20:14] info: WASM EXIT 1
NamedMutex_ThreadExitDisposeRaceTest
is nasty test, it creates threads and mutexes in a 1000 loop and there are two threads racing to destroy the same mutex.
This could be just another manifestation of the MT corruption we're seeing other places where the invalid address is unaligned
Log with dumped worker info:
[08:57:13] fail: [0x000fb4f8--UI- 08:57:13.153] MONO_WASM: Unhandled error: RuntimeError: operation does not support unaligned accesses
[08:57:13] info: [0x000fb4f8--UI- 08:57:13.155] MONO_WASM: Dumping web worker info as seen by UI thread, it could be stale:
[08:57:13] info: 000 | 0x000fb4f8--UI-: isRunning: true isAttached: true isEventLoop:false reuseCount: 0 - UI Thread
[08:57:13] info: 001 | 0x00d25070-dpty: isRunning: true isAttached: true isEventLoop:false reuseCount: 1 -
[08:57:13] info: 002 | 0x02bda650--IO-: isRunning: true isAttached: true isEventLoop:false reuseCount: 1 -
[08:57:13] info: 003 | 0x030e2908-norm: isRunning: true isAttached: true isEventLoop:false reuseCount: 1 - Finalizer
[08:57:13] info: 005 | 0x04c08030-gate: isRunning: true isAttached: true isEventLoop:false reuseCount: 1 - .NET TP Gate
[08:57:13] info: 007 | - : isRunning:false isAttached:false isEventLoop:false reuseCount: 0 - emscripten-pool
[08:57:13] info: 008 | --05cc8030-emsc: isRunning:false isAttached:false isEventLoop:false reuseCount: 1 - unregistered:(.NET Long Running Task)
[08:57:13] info: 006 | --056a5268-emsc: isRunning:false isAttached:false isEventLoop:false reuseCount: 1 - unregistered:(.NET Long Running Task)
[08:57:13] info: 004 | --045e5e68-emsc: isRunning:false isAttached:false isEventLoop:false reuseCount: 1 - unregistered:(.NET TP Worker)
[08:57:13] fail: [0x000fb4f8--UI- 08:57:13.168] MONO_WASM: operation does not support unaligned accesses
RuntimeError: operation does not support unaligned accesses
at a_cas (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8617]:0x223689)
at __private_cond_signal (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8733]:0x228591)
at pthread_cond_signal (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8726]:0x228011)
at call_then_finish_task (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8715]:0x2273be)
at call_with_ctx (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8712]:0x227350)
at em_task_queue_execute (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8697]:0x226ce9)
at receive_notification (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8703]:0x226ed5)
at em_task_queue_execute (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8697]:0x226ce9)
at _emscripten_check_mailbox (http://127.0.0.1:44717/_framework/dotnet.native.wasm:wasm-function[8841]:0x22ecf3)
at callUserCallback (http://127.0.0.1:44717/_framework/dotnet.native.js:8:98666)
at checkMailbox (http://127.0.0.1:44717/_framework/dotnet.native.js:8:99197)
Error Blob
Reproduction Steps
Build: https://dev.azure.com/dnceng-public/public/_build/results?buildId=556904&view=logs&jobId=63c2d0c8-fec2-5788-81c8-f3ac95e8841f
Known issue validation
Build: :mag_right: https://dev.azure.com/dnceng-public/public/_build/results?buildId=556904 Error message validated:
RuntimeError: operation does not support unaligned accesses
Result validation: :white_check_mark: Known issue matched with the provided build. Validation performed at: 2/7/2024 4:03:46 PM UTCReport
Summary