On Wed, 2020-07-15 at 19:03 +0200, David Guillen Fandos wrote: > On Wed, 2020-07-15 at 14:24 +0200, Greg KH wrote: > > On Wed, Jul 15, 2020 at 01:20:54PM +0200, David Guillen Fandos > > wrote: > > > On Wed, 2020-07-15 at 13:12 +0200, Greg KH wrote: > > > > On Wed, Jul 15, 2020 at 12:57:14PM +0200, David Guillen Fandos > > > > wrote: > > > > > On Wed, 2020-07-15 at 12:50 +0200, Greg KH wrote: > > > > > > On Wed, Jul 15, 2020 at 12:31:42PM +0200, David Guillen > > > > > > Fandos > > > > > > wrote: > > > > > > > On Wed, 2020-07-15 at 11:30 +0200, Greg KH wrote: > > > > > > > > On Wed, Jul 15, 2020 at 10:58:03AM +0200, David Guillen > > > > > > > > Fandos > > > > > > > > wrote: > > > > > > > > > Hello linux-usb, > > > > > > > > > > > > > > > > > > I think I might have found a kernel bug related to > > > > > > > > > the > > > > > > > > > USB > > > > > > > > > subsystem > > > > > > > > > (cdc_acm perhaps). > > > > > > > > > > > > > > > > > > Context: I was playing around with a device I'm > > > > > > > > > creating, > > > > > > > > > essentially a > > > > > > > > > USB quad modem device that exposes four modems to the > > > > > > > > > host > > > > > > > > > system. > > > > > > > > > This > > > > > > > > > device is still a prototype so there's a few bugs > > > > > > > > > here > > > > > > > > > and > > > > > > > > > there, > > > > > > > > > most > > > > > > > > > likely in the USB descriptors and control requests. > > > > > > > > > > > > > > > > > > What happens: After plugging the device the system > > > > > > > > > starts > > > > > > > > > spitting > > > > > > > > > warnings and BUGs and it locks up. Most of the time > > > > > > > > > some > > > > > > > > > CPUs > > > > > > > > > get > > > > > > > > > into > > > > > > > > > some spinloop and never comes back (you can see it > > > > > > > > > being > > > > > > > > > detected > > > > > > > > > by > > > > > > > > > the watchdog after a few seconds). Generally after > > > > > > > > > that > > > > > > > > > the > > > > > > > > > USB > > > > > > > > > devices > > > > > > > > > stop working completely and at some point the machine > > > > > > > > > freezes > > > > > > > > > completely. In a couple of ocasions I managed to see > > > > > > > > > a > > > > > > > > > bug > > > > > > > > > in > > > > > > > > > dmesg > > > > > > > > > saying "unable to handle page fault for address XXX" > > > > > > > > > and > > > > > > > > > "Supervisor > > > > > > > > > read access in kernel mode" "error code (0x0000) not > > > > > > > > > present > > > > > > > > > page". > > > > > > > > > I > > > > > > > > > could not get a trace for that one since the kernel > > > > > > > > > died > > > > > > > > > completely > > > > > > > > > and > > > > > > > > > my log files were truncated/lost. > > > > > > > > > > > > > > > > > > Since it is happening to my two machines (both Intel > > > > > > > > > but > > > > > > > > > rather > > > > > > > > > different controllers, Sunrise Point-LP USB 3.0 vs 8 > > > > > > > > > Series/C220) > > > > > > > > > and > > > > > > > > > with different kernel versions I suspect this might > > > > > > > > > be > > > > > > > > > a > > > > > > > > > bug in > > > > > > > > > the > > > > > > > > > kernel. > > > > > > > > > > > > > > > > > > I have 4 logs that I collected, they are sort of > > > > > > > > > long- > > > > > > > > > ish, > > > > > > > > > not > > > > > > > > > sure > > > > > > > > > how > > > > > > > > > to best send them to the list. > > > > > > > > > > > > > > > > Send the crashes with the callback list, that should be > > > > > > > > quite > > > > > > > > small, > > > > > > > > right? We don't need the full log. > > > > > > > > > > > > > > > > The first crash is the most important, the others can > > > > > > > > be > > > > > > > > from > > > > > > > > the > > > > > > > > first > > > > > > > > one and are not reliable. > > > > > > > > > > > > > > > > thanks, > > > > > > > > > > > > > > > > greg k-h > > > > > > > > > > > > > > Ok then, here comes one of the logs, I selected some bits > > > > > > > only > > > > > > > > > > > > > > [ 147.302016] WARNING: CPU: 3 PID: 134 at > > > > > > > kernel/workqueue.c:1473 > > > > > > > __queue_work+0x364/0x410 > > > > > > > [...] > > > > > > > [ 147.302322] Call Trace: > > > > > > > [ 147.302329] <IRQ> > > > > > > > [ 147.302342] queue_work_on+0x36/0x40 > > > > > > > [ 147.302353] __usb_hcd_giveback_urb+0x9c/0x110 > > > > > > > [ 147.302362] usb_giveback_urb_bh+0xa0/0xf0 > > > > > > > [ 147.302372] tasklet_action_common.constprop.0+0x66/0x > > > > > > > 10 > > > > > > > 0 > > > > > > > [ 147.302382] __do_softirq+0xe9/0x2dc > > > > > > > [ 147.302391] irq_exit+0xcf/0x110 > > > > > > > [ 147.302397] do_IRQ+0x55/0xe0 > > > > > > > [ 147.302408] common_interrupt+0xf/0xf > > > > > > > [ 147.302413] </IRQ> > > > > > > > [...] > > > > > > > [ 184.771172] watchdog: BUG: soft lockup - CPU#3 stuck > > > > > > > for > > > > > > > 23s! > > > > > > > [kworker/3:2:134] > > > > > > > > > > > > That was the first message? > > > > > > > > > > > > Ok, we need some more logs, how about the 30 lines right > > > > > > before > > > > > > the > > > > > > above? > > > > > > > > > > > > And what kernel version are you using? > > > > > > > > > > > > thanks, > > > > > > > > > > > > greg k-h > > > > > > > > > > Heh I assumed you would find the 3rd stack more interesting > > > > > since > > > > > it > > > > > involves more subsystems but anyway, here we got, the first > > > > > one > > > > > with > > > > > more context. The trigger as you can see is me connecting the > > > > > USB > > > > > device: > > > > > > > > > > [ 141.445367] usb 1-1: new full-speed USB device number 5 > > > > > using > > > > > xhci_hcd > > > > > [ 141.573592] usb 1-1: New USB device found, idVendor=0483, > > > > > idProduct=5740, bcdDevice= 2.00 > > > > > [ 141.573597] usb 1-1: New USB device strings: Mfr=1, > > > > > Product=2, > > > > > SerialNumber=3 > > > > > [ 141.573601] usb 1-1: Product: Quad-UART serial USB device > > > > > [ 141.573603] usb 1-1: Manufacturer: davidgf.net > > > > > [ 141.573605] usb 1-1: SerialNumber: serialno > > > > > [ 142.375007] cdc_acm 1-1:1.0: ttyACM0: USB ACM device > > > > > [ 142.376623] cdc_acm 1-1:1.2: ttyACM1: USB ACM device > > > > > [ 142.378350] cdc_acm 1-1:1.4: ttyACM2: USB ACM device > > > > > [ 142.379637] cdc_acm 1-1:1.6: ttyACM3: USB ACM device > > > > > [ 142.382473] usbcore: registered new interface driver > > > > > cdc_acm > > > > > [ 142.382476] cdc_acm: USB Abstract Control Model driver for > > > > > USB > > > > > modems and ISDN adapters > > > > > [ 147.301997] ------------[ cut here ]------------ > > > > > [ 147.302016] WARNING: CPU: 3 PID: 134 at > > > > > kernel/workqueue.c:1473 > > > > > __queue_work+0x364/0x410 > > > > > [ 147.302019] Modules linked in: cdc_acm rfcomm ccm > > > > > wireguard > > > > > curve25519_x86_64 libchacha20poly1305 chacha_x86_64 > > > > > poly1305_x86_64 > > > > > libblake2s blake2s_x86_64 ip6_udp_tunnel udp_tunnel > > > > > libcurve25519_generic libchacha libblake2s_generic > > > > > nft_fib_inet > > > > > nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet > > > > > nf_reject_ipv4 > > > > > nf_reject_ipv6 nft_reject nft_ct nft_chain_nat ip6table_nat > > > > > ip6table_mangle ip6table_raw ip6table_security iptable_nat > > > > > nf_nat > > > > > nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 libcrc32c > > > > > iptable_mangle > > > > > iptable_raw iptable_security ip_set nf_tables nfnetlink > > > > > ip6table_filter > > > > > ip6_tables iptable_filter cmac vboxnetadp(OE) vboxnetflt(OE) > > > > > bnep > > > > > vboxdrv(OE) sunrpc vfat fat uvcvideo videobuf2_vmalloc > > > > > videobuf2_memops > > > > > videobuf2_v4l2 videobuf2_common videodev btusb btrtl btbcm > > > > > btintel > > > > > mc > > > > > bluetooth ecdh_generic ecc iTCO_wdt iTCO_vendor_support > > > > > mei_hdcp > > > > > intel_rapl_msr dell_laptop x86_pkg_temp_thermal > > > > > intel_powerclamp > > > > > coretemp kvm_intel kvm irqbypass intel_cstate intel_uncore > > > > > intel_rapl_perf iwlmvm > > > > > [ 147.302121] snd_hda_codec_hdmi mac80211 snd_soc_skl > > > > > snd_soc_sst_ipc > > > > > snd_soc_sst_dsp dell_wmi snd_hda_ext_core dell_smbios > > > > > snd_hda_codec_realtek dcdbas libarc4 wmi_bmof > > > > > dell_wmi_descriptor > > > > > snd_soc_acpi_intel_match snd_soc_acpi intel_wmi_thunderbolt > > > > > snd_hda_codec_generic snd_soc_core ledtrig_audio iwlwifi > > > > > pcspkr > > > > > snd_compress ac97_bus snd_pcm_dmaengine snd_hda_intel > > > > > snd_intel_dspcfg > > > > > snd_hda_codec cfg80211 snd_hda_core snd_hwdep snd_seq > > > > > snd_seq_device > > > > > joydev snd_pcm rfkill snd_timer snd i2c_i801 soundcore idma64 > > > > > int3403_thermal intel_hid int3400_thermal sparse_keymap > > > > > acpi_thermal_rel mei_me intel_xhci_usb_role_switch acpi_pad > > > > > roles > > > > > mei > > > > > intel_pch_thermal processor_thermal_device intel_rapl_common > > > > > int340x_thermal_zone intel_soc_dts_iosf binfmt_misc ip_tables > > > > > dm_crypt > > > > > i915 rtsx_pci_sdmmc mmc_core crct10dif_pclmul crc32_pclmul > > > > > i2c_algo_bit > > > > > cec crc32c_intel drm_kms_helper nvme ghash_clmulni_intel drm > > > > > nvme_core > > > > > serio_raw rtsx_pci hid_multitouch wmi i2c_hid video > > > > > pinctrl_sunrisepoint pinctrl_intel > > > > > [ 147.302218] fuse > > > > > [ 147.302230] CPU: 3 PID: 134 Comm: kworker/3:2 Tainted: > > > > > G IOE 5.7.7-200.fc32.x86_64 #1 > > > > > [ 147.302233] Hardware name: Dell Inc. XPS 13 9350/0PWNCR, > > > > > BIOS > > > > > 1.12.2 > > > > > 12/15/2019 > > > > > [ 147.302260] Workqueue: 0x0 (mm_percpu_wq) > > > > > [ 147.302275] RIP: 0010:__queue_work+0x364/0x410 > > > > > [ 147.302282] Code: e0 f1 69 a9 00 01 1f 00 75 0f 65 48 8b > > > > > 3c > > > > > 25 > > > > > c0 8b > > > > > 01 00 f6 47 24 20 75 25 0f 0b 48 83 c4 10 5b 5d 41 5c 41 5d > > > > > 41 > > > > > 5e > > > > > 41 5f > > > > > c3 <0f> 0b e9 78 fe ff ff 41 83 cc 02 49 8d 57 60 e9 5d fe ff > > > > > ff e8 > > > > > 53 > > > > > [ 147.302286] RSP: 0018:ffffbab980154e68 EFLAGS: 00010002 > > > > > [ 147.302292] RAX: ffff8f551b333790 RBX: 0000000000000048 > > > > > RCX: > > > > > 0000000000000000 > > > > > [ 147.302295] RDX: ffff8f551b333798 RSI: ffff8f5575803718 > > > > > RDI: > > > > > ffff8f5576daa840 > > > > > [ 147.302299] RBP: ffff8f551b333790 R08: ffffffff97856cb0 > > > > > R09: > > > > > 0000000000000000 > > > > > [ 147.302302] R10: 0000000000000000 R11: ffffffff97856cb8 > > > > > R12: > > > > > 0000000000000003 > > > > > [ 147.302306] R13: 0000000000002000 R14: ffff8f5575c14e00 > > > > > R15: > > > > > ffff8f5576db0700 > > > > > [ 147.302311] FS: 0000000000000000(0000) > > > > > GS:ffff8f5576d80000(0000) > > > > > knlGS:0000000000000000 > > > > > [ 147.302315] CS: 0010 DS: 0000 ES: 0000 CR0: > > > > > 0000000080050033 > > > > > [ 147.302319] CR2: 00000000000000b0 CR3: 0000000267774004 > > > > > CR4: > > > > > 00000000003606e0 > > > > > [ 147.302322] Call Trace: > > > > > [ 147.302329] <IRQ> > > > > > [ 147.302342] queue_work_on+0x36/0x40 > > > > > [ 147.302353] __usb_hcd_giveback_urb+0x9c/0x110 > > > > > [ 147.302362] usb_giveback_urb_bh+0xa0/0xf0 > > > > > > > > Are you sure your device is working properly and talking USB > > > > correctly > > > > to the host? It looks like you are just timing out for some > > > > reason. > > > > > > > > But, that warning is showing that something is odd in the usb > > > > workqueue, > > > > which is strange. > > > > > > > > What type of host controller is this talking to? And does your > > > > device > > > > actually answer the urbs being sent to it correctly? > > > > > > > > Using usbmon on this might be the best way to watch the USB > > > > traffic, > > > > if > > > > you don't have a hardware protocol sniffer, which could provide > > > > some > > > > clues as to what is going wrong. > > > > > > > > thanks, > > > > > > > > greg k-h > > > > > > As I mentioned the device is likely buggy, since I'm developing > > > and > > > debugging it. > > > However my ability to debug and fix any issue is limited by the > > > fact > > > that the kernel decides to stop working as usual, making my USB > > > keyboard and mouse useless, if not crashing later due to soft > > > lockups. > > > > > > Shouldn't the kernel be resilient to such devices? > > > > Yes it should, we should not crash. > > > > > > > I've developed quite > > > a few USB devices in the past and I've never ran into things like > > > this > > > on Linux (Windows is another story, rather 'easy' to crash, hang > > > or > > > bluescreen). In any case since I do not have access to a hardware > > > debugger and the machine goes bananas (preventing me from using > > > Wireshark) I do not think I can further debug this issue. I could > > > try > > > to find a kernel version where this does not crash the machine > > > (only > > > tested 5.6.X and 5.7.X so far). Or perhaps use VirtualBox, but > > > I'd > > > need > > > to convice the host OS to ignore the USB device and just forward > > > it > > > to > > > the guest. > > > > Trying to trace down what part of the setup is failing, by using > > usbmon, > > will be good to try to figure out what the problem is here, if you > > can > > do that. > > > > > The firmware for this device can be easily tweaked to expose an > > > arbitrary number (up to 7 I think) of CDC ACM interfaces. When I > > > use > > > one or two there's no issues, three has had some issues (but did > > > not > > > investigate further). Going to four is what consistently triggers > > > kernel issues. > > > > Hm, that might be a clue, what does the output of 'lsusb -v' for > > that > > device when you have 3 and then 4 interfaces? > > > > thanks, > > > > greg k-h > > Hello, > > I will try to see how I can debug further, perhaps I can locate a > machine or kernel that does not crash. Another option can be to > disable > the firmware down to the minimum so that it does not response to the > bulk endpoints (just to the enumeration and some basic things), to > rule > out a bad behaviour. > > The USB descriptor is what you could imagine, just replicate the two > ACM interfaces (control & data) and add more endpoints. Here goes the > one with three ports. Note this one seems to make the kernel crash > just > like the one with four. The only ones that work well are 1 and 2 > ports. > Since I'm not aware of any other commercial solutions (apart from > FTDI) > that use more than 2 ACM ports, could that be the issue? Meaning > there's a bug somewhere and no commercial hardware that can trigger > it. > > For reference the diff between two and three ports (in lsusb) is that > it's missing the last two interaces (with the 3 EPs described). Of > course the bNumInterfaces is 4 instead of 6, and wTotalLength has a > different value. > > Hope this can help somehow. > Thanks > David > > Bus 003 Device 012: ID 0483:5740 STMicroelectronics Virtual COM Port Hey again, I was not aware about the modems Daniele, thanks! So I did some testing on my old BeagleBone black, which has a very old kernel (3.8.13-bone47). In this device the kernel is happy and I was able to do some testing, it seems to work well. The UARTs seem to work well in both directions, no weird shenanigans, no error/warn messages... I'm a bit at loss on how I can debug this further, I will try to use a RPi with a newer kernel and see what happens. I could try to boot a Live USB with older kernels (in my Intel machines) to try to locate a version where it works. Since I'm no kernel expert: any way I can provide more info? The computer becomes unusable shortly after plugging the device so I can't really do any meaningful stuff on it. Thanks again, David
