Proxmox Backup Server is unstable

[EllyMae]

I'm running PBS 3.0-1 in a VM under PVE 8.0.4. I'm trying to run a days-long backup, but after a few days, PBS crashes in the middle of the night. There are no messages in Syslog -- just an abrupt end of the messages produced by the backup followed by the messages produced by the bootup that I initiated.

I need some guidance documenting this so that I can report the problem on Bugzilla.

Thanks.

 

[dcsapak]

are there any messages in the hosts syslog? are there any other tasks running concurrently? gc/verify/etc. ? whats the vm config?

 

[EllyMae]

Thank you so much for the quick reply.

I've attached a snippet of the host's syslog at the time the VM crashed. I don't know how to interpret it, but it seems that it might be a hardware error. (??)

Noting the SMART messages, the Disks display shows that all the disks "pass" SMART. Same goes for PBS which has it's disks passed-through PVE to PBS. Both are running ZFS, and the zpool statuses on both are clean.

 

[dcsapak]

mhmm... a segfault indicates some kind of corruption:

* faulty memory (i'd do a memtest)
* faulty disk -> corrupt files (check the disks via smart (you did already) and check your installed packages with the 'debsums' tool; you have to install it via apt probably)
* faulty cpu (not really an easy way to check this, besides replacing it)
* bug in the program (with only a segfault it's hard to debug and only worth it if you mostly ruled out the underlying hardware)

 

[EllyMae]

Ok. Preparing for the memtest. I'll be back.

Thanks.

 

[EllyMae]

I ran memtest for a few hours, and it didn't find anything untoward. But, I've read that memtest doesn't really put enough load on the system to catch many problems.

Then I read that segfault is just as likely to be caused by programming error. So, I decided to go down that street. First, I went back to PBS version 2. After putting a load on it for a couple of hours, it crashed again.

Then, I went back to PVE version 7. (Remember, I'm running PBS as a VM under PVE.) PBS has been running a heavy load for nearly a full day.

So, I'm going to mark this as solved. But I think Proxmox has a bit of work to do.

 

[dcsapak]

mhmm so it is not really solved...

if you could, would you mind trying to reproduce it once again, and posting the output of 'pveversion -v' and the version of the libc ? e.g. with 'dpkg -l | grep libc6'

with that info we can try see what exactly fails and check where is the bug

EDIT: or you can install systemd-coredump and post the crashdump or
attach to the process with gdb and get a backtrace (if that's possible for you)

 

[EllyMae]

The problem has evolved somewhat.

I think something might be going on with ZFS. Current situation: I backed up the PBS storage device that I'm having trouble. I used ZFS SEND/RECV to get into another pool that is managed by PVE, not PBS. Then I destroyed the PBS pool and rebuilt it in ZFS. Now I am trying to copy the data back using the same method. I can see the disks being busy, and htop show lots of data being transferred. (I have a few ssh sessions going so that I can try to keep an eye on things.) After around 20 GB to 30 GB, PBS becomes unresponsive and will soon crash. Its VM simply shuts down.

I have put V3 of PBS back in; I don't know why. It didn't make any difference.

PVE is still running at V7.

In the PVE syslog, this one message appears:
QEMU[2536599]: kvm: ../hw/usb/core.c:563: usb_packet_check_state: Assertion `!"usb packet state check failed"' failed.

After that, PVE proceeds to shut down PBS.

I can't tell if this is hardware or software. PBS's syslog still shows an abrupt reboot message with no indication that anything unusual is happening.

All five disks are USB-pass-throughed to PBS. There are no other USB devices on the machine.

There is a new 5-bay USB dock from Sabrent. https://sabrent.com/products/ds-sc5b. I've reported the problem to Sabrent, thinking I have a bad dock. They want me to take it all apart, change out different disk drive that I don't have and can't afford, and run it on Windows which isn't going to happen.

I've had another one of these docks for a year, and thought I'd get another one. Both of them are populated with five WD Red Plus 10 TB drives. The two docks are identical except one is managed by PVE and the other is managed by PBS (under PVE).

I thought the problem was in the USB HBA that I'm using. So, I tried plugging the dock into a motherboard USB port. That didn't help. Besides, PVE is using the same HBA without any problem.

Here is information per your prior request. These were taken from the PVE V7 system that I'm currently running.

root@leghorn:~# pveversion -v
proxmox-ve: 7.4-1 (running kernel: 5.15.126-1-pve)
pve-manager: 7.4-17 (running version: 7.4-17/513c62be)
pve-kernel-5.15: 7.4-7
pve-kernel-5.15.126-1-pve: 5.15.126-1
pve-kernel-5.15.102-1-pve: 5.15.102-1
ceph-fuse: 15.2.17-pve1
corosync: 3.1.7-pve1
criu: 3.15-1+pve-1
glusterfs-client: 9.2-1
ifupdown2: 3.1.0-1+pmx4
ksm-control-daemon: 1.4-1
libjs-extjs: 7.0.0-1
libknet1: 1.24-pve2
libproxmox-acme-perl: 1.4.4
libproxmox-backup-qemu0: 1.3.1-1
libproxmox-rs-perl: 0.2.1
libpve-access-control: 7.4.1
libpve-apiclient-perl: 3.2-1
libpve-common-perl: 7.4-2
libpve-guest-common-perl: 4.2-4
libpve-http-server-perl: 4.2-3
libpve-rs-perl: 0.7.7
libpve-storage-perl: 7.4-3
libspice-server1: 0.14.3-2.1
lvm2: 2.03.11-2.1
lxc-pve: 5.0.2-2
lxcfs: 5.0.3-pve1
novnc-pve: 1.4.0-1
proxmox-backup-client: 2.4.3-1
proxmox-backup-file-restore: 2.4.3-1
proxmox-kernel-helper: 7.4-1
proxmox-mail-forward: 0.1.1-1
proxmox-mini-journalreader: 1.3-1
proxmox-widget-toolkit: 3.7.3
pve-cluster: 7.3-3
pve-container: 4.4-6
pve-docs: 7.4-2
pve-edk2-firmware: 3.20230228-4~bpo11+1
pve-firewall: 4.3-5
pve-firmware: 3.6-6
pve-ha-manager: 3.6.1
pve-i18n: 2.12-1
pve-qemu-kvm: 7.2.0-8
pve-xtermjs: 4.16.0-2
qemu-server: 7.4-4
smartmontools: 7.2-pve3
spiceterm: 3.2-2
swtpm: 0.8.0~bpo11+3
vncterm: 1.7-1
zfsutils-linux: 2.1.11-pve1
root@leghorn:~#

root@leghorn:~# dpkg -l | grep libc6~
root@leghorn:~# apt list libc6*
Listing... Done
libc6-amd64-cross/oldstable 2.31-9cross4 all
libc6-amd64-i386-cross/oldstable 2.31-9cross4 all
libc6-amd64-x32-cross/oldstable 2.31-9cross4 all
libc6-arm64-cross/oldstable 2.31-9cross4 all
libc6-armel-cross/oldstable 2.31-9cross4 all
libc6-armhf-cross/oldstable 2.31-9cross4 all
libc6-dbg/oldstable-security 2.31-13+deb11u7 amd64
libc6-dev-amd64-cross/oldstable 2.31-9cross4 all
libc6-dev-amd64-i386-cross/oldstable 2.31-9cross4 all
libc6-dev-amd64-x32-cross/oldstable 2.31-9cross4 all
libc6-dev-arm64-cross/oldstable 2.31-9cross4 all
libc6-dev-armel-cross/oldstable 2.31-9cross4 all
libc6-dev-armhf-cross/oldstable 2.31-9cross4 all
libc6-dev-hppa-cross/oldstable 2.31-9cross4 all
libc6-dev-i386-amd64-cross/oldstable 2.31-9cross4 all
libc6-dev-i386-cross/oldstable 2.31-9cross4 all
libc6-dev-i386-x32-cross/oldstable 2.31-9cross4 all
libc6-dev-i386/oldstable-security 2.31-13+deb11u7 amd64
libc6-dev-m68k-cross/oldstable 2.31-9cross4 all
libc6-dev-mips-cross/oldstable 2.31-11cross1 all
libc6-dev-mips32-mips64-cross/oldstable 2.31-11cross1 all
libc6-dev-mips32-mips64el-cross/oldstable 2.31-11cross1 all
libc6-dev-mips32-mips64r6-cross/oldstable 2.31-11cross1 all
libc6-dev-mips32-mips64r6el-cross/oldstable 2.31-11cross1 all
libc6-dev-mips32-mipsn32-cross/oldstable 2.31-11cross1 all
libc6-dev-mips32-mipsn32el-cross/oldstable 2.31-11cross1 all
libc6-dev-mips32-mipsn32r6-cross/oldstable 2.31-11cross1 all
libc6-dev-mips32-mipsn32r6el-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-mips-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-mipsel-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-mipsn32-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-mipsn32el-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-mipsn32r6-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-mipsn32r6el-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-mipsr6-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64-mipsr6el-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64el-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64r6-cross/oldstable 2.31-11cross1 all
libc6-dev-mips64r6el-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsel-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-mips-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-mips64-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-mips64el-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-mips64r6-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-mips64r6el-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-mipsel-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-mipsr6-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32-mipsr6el-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32el-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32r6-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsn32r6el-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsr6-cross/oldstable 2.31-11cross1 all
libc6-dev-mipsr6el-cross/oldstable 2.31-11cross1 all
libc6-dev-powerpc-cross/oldstable 2.31-9cross4 all
libc6-dev-powerpc-ppc64-cross/oldstable 2.31-9cross4 all
libc6-dev-ppc64-cross/oldstable 2.31-9cross4 all
libc6-dev-ppc64-powerpc-cross/oldstable 2.31-9cross4 all
libc6-dev-ppc64el-cross/oldstable 2.31-9cross4 all
libc6-dev-riscv64-cross/oldstable 2.31-9cross4 all
libc6-dev-s390-s390x-cross/oldstable 2.31-9cross4 all
libc6-dev-s390x-cross/oldstable 2.31-9cross4 all
libc6-dev-sh4-cross/oldstable 2.31-9cross4 all
libc6-dev-sparc-sparc64-cross/oldstable 2.31-9cross4 all
libc6-dev-sparc64-cross/oldstable 2.31-9cross4 all
libc6-dev-x32-amd64-cross/oldstable 2.31-9cross4 all
libc6-dev-x32-cross/oldstable 2.31-9cross4 all
libc6-dev-x32-i386-cross/oldstable 2.31-9cross4 all
libc6-dev-x32/oldstable-security 2.31-13+deb11u7 amd64
libc6-dev/oldstable-security 2.31-13+deb11u7 amd64
libc6-hppa-cross/oldstable 2.31-9cross4 all
libc6-i386-amd64-cross/oldstable 2.31-9cross4 all
libc6-i386-cross/oldstable 2.31-9cross4 all
libc6-i386-x32-cross/oldstable 2.31-9cross4 all
libc6-i386/oldstable-security 2.31-13+deb11u7 amd64
libc6-m68k-cross/oldstable 2.31-9cross4 all
libc6-mips-cross/oldstable 2.31-11cross1 all
libc6-mips32-mips64-cross/oldstable 2.31-11cross1 all
libc6-mips32-mips64el-cross/oldstable 2.31-11cross1 all
libc6-mips32-mips64r6-cross/oldstable 2.31-11cross1 all
libc6-mips32-mips64r6el-cross/oldstable 2.31-11cross1 all
libc6-mips32-mipsn32-cross/oldstable 2.31-11cross1 all
libc6-mips32-mipsn32el-cross/oldstable 2.31-11cross1 all
libc6-mips32-mipsn32r6-cross/oldstable 2.31-11cross1 all
libc6-mips32-mipsn32r6el-cross/oldstable 2.31-11cross1 all
libc6-mips64-cross/oldstable 2.31-11cross1 all
libc6-mips64-mips-cross/oldstable 2.31-11cross1 all
libc6-mips64-mipsel-cross/oldstable 2.31-11cross1 all
libc6-mips64-mipsn32-cross/oldstable 2.31-11cross1 all
libc6-mips64-mipsn32el-cross/oldstable 2.31-11cross1 all
libc6-mips64-mipsn32r6-cross/oldstable 2.31-11cross1 all
libc6-mips64-mipsn32r6el-cross/oldstable 2.31-11cross1 all
libc6-mips64-mipsr6-cross/oldstable 2.31-11cross1 all
libc6-mips64-mipsr6el-cross/oldstable 2.31-11cross1 all
libc6-mips64el-cross/oldstable 2.31-11cross1 all
libc6-mips64r6-cross/oldstable 2.31-11cross1 all
libc6-mips64r6el-cross/oldstable 2.31-11cross1 all
libc6-mipsel-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-mips-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-mips64-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-mips64el-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-mips64r6-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-mips64r6el-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-mipsel-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-mipsr6-cross/oldstable 2.31-11cross1 all
libc6-mipsn32-mipsr6el-cross/oldstable 2.31-11cross1 all
libc6-mipsn32el-cross/oldstable 2.31-11cross1 all
libc6-mipsn32r6-cross/oldstable 2.31-11cross1 all
libc6-mipsn32r6el-cross/oldstable 2.31-11cross1 all
libc6-mipsr6-cross/oldstable 2.31-11cross1 all
libc6-mipsr6el-cross/oldstable 2.31-11cross1 all
libc6-powerpc-cross/oldstable 2.31-9cross4 all
libc6-powerpc-ppc64-cross/oldstable 2.31-9cross4 all
libc6-ppc64-cross/oldstable 2.31-9cross4 all
libc6-ppc64-powerpc-cross/oldstable 2.31-9cross4 all
libc6-ppc64el-cross/oldstable 2.31-9cross4 all
libc6-riscv64-cross/oldstable 2.31-9cross4 all
libc6-s390-s390x-cross/oldstable 2.31-9cross4 all
libc6-s390x-cross/oldstable 2.31-9cross4 all
libc6-sh4-cross/oldstable 2.31-9cross4 all
libc6-sparc-sparc64-cross/oldstable 2.31-9cross4 all
libc6-sparc64-cross/oldstable 2.31-9cross4 all
libc6-x32-amd64-cross/oldstable 2.31-9cross4 all
libc6-x32-cross/oldstable 2.31-9cross4 all
libc6-x32-i386-cross/oldstable 2.31-9cross4 all
libc6-x32/oldstable-security 2.31-13+deb11u7 amd64
libc6.1-alpha-cross/oldstable 2.31-9cross4 all
libc6.1-dev-alpha-cross/oldstable 2.31-9cross4 all
libc6/oldstable-security,now 2.31-13+deb11u7 amd64 [installed]
root@leghorn:~#

 

[EllyMae]

root@leghorn:~# dpkg -l | grep libc6
ii  libc6:amd64                          2.31-13+deb11u7                amd64        GNU C Library: Shared libraries
root@leghorn:~#

 

[fiona]

Hi,

In the PVE syslog, this one message appears:
QEMU[2536599]: kvm: ../hw/usb/core.c:563: usb_packet_check_state: Assertion `!"usb packet state check failed"' failed.

that is an assertion failure in the USB subsystem in QEMU, meaning it encountered an unexpected situation and aborted because of it. Could you share the VM configuration?

I can't tell if this is hardware or software. PBS's syslog still shows an abrupt reboot message with no indication that anything unusual is happening.

All five disks are USB-pass-throughed to PBS. There are no other USB devices on the machine.

There is a new 5-bay USB dock from Sabrent. https://sabrent.com/products/ds-sc5b. I've reported the problem to Sabrent, thinking I have a bad dock. They want me to take it all apart, change out different disk drive that I don't have and can't afford, and run it on Windows which isn't going to happen.

I've had another one of these docks for a year, and thought I'd get another one. Both of them are populated with five WD Red Plus 10 TB drives. The two docks are identical except one is managed by PVE and the other is managed by PBS (under PVE).

I thought the problem was in the USB HBA that I'm using. So, I tried plugging the dock into a motherboard USB port. That didn't help. Besides, PVE is using the same HBA without any problem.

It's likely related to the USB passthrough, but the question remains if it's a QEMU bug or hardware issue or if QEMU could handle the error more gracefully. To get a more complete picture, you can attach GDB to the VM with

gdb --ex 'set pagination off' --ex 'handle SIGUSR1 noprint nostop' --ex 'handle SIGPIPE noprint nostop' --ex 'c' -p $(cat /var/run/qemu-server/<put your VMID here>.pid)

(replacing <put your VMID here> with the actual ID) before the crash and then when the crash happens, type thread apply all backtrace in the GDB session.

EDIT: there also is a tracepoint in QEMU before the assertion, so you can use

qm set <ID> --args '-trace usb_packet_state_fault,file=/tmp/usb-fault.log'

(needs to be done before starting the VM). QEMU will create a log file /tmp/usb-fault.log which should contain a bit more information about the state after the crash happened.

 

[EllyMae]

Fiona, thanks for that plan. I'll use it if necessary. I know you're trying your best to debug this.

Before I read your reply, I began the process of trying out something different. I woke up this morning with the thought that it might not be a good idea to run ZFS in a VM with passed-through disks. So, I decided to go the more traditional route. I have:

1. removed the pass-throughs from the PBS VM.
2. imported the PBS pool in PVE
3. defined a virtual disk in the PBS VM that has almost all the available space given in zfs list.
   Now, PVE is managing both of the ZFS pools.

I am currently in the process of using scp to copy the backed up data that is in the PVE ZFS pool to the EXT4 filesystem (new virtual disk) inside of PBS. It's moving along smoothly so far. We are at 472 GB out of a total of 12.3 TB. That's the farthest I've gotten so far. Keeping my figures crossed.

After this copy, I will be running zpool scrub on the PBS pool, and also a full verify of the newly-copied datastore on PBS. (Actually, there are two datastores, and a bunch of data that are not in datastores.)

If I run into problems with this process, I'll be continuing with the debugging with you.

Thanks again for your ongoing help!

 

[EllyMae]

Well, after all of that, it turned out that the problem was still happening, but with different symptoms. But I think I've finally found and fixed the problem. I'm giving it more time, in case it comes back after 24 hours, like the last time. I'll be back soon with the details. Power on.

 

[blablazzz]

What

Well, after all of that, it turned out that the problem was still happening, but with different symptoms. But I think I've finally found and fixed the problem. I'm giving it more time, in case it comes back after 24 hours, like the last time. I'll be back soon with the details. Power on.

What was the fix? I have very similar problem.

 

[_gabriel]

zfs on smr hdd over usb can't be stable.

 

[black0ut]

I have the exact same issue. I'm also trying to use the Sabrent DS-SC5B external disk station via USB passthrough in a VM with a ZFS pool managed inside the VM.

Since there's no answer from EllyMae about the fix, I could share some more information.

Here's the full gdb backtrace:

Thread 23 (Thread 0x7241536006c0 (LWP 137078) "vnc_worker"):
#0  __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x61d8d0114cfc) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x61d8d0114cfc, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0, cancel=cancel@entry=true) at ./nptl/futex-internal.c:87
#2  0x0000724d7f2d9efb in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x61d8d0114cfc, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0) at ./nptl/futex-internal.c:139
#3  0x0000724d7f2dc558 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x61d8d0114d08, cond=0x61d8d0114cd0) at ./nptl/pthread_cond_wait.c:503
#4  ___pthread_cond_wait (cond=0x61d8d0114cd0, mutex=0x61d8d0114d08) at ./nptl/pthread_cond_wait.c:618
#5  0x000061d8cdb1fdeb in ?? ()
#6  0x000061d8cd5abf2b in ?? ()
#7  0x000061d8cd5acbc8 in ?? ()
#8  0x000061d8cdb1f2d8 in ?? ()
#9  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#10 0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 22 (Thread 0x72415e4006c0 (LWP 137076) "SPICE Worker"):
#0  0x0000724d7f35015f in __GI___poll (fds=0x7240f80024e0, nfds=2, timeout=2147483647) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x0000724d80d3e9ae in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#2  0x0000724d80d3ecef in g_main_loop_run () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#3  0x0000724d81470fa9 in ?? () from /lib/x86_64-linux-gnu/libspice-server.so.1
#4  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#5  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 21 (Thread 0x72415f2006c0 (LWP 137075) "libusb_event"):
#0  0x0000724d7f35015f in __GI___poll (fds=0x72415f1fb0e0, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x0000724d812f0497 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#2  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#3  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 20 (Thread 0x724164a006c0 (LWP 137073) "CPU 15/KVM"):
#0  __GI___ioctl (fd=58, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 19 (Thread 0x7241654006c0 (LWP 137072) "CPU 14/KVM"):
#0  __GI___ioctl (fd=56, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 18 (Thread 0x724165e006c0 (LWP 137071) "CPU 13/KVM"):
#0  __GI___ioctl (fd=54, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 17 (Thread 0x7241668006c0 (LWP 137070) "CPU 12/KVM"):
#0  __GI___ioctl (fd=52, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 16 (Thread 0x7241672006c0 (LWP 137069) "CPU 11/KVM"):
#0  __GI___ioctl (fd=50, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 15 (Thread 0x724167c006c0 (LWP 137068) "CPU 10/KVM"):
#0  __GI___ioctl (fd=48, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 14 (Thread 0x724d70c006c0 (LWP 137067) "CPU 9/KVM"):
#0  __GI___ioctl (fd=46, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 13 (Thread 0x724d716006c0 (LWP 137066) "CPU 8/KVM"):
#0  __GI___ioctl (fd=44, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 12 (Thread 0x724d720006c0 (LWP 137065) "CPU 7/KVM"):
#0  __GI___ioctl (fd=42, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 11 (Thread 0x724d72a006c0 (LWP 137064) "CPU 6/KVM"):
#0  __GI___ioctl (fd=40, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 10 (Thread 0x724d734006c0 (LWP 137063) "CPU 5/KVM"):
#0  __GI___ioctl (fd=38, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 9 (Thread 0x724d73e006c0 (LWP 137062) "CPU 4/KVM"):
#0  __GI___ioctl (fd=36, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 8 (Thread 0x724d78a006c0 (LWP 137061) "CPU 3/KVM"):
#0  __GI___ioctl (fd=34, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 7 (Thread 0x724d794006c0 (LWP 137060) "CPU 2/KVM"):
#0  __GI___ioctl (fd=32, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 6 (Thread 0x724d79e006c0 (LWP 137059) "CPU 1/KVM"):
#0  futex_wait (private=0, expected=2, futex_word=0x61d8ce45be40) at ../sysdeps/nptl/futex-internal.h:146
#1  __GI___lll_lock_wait (futex=futex@entry=0x61d8ce45be40, private=0) at ./nptl/lowlevellock.c:49
#2  0x0000724d7f2e03c2 in lll_mutex_lock_optimized (mutex=0x61d8ce45be40) at ./nptl/pthread_mutex_lock.c:48
#3  ___pthread_mutex_lock (mutex=0x61d8ce45be40) at ./nptl/pthread_mutex_lock.c:93
#4  0x000061d8cdb1f6b3 in ?? ()
#5  0x000061d8cd785ac6 in ?? ()
#6  0x000061d8cd932829 in ?? ()
#7  0x000061d8cd932953 in ?? ()
#8  0x000061d8cd932c9e in ?? ()
#9  0x000061d8cd985e06 in ?? ()
#10 0x000061d8cd98708d in ?? ()
#11 0x000061d8cdb1f2d8 in ?? ()
#12 0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#13 0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 5 (Thread 0x724d7ae006c0 (LWP 137058) "CPU 0/KVM"):
#0  __GI___ioctl (fd=28, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 4 (Thread 0x724d7c707500 (LWP 137057) "vhost-136976"):
#0  0x0000000000000000 in ?? ()
Backtrace stopped: Cannot access memory at address 0x0

Thread 3 (Thread 0x724d7b8006c0 (LWP 136978) "kvm"):
#0  0x0000724d7f350256 in __ppoll (fds=0x724d6c003280, nfds=20, timeout=<optimized out>, sigmask=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:42
#1  0x000061d8cdb1cc89 in ?? ()
#2  0x000061d8cdb1c17d in ?? ()
#3  0x000061d8cd9c8af6 in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 2 (Thread 0x724d7c2006c0 (LWP 136977) "call_rcu"):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x000061d8cdb2045a in ?? ()
#2  0x000061d8cdb29d62 in ?? ()
#3  0x000061d8cdb1f2d8 in ?? ()
#4  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#5  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 1 (Thread 0x724d7c707500 (LWP 136976) "kvm"):
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1  0x0000724d7f2dee8f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  0x0000724d7f28ffb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x0000724d7f27a472 in __GI_abort () at ./stdlib/abort.c:79
#4  0x0000724d7f27a395 in __assert_fail_base (fmt=0x724d7f3eea90 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x61d8cdc81758 "!\"usb packet state check failed\"", file=file@entry=0x61d8cdc81583 "../hw/usb/core.c", line=line@entry=563, function=function@entry=0x61d8cdc81b20 "usb_packet_check_state") at ./assert/assert.c:92
#5  0x0000724d7f288eb2 in __GI___assert_fail (assertion=0x61d8cdc81758 "!\"usb packet state check failed\"", file=0x61d8cdc81583 "../hw/usb/core.c", line=563, function=0x61d8cdc81b20 "usb_packet_check_state") at ./assert/assert.c:101
#6  0x000061d8cd721c6f in ?? ()
#7  0x000061d8cd722a2b in ?? ()
#8  0x000061d8cd814ffd in ?? ()
#9  0x0000724d812e8e95 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#10 0x0000724d812ef2f4 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#11 0x0000724d812f00a2 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#12 0x0000724d812e883a in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#13 0x0000724d812e9d78 in libusb_handle_events_timeout_completed () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#14 0x000061d8cd811d4b in ?? ()
#15 0x000061d8cdb1b7eb in ?? ()
#16 0x000061d8cdb1c042 in ?? ()
#17 0x000061d8cdb3148e in ?? ()
#18 0x0000724d80d3e7a9 in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#19 0x000061d8cdb32ef8 in ?? ()
#20 0x000061d8cd78faa7 in ?? ()
#21 0x000061d8cd98ff46 in ?? ()
#22 0x0000724d7f27b24a in __libc_start_call_main (main=main@entry=0x61d8cd580480 <main>, argc=argc@entry=104, argv=argv@entry=0x7ffd38100ad8) at ../sysdeps/nptl/libc_start_call_main.h:58
#23 0x0000724d7f27b305 in __libc_start_main_impl (main=0x61d8cd580480 <main>, argc=104, argv=0x7ffd38100ad8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffd38100ac8) at ../csu/libc-start.c:360
#24 0x000061d8cd5820a1 in ?? ()

and furthermore here's the trace from QEMU:

usb_packet_state_fault bus 1, port 5, ep 0, packet 0x72410c009588, state complete, expected async
kvm: ../hw/usb/core.c:563: usb_packet_check_state: Assertion `!"usb packet state check failed"' failed.

To trigger the error I only need to put some IO-load (> 500mb/s) on the disks, everything below this threshold works for me.

Maybe someone could assist fixing this.

PS: I'm not trying to use PBS in a VM, I'm trying to use TrueNAS scale as the VMs OS.

best regards

 

[fiona]

Hi,

I have the exact same issue. I'm also trying to use the Sabrent DS-SC5B external disk station via USB passthrough in a VM with a ZFS pool managed inside the VM.

Since there's no answer from EllyMae about the fix, I could share some more information.

Here's the full gdb backtrace:

Thread 23 (Thread 0x7241536006c0 (LWP 137078) "vnc_worker"):
#0  __futex_abstimed_wait_common64 (private=0, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x61d8d0114cfc) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x61d8d0114cfc, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0, cancel=cancel@entry=true) at ./nptl/futex-internal.c:87
#2  0x0000724d7f2d9efb in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x61d8d0114cfc, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=0) at ./nptl/futex-internal.c:139
#3  0x0000724d7f2dc558 in __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x61d8d0114d08, cond=0x61d8d0114cd0) at ./nptl/pthread_cond_wait.c:503
#4  ___pthread_cond_wait (cond=0x61d8d0114cd0, mutex=0x61d8d0114d08) at ./nptl/pthread_cond_wait.c:618
#5  0x000061d8cdb1fdeb in ?? ()
#6  0x000061d8cd5abf2b in ?? ()
#7  0x000061d8cd5acbc8 in ?? ()
#8  0x000061d8cdb1f2d8 in ?? ()
#9  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#10 0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 22 (Thread 0x72415e4006c0 (LWP 137076) "SPICE Worker"):
#0  0x0000724d7f35015f in __GI___poll (fds=0x7240f80024e0, nfds=2, timeout=2147483647) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x0000724d80d3e9ae in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#2  0x0000724d80d3ecef in g_main_loop_run () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#3  0x0000724d81470fa9 in ?? () from /lib/x86_64-linux-gnu/libspice-server.so.1
#4  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#5  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 21 (Thread 0x72415f2006c0 (LWP 137075) "libusb_event"):
#0  0x0000724d7f35015f in __GI___poll (fds=0x72415f1fb0e0, nfds=2, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29
#1  0x0000724d812f0497 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#2  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#3  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 20 (Thread 0x724164a006c0 (LWP 137073) "CPU 15/KVM"):
#0  __GI___ioctl (fd=58, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 19 (Thread 0x7241654006c0 (LWP 137072) "CPU 14/KVM"):
#0  __GI___ioctl (fd=56, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 18 (Thread 0x724165e006c0 (LWP 137071) "CPU 13/KVM"):
#0  __GI___ioctl (fd=54, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 17 (Thread 0x7241668006c0 (LWP 137070) "CPU 12/KVM"):
#0  __GI___ioctl (fd=52, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 16 (Thread 0x7241672006c0 (LWP 137069) "CPU 11/KVM"):
#0  __GI___ioctl (fd=50, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 15 (Thread 0x724167c006c0 (LWP 137068) "CPU 10/KVM"):
#0  __GI___ioctl (fd=48, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 14 (Thread 0x724d70c006c0 (LWP 137067) "CPU 9/KVM"):
#0  __GI___ioctl (fd=46, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 13 (Thread 0x724d716006c0 (LWP 137066) "CPU 8/KVM"):
#0  __GI___ioctl (fd=44, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 12 (Thread 0x724d720006c0 (LWP 137065) "CPU 7/KVM"):
#0  __GI___ioctl (fd=42, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 11 (Thread 0x724d72a006c0 (LWP 137064) "CPU 6/KVM"):
#0  __GI___ioctl (fd=40, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 10 (Thread 0x724d734006c0 (LWP 137063) "CPU 5/KVM"):
#0  __GI___ioctl (fd=38, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 9 (Thread 0x724d73e006c0 (LWP 137062) "CPU 4/KVM"):
#0  __GI___ioctl (fd=36, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 8 (Thread 0x724d78a006c0 (LWP 137061) "CPU 3/KVM"):
#0  __GI___ioctl (fd=34, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 7 (Thread 0x724d794006c0 (LWP 137060) "CPU 2/KVM"):
#0  __GI___ioctl (fd=32, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 6 (Thread 0x724d79e006c0 (LWP 137059) "CPU 1/KVM"):
#0  futex_wait (private=0, expected=2, futex_word=0x61d8ce45be40) at ../sysdeps/nptl/futex-internal.h:146
#1  __GI___lll_lock_wait (futex=futex@entry=0x61d8ce45be40, private=0) at ./nptl/lowlevellock.c:49
#2  0x0000724d7f2e03c2 in lll_mutex_lock_optimized (mutex=0x61d8ce45be40) at ./nptl/pthread_mutex_lock.c:48
#3  ___pthread_mutex_lock (mutex=0x61d8ce45be40) at ./nptl/pthread_mutex_lock.c:93
#4  0x000061d8cdb1f6b3 in ?? ()
#5  0x000061d8cd785ac6 in ?? ()
#6  0x000061d8cd932829 in ?? ()
#7  0x000061d8cd932953 in ?? ()
#8  0x000061d8cd932c9e in ?? ()
#9  0x000061d8cd985e06 in ?? ()
#10 0x000061d8cd98708d in ?? ()
#11 0x000061d8cdb1f2d8 in ?? ()
#12 0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#13 0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 5 (Thread 0x724d7ae006c0 (LWP 137058) "CPU 0/KVM"):
#0  __GI___ioctl (fd=28, request=44672) at ../sysdeps/unix/sysv/linux/ioctl.c:36
#1  0x000061d8cd9856cf in ?? ()
#2  0x000061d8cd985ba5 in ?? ()
#3  0x000061d8cd98708d in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 4 (Thread 0x724d7c707500 (LWP 137057) "vhost-136976"):
#0  0x0000000000000000 in ?? ()
Backtrace stopped: Cannot access memory at address 0x0

Thread 3 (Thread 0x724d7b8006c0 (LWP 136978) "kvm"):
#0  0x0000724d7f350256 in __ppoll (fds=0x724d6c003280, nfds=20, timeout=<optimized out>, sigmask=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:42
#1  0x000061d8cdb1cc89 in ?? ()
#2  0x000061d8cdb1c17d in ?? ()
#3  0x000061d8cd9c8af6 in ?? ()
#4  0x000061d8cdb1f2d8 in ?? ()
#5  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#6  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 2 (Thread 0x724d7c2006c0 (LWP 136977) "call_rcu"):
#0  syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38
#1  0x000061d8cdb2045a in ?? ()
#2  0x000061d8cdb29d62 in ?? ()
#3  0x000061d8cdb1f2d8 in ?? ()
#4  0x0000724d7f2dd134 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#5  0x0000724d7f35d7dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 1 (Thread 0x724d7c707500 (LWP 136976) "kvm"):
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1  0x0000724d7f2dee8f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  0x0000724d7f28ffb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x0000724d7f27a472 in __GI_abort () at ./stdlib/abort.c:79
#4  0x0000724d7f27a395 in __assert_fail_base (fmt=0x724d7f3eea90 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x61d8cdc81758 "!\"usb packet state check failed\"", file=file@entry=0x61d8cdc81583 "../hw/usb/core.c", line=line@entry=563, function=function@entry=0x61d8cdc81b20 "usb_packet_check_state") at ./assert/assert.c:92
#5  0x0000724d7f288eb2 in __GI___assert_fail (assertion=0x61d8cdc81758 "!\"usb packet state check failed\"", file=0x61d8cdc81583 "../hw/usb/core.c", line=563, function=0x61d8cdc81b20 "usb_packet_check_state") at ./assert/assert.c:101
#6  0x000061d8cd721c6f in ?? ()
#7  0x000061d8cd722a2b in ?? ()
#8  0x000061d8cd814ffd in ?? ()
#9  0x0000724d812e8e95 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#10 0x0000724d812ef2f4 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#11 0x0000724d812f00a2 in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#12 0x0000724d812e883a in ?? () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#13 0x0000724d812e9d78 in libusb_handle_events_timeout_completed () from /lib/x86_64-linux-gnu/libusb-1.0.so.0
#14 0x000061d8cd811d4b in ?? ()
#15 0x000061d8cdb1b7eb in ?? ()
#16 0x000061d8cdb1c042 in ?? ()
#17 0x000061d8cdb3148e in ?? ()
#18 0x0000724d80d3e7a9 in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#19 0x000061d8cdb32ef8 in ?? ()
#20 0x000061d8cd78faa7 in ?? ()
#21 0x000061d8cd98ff46 in ?? ()
#22 0x0000724d7f27b24a in __libc_start_call_main (main=main@entry=0x61d8cd580480 <main>, argc=argc@entry=104, argv=argv@entry=0x7ffd38100ad8) at ../sysdeps/nptl/libc_start_call_main.h:58
#23 0x0000724d7f27b305 in __libc_start_main_impl (main=0x61d8cd580480 <main>, argc=104, argv=0x7ffd38100ad8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffd38100ac8) at ../csu/libc-start.c:360
#24 0x000061d8cd5820a1 in ?? ()

and furthermore here's the trace from QEMU:

usb_packet_state_fault bus 1, port 5, ep 0, packet 0x72410c009588, state complete, expected async
kvm: ../hw/usb/core.c:563: usb_packet_check_state: Assertion `!"usb packet state check failed"' failed.

To trigger the error I only need to put some IO-load (> 500mb/s) on the disks, everything below this threshold works for me.

Maybe someone could assist fixing this.

PS: I'm not trying to use PBS in a VM, I'm trying to use TrueNAS scale as the VMs OS.

best regards

unfortunately, it seems you didn't have the necessary debug symbols installed, so there's a lot of question marks in the backtrace. You need pve-qemu-kvm-dbsym and also libusb-1.0-0-dbgsym the latter of which can be obtained like described here: https://wiki.debian.org/HowToGetABacktrace

 

[black0ut]

Hi fiona,

thank you for your quick response. Sorry about the missing debug symbols.

I installed the missing packages, there are still some question marks left, but in Thread 1, where the actual "USB packet state check fails" are located is no more question mark left. I shortened the output to what I think is useful for the analytics, because the forum doesn't let me post this much characters.

Here's the gdb output for further analytics:

Thread 1 (Thread 0x740b867e9500 (LWP 165407) "kvm"):
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1  0x0000740b896dee8f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
#2  0x0000740b8968ffb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x0000740b8967a472 in __GI_abort () at ./stdlib/abort.c:79
#4  0x0000740b8967a395 in __assert_fail_base (fmt=0x740b897eea90 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x5d2c21028758 "!\"usb packet state check failed\"", file=file@entry=0x5d2c21028583 "../hw/usb/core.c", line=line@entry=563, function=function@entry=0x5d2c21028b20 <__PRETTY_FUNCTION__.8> "usb_packet_check_state") at ./assert/assert.c:92
#5  0x0000740b89688eb2 in __GI___assert_fail (assertion=assertion@entry=0x5d2c21028758 "!\"usb packet state check failed\"", file=file@entry=0x5d2c21028583 "../hw/usb/core.c", line=line@entry=563, function=function@entry=0x5d2c21028b20 <__PRETTY_FUNCTION__.8> "usb_packet_check_state") at ./assert/assert.c:101
#6  0x00005d2c20ac8c6f in usb_packet_check_state (p=p@entry=0x73ff1c02ea38, expected=expected@entry=USB_PACKET_ASYNC) at ../hw/usb/core.c:563
#7  0x00005d2c20ac9a2b in usb_packet_complete (dev=0x5d2c24ef4190, p=p@entry=0x73ff1c02ea38) at ../hw/usb/core.c:490
#8  0x00005d2c20bbbffd in usb_host_req_complete_data (xfer=<optimized out>) at ../hw/usb/host-libusb.c:490
#9  0x0000740b8b3b3e95 in usbi_handle_transfer_completion (itransfer=itransfer@entry=0x73ff1cc133e0, status=LIBUSB_TRANSFER_COMPLETED) at ../../libusb/io.c:1716
#10 0x0000740b8b3ba2f4 in handle_bulk_completion (urb=0x73ff1cbd6110, itransfer=0x73ff1cc133e0) at ../../libusb/os/linux_usbfs.c:2468
#11 reap_for_handle (handle=handle@entry=0x5d2c23af2560) at ../../libusb/os/linux_usbfs.c:2682
#12 0x0000740b8b3bb0a2 in op_handle_events (ctx=0x5d2c24eeb840, event_data=0x5d2c23af2660, count=5, num_ready=0) at ../../libusb/os/linux_usbfs.c:2748
#13 0x0000740b8b3b383a in handle_events (ctx=ctx@entry=0x5d2c24eeb840, tv=tv@entry=0x7ffe32e4cf10) at ../../libusb/io.c:2274
#14 0x0000740b8b3b4d78 in libusb_handle_events_timeout_completed (ctx=0x5d2c24eeb840, tv=tv@entry=0x7ffe32e4cf70, completed=completed@entry=0x0) at ../../libusb/io.c:2361
#15 0x0000740b8b3b4da7 in libusb_handle_events_timeout (ctx=<optimized out>, tv=tv@entry=0x7ffe32e4cf70) at ../../libusb/io.c:2414
#16 0x00005d2c20bb8d4b in usb_host_handle_fd (opaque=<optimized out>) at ../hw/usb/host-libusb.c:241
#17 0x00005d2c20ec27eb in aio_dispatch_handler (ctx=ctx@entry=0x5d2c23258650, node=0x5d2c23af2690) at ../util/aio-posix.c:382
#18 0x00005d2c20ec3042 in aio_dispatch_handlers (ctx=0x5d2c23258650) at ../util/aio-posix.c:414
#19 aio_dispatch (ctx=0x5d2c23258650) at ../util/aio-posix.c:424
#20 0x00005d2c20ed848e in aio_ctx_dispatch (source=<optimized out>, callback=<optimized out>, user_data=<optimized out>) at ../util/async.c:358
#21 0x0000740b8b0587a9 in g_main_dispatch (context=0x5d2c23266150) at ../../../glib/gmain.c:3454
#22 g_main_context_dispatch (context=context@entry=0x5d2c23266150) at ../../../glib/gmain.c:4172
#23 0x00005d2c20ed9ef8 in glib_pollfds_poll () at ../util/main-loop.c:290
#24 os_host_main_loop_wait (timeout=70896729) at ../util/main-loop.c:313
#25 main_loop_wait (nonblocking=nonblocking@entry=0) at ../util/main-loop.c:592
#26 0x00005d2c20b36aa7 in qemu_main_loop () at ../softmmu/runstate.c:732
#27 0x00005d2c20d36f46 in qemu_default_main () at ../softmmu/main.c:37
#28 0x0000740b8967b24a in __libc_start_call_main (main=main@entry=0x5d2c20927480 <main>, argc=argc@entry=104, argv=argv@entry=0x7ffe32e4d2a8) at ../sysdeps/nptl/libc_start_call_main.h:58
#29 0x0000740b8967b305 in __libc_start_main_impl (main=0x5d2c20927480 <main>, argc=104, argv=0x7ffe32e4d2a8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffe32e4d298) at ../csu/libc-start.c:360
#30 0x00005d2c209290a1 in _start ()

best regards

 

[fiona]

The expected state is async, but the packet actually has complete.

In hw/usb/core.c: usb_handle_packet() (reference) there's one place where the complete state is set:

            /*
             * When pipelining is enabled usb-devices must always return async,
             * otherwise packets can complete out of order!
             */
            assert(p->stream || !p->ep->pipeline ||
                   QTAILQ_EMPTY(&p->ep->queue));
            if (p->status != USB_RET_NAK) {
                usb_pcap_data(p, false);
                usb_packet_set_state(p, USB_PACKET_COMPLETE);
            }

AFAICT, the only other place where the complete state is set is usb_packet_complete_one(). That function in turn is only called by usb_packet_complete() after the state check, so we can rule those out, and by usb_combined_input_packet_complete(). I'm not sure usb_packet_complete() can be called for such a packet though (as that path is taken in your backtrace).

I'm just guessing, but maybe your device somehow ends up triggering two of those completion paths or similar, violating some assumption QEMU devs made.

You might also want to add a trace for the tracepoint usb_packet_state_change (or even trace the wildcard usb_* to get the full picture), maybe seeing the state history helps and you might also want to report the issue upstream. I'm very much not familiar with the USB code and we do not make any modifications there. Upstream maintainers can tell you more and maybe there is a way turn the assert into a non-fatal error report instead (but that'll require understanding what exactly goes wrong first).