thread 'vsock-event-loop' panicked in some cases during vmm termination

[askfongjojo]

I found two core files after running some heavy fio (80 threads) and bonnie++ write workloads. They both show this stack:

BRM42220016 # mdb /pool/ext/cd3fdbae-a9d9-4db7-866a-bca36f6dd634/crypt/debug/core.oxz_propolis-server_a2f91c78-bfe9-4dfb-9e0a-9e2047a1cdc5.propolis-server.14130.1775597169
Loading modules: [ libumem.so.1 libnvpair.so.1 libc.so.1 ld.so.1 ]
> $C ! demangle
fffff7ffe9bff000 libc.so.1`_lwp_kill+0xa()
fffff7ffe9bff030 libc.so.1`raise+0x22(6)
fffff7ffe9bff080 libc.so.1`abort+0x58()
fffff7ffe9bff090 ~std::sys::pal::unix::abort_internal::h515b31030a784ec5+8()
fffff7ffe9bff0a0 ~std::process::abort::h263ae6dd5f7f06e2+8()
fffff7ffe9bff0b0 ~__rustc::__rust_abort+8()
fffff7ffe9bff0c0 ~__rustc::__rust_start_panic+8()
fffff7ffe9bff120 __rustc::rust_panic+0xd()
fffff7ffe9bff1e0 std::panicking::rust_panic_with_hook::h24c1a837a734501c+0x224()
fffff7ffe9bff220 std::panicking::begin_panic_handler::{{closure}}::hebb980b0c684b90d+0x98()
fffff7ffe9bff230 ~std::sys::backtrace::__rust_end_short_backtrace::h4b651dba38b6cba9+8()
fffff7ffe9bff260 ~__rustc::rust_begin_unwind+0x1b()
fffff7ffe9bff290 ~core::panicking::panic_fmt::h717aa56ae600c892+0x1e()
fffff7ffe9bff2f0 ~core::option::expect_failed::h0ec994f1b2301c5c+0x59()
fffff7ffe9bff3d0 propolis::hw::virtio::vsock::VsockVq::try_rx_permit::h521ac06a921908d5+0x241()
fffff7ffe9bff560 propolis::vsock::poller::VsockPoller::process_pending_rx::ha06e1b30f7bdfcc1+0x23()
fffff7ffe9bffb40 propolis::vsock::poller::VsockPoller::handle_events::hc79a2b7771ee5b60+0xd8()
fffff7ffe9bffbd0 propolis::vsock::poller::VsockPoller::poller_loop::ha9ffbd6ea4fe3a90+0x9b()
fffff7ffe9bffbf0 std::sys::backtrace::__rust_begin_short_backtrace::ha421c807d7878c83+0xe()
fffff7ffe9bfff80 core::ops::function::FnOnce::call_once{{vtable.shim}}::hd4fa5720c9a360c3+0xa0()
fffff7ffe9bfffb0 std::sys::pal::unix::thread::Thread::new::thread_start::h128a92fdf19e3e8a+0x2f()
fffff7ffe9bfffe0 libc.so.1`_thrp_setup+0x77(fffff7ffeef47240)
fffff7ffe9bffff0 libc.so.1`_lwp_start()

The propolis logs both ended with the following error:

03:58:03.501Z INFO propolis-server (vm_state_driver): Terminating serial task
03:58:03.501Z INFO propolis-server (vm_state_driver): Returning from serial task
03:58:03.501Z INFO propolis-server (vm_state_driver): beginning graceful shutdown
    file = /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.7/src/server.rs:317
    local_addr = [fd00:1122:3344:10b::1:1431]:35321
03:58:03.501Z INFO propolis-server (vm_state_driver): publishing new instance state
    gen = 4
    migration = InstanceMigrateStatusResponse { migration_in: None, migration_out: None }
    state = Destroyed
03:58:03.511Z INFO propolis-server: request completed
    latency_us = 70
    local_addr = [fd00:1122:3344:10b::1:1431]:12400
    method = GET
    remote_addr = [fd00:1122:3344:10b::1]:33282
    req_id = 5edc6f34-ff84-420f-ab5e-a2b5de9533f0
    response_code = 200
    uri = /instance/state-monitor
03:58:03.517Z ERRO propolis-server (vm_state_driver): one of the notify channels was closed!
    job = notify
    session_id = 4c293931-3a75-4b5b-bd23-e75e441b2b17
03:58:03.517Z INFO propolis-server (vm_state_driver): notify_task exiting
    job = notify
    session_id = 4c293931-3a75-4b5b-bd23-e75e441b2b17
03:58:03.599Z ERRO propolis-server (vm_state_driver): one of the notify channels was closed!
    job = notify
    session_id = 4e2f67d3-db09-4824-846f-415c3a333f44
03:58:03.599Z INFO propolis-server (vm_state_driver): notify_task exiting
    job = notify
    session_id = 4e2f67d3-db09-4824-846f-415c3a333f44
03:58:03.599Z ERRO propolis-server (vm_state_driver): one of the notify channels was closed!
    job = notify
    session_id = e14fc61c-960f-4db6-99a0-99462f72d555
03:58:03.599Z INFO propolis-server (vm_state_driver): notify_task exiting
    job = notify
    session_id = e14fc61c-960f-4db6-99a0-99462f72d555

thread 'vsock-event-loop' panicked at lib/propolis/src/hw/virtio/vsock.rs:116:45:
mem access for write
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

[askfongjojo]

The complete propolis log and core file for one of the vmm have been downloaded to /staff/core/propolis-1110.

[askfongjojo]

Turned out I was wrong about the "after running some heavy fio (80 threads) and bonnie++ write workloads" condition - those VMMs were actually terminated shortly after coming up, according to the propolis logs. These instances might have been terminated by the test harness when it hit a certain condition that caused it to abort the test and trigger VM teardown. For that situation, @iximeow identified the race condition which could trigger it.

[iximeow]

(that race should then be addressed by #1112 )

[iximeow]

there's the shutdown race and panic that Angela saw above, and a very similar race on the setup. if PciVirtioSock has an excruciatingly long delay (2 seconds) between creating the vsock device and attaching it:

            let device = virtio::PciVirtioSock::new(
                num_queues,
                guest_cid,
                self.log.new(slog::o!("dev" => "virtio-socket")),
                mappings,
            );

            self.devices.insert(vsock.id.clone(), device.clone());
            chipset.pci_attach(bdf, device);

then it's possible the vsock poller will try checking for guest memory before we've actually attached it over at chipset.pci_attach(bdf, device). this seems to be the form of race that @leftwo hit a bunch upon powering up madrid this morning.