Librem 14 Camera Sporadically Disconnecting from VMs

oijawyuh · July 16, 2022, 5:26am

I increased sys-usb RAM from 300MB to 1024MB and it solved this problem for me. See:

github.com/QubesOS/qubes-issues

stub_rx page allocation failure in sys-usb when using a webcam attached to separate qube

opened 09:26AM - 15 Nov 20 UTC

closed 04:12AM - 28 Jan 23 UTC

icequbes1

T: bug C: core P: default r4.1-dom0-stable diagnosed r4.2-host-cur-test

**Qubes OS version** R4.0, `current` repo, dom0 and VM kernels on kernel-latest…, 5.8.16-1. Edit: all qubes mentioned are Fedora 32 **Affected component(s) or functionality** app-linux-input-proxy, salt formulas, or perhaps documentation **Brief summary** A USB webcam hosted by sys-usb that was attached to another qube resulted in a kernel error within sys-usb once video streaming began. Increasing the (default) amount of memory allocated to sys-usb resolved the issue. **How Reproducible** 100% consistent with the webcam in question and sys-usb at 300MB of non-balanced memory. **To Reproduce** Steps to reproduce the behavior: 1. Start sys-usb 2. Attach the webcam using the devices widget to a qube 3. Run `cheese` to begin video preview **Expected behavior** Video acquisition can be seen in the `cheese` preview window. **Actual behavior** 1. A black window is seen in `cheese` saying connection lost, no video is streamed 2. Webcam light remains active. 3. A kernel "page allocation failure" is observed in the kernel log 4. The devices widget shows the webcam is no longer connected to the qube. 5. The webcam remains in a bad state until an unload/load of `xhci_pci` within sys-usb is performed. **Additional context** When executing `cheese` within sys-usb (eliminating usbip/usb-proxy), there is no error and video is streamed properly. The bad behavior is only observed when the USB device is proxied to another qube. My assumption is that while this scenario could potentially be specific to the camera I use, I don't think it's out of the ordinary to assume other users may run into similar issues. dmesg log of sys-usb once `cheese` starts in the other qube: ``` [ 668.497111] usbip-host 1-2.1: unlinked by a call to usb_unlink_urb() [ 668.653607] usbip-host 1-2.1: unlinked by a call to usb_unlink_urb() [ 668.849225] usbip-host 1-2.1: usb_set_interface done: inf 1 alt 11 [ 668.853039] stub_rx: page allocation failure: order:5, mode:0x40dc0(GFP_KERNEL|__GFP_COMP|__GFP_ZERO), nodemask=(null),cpuset=/,mems_allowed=0 [ 668.853102] CPU: 1 PID: 2079 Comm: stub_rx Tainted: G O 5.8.16-1.qubes.x86_64 #1 [ 668.853138] Hardware name: Xen HVM domU, BIOS 4.8.5-26.fc25 11/11/2020 [ 668.853163] Call Trace: [ 668.853192] dump_stack+0x6d/0x8b [ 668.853211] warn_alloc+0x123/0x190 [ 668.853231] __alloc_pages_slowpath.constprop.110+0xd84/0xe20 [ 668.853257] ? printk+0x63/0x7f [ 668.853277] __alloc_pages_nodemask+0x2e4/0x350 [ 668.853303] kmalloc_order+0x18/0x70 [ 668.853329] kmalloc_order_trace+0x1d/0xa0 [ 668.853361] stub_recv_cmd_submit+0x16d/0xbf0 [usbip_host] [ 668.853394] stub_rx_loop+0x243/0x300 [usbip_host] [ 668.853427] ? stub_recv_cmd_submit+0xbf0/0xbf0 [usbip_host] [ 668.853469] kthread+0xfc/0x130 [ 668.853495] ? kthread_associate_blkcg+0x90/0x90 [ 668.853522] ret_from_fork+0x22/0x30 [ 668.853594] Mem-Info: [ 668.853622] active_anon:4203 inactive_anon:3929 isolated_anon:0 active_file:4906 inactive_file:6686 isolated_file:0 unevictable:1695 dirty:630 writeback:0 slab_reclaimable:6616 slab_unreclaimable:11566 mapped:7764 shmem:16 pagetables:1201 bounce:0 free:1593 free_pcp:10 free_cma:0 [ 668.853749] Node 0 active_anon:16812kB inactive_anon:15716kB active_file:19624kB inactive_file:26744kB unevictable:6780kB isolated(anon):0kB isolated(file):0kB mapped:31056kB dirty:2520kB writeback:0kB shmem:64kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB all_unreclaimable? no [ 668.853848] Node 0 DMA free:2336kB min:132kB low:164kB high:196kB reserved_highatomic:0KB active_anon:516kB inactive_anon:572kB active_file:692kB inactive_file:912kB unevictable:100kB writepending:52kB present:15992kB managed:15908kB mlocked:100kB kernel_stack:400kB pagetables:516kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB [ 668.853957] lowmem_reserve[]: 0 201 201 201 201 [ 668.853979] Node 0 DMA32 free:4036kB min:1748kB low:2184kB high:2620kB reserved_highatomic:2048KB active_anon:16296kB inactive_anon:15144kB active_file:18792kB inactive_file:25852kB unevictable:6680kB writepending:2452kB present:274396kB managed:205140kB mlocked:6680kB kernel_stack:3212kB pagetables:4288kB bounce:0kB free_pcp:40kB local_pcp:0kB free_cma:0kB [ 668.854093] lowmem_reserve[]: 0 0 0 0 0 [ 668.854110] Node 0 DMA: 175*4kB (UE) 80*8kB (UE) 33*16kB (UE) 11*32kB (UE) 2*64kB (UE) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2348kB [ 668.854170] Node 0 DMA32: 341*4kB (UMEH) 118*8kB (UMEH) 23*16kB (UMH) 9*32kB (H) 11*64kB (H) 2*128kB (H) 1*256kB (H) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4180kB [ 668.854279] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB [ 668.854327] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB [ 668.854373] 14403 total pagecache pages [ 668.854402] 2765 pages in swap cache [ 668.854422] Swap cache stats: add 160045, delete 157280, find 66226/97693 [ 668.854456] Free swap = 920060kB [ 668.854476] Total swap = 1048572kB [ 668.854492] 72597 pages RAM [ 668.854503] 0 pages HighMem/MovableOnly [ 668.854517] 17335 pages reserved [ 668.854532] 0 pages cma reserved [ 668.854546] 0 pages hwpoisoned [ 668.854997] usbip-host 1-2.1: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection [ 668.855254] usbip-host 1-2.1: stopped by a call to usb_kill_urb() because of cleaning up a virtual connection ``` dmesg within qube with attached cam at the point `cheese` is run: ``` [ 5950.838024] vhci_hcd: unlink->seqnum 503 [ 5950.838060] vhci_hcd: urb->status -104 [ 5950.994516] vhci_hcd: unlink->seqnum 510 [ 5950.994546] vhci_hcd: urb->status -104 [ 5951.195819] vhci_hcd: connection closed [ 5951.195972] vhci_hcd: stop threads [ 5951.196013] vhci_hcd: release socket [ 5951.196033] vhci_hcd: disconnect device [ 5951.196162] usb 1-1: USB disconnect, device number 9 (cheese:6530): cheese-WARNING **: 00:23:48.480: Could not read from resource.: gstv4l2bufferpool.c(1126): gst_v4l2_buffer_pool_poll (): /GstCameraBin:camerabin/GstWrapperCameraBinSrc:camera_source/GstBin:bin35/GstV4l2Src:v4l2src1: poll error 1: Invalid argument (22) ``` **Solutions you've tried** By default the sys-usb salt formula specifies 300MB of memory. After raising sys-usb to 1024MB, the issue was no longer observed. One simple solution may be documentation instructing users to raise the amount of memory for sys-usb (within online docs or a popup within the devices widget?). Another option is to raise the default amount of memory allocated to sys-usb in the salt formulas (/srv/formulas/base/virtual-machines-formula/qvm/sys-usb.sls) from 300MB to some higher number. I did not do a binary search to figure out the minimum. **Relevant [documentation](https://www.qubes-os.org/doc/) you've consulted** https://www.qubes-os.org/doc/usb-devices/ **Related, [non-duplicate](https://www.qubes-os.org/doc/reporting-bugs/#new-issues-should-not-be-duplicates-of-existing-issues) issues** - #2681 seems most related, as it is a paging request kernel BUG, but against R3.2 - #2594 - #3778 - #4035