The hotplug of a usb-c disk works well but com.canonical.certification::usb-c/insert test failed

[eugene-yujinwu]

Bug Description

We had a Kingshare Portable SSD type-c usb disk which used to test the usb-c disk tests. It works well before, but recently, the Checkbox will fail the com.canonical.certification::usb-c/insert test.

[Checkbox job com.canonical.certification::after-suspend-usb-c/insert output]

stdout

INSERT NOW

Timeout: 30 seconds

stderr

/bin/sh: 1: kill: Illegal number: -
Traceback (most recent call last):
File "/usr/bin/checkbox-support-run_watcher", line 8, in
sys.exit(main())
^^^^^^
File "/usr/lib/python3/dist-packages/checkbox_support/helpers/timeout.py", line 93, in _f
return run_with_timeout(f, timeout_s, *args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3/dist-packages/checkbox_support/helpers/timeout.py", line 78, in run_with_timeout
raise TimeoutError("Task unable to finish in {}s".format(timeout_s))
TimeoutError: Task unable to finish in 30s

To Reproduce

1.run commad: checkbox-cli run com.canonical.certification::usb-c/insert
2. Insert the Kingshare Portable SSD type-c usb disk

Environment

Image: canonical-oem-sutton-noble-oem-24.04b-proposed-20240723-3
system-manufacturer: LENOVO
system-product-name: 21M1SIT002
bios-version: R2NET18F (0.18 )
CPU: AMD Ryzen AI 7 PRO 160 w/ Radeon 870M (16x)
GPU: c2:00.0 Display controller [0380]: Advanced Micro Devices, Inc. [AMD/ATI] Device [1002:150e] (rev d2)
amd-vbios: 113-STRIXEMU-001["150E"]
kernel-version: 6.10.0-1005-oem

Relevant log output

Aug 27 12:23:56 Drift2-P-2 google-chrome.desktop[7386]: [451803:451839:0827/122356.519320:ERROR:connection_factory_impl.cc(483)] ConnectionHandler failed with net error: -2
Aug 27 12:24:58 Drift2-P-2 google-chrome.desktop[7386]: [451803:451839:0827/122458.362504:ERROR:connection_factory_impl.cc(483)] ConnectionHandler failed with net error: -2
Aug 27 12:25:01 Drift2-P-2 CRON[502388]: pam_unix(cron:session): session opened for user root(uid=0) by (uid=0)
Aug 27 12:25:01 Drift2-P-2 CRON[502389]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Aug 27 12:25:01 Drift2-P-2 CRON[502388]: pam_unix(cron:session): session closed for user root
Aug 27 12:26:00 Drift2-P-2 google-chrome.desktop[7386]: [451803:451839:0827/122600.220415:ERROR:connection_factory_impl.cc(483)] ConnectionHandler failed with net error: -2
Aug 27 12:27:01 Drift2-P-2 google-chrome.desktop[7386]: [451803:451839:0827/122701.956594:ERROR:connection_factory_impl.cc(483)] ConnectionHandler failed with net error: -2
Aug 27 12:28:03 Drift2-P-2 google-chrome.desktop[7386]: [451803:451839:0827/122803.698363:ERROR:connection_factory_impl.cc(483)] ConnectionHandler failed with net error: -2
Aug 27 12:28:26 Drift2-P-2 tracker-extract[501542]: Task for 'file:///home/eugene/Documents/WeChat%20Files/wxid_6mvu2pauiv8e21/FileStorage/Cache/2024-08/271de3568096491ad7f600675fc75a6d_t.jpg' finished with error: Could not get any metadata for uri:'file:///home/eugene/Documents/WeChat%20Files/wxid_6mvu2pauiv8e21/FileStorage/Cache/2024-08/271de3568096491ad7f600675fc75a6d_t.jpg' and mime:'image/jpeg'
Aug 27 12:28:26 Drift2-P-2 tracker-extract-3[501542]: Not a JPEG file: starts with 0x89 0x50

Aug 27 12:29:03 Drift2-P-2 kernel: usb 4-1: new SuperSpeed Plus Gen 2x1 USB device number 47 using xhci_hcd
Aug 27 12:29:03 Drift2-P-2 kernel: usb 4-1: New USB device found, idVendor=2109, idProduct=0715, bcdDevice= 0.00
Aug 27 12:29:03 Drift2-P-2 kernel: usb 4-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Aug 27 12:29:03 Drift2-P-2 kernel: usb 4-1: Product: VLI Product String
Aug 27 12:29:03 Drift2-P-2 kernel: usb 4-1: Manufacturer: VLI Manufacture String
Aug 27 12:29:03 Drift2-P-2 kernel: usb 4-1: SerialNumber: 000000123E12
Aug 27 12:29:03 Drift2-P-2 kernel: scsi host0: uas
Aug 27 12:29:03 Drift2-P-2 kernel: scsi 0:0:0:0: Direct-Access     KINGSHAR KSP6120S         2210 PQ: 0 ANSI: 6
Aug 27 12:29:03 Drift2-P-2 mtp-probe[502529]: checking bus 4, device 47: "/sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:2b:00.0/usb4/4-1"
Aug 27 12:29:03 Drift2-P-2 mtp-probe[502529]: bus: 4, device: 47 was not an MTP device
Aug 27 12:29:03 Drift2-P-2 kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0
Aug 27 12:29:03 Drift2-P-2 kernel: sd 0:0:0:0: [sda] 234441648 512-byte logical blocks: (120 GB/112 GiB)
Aug 27 12:29:03 Drift2-P-2 kernel: sd 0:0:0:0: [sda] Write Protect is off
Aug 27 12:29:03 Drift2-P-2 kernel: sd 0:0:0:0: [sda] Mode Sense: 2f 00 00 00
Aug 27 12:29:03 Drift2-P-2 kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Aug 27 12:29:03 Drift2-P-2 kernel: sd 0:0:0:0: [sda] Preferred minimum I/O size 4096 bytes
Aug 27 12:29:03 Drift2-P-2 kernel: sd 0:0:0:0: [sda] Optimal transfer size 33553920 bytes not a multiple of preferred minimum block size (4096 bytes)
Aug 27 12:29:03 Drift2-P-2 kernel:  sda: sda1
Aug 27 12:29:03 Drift2-P-2 kernel: sd 0:0:0:0: [sda] Attached SCSI disk
Aug 27 12:29:03 Drift2-P-2 audit[321237]: AVC apparmor="DENIED" operation="open" class="file" profile="snap.notepad-plus-plus.notepad-plus-plus" name="/sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:2b:00.0/usb4/4-1/busnum" pid=321237 comm="winedevice.exe" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
Aug 27 12:29:03 Drift2-P-2 kernel: audit: type=1400 audit(1724732943.640:851): apparmor="DENIED" operation="open" class="file" profile="snap.notepad-plus-plus.notepad-plus-plus" name="/sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:2b:00.0/usb4/4-1/busnum" pid=321237 comm="winedevice.exe" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
Aug 27 12:29:03 Drift2-P-2 boltd[1725]: probing: started [1000]
Aug 27 12:29:03 Drift2-P-2 mtp-probe[502546]: checking bus 4, device 47: "/sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:2b:00.0/usb4/4-1"
Aug 27 12:29:03 Drift2-P-2 mtp-probe[502546]: bus: 4, device: 47 was not an MTP device
Aug 27 12:29:03 Drift2-P-2 audit[321237]: AVC apparmor="DENIED" operation="open" class="file" profile="snap.notepad-plus-plus.notepad-plus-plus" name="/sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:2b:00.0/usb4/4-1/busnum" pid=321237 comm="winedevice.exe" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
Aug 27 12:29:03 Drift2-P-2 kernel: audit: type=1400 audit(1724732943.652:852): apparmor="DENIED" operation="open" class="file" profile="snap.notepad-plus-plus.notepad-plus-plus" name="/sys/devices/pci0000:00/0000:00:1c.4/0000:03:00.0/0000:04:02.0/0000:2b:00.0/usb4/4-1/busnum" pid=321237 comm="winedevice.exe" requested_mask="r" denied_mask="r" fsuid=1000 ouid=0
Aug 27 12:29:03 Drift2-P-2 systemd-udevd[502550]: sda: Process '/usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/sda' failed with exit code 1.
Aug 27 12:29:03 Drift2-P-2 systemd-udevd[502522]: sda1: Process '/usr/bin/unshare -m /usr/bin/snap auto-import --mount=/dev/sda1' failed with exit code 1.
Aug 27 12:29:03 Drift2-P-2 kernel: EXT4-fs (sda1): recovery complete
Aug 27 12:29:03 Drift2-P-2 kernel: EXT4-fs (sda1): mounted filesystem d23cfa8e-8a2c-485e-9236-ede097eb3090 r/w with ordered data mode. Quota mode: none.
Aug 27 12:29:03 Drift2-P-2 udisksd[1677]: Mounted /dev/sda1 at /media/eugene/u on behalf of uid 1000
Aug 27 12:29:03 Drift2-P-2 dbus-daemon[2953]: [session uid=1000 pid=2953] Activating service name='org.gnome.Shell.HotplugSniffer' requested by ':1.39' (uid=1000 pid=3327 comm="/usr/bin/gnome-shell " label="unconfined")
Aug 27 12:29:03 Drift2-P-2 dbus-daemon[2953]: [session uid=1000 pid=2953] Successfully activated service 'org.gnome.Shell.HotplugSniffer'
Aug 27 12:29:05 Drift2-P-2 google-chrome.desktop[7386]: [451803:451839:0827/122905.404627:ERROR:connection_factory_impl.cc(483)] ConnectionHandler failed with net error: -2
Aug 27 12:29:06 Drift2-P-2 boltd[1725]: probing: timeout, done: [2868135] (2000000)
Aug 27 12:29:15 Drift2-P-2 dbus-daemon[1636]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.23306' (uid=1000 pid=468614 comm="/usr/bin/nautilus --gapplication-service " label="unconfined")
Aug 27 12:29:15 Drift2-P-2 systemd[1]: Starting Hostname Service...
Aug 27 12:29:15 Drift2-P-2 gnome-shell[3327]: Can't update stage views actor <unnamed>[<MetaWindowGroup>:0x601fe9b642f0] is on because it needs an allocation.
Aug 27 12:29:15 Drift2-P-2 gnome-shell[3327]: Can't update stage views actor <unnamed>[<MetaWindowActorX11>:0x601fee4fb6f0] is on because it needs an allocation.
Aug 27 12:29:15 Drift2-P-2 gnome-shell[3327]: Can't update stage views actor <unnamed>[<MetaSurfaceActorX11>:0x601fe9ebcde0] is on because it needs an allocation.
Aug 27 12:29:15 Drift2-P-2 dbus-daemon[1636]: [system] Successfully activated service 'org.freedesktop.hostname1'
Aug 27 12:29:15 Drift2-P-2 systemd[1]: Started Hostname Service.
Aug 27 12:29:17 Drift2-P-2 gnome-shell[3327]: Can't update stage views actor <unnamed>[<MetaWindowGroup>:0x601fe9b642f0] is on because it needs an allocation.
Aug 27 12:29:17 Drift2-P-2 gnome-shell[3327]: Can't update stage views actor <unnamed>[<MetaWindowActorX11>:0x601fee4fb6f0] is on because it needs an allocation.
Aug 27 12:29:17 Drift2-P-2 gnome-shell[3327]: Can't update stage views actor <unnamed>[<MetaSurfaceActorX11>:0x601fe9ebcde0] is on because it needs an allocation.

Additional context

No response

[syncronize-issues-to-jira]

Thank you for reporting us your feedback!

The internal ticket has been created: https://warthogs.atlassian.net/browse/CHECKBOX-1545.

This message was autogenerated

[pieqq]

Can you please try the following:

1. In a terminal, launch a shell inside the Checkbox snap: checkbox.shell
2. Open another terminal, and output the journal logs: sudo journalctl -f
3. In the first terminal (the Checkbox shell), launch the USB insert test: checkbox-support-run_watcher insertion usb3
4. Wait for INSERT NOW and insert the USB drive
5. If it doesn't work, share the output from sudo journalctl -f

Also, can you try the same command with a USB-A drive and/or another USB-C USB stick?

Thanks,

[eugene-yujinwu]

@pieqq hi, I think I had find the root cause of this issue. This USB-c disks is a usb3.2 device with uas driver, it doesn't covered by the run_watcher.py. I will try to fix it and submit a PR for it. Thanks!