WASM copy-on-write strategy breaks when running docker image on Mac M1

[mikiquantum]

Is there an existing issue?

• I have searched the existing issues

Experiencing problems? Have you tried our Stack Exchange first?

• This is not a support question.

Description of bug

When running rococo-local using image parity/polkadot:v0.9.23 (same for parity/polkadot:v0.9.24), after a session change, ~20-30 blocks, both validators alice and bob fail with the following errors:

2022-06-17 23:34:36.095  WARN tokio-runtime-worker sc_service::client::client: Block prepare storage changes error: Error at calling runtime api: Execution failed: Execution aborted due to trap: wasm trap: out of bounds memory access
WASM backtrace:

    0: 0x1c729e - <unknown>!<ahash::random_state::RandomState as core::default::Default>::default::h922cce98276ba0ef
    1: 0x1ecffb - <unknown>!pallet_session::historical::ProvingTrie<T>::generate_for::hca60d5b29bd7ea83
    2: 0x1e5368 - <unknown>!pallet_session::<impl pallet_session::pallet::Pallet<T>>::rotate_session::he420142a51c0b3a4
    3: 0x2ce30 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::initialize_block_impl::h12b224f847a42c83
    4: 0x26ff3 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::initialize_block::hde77e842c81f8322
    5: 0x2c273b - <unknown>!Core_execute_block

and

2022-06-17 23:51:54.045  WARN tokio-runtime-worker babe: Proposing failed: Import failed: Error at calling runtime api: Execution failed: Execution aborted due to trap: wasm trap: uninitialized element
WASM backtrace:

    0: 0x1c72a1 - <unknown>!<ahash::random_state::RandomState as core::default::Default>::default::h922cce98276ba0ef
    1: 0x1ecffb - <unknown>!pallet_session::historical::ProvingTrie<T>::generate_for::hca60d5b29bd7ea83
    2: 0x1e5368 - <unknown>!pallet_session::<impl pallet_session::pallet::Pallet<T>>::rotate_session::he420142a51c0b3a4
    3: 0x2ce30 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::initialize_block_impl::h12b224f847a42c83
    4: 0x26ff3 - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::initialize_block::hde77e842c81f8322
    5: 0x2c3c95 - <unknown>!Core_initialize_block

At this point the chain stop producing blocks.

Digging a bit deeper, I notice this change on v0.9.23: #11232 and it mentions that if not on linux the performance would degrade, but in this case, adding one extra level of virtualization when running docker on a M1 seems to break block production.

In addition, I notice that if I run the validators with flag --wasmtime-instantiation-strategy=legacy-instance-reuse, then the error doesn't happen, but since it seems that the flag is deprecated and will be dropped in next releases, I think we should understand why is not compatible when running in this setup, since most of our development is in mac m1s.

Steps to reproduce

• Have a Mac with M1
• Run this docker compose file (docker-compose -f ./yourcomposefile.yml up -d)

# Node Key Alice: `subkey inspect //Alice`
# Node Key Bob: `subkey inspect //Bob`
version: '3'
services:
  node_alice:
    container_name: alice
    image: "parity/polkadot:v0.9.23"
    ports:
      - "30333:30333"
      - "9933:9933"
      - "9944:9944"
    command: >
      --chain=rococo-local
      --node-key=e5be9a5092b81bca64be81d212e7f2f9eba183bb7a90954f7b76361f6edb5c0a
      --wasm-execution=compiled
      --execution=wasm
      --base-path=/data
      --port 30333
      --rpc-port 9933
      --ws-port 9944
      --rpc-external
      --rpc-cors all
      --ws-external
      --rpc-methods=Unsafe
      --alice
      --log="main,info,xcm=trace,xcm-executor=trace"

  node_bob:
    container_name: bob
    image: "parity/polkadot:v0.9.23"
    ports:
      - "30344:30333"
      - "9935:9933"
      - "9945:9944"
    command: >
      --chain=rococo-local
      --node-key=398f0c28f98885e046333d4a41c19cee4c37368a9832c6502f6cfd182e2aef89
      --base-path=/data
      --wasm-execution=compiled
      --execution=wasm
      --port 30333
      --rpc-port 9933
      --ws-port 9944
      --rpc-external
      --ws-external
      --rpc-cors all
      --rpc-methods=Unsafe
      --bob
      --log="main,info,xcm=trace,xcm-executor=trace"

• Wait for 20-30 blocks until the errors start happening.
• Bring all down: docker-compose -f ./yourcomposefile.yml down

[bkchr]

CC @koute

[koute]

Hmm.... it's failing always at the same place, from the error it looks like it's accessing uninitialized memory, and that place where it's failing accesses a global variable. Looks like the memory might not be properly cleared between runtime invocations.

I've seen something like this before: qemu's user mode emulator has a bug where it doesn't properly emulate madvise(MADV_DONTNEED) that wasmtime's CoW implementation uses; I wonder if whatever Docker's using on M1 Macs has the same or similar issue?

So I'm guessing this is probably a bug either in wasmtime or in Docker (in which case it should be possible to fix it) or in Apple's software (in which case unless we find some sort of a workaround there won't be much we can do).

I'll try to take a closer look at this if I can get someone to remotely lend me an M1 Mac.

[bkchr]

Ahhh! Good point. Yeah that is broken in Qemu. I was once confused why my tests are failing on my virtual machine on my M1. bytecodealliance/wasmtime#3770 this is the solution in their CI. Maybe we could try to detect QEMU and then disable the instance reuse?

[koute]

So does Docker on M1 Macs use qemu's user mode emulation?

It is weird that legacy instance reuse scheme seems to work, because it also uses madvise(MADV_DONTNEED) to clear its memory. Although it's probably also subtly broken and only works by accident; for that instantiation scheme the whole WASM executor is never actually reinitialized from scratch, so it handles not clearing the memory better (but it will still break, so it's still broken, just a little less broken).

Maybe we could try to detect QEMU and then disable the instance reuse?

Hmm.... yeah, I think that's a good idea. Detecting whether madvise(MADV_DONTNEED) works should be trivial - we can just allocate a dummy page, write something to it, madvise it, and then see whether it's cleared. If it's not we print out a warning (or an error?) and forcibly disable the memory reuse. That'll result in a performance hit, but that's a lot better than being incorrect.

I'll whip up a PR.

[koute]

@mikiquantum Can you perhaps try to do a retest with the patch from this PR applied and see if the issue's still there? #11722

[mikiquantum]

@koute thanks for the quick response and action! I will try running the tests in a docker env and try building the substrate node docker image and try running it too.

[mikiquantum]

@koute Trying to build a polkadot docker image with updated dependencies based on your fork/branch and I am getting this compilation error when running the docker build:

   Compiling cranelift-codegen v0.82.3
   Compiling http-body v0.4.5
error[E0432]: unresolved imports `alloc::ffi`, `core::ffi::c_char`, `core::ffi::CStr`, `core::ffi::FromBytesWithNulError`, `crate::ffi::CString`, `crate::ffi::CString`, `crate::ffi::CString`, `crate::ffi::CString`
   |
  ::: /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/rustix-0.35.6/src/ffi/mod.rs:14:12
   |
14 |     alloc::ffi::{CString, NulError},
   |            ^^^ could not find `ffi` in `alloc`
15 |     core::ffi::{c_char, CStr, FromBytesWithNulError},
   |                 ^^^^^^  ^^^^  ^^^^^^^^^^^^^^^^^^^^^ no `FromBytesWithNulError` in `ffi`
   |                 |       |
   |                 |       no `CStr` in `ffi`
   |                 no `c_char` in `ffi`
  --> /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/rustix-0.35.6/src/imp/linux_raw/fs/dir.rs:2:24
   |
2  | use crate::ffi::{CStr, CString};
   |                        ^^^^^^^
   |
  ::: /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/rustix-0.35.6/src/fs/at.rs:8:24
   |
8  | use crate::ffi::{CStr, CString};
   |                        ^^^^^^^
   |
  ::: /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/rustix-0.35.6/src/path/arg.rs:8:24
   |
8  | use crate::ffi::{CStr, CString};
   |                        ^^^^^^^
   |
  ::: /usr/local/cargo/registry/src/github.com-1ecc6299db9ec823/rustix-0.35.6/src/process/chdir.rs:1:5
   |
1  | use crate::ffi::CString;
   |     ^^^^^^^^^^^^^^^^^^^

For more information about this error, try `rustc --explain E0432`.
error: could not compile `rustix` due to previous error
warning: build failed, waiting for other jobs to finish...
error: build failed

For context:

• ubuntu 20.04 / amd host
• This patch mikiquantum/polkadot@d0f6f69
• This docker file: https://github.com/mikiquantum/polkadot/blob/master/scripts/ci/dockerfiles/polkadot/polkadot_builder.Dockerfile

There are two versions of rustix now v0.33.7 and v0.35.6 the latter used by sc-executor-wasmtime.

[sunfishcode]

The issue is related to this line. This might be fixable by removing the default-features = false, or adding the "std" as a feature on that line. Or, it might be fixed by compiling with nightly Rust.

Rustix has an experimental no-std mode which is enabled when the "std" feature is not enabled. Setting default-features = false disables the "std" feature, enabling this mode. However, it's experimental and currently only works on nightly Rust.

[mikiquantum]

Thanks @sunfishcode , that is it. I modified the docker image slightly to use nightly instead and the compilation went through. I guess that polkadot_builder.Dockerfile file is not used to build the docker images that are published. Possibly, instead the binary is built elsewhere using some nightly and later injected in the docker image when building.

In any case, @koute seems that the fix is working fine, the local chain has been progressing passed the 30 block mark.

[koute]

@sunfishcode Thanks for your explanation and @mikiquantum thanks for the retest!

Technically my fix is more of a workaround instead of a proper fix, but since the issue's not in our code there's not much else we can do. It'd probably be a good idea to raise this issue with Docker to let them know that this is broken; this function plus the #[test] below it could be used as a minimal reproduction of the problem: copy-paste it into a new crate, run cargo add rustix --features all-apis and then run cargo test to see it fail.