Re: System crash/lockup after plugging CDC ACM device

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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






[Index of Archives]     [Linux Media]     [Linux Input]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [Old Linux USB Devel Archive]

  Powered by Linux