search

nutanix / libvfio-user

framework for emulating devices in userspace
BSD 3-Clause "New" or "Revised" License
154 stars 49 forks source link

nvmf_vfio_user_prop_req_rsp: failed to map Admin queue #757

Closed chen622 closed 7 months ago

chen622 commented 11 months ago

I tried to follow the tutorial to build an environment based on SPDK and QEMU, register the host memory as a virtual nvme disk, and map it to the QEMU virtual machine. But when I started the virtual machine, the nvmf program reported an error: nvmf-error-log virtual machine: vm-error-log

I tried to locate the error and finally locate this code, which shows that region->info.vaddr is NULL.

Environment:

Operation:

dpdk-hugepages.py -p 2M --setup 4G
spdk_tgt -m 0xE0 &
rm -f /var/run/{cntrl,bar0}
rpc.py nvmf_create_transport -t VFIOUSER
rpc.py bdev_malloc_create 2048 512 -b Malloc0
rpc.py nvmf_create_subsystem nqn.2019-07.io.spdk:cnode0 -a -s SPDK0
rpc.py nvmf_subsystem_add_ns nqn.2019-07.io.spdk:cnode0 Malloc0
rpc.py nvmf_subsystem_add_listener nqn.2019-07.io.spdk:cnode0 -t VFIOUSER -a /var/run -s 0
qemu-system-x86_64 -enable-kvm -m 512M -object memory-backend-file,id=mem0,size=512M,mem-path=/dev/hugepages,share=on,prealloc=yes centos.qcow2 -device vfio-user-pci,socket=/var/run/cntrl -vnc :1
swapnili commented 11 months ago

Can you try using https://github.com/oracle/qemu/tree/vfio-user-p3.0 Qemu and latest spdk

chen622 commented 11 months ago

I tried qemu vfio-user-p3.0 and latest SPDK, but still not work.

tmakatos commented 11 months ago

@chen622 can you paste the full SPDK and QEMU logs?

chen622 commented 11 months ago

Upon further examination, I discovered that the issue lies within memory mapping. I scrutinized the regions in the DMA, noting that all vaddr values were NULL, which is not permissible when creating queues.

image

I also traced the process of establishing a connection between QEMU and SPDK, and identified the problem originating from this link: https://github.com/oracle/qemu/blob/fd575858e4e701f242b3031e07f414fcf1556305/hw/vfio/user.c#L2009, where a -1 return value caused the failure to accurately transmit memory information to SPDK.

image image

So, is this the cause of the issue, and do you have any idea why memory_region_get_fd return -1 ?

tmakatos commented 11 months ago

That would be for @jraman567 to tell, but I still think pasting the full QEMU logs would be helpful.

jraman567 commented 11 months ago

I'll take a look at this, and get back.

jraman567 commented 11 months ago

@chen622 Please share the full QEMU & SPDK logs.

I'm unsure if memory_region_get_fd() returning "-1" for fd is a problem in the case mentioned above.

It would probably return -1 for any memory region other than "mem0" (MemoryRegion->name) that you created. In your case, it returns "-1" for "pc.ram".

chen622 commented 11 months ago

SPDK logs

[2023-08-29 11:14:23.747712] Starting SPDK v23.01.1 git sha1 186986c / DPDK 22.11.1 initialization...
[2023-08-29 11:14:23.747993] [ DPDK EAL parameters: spdk_tgt --no-shconf -c 0x2 --huge-unlink --log-level=lib.eal:6 --log-level=lib.cryptodev:5 --log-level=user1:6 --iova-mode=pa --base-virtaddr=0x200000000000 --match-allocations --file-prefix=spdk_pid16887 ]
TELEMETRY: No legacy callbacks, legacy socket not created
[2023-08-29 11:14:23.884289] app.c: 712:spdk_app_start: *NOTICE*: Total cores available: 1
[2023-08-29 11:14:23.979883] reactor.c: 926:reactor_run: *NOTICE*: Reactor started on core 1
[2023-08-29 11:14:24.087234] accel_sw.c: 681:sw_accel_module_init: *NOTICE*: Accel framework software module initialized.
[2023-08-29 11:14:24.150904] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 6 voluntary context switches and 5 involuntary context switches in the last second.
[2023-08-29 11:14:25.149918] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 1 voluntary context switches and 4 involuntary context switches in the last second.
[2023-08-29 11:14:26.148931] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 0 voluntary context switches and 1 involuntary context switches in the last second.
[2023-08-29 11:14:26.777932] vbdev_lvol.c:1404:_vbdev_lvs_examine_cb: *INFO*: Lvol store not found on Malloc0
[2023-08-29 11:14:27.147938] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 0 voluntary context switches and 1 involuntary context switches in the last second.
[2023-08-29 11:15:10.319449] vfio_user.c:2811:nvmf_vfio_user_prop_req_rsp_set: *ERROR*: /var/run/: failed to enable ctrlr
[2023-08-29 11:15:10.319505] vfio_user.c:1158:fail_ctrlr: *ERROR*: :/var/run/ failing controller
[2023-08-29 11:15:11.104364] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 0 voluntary context switches and 1 involuntary context switches in the last second.

QEMU logs

The log file is quite large; you can use this OneDrive link https://1drv.ms/u/s!AlJabMSpbPfP7FLKVp43Tljx5LV_?e=Fxc3D3 to view it.

tmakatos commented 11 months ago

@chen622 can you enable additional debugging on SPDK to include the original error message ("failed to map Admin queue")?

tmakatos commented 11 months ago

@chen622 SPDK 72a5fa139 is pretty old, what are the SPDK and QEMU logs with latest stable SPDK (v23.05)?

chen622 commented 11 months ago

I tried to follow the tutorial to build an environment based on SPDK and QEMU, register the host memory as a virtual nvme disk, and map it to the QEMU virtual machine. But when I started the virtual machine, the nvmf program reported an error: nvmf-error-log virtual machine: vm-error-log

I tried to locate the error and finally locate this code, which shows that region->info.vaddr is NULL.

Environment:

  • QEMU d377d483f9
  • SPDK 72a5fa139 (Also tried the latest version.)
  • CPU AMD Ryzen 5 3600
  • OS Rocky 9

Operation:

dpdk-hugepages.py -p 2M --setup 4G
spdk_tgt -m 0xE0 &
rm -f /var/run/{cntrl,bar0}
rpc.py nvmf_create_transport -t VFIOUSER
rpc.py bdev_malloc_create 2048 512 -b Malloc0
rpc.py nvmf_create_subsystem nqn.2019-07.io.spdk:cnode0 -a -s SPDK0
rpc.py nvmf_subsystem_add_ns nqn.2019-07.io.spdk:cnode0 Malloc0
rpc.py nvmf_subsystem_add_listener nqn.2019-07.io.spdk:cnode0 -t VFIOUSER -a /var/run -s 0
qemu-system-x86_64 -enable-kvm -m 512M -object memory-backend-file,id=mem0,size=512M,mem-path=/dev/hugepages,share=on,prealloc=yes centos.qcow2 -device vfio-user-pci,socket=/var/run/cntrl -vnc :1

The first comment is run with SPDK 72a5fa139.

SPDK logs

[2023-08-29 11:14:23.747712] Starting SPDK v23.01.1 git sha1 186986c / DPDK 22.11.1 initialization...
[2023-08-29 11:14:23.747993] [ DPDK EAL parameters: spdk_tgt --no-shconf -c 0x2 --huge-unlink --log-level=lib.eal:6 --log-level=lib.cryptodev:5 --log-level=user1:6 --iova-mode=pa --base-virtaddr=0x200000000000 --match-allocations --file-prefix=spdk_pid16887 ]
TELEMETRY: No legacy callbacks, legacy socket not created
[2023-08-29 11:14:23.884289] app.c: 712:spdk_app_start: *NOTICE*: Total cores available: 1
[2023-08-29 11:14:23.979883] reactor.c: 926:reactor_run: *NOTICE*: Reactor started on core 1
[2023-08-29 11:14:24.087234] accel_sw.c: 681:sw_accel_module_init: *NOTICE*: Accel framework software module initialized.
[2023-08-29 11:14:24.150904] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 6 voluntary context switches and 5 involuntary context switches in the last second.
[2023-08-29 11:14:25.149918] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 1 voluntary context switches and 4 involuntary context switches in the last second.
[2023-08-29 11:14:26.148931] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 0 voluntary context switches and 1 involuntary context switches in the last second.
[2023-08-29 11:14:26.777932] vbdev_lvol.c:1404:_vbdev_lvs_examine_cb: *INFO*: Lvol store not found on Malloc0
[2023-08-29 11:14:27.147938] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 0 voluntary context switches and 1 involuntary context switches in the last second.
[2023-08-29 11:15:10.319449] vfio_user.c:2811:nvmf_vfio_user_prop_req_rsp_set: *ERROR*: /var/run/: failed to enable ctrlr
[2023-08-29 11:15:10.319505] vfio_user.c:1158:fail_ctrlr: *ERROR*: :/var/run/ failing controller
[2023-08-29 11:15:11.104364] reactor.c: 608:get_rusage: *INFO*: Reactor 1: 0 voluntary context switches and 1 involuntary context switches in the last second.

QEMU logs

The log file is quite large; you can use this OneDrive link https://1drv.ms/u/s!AlJabMSpbPfP7FLKVp43Tljx5LV_?e=Fxc3D3 to view it.

This one is run with SPDK v23.01.1. The error message has been modified with the version change.

image

The log with QEMU vfio-user-p3.1: https://1drv.ms/u/s!AlJabMSpbPfP7FN0kP25RS1La03y?e=JaC97Y

The logs with debug message of SPDK v23.05:

[2023-08-29 18:20:47.563005] Starting SPDK v23.05 git sha1 dfebd16 / DPDK 22.11.1 initialization...
[2023-08-29 18:20:47.563238] [ DPDK EAL parameters: spdk_tgt --no-shconf -c 0x2 --huge-unlink --log-level=lib.eal:6 --log-level=lib.cryptodev:5 --log-level=user1:6 --iova-mode=pa --base-virtaddr=0x200000000000 --match-allocations --file-prefix=spdk_pid10699 ]
TELEMETRY: No legacy callbacks, legacy socket not created
[2023-08-29 18:20:47.704510] app.c: 767:spdk_app_start: *NOTICE*: Total cores available: 1
[2023-08-29 18:20:47.846262] reactor.c: 937:reactor_run: *NOTICE*: Reactor started on core 1
[2023-08-29 18:20:47.980066] accel_sw.c: 603:sw_accel_module_init: *NOTICE*: Accel framework software module initialized.
[2023-08-29 18:21:31.559762] vfio_user.c:1305:nvmf_vfio_user_create: *DEBUG*: vfio_user transport: disable_mappable_bar0=0
[2023-08-29 18:21:31.559810] vfio_user.c:1307:nvmf_vfio_user_create: *DEBUG*: vfio_user transport: disable_adaptive_irq=0
[2023-08-29 18:21:31.559815] vfio_user.c:1309:nvmf_vfio_user_create: *DEBUG*: vfio_user transport: disable_shadow_doorbells=1
[2023-08-29 18:21:31.559835] vfio_user.c:4718:nvmf_vfio_user_poll_group_create: *DEBUG*: create poll group
[2023-08-29 18:21:32.176857] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: added PCI cap "Power Management" size=0x8 offset=0x40
[2023-08-29 18:21:32.176888] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: added PCI cap "PCI Express" size=0x3c offset=0x48
[2023-08-29 18:21:32.176894] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: added PCI cap "MSI-X" size=0xc offset=0x84
[2023-08-29 18:21:32.176909] vfio_user.c:4259:vfio_user_register_accept_poller: *DEBUG*: registering accept poller
[2023-08-29 18:21:40.509586] vfio_user.c:4663:nvmf_vfio_user_accept: *DEBUG*: attach succeeded
[2023-08-29 18:21:40.509613] vfio_user.c:4340:nvmf_vfio_user_create_ctrlr: *DEBUG*: /var/run/
[2023-08-29 18:21:40.509703] vfio_user.c:5204:nvmf_vfio_user_poll_group_add: *DEBUG*: /var/run/: add QP0=0x1d5f540(0x1d5f540) to poll_group=0x1d60560
[2023-08-29 18:21:40.509712] vfio_user.c:5241:nvmf_vfio_user_poll_group_add: *DEBUG*: /var/run/: sending connect fabrics command for qid:0 cntlid=0x1
[2023-08-29 18:21:40.520763] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:21:40.520783] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:21:40.520791] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:21:40.520799] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0, 0xa0000) offset=0 flags=0x3
[2023-08-29 18:21:40.520830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:21:40.521750] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:21:40.521757] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:21:40.521763] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:21:40.521768] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xc0000, 0xe0000) offset=0 flags=0x1
[2023-08-29 18:21:40.521781] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:21:40.522747] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:21:40.522754] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:21:40.522758] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:21:40.522763] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xe0000, 0x100000) offset=0 flags=0x1
[2023-08-29 18:21:40.522775] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:21:40.523747] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:21:40.523754] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:21:40.523758] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:21:40.523771] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0x100000, 0x40000000) offset=0 flags=0x3
[2023-08-29 18:21:40.523784] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:21:40.524745] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:21:40.524751] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:21:40.524755] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:21:40.524760] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xfffc0000, 0x100000000) offset=0 flags=0x1
[2023-08-29 18:21:40.524771] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:21:40.525746] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: devinfo flags 0x3, num_regions 10, num_irqs 5
[2023-08-29 18:21:40.526746] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[0] offset 0 flags 0x7 size 8192 argsz 64
[2023-08-29 18:21:40.527744] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: dev_get_caps: area 0 [0x1000, 0x2000)
[2023-08-29 18:21:40.527751] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[0] offset 0 flags 0xf size 8192 argsz 64
[2023-08-29 18:21:40.528743] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[1] offset 0 flags 0 size 0 argsz 32
[2023-08-29 18:21:40.529742] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[2] offset 0 flags 0 size 0 argsz 32
[2023-08-29 18:21:40.530743] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[3] offset 0 flags 0 size 0 argsz 32
[2023-08-29 18:21:40.531740] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[4] offset 0 flags 0x3 size 8192 argsz 32
[2023-08-29 18:21:40.532739] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[5] offset 0 flags 0x3 size 4096 argsz 32
[2023-08-29 18:21:40.536736] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[6] offset 0 flags 0 size 0 argsz 32
[2023-08-29 18:21:40.537737] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[7] offset 0 flags 0x3 size 4096 argsz 32
[2023-08-29 18:21:40.538734] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[8] offset 0 flags 0 size 0 argsz 32
[2023-08-29 18:21:40.539734] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[9] offset 0 flags 0x7 size 49152 argsz 80
[2023-08-29 18:21:40.540733] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: dev_get_caps: area 0 [0x1000, 0xc000)
[2023-08-29 18:21:40.540740] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region_info[9] offset 0 flags 0xf size 49152 argsz 80
[2023-08-29 18:21:40.542745] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 4096 bytes at 0
[2023-08-29 18:21:40.543731] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0x30:4)
[2023-08-29 18:21:40.544729] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: write mask to EROM ignored
[2023-08-29 18:21:40.544736] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xfffff800 to (0x30:4)
[2023-08-29 18:21:40.545728] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0x30:4)
[2023-08-29 18:21:40.546727] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: cleared EROM
[2023-08-29 18:21:40.546733] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x30:4)
[2023-08-29 18:21:40.547732] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0x10:4)
[2023-08-29 18:21:40.548731] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0x20:4)
[2023-08-29 18:21:40.549730] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0x24:4)
[2023-08-29 18:21:40.550730] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x1ff from (0x86:2)
[2023-08-29 18:21:40.551728] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x4 from (0x88:4)
[2023-08-29 18:21:40.552727] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x5 from (0x8c:4)
[2023-08-29 18:21:40.560721] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x1 from (0x3d:1)
[2023-08-29 18:21:40.561722] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x1 from (0x3d:1)
[2023-08-29 18:21:40.562721] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: setting IRQ INTx flags=0x24 range [0, 1)
[2023-08-29 18:21:40.562728] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: event fd[0]=463
[2023-08-29 18:21:40.563718] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: setting IRQ ERR flags=0x24 range [0, 1)
[2023-08-29 18:21:40.563725] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: event fd[0]=464
[2023-08-29 18:21:40.581705] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: disabling IRQ type INTx range [0, 1)
[2023-08-29 18:21:40.584701] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x8 from (0x44:2)
[2023-08-29 18:21:40.585699] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0x4:2)
[2023-08-29 18:21:40.586699] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x4:2)
[2023-08-29 18:21:40.587696] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:21:40.587703] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:21:40.587707] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:21:40.587712] vfio_user.c:3082:vfio_user_log: *INFO*: /var/run/: device reset by client
[2023-08-29 18:21:40.587722] vfio_user.c:3592:vfio_user_device_reset: *DEBUG*: Device reset type 0
[2023-08-29 18:21:40.587733] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:21:40.588697] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x1 from (0x3d:1)
[2023-08-29 18:21:40.589698] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: setting IRQ INTx flags=0x24 range [0, 1)
[2023-08-29 18:21:40.589705] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: event fd[0]=463
[2023-08-29 18:21:40.590695] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR0 addr 0x0
[2023-08-29 18:21:40.590701] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x10:4)
[2023-08-29 18:21:40.591694] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x14:4)
[2023-08-29 18:21:40.592693] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x18:4)
[2023-08-29 18:21:40.593692] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x1c:4)
[2023-08-29 18:21:40.594691] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR4 addr 0x0
[2023-08-29 18:21:40.594697] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x20:4)
[2023-08-29 18:21:40.595690] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR5 addr 0x0
[2023-08-29 18:21:40.595696] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x24:4)
[2023-08-29 18:22:20.777840] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.777877] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.777883] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.777889] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xc0000, 0xe0000) flags=0
[2023-08-29 18:22:20.777903] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.778829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.778835] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.778839] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.778844] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xe0000, 0x100000) flags=0
[2023-08-29 18:22:20.778862] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.779831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.779839] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.779843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.779848] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0x100000, 0x40000000) flags=0
[2023-08-29 18:22:20.779858] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.780830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.780836] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.780840] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.780845] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xc0000, 0xd0000) offset=0 flags=0x3
[2023-08-29 18:22:20.780859] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.781829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.781836] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.781840] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.781844] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xd0000, 0xe0000) offset=0 flags=0x1
[2023-08-29 18:22:20.781856] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.782828] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.782834] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.782838] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.782842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xe0000, 0xf0000) offset=0 flags=0x1
[2023-08-29 18:22:20.782853] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.783829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.783834] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.783838] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.783843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xf0000, 0x40000000) offset=0 flags=0x3
[2023-08-29 18:22:20.783854] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.784829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.784835] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.784839] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.784843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xc0000, 0xd0000) flags=0
[2023-08-29 18:22:20.784854] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.785829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.785835] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.785839] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.785843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xd0000, 0xe0000) flags=0
[2023-08-29 18:22:20.785854] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.786828] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.786839] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.786843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.786847] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xe0000, 0xf0000) flags=0
[2023-08-29 18:22:20.786858] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.787829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.787834] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.787838] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.787842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xf0000, 0x40000000) flags=0
[2023-08-29 18:22:20.787853] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.788829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.788834] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.788838] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.788843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xc0000, 0x40000000) offset=0 flags=0x3
[2023-08-29 18:22:20.788853] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.881839] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x4e58 from (0:2)
[2023-08-29 18:22:20.882829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x108 from (0xa:2)
[2023-08-29 18:22:20.883829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0xe:1)
[2023-08-29 18:22:20.885829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x4e58 from (0:2)
[2023-08-29 18:22:20.886829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x108 from (0xa:2)
[2023-08-29 18:22:20.887831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0xe:1)
[2023-08-29 18:22:20.890829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x4e58 from (0:2)
[2023-08-29 18:22:20.891829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x14e58 from (0:4)
[2023-08-29 18:22:20.892830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x1080200 from (0x8:4)
[2023-08-29 18:22:20.893829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0xe:1)
[2023-08-29 18:22:20.894829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0xe:1)
[2023-08-29 18:22:20.905831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR0 addr 0xffffffff
[2023-08-29 18:22:20.905840] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xffffffff to (0x10:4)
[2023-08-29 18:22:20.906830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR0 addr 0x0
[2023-08-29 18:22:20.906838] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x10:4)
[2023-08-29 18:22:20.907831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xffffffff to (0x14:4)
[2023-08-29 18:22:20.908830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x14:4)
[2023-08-29 18:22:20.909829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xffffffff to (0x18:4)
[2023-08-29 18:22:20.910829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x18:4)
[2023-08-29 18:22:20.911830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xffffffff to (0x1c:4)
[2023-08-29 18:22:20.912829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x1c:4)
[2023-08-29 18:22:20.913830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR4 addr 0xffffffff
[2023-08-29 18:22:20.913836] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xffffffff to (0x20:4)
[2023-08-29 18:22:20.914830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR4 addr 0x0
[2023-08-29 18:22:20.914836] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x20:4)
[2023-08-29 18:22:20.915829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR5 addr 0xffffffff
[2023-08-29 18:22:20.915835] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xffffffff to (0x24:4)
[2023-08-29 18:22:20.916829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR5 addr 0x0
[2023-08-29 18:22:20.916835] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x24:4)
[2023-08-29 18:22:20.917829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: write mask to EROM ignored
[2023-08-29 18:22:20.917836] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xfffff800 to (0x30:4)
[2023-08-29 18:22:20.918829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: cleared EROM
[2023-08-29 18:22:20.918835] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0 to (0x30:4)
[2023-08-29 18:22:20.925829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR0 addr 0xfebf0000
[2023-08-29 18:22:20.925837] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xfebf0000 to (0x10:4)
[2023-08-29 18:22:20.926829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR4 addr 0xfebf2000
[2023-08-29 18:22:20.926835] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xfebf2000 to (0x20:4)
[2023-08-29 18:22:20.927828] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: BAR5 addr 0xfebf5000
[2023-08-29 18:22:20.927834] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xfebf5000 to (0x24:4)
[2023-08-29 18:22:20.936829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.936838] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.936842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.936848] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xfd000000, 0xfe000000) offset=0 flags=0x3
[2023-08-29 18:22:20.936861] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.939829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x1 from (0x3d:1)
[2023-08-29 18:22:20.940830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: ILINE=b
[2023-08-29 18:22:20.940837] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0xb to (0x3c:1)
[2023-08-29 18:22:20.941830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0 from (0x4:2)
[2023-08-29 18:22:20.942829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: I/O space enabled
[2023-08-29 18:22:20.942836] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: memory space enabled
[2023-08-29 18:22:20.942841] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: SERR# enabled
[2023-08-29 18:22:20.942846] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0x103 to (0x4:2)
[2023-08-29 18:22:20.943829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.943836] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.943840] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.943844] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xfebf1000, 0xfebf2000) offset=0 flags=0x3
[2023-08-29 18:22:20.943855] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.947829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.947836] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.947840] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.947845] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0, 0xa0000) flags=0
[2023-08-29 18:22:20.947874] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.948829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.948835] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.948839] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.948843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xc0000, 0x40000000) flags=0
[2023-08-29 18:22:20.948854] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.949829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.949836] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.949840] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.949844] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0, 0x40000000) offset=0 flags=0x3
[2023-08-29 18:22:20.949857] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.954829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.954836] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.954840] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.954845] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0, 0x40000000) flags=0
[2023-08-29 18:22:20.954856] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.955829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.955835] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.955839] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.955844] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0, 0xa0000) offset=0 flags=0x3
[2023-08-29 18:22:20.955855] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.956829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:20.956834] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:20.956838] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:20.956842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xc0000, 0x40000000) offset=0 flags=0x3
[2023-08-29 18:22:20.956853] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:20.968830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x1 from (0x3d:1)
[2023-08-29 18:22:20.969830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0xb from (0x3c:1)
[2023-08-29 18:22:21.026833] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:21.026856] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:21.026861] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:21.026866] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xfebe0000, 0xfebf0000) offset=0 flags=0x1
[2023-08-29 18:22:21.026881] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:21.038828] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:21.038835] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:21.038839] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced immediately
[2023-08-29 18:22:21.038844] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xfebe0000, 0xfebf0000) flags=0
[2023-08-29 18:22:21.038863] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:21.394842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x103 from (0x4:2)
[2023-08-29 18:22:21.395832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0x103 to (0x4:2)
[2023-08-29 18:22:21.396846] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x10300 from (0x8:4)
[2023-08-29 18:22:21.397831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x1e0100ff from (0:4)
[2023-08-29 18:22:21.398830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x20 from (0x4:4)
[2023-08-29 18:22:21.399829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: read 0x103 from (0x4:2)
[2023-08-29 18:22:21.400830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: bus master enabled
[2023-08-29 18:22:21.400837] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region7: wrote 0x107 to (0x4:2)
[2023-08-29 18:22:21.401835] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: wrote 0 to (0x14:4)
[2023-08-29 18:22:21.402830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x20 from (0x4:4)
[2023-08-29 18:22:21.403830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x1e0100ff from (0:4)
[2023-08-29 18:22:21.404830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0 from (0x1c:4)
[2023-08-29 18:22:21.405829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x20 from (0x4:4)
[2023-08-29 18:22:21.406831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x1e0100ff from (0:4)
[2023-08-29 18:22:21.408830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: wrote 0xff003f to (0x24:4)
[2023-08-29 18:22:21.409830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: wrote 0x3ffdd000 to (0x28:4)
[2023-08-29 18:22:21.410829] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: wrote 0 to (0x2c:4)
[2023-08-29 18:22:21.411831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: wrote 0x3ffde000 to (0x30:4)
[2023-08-29 18:22:21.412834] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: wrote 0 to (0x34:4)
[2023-08-29 18:22:21.413831] vfio_user.c:2816:enable_ctrlr: *DEBUG*: /var/run/: enabling controller
[2023-08-29 18:22:21.413846] vfio_user.c:2856:nvmf_vfio_user_prop_req_rsp_set: *ERROR*: /var/run/: failed to enable ctrlr
[2023-08-29 18:22:21.413877] vfio_user.c:1126:fail_ctrlr: *ERROR*: :/var/run/ failing controller
[2023-08-29 18:22:21.413885] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: wrote 0x460001 to (0x14:4)
[2023-08-29 18:22:21.414831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x20 from (0x4:4)
[2023-08-29 18:22:21.415830] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x1e0100ff from (0:4)
[2023-08-29 18:22:21.416832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: region0: read 0x3 from (0x1c:4)
[2023-08-29 18:22:26.422853] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.422912] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.422921] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.422927] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.422940] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.422945] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.422950] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.422955] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xfeb80000, 0xfebc0000) offset=0 flags=0x1
[2023-08-29 18:22:26.422978] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.422982] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.423012] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.436832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.436839] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.436843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.436848] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.436854] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.436858] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.436863] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.436867] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xfeb80000, 0xfebc0000) flags=0
[2023-08-29 18:22:26.436881] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.436885] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.436891] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.515832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.515840] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.515845] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.515849] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.515855] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.515860] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.515864] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.515868] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xc0000, 0x40000000) flags=0
[2023-08-29 18:22:26.515880] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.515884] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.515890] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.516831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.516837] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.516841] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.516846] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.516851] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.516856] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.516860] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.516865] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xc0000, 0xcb000) offset=0 flags=0x1
[2023-08-29 18:22:26.516877] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.516881] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.516887] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.517832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.517838] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.517842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.517854] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.517860] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.517864] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.517868] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.517873] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xcb000, 0xce000) offset=0 flags=0x3
[2023-08-29 18:22:26.517884] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.517888] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.517894] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.518832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.518839] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.518843] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.518847] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.518852] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.518857] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.518861] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.518865] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xce000, 0xd0000) offset=0 flags=0x1
[2023-08-29 18:22:26.518876] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.518881] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.518886] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.519832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.519838] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.519842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.519846] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.519851] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.519856] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.519860] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.519864] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xd0000, 0xf0000) offset=0 flags=0x3
[2023-08-29 18:22:26.519875] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.519879] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.519885] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.520831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.520837] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.520841] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.520845] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.520850] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.520855] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.520859] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.520869] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xf0000, 0x100000) offset=0 flags=0x1
[2023-08-29 18:22:26.520880] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.520884] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.520890] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.521832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.521838] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.521842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.521846] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.521852] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.521856] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.521860] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.521865] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0x100000, 0x40000000) offset=0 flags=0x3
[2023-08-29 18:22:26.521876] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.521881] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.521887] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.523832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.523838] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.523842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.523847] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.523852] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.523857] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.523861] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.523865] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xce000, 0xd0000) flags=0
[2023-08-29 18:22:26.523876] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.523881] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.523886] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.524831] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.524836] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.524841] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.524845] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.524850] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.524855] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.524859] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.524863] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region [0xd0000, 0xf0000) flags=0
[2023-08-29 18:22:26.524875] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.524879] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.524885] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.525832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.525840] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.525844] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.525849] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.525854] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.525859] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.525863] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.525867] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xce000, 0xe8000) offset=0 flags=0x1
[2023-08-29 18:22:26.525880] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.525884] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.525890] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.526832] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: quiescing device
[2023-08-29 18:22:26.526838] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.526842] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device will quiesce asynchronously
[2023-08-29 18:22:26.526846] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.526852] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.526856] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.526860] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.526864] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: adding DMA region [0xe8000, 0xf0000) offset=0 flags=0x3
[2023-08-29 18:22:26.526876] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.526880] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.526886] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.761847] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: failed to receive request header: No message of desired type
[2023-08-29 18:22:26.761889] vfio_user.c:3082:vfio_user_log: *INFO*: /var/run/: vfu_reset_ctx: No message of desired type
[2023-08-29 18:22:26.761896] vfio_user.c:3336:vfio_user_dev_quiesce_cb: *DEBUG*: /var/run/ starts to quiesce
[2023-08-29 18:22:26.761904] vfio_user.c:3271:vfio_user_quiesce_pg: *DEBUG*: quiesced pg:0x1d60560
[2023-08-29 18:22:26.761916] vfio_user.c:3245:vfio_user_pause_done: *DEBUG*: /var/run/ pause done with status 0
[2023-08-29 18:22:26.761921] vfio_user.c:3204:vfio_user_quiesce_done: *DEBUG*: /var/run/ device quiesced
[2023-08-29 18:22:26.761926] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device quiesced with error=0
[2023-08-29 18:22:26.761932] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0xfffc0000, 0x100000000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.761937] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0xfd000000, 0xfe000000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.761942] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0xfebf1000, 0xfebf2000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.761946] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[(nil), 0xa0000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.761951] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0xc0000, 0xcb000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.761955] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0xcb000, 0xce000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.762001] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0xf0000, 0x100000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.762006] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0x100000, 0x40000000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.762010] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0xce000, 0xe8000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.762015] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: removing DMA region iova=[0xe8000, 0xf0000) vaddr=(nil) mapping=[(nil), (nil))
[2023-08-29 18:22:26.762019] vfio_user.c:3592:vfio_user_device_reset: *DEBUG*: Device reset type 1
[2023-08-29 18:22:26.762026] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: disabling IRQ type REQ range [0, 1)
[2023-08-29 18:22:26.762030] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: disabling IRQ type ERR range [0, 1)
[2023-08-29 18:22:26.762052] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: device unquiesced
[2023-08-29 18:22:26.762057] vfio_user.c:3220:vfio_user_quiesce_done: *DEBUG*: /var/run/ start to resume
[2023-08-29 18:22:26.762070] vfio_user.c:3182:vfio_user_endpoint_resume_done: *DEBUG*: /var/run/ resumed done with status 0
[2023-08-29 18:22:26.762834] vfio_user.c:3088:vfio_user_log: *ERROR*: /var/run/: tran_sock_get_request_header: not connected
[2023-08-29 18:22:26.762869] vfio_user.c:3088:vfio_user_log: *ERROR*: /var/run/: failed to receive request: Transport endpoint is not connected
[2023-08-29 18:22:26.762878] vfio_user.c:4862:vfio_user_destroy_ctrlr: *DEBUG*: /var/run/ stop processing
[2023-08-29 18:22:26.762887] vfio_user.c:5258:nvmf_vfio_user_poll_group_remove: *DEBUG*: /var/run/: remove NVMf QP0=0x1d5f540 from NVMf poll_group=0x1d60560
[2023-08-29 18:22:26.762891] vfio_user.c:1837:delete_sq_done: *DEBUG*: /var/run/: delete sqid:0=0x1d5f540 done
[2023-08-29 18:22:26.762906] vfio_user.c:1857:delete_sq_done: *DEBUG*: /var/run/: try to delete cqid:0=0x1d5f670
[2023-08-29 18:22:26.762911] vfio_user.c:4324:free_ctrlr: *DEBUG*: free /var/run/
[2023-08-29 18:22:26.762915] vfio_user.c:1879:free_qp: *DEBUG*: /var/run/: Free sqid:0
[2023-08-29 18:22:26.762919] vfio_user.c:1891:free_qp: *DEBUG*: /var/run/: Free cqid:0
[2023-08-29 18:22:26.762929] vfio_user.c:4259:vfio_user_register_accept_poller: *DEBUG*: registering accept poller
[2023-08-29 18:22:28.855088] vfio_user.c:4823:nvmf_vfio_user_poll_group_destroy: *DEBUG*: destroy poll group
[2023-08-29 18:22:28.855202] vfio_user.c:4549:nvmf_vfio_user_stop_listen: *DEBUG*: /var/run/: stop listen
[2023-08-29 18:22:28.855210] vfio_user.c:1146:nvmf_vfio_user_destroy_endpoint: *DEBUG*: destroy endpoint /var/run/
[2023-08-29 18:22:28.855267] vfio_user.c:3082:vfio_user_log: *INFO*: /var/run/: vfu_reset_ctx: Cannot send after transport endpoint shutdown
[2023-08-29 18:22:28.855275] vfio_user.c:3592:vfio_user_device_reset: *DEBUG*: Device reset type 1
[2023-08-29 18:22:28.855281] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: disabling IRQ type REQ range [0, 1)
[2023-08-29 18:22:28.855286] vfio_user.c:3080:vfio_user_log: *DEBUG*: /var/run/: disabling IRQ type ERR range [0, 1)
[2023-08-29 18:22:28.855310] vfio_user.c:1183:nvmf_vfio_user_destroy: *DEBUG*: destroy transport
tmakatos commented 11 months ago

@chen622 please use QEMU vfio-user-p3.1 and SPDK v23.05 from no own, the previous instructions were too old (I'm updating this here: https://github.com/nutanix/libvfio-user/pull/769).

I've tried this locally and it works, so not sure what's wrong on your side.

[2023-08-29 18:22:21.413831] vfio_user.c:2816:enable_ctrlr: *DEBUG*: /var/run/: enabling controller
[2023-08-29 18:22:21.413846] vfio_user.c:2856:nvmf_vfio_user_prop_req_rsp_set: *ERROR*: /var/run/: failed to enable ctrlr
[2023-08-29 18:22:21.413877] vfio_user.c:1126:fail_ctrlr: *ERROR*: :/var/run/ failing controller

Annoyingly the latest version doesn't report errno. Looking at the code, map_one is the prime suspect so it's probably the same erro as with the older code. Can you apply https://review.spdk.io/gerrit/c/spdk/spdk/+/19586 and try again?

chen622 commented 7 months ago

This could be a bug in QEMU specific to certain devices. I haven't encountered it again after switching to a different device.