Loader crashes, Monitor closed, Linux

**Bob Larkin** · 07-04-2020, 06:41 PM

The system is 64-bit Linux, Ubuntu 18.04, lots of memory, etc.

1-Turn on PC
2-Plug in T3.6 with Audio adapter, nothing else
3-Open Serial Monitor
4-Load simple INO

Code:

/* TestLoader.ino  Bob Larkin 3 July 2020
 */

void setup(void) {
  Serial.begin(9600);
  delay(1000);
  Serial.println("Test Loader");
}

void loop() {
}

5-This works fine, over and over. But wait,
6-Close Serial Monitor
7-Load same little program. All seems OK
8-Load it again and error message shows on IDE:

Code:

Arduino: 1.8.12 (Linux), TD: 1.52, Board: "Teensy 3.6, Serial, 180 MHz, Faster, US English"

Sketch uses 14016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4948 bytes (1%) of dynamic memory, leaving 257196 bytes for local variables. Maximum is 262144 bytes.
/home/bob/arduino-1.8.12/hardware/teensy/../tools/teensy_post_compile -file=TestLoader.ino -path=/tmp/arduino_build_61261 -tools=/home/bob/arduino-1.8.12/hardware/teensy/../tools -board=TEENSY36 -reboot -port=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10 -portlabel=/dev/bus/usb/003/013 Bootloader -portprotocol=Teensy 
An error occurred while uploading the sketch

The Loader Verbose:

Code:

10:05:51.297 (ports 5): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0
10:05:51.297 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:05:51.297 (ports 5):   model=34 (Teensy 3.6)
10:05:51.297 (ports 5): usb_add: /dev/bus/usb/003/014 (Teensy 3.6) Serial
10:05:51.297 (ports 5): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.1
10:05:51.297 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:05:51.297 (ports 5): usb_add: /dev/bus/usb/003/014 (Teensy 3.6) Serial
10:05:51.299 (ports 5): add child:  subsys=tty, type=(null), location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0/tty/ttyACM0
10:05:51.299 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:05:51.299 (ports 5):   devnode=/dev/ttyACM0, subsystem=tty, ifacenum=0
10:05:51.299 (ports 5): usb_add: /dev/ttyACM0 (Teensy 3.6) Serial
10:05:51.299 (ports 5): unknown action: bind
10:05:51.300 (ports 5): unknown action: bind
10:05:51.302 (ports 5): unknown action: bind
10:06:11.429 (post_compile 26): Begin, version=1.52
10:06:11.429 (loader): remote connection 8 opened
10:06:11.430 (post_compile 26): Sending command: comment: Teensyduino 1.52 - LINUX64 (teensy_post_compile)
10:06:11.430 (loader): remote cmd from 8: "comment: Teensyduino 1.52 - LINUX64 (teensy_post_compile)"
10:06:11.431 (loader): remote cmd from 8: "status"
10:06:11.431 (loader): file changed
10:06:11.439 (loader): File "TestLoader.ino.hex". 14020 bytes, 1% used
10:06:11.531 (post_compile 26): Status: 1, 1, 0, 5, 0, 0, /tmp/arduino_build_61261/, TestLoader.ino.hex
10:06:11.531 (post_compile 26): Disconnect
10:06:11.547 (post_compile 27): Begin, version=1.52
10:06:11.562 (loader): remote connection 10 opened
10:06:11.562 (post_compile 27): Sending command: comment: Teensyduino 1.52 - LINUX64 (teensy_post_compile)
10:06:11.573 (loader): remote cmd from 10: "comment: Teensyduino 1.52 - LINUX64 (teensy_post_compile)"
10:06:11.573 (loader): remote connection 8 closed
10:06:11.574 (loader): remote cmd from 10: "status"
10:06:11.659 (post_compile 27): Status: 1, 1, 0, 5, 0, 0, /tmp/arduino_build_61261/, TestLoader.ino.hex
10:06:11.659 (post_compile 27): Disconnect
10:06:11.669 (post_compile 28): Running teensy_reboot: /home/bob/arduino-1.8.12/hardware/teensy/../tools/teensy_reboot
10:06:11.669 (loader): remote connection 10 closed
10:06:11.670 (loader): remote connection 8 opened
10:06:11.671 (reboot 29): Begin, version=1.52
10:06:11.671 (reboot 29): location = /sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:11.671 (reboot 29): portlabel = /dev/bus/usb/003/013 Bootloader
10:06:11.671 (reboot 29): portprotocol = Teensy
10:06:11.671 (reboot 29): Only location /sys/devices/pci0000:00/0000:00:14.0/usb3/3-10 will be tried
10:06:11.680 (loader): remote connection 8 closed
10:06:11.682 (loader): remote connection 8 opened
10:06:11.683 (reboot 29): add device: subsys=usb, type=usb_device, location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:11.683 (reboot 29):   devnode=/dev/bus/usb/003/014, subsystem=usb, ifacenum=-1
10:06:11.683 (reboot 29): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0
10:06:11.683 (reboot 29):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:11.683 (reboot 29):   model=34 (Teensy 3.6)
10:06:11.683 (reboot 29): add child:  subsys=tty, type=(null), location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0/tty/ttyACM0
10:06:11.683 (reboot 29):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:11.683 (reboot 29):   devnode=/dev/ttyACM0, subsystem=tty, ifacenum=0
10:06:11.683 (reboot 29): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.1
10:06:11.683 (reboot 29):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:11.731 (loader): remote cmd from 8: "show:arduino_attempt_reboot"
10:06:11.731 (loader): got request to show arduino rebooting message
10:06:11.734 (loader): remote cmd from 8: "comment: Teensyduino 1.52 - LINUX64 (teensy_reboot)"
10:06:11.734 (loader): remote cmd from 8: "status"
10:06:17.021 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0/tty/ttyACM0
10:06:17.021 (ports 5):   devnode=/dev/bus/usb/003/014, subsystem=usb, ifacenum=-1
10:06:17.022 (ports 5): unknown action: unbind
10:06:17.025 (ports 5): unknown action: unbind
10:06:17.025 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.1
10:06:17.026 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0
10:06:17.026 (ports 5): unknown action: unbind
10:06:17.027 (ports 5): del device: location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:17.077 (loader): remote cmd from 8: "status"
10:06:17.137 (loader): remote connection 8 closed
10:06:17.442 (ports 5): add device: subsys=usb, type=usb_device, location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:17.442 (ports 5):   devnode=/dev/bus/usb/003/015, subsystem=usb, ifacenum=-1
10:06:17.442 (ports 5): usb_add: /dev/bus/usb/003/015 (Teensy 3.6) Bootloader
10:06:17.444 (ports 5): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0
10:06:17.444 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:17.444 (ports 5): usb_add: /dev/bus/usb/003/015 (Teensy 3.6) Bootloader
10:06:17.446 (ports 5): add child:  subsys=hid, type=(null), location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0/0003:16C0:0478.000B
10:06:17.446 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:17.446 (ports 5):   model=34 (Teensy 3.6)
10:06:17.446 (ports 5): usb_add: /dev/bus/usb/003/015 (Teensy 3.6) Bootloader
10:06:17.448 (ports 5): add child:  subsys=hidraw, type=(null), location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0/0003:16C0:0478.000B/hidraw/hidraw3
10:06:17.448 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:17.448 (ports 5): usb_add: /dev/bus/usb/003/015 (Teensy 3.6) Bootloader
10:06:17.449 (ports 5): unknown action: bind
10:06:17.451 (ports 5): unknown action: bind
10:06:17.452 (ports 5): unknown action: bind
10:06:17.566 (loader): Device came online, code_size = 1048576
10:06:17.566 (loader): Board is: Teensy 3.6 (MK66FX1M0), version 1.03
10:06:17.567 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0/0003:16C0:0478.000B/hidraw/hidraw3
10:06:17.567 (ports 5): unknown action: unbind
10:06:17.568 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0/0003:16C0:0478.000B
10:06:17.568 (ports 5): unknown action: unbind
10:06:17.573 (loader): File "TestLoader.ino.hex". 14020 bytes, 1% used
10:06:17.576 (loader): set background IMG_ONLINE
10:06:17.584 (loader): File "TestLoader.ino.hex". 14020 bytes, 1% used
10:06:17.588 (loader): elf appears to be for Teensy 3.6 (MK66FX1M0) (1048576 bytes)
10:06:17.588 (loader): elf binary data matches hex file
10:06:17.588 (loader): elf file is for Teensy 3.6 (MK66FX1M0)
10:06:17.591 (loader): begin operation
10:06:17.596 (loader): flash, block=0, bs=1024, auto=1
10:06:17.597 (loader):  gauge old value = 0
10:06:17.598 (loader): flash, block=1, bs=1024, auto=1
10:06:17.599 (loader):  gauge old value = 1
10:06:17.612 (loader): flash, block=2, bs=1024, auto=1
10:06:17.613 (loader):  gauge old value = 2
10:06:17.614 (loader): flash, block=3, bs=1024, auto=1
10:06:17.888 (loader):  gauge old value = 3
10:06:17.890 (loader): flash, block=4, bs=1024, auto=1
10:06:17.891 (loader):  gauge old value = 4
10:06:17.893 (loader): flash, block=5, bs=1024, auto=1
10:06:17.909 (loader):  gauge old value = 5
10:06:17.911 (loader): flash, block=6, bs=1024, auto=1
10:06:17.912 (loader):  gauge old value = 6
10:06:17.914 (loader): flash, block=7, bs=1024, auto=1
10:06:17.915 (loader):  gauge old value = 7
10:06:17.917 (loader): flash, block=8, bs=1024, auto=1
10:06:17.933 (loader):  gauge old value = 8
10:06:17.935 (loader): flash, block=9, bs=1024, auto=1
10:06:17.936 (loader):  gauge old value = 9
10:06:17.937 (loader): flash, block=10, bs=1024, auto=1
10:06:17.939 (loader):  gauge old value = 10
10:06:17.940 (loader): flash, block=11, bs=1024, auto=1
10:06:17.956 (loader):  gauge old value = 11
10:06:17.958 (loader): flash, block=12, bs=1024, auto=1
10:06:17.959 (loader):  gauge old value = 12
10:06:17.961 (loader): flash, block=13, bs=1024, auto=1
10:06:17.962 (loader):  gauge old value = 13
10:06:17.965 (loader): sending reboot
10:06:17.981 (loader): begin wait_until_offline
10:06:18.050 (ports 5): unknown action: unbind
10:06:18.051 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0
10:06:18.051 (ports 5): unknown action: unbind
10:06:18.052 (ports 5): del device: location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:18.081 (loader): HID/linux: something changed, try reading a descriptor
10:06:18.081 (loader): HID/linux: Device was just disconnected
10:06:18.081 (loader): offline, waited 2
10:06:18.082 (loader): end operation, total time = 0.490 seconds
10:06:18.082 (loader): set background IMG_REBOOT_OK
10:06:18.083 (loader): redraw timer set, image 14 to show for 1200 ms
10:06:18.506 (ports 5): add device: subsys=usb, type=usb_device, location=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
10:06:18.506 (ports 5):   devnode=/dev/bus/usb/003/016, subsystem=usb, ifacenum=-1
10:06:18.506 (ports 5): usb_add: /dev/bus/usb/003/016 (Teensy 3.6) Serial
10:06:19.283 (loader): redraw, image 9

9-Any attempt to Load again results in a non-responsive Loader. Other indications are that portions of Linux has also been corrupted. The solution becomes a Linux reboot (sometimes needs multiple)

This has been causing problems for some while, but they seemed "random". This now seems to isolate the issue to Loading without the Serial Monitor being open. I can now work around the issue by always having the Monitor open,or so it seems at this point.

Can anyone duplicate this problem?
Bob

**manitou** · 07-04-2020, 08:18 PM

sketch seems to work OK for me on ubuntu 18.04 (64-bit) with 1.8.12 and 1.53-beta2. i did see one fail to upload, but next upload was OK. nothing fatal

Code:

Opening Teensy Loader...
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.
An error occurred while uploading the sketch
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.
Sketch uses 12016 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4196 bytes (1%) of dynamic memory, leaving 257948 bytes for local variables. Maximum is 262144 bytes.

do you have the latest udev rules ? https://www.pjrc.com/teensy/49-teensy.rules

you could try while(!Serial) after Serial.begin

**Bob Larkin** · 07-04-2020, 09:38 PM

Thanks for the ideas.

udev rule is per that link.

I tried !Serial, as

Code:

/* TestLoader.ino  Bob Larkin 3 July 2020
 */

void setup(void) {
  Serial.begin(9600);
  while(!Serial) ;
  Serial.println("Test Loader");
}

void loop() {
}

but no change, the problem is still there.

Did you have the Serial Monitor closed? That turns it on and off for me. "Monitor on" is apparently no problem, but I'm never quite sure as I have seen so many variations of this over the last few weeks, and I was not thinking it related to the Serial Monitor.

Bob

**manitou** · 07-04-2020, 10:16 PM

Originally Posted by Bob Larkin

Thanks for the ideas.

udev rule is per that link.

Did you have the Serial Monitor closed? That turns it on and off for me. "Monitor on" is apparently no problem, but I'm never quite sure as I have seen so many variations of this over the last few weeks, and I was not thinking it related to the Serial Monitor.

Bob

yep, i tested with Serial Monitor open and closed as per your directions in post #1. maybe upgrade to teensyduino 1.53?

with IDE, loader, and serial monitor closed, do a ps uax | grep teen to see if you happen to have any rogue teensy tasks running?

**PaulStoffregen** · 07-04-2020, 11:30 PM

There is a bug on Linux which causes "An error occurred while uploading the sketch" to be mistakenly printed, but then the upload happens successfully a second or two later. Or simply trying again works. It's on my list of low-priority bugs to fix.

I use Ubuntu 18.04 as my primary desktop system. So far I've not seen Teensy Loader crash.

Here's a few idea to hopefully collect more info about what's going wrong.

1: Try running "tail -f /var/log/syslog" in a terminal, so you can see the Kernel's messages about USB device removal and detection. If Arduino and/or Teensy Loader aren't seeing your board, this can tell you with certainty whether it really is connected, at least as far as the Linux Kernel knows.

2: In Arduino's Tools > Ports you should see Teensy twice, under "Teensy ports" and "Serial Ports". If you select the Teensy Ports device, all serial monitor communication is by native helper programs which communicate with the Java runtime via stdin/stdout/stderr. If you select the device in "Serial Ports", helpers are still used to communicate with Teensy Loader, but all communication done by the Serial Monitor is through Java libraries. Maybe this makes a difference, or maybe not?

3: Quit Arduino, so it doesn't overwrite your changes. Then edit the file ".arduino15/preferences.txt". At the end, add "discovery.debug=true". When you run Arduino again, this will cause the it to print lots of info as it watches for USB devices to come and go.

I have no idea what's going wrong on your system. I don't even have a clear picture of what you're really experiencing on your screen. But hopefully these 3 things can help you collect more info. I'd really like to understand what's happening, and if there is a bug in Teensy Loader or any other software, I definitely want to fix it. But first I need just know what's really happening and develop an understanding of why.

**Bob Larkin** · 07-05-2020, 08:09 PM

Thanks much, Paul. Here are the results of your experiments. But first, a couple of notes. The problem went away for many tries, yesterday. I brought it back by running this same sketch on a T4.0 (selecting proper device and serial port at each point). It has not gone away again after perhaps 20 tries, each necessarily including a full reboot of Linux. For each reboot, Linux required a hardware power off and sometimes two restarts. After each "Sketch/Load" in the IDE, I would eventually get a Crash Dialog Box, the one that asks if you want to submit a dump.

Fortunately, Geany, the Terminal and the Arduino IDE continue to operate properly, afterthe Load attempt, so data can be gotten.

Also, sometimes the crash is on the first Load and sometimes on the second!

I have USB2 and USB3 that produce the same result. That suggests that USB hardware and low-level drivers are probably OK.

Responding to your experiments: 1-running tail...syslog. Here is the output with my notes being pretty obvious:

Code:

Bob Note: Connect T3.6 to USB port,  syslog:

Jul  5 09:30:22 bob-desktop kernel: [  309.304237] usb 3-10: new full-speed USB device number 4 using xhci_hcd
Jul  5 09:30:22 bob-desktop kernel: [  309.452986] usb 3-10: New USB device found, idVendor=16c0, idProduct=0483
Jul  5 09:30:22 bob-desktop kernel: [  309.452987] usb 3-10: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jul  5 09:30:22 bob-desktop kernel: [  309.452988] usb 3-10: Product: USB Serial
Jul  5 09:30:22 bob-desktop kernel: [  309.452990] usb 3-10: Manufacturer: Teensyduino
Jul  5 09:30:22 bob-desktop kernel: [  309.452990] usb 3-10: SerialNumber: 3052850
Jul  5 09:30:22 bob-desktop kernel: [  309.460241] cdc_acm 3-10:1.0: ttyACM0: USB ACM device
Jul  5 09:30:22 bob-desktop kernel: [  309.460379] usbcore: registered new interface driver cdc_acm
Jul  5 09:30:22 bob-desktop kernel: [  309.460380] cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
Jul  5 09:30:22 bob-desktop upowerd[984]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:14.0/usb3/3-10
Jul  5 09:30:22 bob-desktop upowerd[984]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.1
Jul  5 09:30:22 bob-desktop upowerd[984]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:14.0/usb3/3-10/3-10:1.0
Jul  5 09:30:24 bob-desktop ModemManager[642]: <info>  [device /sys/devices/pci0000:00/0000:00:14.0/usb3/3-10] creating modem with plugin 'Generic' and '1' ports
Jul  5 09:30:24 bob-desktop ModemManager[642]: <warn>  Couldn't create modem for device '/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10': Failed to find primary AT port

Bob Note: omit 2 lines here of cron activity with wifi

Bob Note: Do Sketch/Upload,  syslog:

Jul  5 09:35:52 bob-desktop kernel: [  639.237630] usb 3-10: USB disconnect, device number 4
Jul  5 09:35:52 bob-desktop kernel: [  639.764548] ------------[ cut here ]------------
Jul  5 09:35:52 bob-desktop kernel: [  639.764551] URB ffff9da213c90000 submitted while active
Jul  5 09:35:52 bob-desktop kernel: [  639.764567] WARNING: CPU: 3 PID: 2066 at /build/linux-UhTchP/linux-4.15.0/drivers/usb/core/urb.c:364 usb_submit_urb+0x442/0x5b0
Jul  5 09:35:52 bob-desktop kernel: [  639.764567] Modules linked in: cdc_acm usblp snd_hda_codec_hdmi intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc mxm_wmi aesni_intel i915 88x2bu(OE) aes_x86_64 crypto_simd joydev drm_kms_helper glue_helper cryptd snd_hda_codec_realtek input_leds drm snd_hda_codec_generic intel_cstate i2c_algo_bit intel_rapl_perf fb_sys_fops cfg80211 snd_soc_rt5640 syscopyarea snd_hda_intel sysfillrect mei_me snd_hda_codec snd_soc_rl6231 mei lpc_ich sysimgblt snd_soc_core snd_hda_core snd_hwdep shpchp snd_compress ac97_bus snd_pcm_dmaengine snd_pcm snd_timer snd soundcore mac_hid intel_smartconnect wmi acpi_pad video sch_fq_codel parport_pc ppdev lp parport ip_tables x_tables autofs4 uas usb_storage hid_logitech_hidpp hid_logitech_dj
Jul  5 09:35:52 bob-desktop kernel: [  639.764591]  hid_generic usbhid hid e1000e ahci ptp r8169 libahci mii pps_core
Jul  5 09:35:52 bob-desktop kernel: [  639.764596] CPU: 3 PID: 2066 Comm: kworker/3:0 Tainted: G        W  OE    4.15.0-108-generic #109-Ubuntu
Jul  5 09:35:52 bob-desktop kernel: [  639.764597] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./Z97 Extreme6, BIOS P1.40 09/15/2014
Jul  5 09:35:52 bob-desktop kernel: [  639.764601] Workqueue: events acm_softint [cdc_acm]
Jul  5 09:35:52 bob-desktop kernel: [  639.764605] RIP: 0010:usb_submit_urb+0x442/0x5b0
Jul  5 09:35:52 bob-desktop kernel: [  639.764605] RSP: 0018:ffffb5e08598fdd8 EFLAGS: 00010282
Jul  5 09:35:52 bob-desktop kernel: [  639.764607] RAX: 0000000000000000 RBX: ffff9da213c90000 RCX: 0000000000000006
Jul  5 09:35:52 bob-desktop kernel: [  639.764608] RDX: 0000000000000007 RSI: 0000000000000082 RDI: ffff9da26fad6490
Jul  5 09:35:52 bob-desktop kernel: [  639.764608] RBP: ffffb5e08598fe18 R08: 0000000000000404 R09: 0000000000000004
Jul  5 09:35:52 bob-desktop kernel: [  639.764609] R10: 0000000000000000 R11: 0000000000000001 R12: 0000000000000008
Jul  5 09:35:52 bob-desktop kernel: [  639.764610] R13: 0000000001400000 R14: ffff9da25a87f020 R15: 0000000000000000
Jul  5 09:35:52 bob-desktop kernel: [  639.764611] FS:  0000000000000000(0000) GS:ffff9da26fac0000(0000) knlGS:0000000000000000
Jul  5 09:35:52 bob-desktop kernel: [  639.764612] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jul  5 09:35:52 bob-desktop kernel: [  639.764613] CR2: 00007f9d11600250 CR3: 0000000345e0a001 CR4: 00000000001606e0
Jul  5 09:35:52 bob-desktop kernel: [  639.764614] Call Trace:
Jul  5 09:35:52 bob-desktop kernel: [  639.764619]  ? __switch_to_asm+0x41/0x70
Jul  5 09:35:52 bob-desktop kernel: [  639.764621]  ? __switch_to_asm+0x35/0x70
Jul  5 09:35:52 bob-desktop kernel: [  639.764624]  acm_submit_read_urb+0x42/0x90 [cdc_acm]
Jul  5 09:35:52 bob-desktop kernel: [  639.764626]  acm_softint+0x6b/0xe0 [cdc_acm]
Jul  5 09:35:52 bob-desktop kernel: [  639.764630]  process_one_work+0x1de/0x420
Jul  5 09:35:52 bob-desktop kernel: [  639.764632]  worker_thread+0x32/0x410
Jul  5 09:35:52 bob-desktop kernel: [  639.764634]  kthread+0x121/0x140
Jul  5 09:35:52 bob-desktop kernel: [  639.764635]  ? process_one_work+0x420/0x420
Jul  5 09:35:52 bob-desktop kernel: [  639.764637]  ? kthread_create_worker_on_cpu+0x70/0x70
Jul  5 09:35:52 bob-desktop kernel: [  639.764639]  ret_from_fork+0x35/0x40
Jul  5 09:35:52 bob-desktop kernel: [  639.764640] Code: 83 f1 01 45 89 c8 41 81 c0 a4 03 00 00 e9 1b fe ff ff 48 89 fe 48 c7 c7 60 fc 76 99 89 45 d0 c6 05 03 26 ed 00 01 e8 9e 01 95 ff <0f> 0b 8b 45 d0 e9 00 fc ff ff 66 83 79 06 00 0f 84 10 ff ff ff 
Jul  5 09:35:52 bob-desktop kernel: [  639.764655] ---[ end trace e3350ea79f55d69c ]---
Jul  5 09:35:52 bob-desktop kernel: [  639.764658] ���Z�������Z���� T: urb 8 failed submission with -16
Jul  5 09:35:52 bob-desktop kernel: [  639.764661] ���Z�������Z���� T: urb 10 failed submission with -16
Jul  5 09:35:52 bob-desktop kernel: [  639.764663] ���Z�������Z���� T: urb 12 failed submission with -22
Jul  5 09:35:52 bob-desktop kernel: [  639.764664] ���Z�������Z���� T: urb 13 failed submission with -22
Jul  5 09:35:52 bob-desktop kernel: [  639.764668] BUG: unable to handle kernel paging request at 0000000414843238
Jul  5 09:35:52 bob-desktop kernel: [  639.764672] IP: usb_submit_urb+0xe/0x5b0
Jul  5 09:35:52 bob-desktop kernel: [  639.764673] PGD 0 P4D 0 
Jul  5 09:35:52 bob-desktop kernel: [  639.764675] Oops: 0000 [#1] SMP PTI
Jul  5 09:35:52 bob-desktop kernel: [  639.764677] Modules linked in: cdc_acm usblp snd_hda_codec_hdmi intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc mxm_wmi aesni_intel i915 88x2bu(OE) aes_x86_64 crypto_simd joydev drm_kms_helper glue_helper cryptd snd_hda_codec_realtek input_leds drm snd_hda_codec_generic intel_cstate i2c_algo_bit intel_rapl_perf fb_sys_fops cfg80211 snd_soc_rt5640 syscopyarea snd_hda_intel sysfillrect mei_me snd_hda_codec snd_soc_rl6231 mei lpc_ich sysimgblt snd_soc_core snd_hda_core snd_hwdep shpchp snd_compress ac97_bus snd_pcm_dmaengine snd_pcm snd_timer snd soundcore mac_hid intel_smartconnect wmi acpi_pad video sch_fq_codel parport_pc ppdev lp parport ip_tables x_tables autofs4 uas usb_storage hid_logitech_hidpp hid_logitech_dj
Jul  5 09:35:52 bob-desktop kernel: [  639.764692]  hid_generic usbhid hid e1000e ahci ptp r8169 libahci mii pps_core
Jul  5 09:35:52 bob-desktop kernel: [  639.764696] CPU: 3 PID: 2066 Comm: kworker/3:0 Tainted: G        W  OE    4.15.0-108-generic #109-Ubuntu
Jul  5 09:35:52 bob-desktop kernel: [  639.764697] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./Z97 Extreme6, BIOS P1.40 09/15/2014
Jul  5 09:35:52 bob-desktop kernel: [  639.764700] Workqueue: events acm_softint [cdc_acm]
Jul  5 09:35:52 bob-desktop kernel: [  639.764703] RIP: 0010:usb_submit_urb+0xe/0x5b0
Jul  5 09:35:52 bob-desktop kernel: [  639.764704] RSP: 0018:ffffb5e08598fe20 EFLAGS: 00010202
Jul  5 09:35:52 bob-desktop kernel: [  639.764705] RAX: 00000000ffffffea RBX: ffff9da25a87f020 RCX: 0000000000000006
Jul  5 09:35:52 bob-desktop kernel: [  639.764707] RDX: 0000000001400000 RSI: 0000000001400000 RDI: 0000000414843180
Jul  5 09:35:52 bob-desktop kernel: [  639.764708] RBP: ffffb5e08598fe48 R08: 0000000000000425 R09: 0000000000000004
Jul  5 09:35:52 bob-desktop kernel: [  639.764709] R10: 0000000000000000 R11: ffffffff99f6080d R12: 000000000000000e
Jul  5 09:35:52 bob-desktop kernel: [  639.764710] R13: 000000000000000e R14: ffff9da25a87f020 R15: 0000000000000000
Jul  5 09:35:52 bob-desktop kernel: [  639.764712] FS:  0000000000000000(0000) GS:ffff9da26fac0000(0000) knlGS:0000000000000000
Jul  5 09:35:52 bob-desktop kernel: [  639.764713] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jul  5 09:35:52 bob-desktop kernel: [  639.764714] CR2: 0000000414843238 CR3: 0000000345e0a001 CR4: 00000000001606e0
Jul  5 09:35:52 bob-desktop kernel: [  639.764715] Call Trace:
Jul  5 09:35:52 bob-desktop kernel: [  639.764717]  ? acm_submit_read_urb+0x42/0x90 [cdc_acm]
Jul  5 09:35:52 bob-desktop kernel: [  639.764720]  acm_softint+0x6b/0xe0 [cdc_acm]
Jul  5 09:35:52 bob-desktop kernel: [  639.764722]  process_one_work+0x1de/0x420
Jul  5 09:35:52 bob-desktop kernel: [  639.764725]  worker_thread+0x32/0x410
Jul  5 09:35:52 bob-desktop kernel: [  639.764727]  kthread+0x121/0x140
Jul  5 09:35:52 bob-desktop kernel: [  639.764729]  ? process_one_work+0x420/0x420
Jul  5 09:35:52 bob-desktop kernel: [  639.764730]  ? kthread_create_worker_on_cpu+0x70/0x70
Jul  5 09:35:52 bob-desktop kernel: [  639.764733]  ret_from_fork+0x35/0x40
Jul  5 09:35:52 bob-desktop kernel: [  639.764735] Code: f3 c3 48 83 c7 10 31 c9 ba 01 00 00 00 be 03 00 00 00 e8 a6 76 99 ff 5d c3 0f 1f 40 00 0f 1f 44 00 00 48 85 ff 0f 84 98 05 00 00 <48> 83 bf b8 00 00 00 00 0f 84 8a 05 00 00 55 48 89 e5 41 57 41 
Jul  5 09:35:52 bob-desktop kernel: [  639.764751] RIP: usb_submit_urb+0xe/0x5b0 RSP: ffffb5e08598fe20
Jul  5 09:35:52 bob-desktop kernel: [  639.764752] CR2: 0000000414843238
Jul  5 09:35:52 bob-desktop kernel: [  639.764754] ---[ end trace e3350ea79f55d69d ]---
Jul  5 09:36:23 bob-desktop kernel: [  670.459850] cdc_acm 3-10:1.0: failed to set dtr/rts
Jul  5 09:36:23 bob-desktop kernel: [  670.459878] ------------[ cut here ]------------
Jul  5 09:36:23 bob-desktop kernel: [  670.459893] WARNING: CPU: 3 PID: 0 at /build/linux-UhTchP/linux-4.15.0/kernel/workqueue.c:1446 __queue_work+0x36c/0x420
Jul  5 09:36:23 bob-desktop kernel: [  670.459895] Modules linked in: cdc_acm usblp snd_hda_codec_hdmi intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc mxm_wmi aesni_intel i915 88x2bu(OE) aes_x86_64 crypto_simd joydev drm_kms_helper glue_helper cryptd snd_hda_codec_realtek input_leds drm snd_hda_codec_generic intel_cstate i2c_algo_bit intel_rapl_perf fb_sys_fops cfg80211 snd_soc_rt5640 syscopyarea snd_hda_intel sysfillrect mei_me snd_hda_codec snd_soc_rl6231 mei lpc_ich sysimgblt snd_soc_core snd_hda_core snd_hwdep shpchp snd_compress ac97_bus snd_pcm_dmaengine snd_pcm snd_timer snd soundcore mac_hid intel_smartconnect wmi acpi_pad video sch_fq_codel parport_pc ppdev lp parport ip_tables x_tables autofs4 uas usb_storage hid_logitech_hidpp hid_logitech_dj
Jul  5 09:36:23 bob-desktop kernel: [  670.459933]  hid_generic usbhid hid e1000e ahci ptp r8169 libahci mii pps_core
Jul  5 09:36:23 bob-desktop kernel: [  670.459941] CPU: 3 PID: 0 Comm: swapper/3 Tainted: G      D W  OE    4.15.0-108-generic #109-Ubuntu
Jul  5 09:36:23 bob-desktop kernel: [  670.459943] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./Z97 Extreme6, BIOS P1.40 09/15/2014
Jul  5 09:36:23 bob-desktop kernel: [  670.459947] RIP: 0010:__queue_work+0x36c/0x420
Jul  5 09:36:23 bob-desktop kernel: [  670.459949] RSP: 0018:ffff9da26fac3ca0 EFLAGS: 00010086
Jul  5 09:36:23 bob-desktop kernel: [  670.459951] RAX: 0000000000000024 RBX: 0000000000000003 RCX: 0000000000000006
Jul  5 09:36:23 bob-desktop kernel: [  670.459953] RDX: 0000000000000000 RSI: 00000000000000f6 RDI: ffff9da26fad6490
Jul  5 09:36:23 bob-desktop kernel: [  670.459955] RBP: ffff9da26fac3cd8 R08: 0000000000000447 R09: 000000000000000f
Jul  5 09:36:23 bob-desktop kernel: [  670.459957] R10: 0000000000000040 R11: ffffffff99f6080d R12: ffff9da25f418c00
Jul  5 09:36:23 bob-desktop kernel: [  670.459959] R13: 0000000000002000 R14: ffff9da25a87f790 R15: ffff9da26fae6500
Jul  5 09:36:23 bob-desktop kernel: [  670.459962] FS:  0000000000000000(0000) GS:ffff9da26fac0000(0000) knlGS:0000000000000000
Jul  5 09:36:23 bob-desktop kernel: [  670.459964] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jul  5 09:36:23 bob-desktop kernel: [  670.459966] CR2: 00007fd49cbdb180 CR3: 0000000345e0a005 CR4: 00000000001606e0
Jul  5 09:36:23 bob-desktop kernel: [  670.459968] Call Trace:
Jul  5 09:36:23 bob-desktop kernel: [  670.459970]  <IRQ>
Jul  5 09:36:23 bob-desktop kernel: [  670.459977]  queue_work_on+0x38/0x40
Jul  5 09:36:23 bob-desktop kernel: [  670.459983]  acm_write_bulk+0x70/0x80 [cdc_acm]
Jul  5 09:36:23 bob-desktop kernel: [  670.459989]  __usb_hcd_giveback_urb+0xa4/0x140
Jul  5 09:36:23 bob-desktop kernel: [  670.459993]  usb_hcd_giveback_urb+0xb8/0xe0
Jul  5 09:36:23 bob-desktop kernel: [  670.459997]  xhci_giveback_urb_in_irq.isra.40+0x84/0xf0
Jul  5 09:36:23 bob-desktop kernel: [  670.460001]  handle_cmd_completion+0x99f/0x1050
Jul  5 09:36:23 bob-desktop kernel: [  670.460006]  xhci_irq+0x349/0x460
Jul  5 09:36:23 bob-desktop kernel: [  670.460011]  ? lapic_next_deadline+0x26/0x30
Jul  5 09:36:23 bob-desktop kernel: [  670.460014]  xhci_msi_irq+0x11/0x20
Jul  5 09:36:23 bob-desktop kernel: [  670.460020]  __handle_irq_event_percpu+0x44/0x1a0
Jul  5 09:36:23 bob-desktop kernel: [  670.460024]  handle_irq_event_percpu+0x32/0x80
Jul  5 09:36:23 bob-desktop kernel: [  670.460028]  handle_irq_event+0x3b/0x60
Jul  5 09:36:23 bob-desktop kernel: [  670.460032]  handle_edge_irq+0x83/0x1a0
Jul  5 09:36:23 bob-desktop kernel: [  670.460036]  handle_irq+0x20/0x30
Jul  5 09:36:23 bob-desktop kernel: [  670.460040]  do_IRQ+0x50/0xe0
Jul  5 09:36:23 bob-desktop kernel: [  670.460045]  common_interrupt+0x8c/0x8c
Jul  5 09:36:23 bob-desktop kernel: [  670.460047]  </IRQ>
Jul  5 09:36:23 bob-desktop kernel: [  670.460053] RIP: 0010:cpuidle_enter_state+0xa7/0x2f0
Jul  5 09:36:23 bob-desktop kernel: [  670.460055] RSP: 0018:ffffb5e081927e68 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffdc
Jul  5 09:36:23 bob-desktop kernel: [  670.460059] RAX: ffff9da26fae1840 RBX: 0000009c1a85b11f RCX: 000000000000001f
Jul  5 09:36:23 bob-desktop kernel: [  670.460062] RDX: 0000009c1a85b11f RSI: fffffffb09f8202c RDI: 0000000000000000
Jul  5 09:36:23 bob-desktop kernel: [  670.460065] RBP: ffffb5e081927ea8 R08: 0000000000000004 R09: 0000000000021080
Jul  5 09:36:23 bob-desktop kernel: [  670.460069] R10: ffffb5e081927e38 R11: 00000243a80c8b08 R12: ffff9da26faeba00
Jul  5 09:36:23 bob-desktop kernel: [  670.460071] R13: 0000000000000005 R14: ffffffff99b733f8 R15: 0000000000000000
Jul  5 09:36:23 bob-desktop kernel: [  670.460079]  ? cpuidle_enter_state+0x97/0x2f0
Jul  5 09:36:23 bob-desktop kernel: [  670.460084]  cpuidle_enter+0x17/0x20
Jul  5 09:36:23 bob-desktop kernel: [  670.460091]  call_cpuidle+0x23/0x40
Jul  5 09:36:23 bob-desktop kernel: [  670.460096]  do_idle+0x18c/0x1f0
Jul  5 09:36:23 bob-desktop kernel: [  670.460101]  cpu_startup_entry+0x73/0x80
Jul  5 09:36:23 bob-desktop kernel: [  670.460106]  start_secondary+0x1ab/0x200
Jul  5 09:36:23 bob-desktop kernel: [  670.460112]  secondary_startup_64+0xa5/0xb0
Jul  5 09:36:23 bob-desktop kernel: [  670.460115] Code: 24 20 74 14 e8 76 90 00 00 48 85 c0 74 0a 48 8b 40 20 4c 3b 60 08 74 31 0f 0b e9 f7 fd ff ff 48 c7 c7 78 4a 6b 99 e8 a4 92 04 00 <0f> 0b 49 8b 3f c6 07 00 0f 1f 40 00 e9 da fd ff ff 41 83 cc 02 
Jul  5 09:36:23 bob-desktop kernel: [  670.460141] ---[ end trace e3350ea79f55d69e ]---
Jul  5 09:36:23 bob-desktop kernel: [  670.460233] BUG: unable to handle kernel paging request at ffff9da25b513554
Jul  5 09:36:23 bob-desktop kernel: [  670.460245] IP: usb_kill_urb+0x3a/0xc0
Jul  5 09:36:23 bob-desktop kernel: [  670.460251] PGD 346595067 P4D 346595067 PUD 346599067 PMD 41b445063 PTE 800000041b513061
Jul  5 09:36:23 bob-desktop kernel: [  670.460257] Oops: 0003 [#2] SMP PTI
Jul  5 09:36:23 bob-desktop kernel: [  670.460260] Modules linked in: cdc_acm usblp snd_hda_codec_hdmi intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc mxm_wmi aesni_intel i915 88x2bu(OE) aes_x86_64 crypto_simd joydev drm_kms_helper glue_helper cryptd snd_hda_codec_realtek input_leds drm snd_hda_codec_generic intel_cstate i2c_algo_bit intel_rapl_perf fb_sys_fops cfg80211 snd_soc_rt5640 syscopyarea snd_hda_intel sysfillrect mei_me snd_hda_codec snd_soc_rl6231 mei lpc_ich sysimgblt snd_soc_core snd_hda_core snd_hwdep shpchp snd_compress ac97_bus snd_pcm_dmaengine snd_pcm snd_timer snd soundcore mac_hid intel_smartconnect wmi acpi_pad video sch_fq_codel parport_pc ppdev lp parport ip_tables x_tables autofs4 uas usb_storage hid_logitech_hidpp hid_logitech_dj
Jul  5 09:36:23 bob-desktop kernel: [  670.460286]  hid_generic usbhid hid e1000e ahci ptp r8169 libahci mii pps_core
Jul  5 09:36:23 bob-desktop kernel: [  670.460293] CPU: 3 PID: 2063 Comm: teensy_reboot Tainted: G      D W  OE    4.15.0-108-generic #109-Ubuntu
Jul  5 09:36:23 bob-desktop kernel: [  670.460295] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./Z97 Extreme6, BIOS P1.40 09/15/2014
Jul  5 09:36:23 bob-desktop kernel: [  670.460299] RIP: 0010:usb_kill_urb+0x3a/0xc0
Jul  5 09:36:23 bob-desktop kernel: [  670.460301] RSP: 0018:ffffb5e0859e7d38 EFLAGS: 00010206
Jul  5 09:36:23 bob-desktop kernel: [  670.460303] RAX: 0000000000000000 RBX: ffff9da25b513540 RCX: ffffffff99bd2598
Jul  5 09:36:23 bob-desktop kernel: [  670.460305] RDX: 0000000000000001 RSI: 0000000000000286 RDI: ffff9da25b513540
Jul  5 09:36:23 bob-desktop kernel: [  670.460307] RBP: ffffb5e0859e7d78 R08: 0000000000000000 R09: 00000000000006da
Jul  5 09:36:23 bob-desktop kernel: [  670.460309] R10: 0000000000000000 R11: 00000243a81fc3fc R12: ffff9da25a87f440
Jul  5 09:36:23 bob-desktop kernel: [  670.460310] R13: ffff9da25a87f000 R14: ffff9da25d72fb20 R15: ffff9da213acf0c0
Jul  5 09:36:23 bob-desktop kernel: [  670.460313] FS:  00007f807d769b80(0000) GS:ffff9da26fac0000(0000) knlGS:0000000000000000
Jul  5 09:36:23 bob-desktop kernel: [  670.460315] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jul  5 09:36:23 bob-desktop kernel: [  670.460317] CR2: ffff9da25b513554 CR3: 00000003b106e006 CR4: 00000000001606e0
Jul  5 09:36:23 bob-desktop kernel: [  670.460318] Call Trace:
Jul  5 09:36:23 bob-desktop kernel: [  670.460323]  ? wait_woken+0x80/0x80
Jul  5 09:36:23 bob-desktop kernel: [  670.460328]  acm_kill_urbs+0x59/0x70 [cdc_acm]
Jul  5 09:36:23 bob-desktop kernel: [  670.460332]  acm_port_shutdown+0x84/0x90 [cdc_acm]
Jul  5 09:36:23 bob-desktop kernel: [  670.460337]  tty_port_shutdown+0x80/0x90
Jul  5 09:36:23 bob-desktop kernel: [  670.460341]  tty_port_close+0x3d/0x70
Jul  5 09:36:23 bob-desktop kernel: [  670.460345]  acm_tty_close+0x22/0x30 [cdc_acm]
Jul  5 09:36:23 bob-desktop kernel: [  670.460348]  tty_release+0x124/0x600
Jul  5 09:36:23 bob-desktop kernel: [  670.460354]  __fput+0xea/0x220
Jul  5 09:36:23 bob-desktop kernel: [  670.460358]  ____fput+0xe/0x10
Jul  5 09:36:23 bob-desktop kernel: [  670.460363]  task_work_run+0x9d/0xc0
Jul  5 09:36:23 bob-desktop kernel: [  670.460367]  exit_to_usermode_loop+0xc0/0xd0
Jul  5 09:36:23 bob-desktop kernel: [  670.460375]  do_syscall_64+0x121/0x130
Jul  5 09:36:23 bob-desktop kernel: [  670.460383]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
Jul  5 09:36:23 bob-desktop kernel: [  670.460390] RIP: 0033:0x7f807d07e8d4
Jul  5 09:36:23 bob-desktop kernel: [  670.460395] RSP: 002b:00007fffc2684cd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
Jul  5 09:36:23 bob-desktop kernel: [  670.460404] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f807d07e8d4
Jul  5 09:36:23 bob-desktop kernel: [  670.460411] RDX: 0000000000000000 RSI: 0000000000005401 RDI: 0000000000000004
Jul  5 09:36:23 bob-desktop kernel: [  670.460418] RBP: 0000000000000000 R08: ffffffffffffff70 R09: 00007fffc2684c7c
Jul  5 09:36:23 bob-desktop kernel: [  670.460425] R10: 0000000000000006 R11: 0000000000000246 R12: 0000000000000005
Jul  5 09:36:23 bob-desktop kernel: [  670.460432] R13: 0000000000000005 R14: 0000000000000000 R15: 0000000000000000
Jul  5 09:36:23 bob-desktop kernel: [  670.460440] Code: 48 83 ec 30 65 48 8b 04 25 28 00 00 00 48 89 45 e8 31 c0 e8 c9 ce 27 00 48 85 db 74 2f 48 83 7b 48 00 74 28 48 83 7b 50 00 74 21 <f0> ff 43 14 be fe ff ff ff 48 89 df e8 c5 ea ff ff e8 a0 ce 27 
Jul  5 09:36:23 bob-desktop kernel: [  670.460487] RIP: usb_kill_urb+0x3a/0xc0 RSP: ffffb5e0859e7d38
Jul  5 09:36:23 bob-desktop kernel: [  670.460493] CR2: ffff9da25b513554
Jul  5 09:36:23 bob-desktop kernel: [  670.460498] ---[ end trace e3350ea79f55d69f ]---

Bob note: At this point Loader window is dead

At this point Loader window is dead and after a few seconds, a Linux "Crash" box appears (the one that asks if we want to report system error). The Crash Report from /var/crash:

Code:

ProblemType: KernelOops
Annotation: Your system might become unstable now and might need to be restarted.
Date: Sun Jul  5 09:36:39 2020
Failure: oops
OopsText:
 BUG: unable to handle kernel paging request at ffff9da25b513554
 IP: usb_kill_urb+0x3a/0xc0
 PGD 346595067 P4D 346595067 PUD 346599067 PMD 41b445063 PTE 800000041b513061
 Oops: 0003 [#2] SMP PTI
 Modules linked in: cdc_acm usblp snd_hda_codec_hdmi intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc mxm_wmi aesni_intel i915 88x2bu(OE) aes_x86_64 crypto_simd joydev drm_kms_helper glue_helper cryptd snd_hda_codec_realtek input_leds drm snd_hda_codec_generic intel_cstate i2c_algo_bit intel_rapl_perf fb_sys_fops cfg80211 snd_soc_rt5640 syscopyarea snd_hda_intel sysfillrect mei_me snd_hda_codec snd_soc_rl6231 mei lpc_ich sysimgblt snd_soc_core snd_hda_core snd_hwdep shpchp snd_compress ac97_bus snd_pcm_dmaengine snd_pcm snd_timer snd soundcore mac_hid intel_smartconnect wmi acpi_pad video sch_fq_codel parport_pc ppdev lp parport ip_tables x_tables autofs4 uas usb_storage hid_logitech_hidpp hid_logitech_dj
  hid_generic usbhid hid e1000e ahci ptp r8169 libahci mii pps_core
 CPU: 3 PID: 2063 Comm: teensy_reboot Tainted: G      D W  OE    4.15.0-108-generic #109-Ubuntu
 Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./Z97 Extreme6, BIOS P1.40 09/15/2014
 RIP: 0010:usb_kill_urb+0x3a/0xc0
 RSP: 0018:ffffb5e0859e7d38 EFLAGS: 00010206
 RAX: 0000000000000000 RBX: ffff9da25b513540 RCX: ffffffff99bd2598
 RDX: 0000000000000001 RSI: 0000000000000286 RDI: ffff9da25b513540
 RBP: ffffb5e0859e7d78 R08: 0000000000000000 R09: 00000000000006da
 R10: 0000000000000000 R11: 00000243a81fc3fc R12: ffff9da25a87f440
 R13: ffff9da25a87f000 R14: ffff9da25d72fb20 R15: ffff9da213acf0c0
 FS:  00007f807d769b80(0000) GS:ffff9da26fac0000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: ffff9da25b513554 CR3: 00000003b106e006 CR4: 00000000001606e0
 Call Trace:
  ? wait_woken+0x80/0x80
  acm_kill_urbs+0x59/0x70 [cdc_acm]
  acm_port_shutdown+0x84/0x90 [cdc_acm]
  tty_port_shutdown+0x80/0x90
  tty_port_close+0x3d/0x70
  acm_tty_close+0x22/0x30 [cdc_acm]
  tty_release+0x124/0x600
  __fput+0xea/0x220
  ____fput+0xe/0x10
  task_work_run+0x9d/0xc0
  exit_to_usermode_loop+0xc0/0xd0
  do_syscall_64+0x121/0x130
  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
 RIP: 0033:0x7f807d07e8d4
 RSP: 002b:00007fffc2684cd8 EFLAGS: 00000246 ORIG_RAX: 0000000000000003
 RAX: 0000000000000000 RBX: 0000000000000000 RCX: 00007f807d07e8d4
 RDX: 0000000000000000 RSI: 0000000000005401 RDI: 0000000000000004
 RBP: 0000000000000000 R08: ffffffffffffff70 R09: 00007fffc2684c7c
 R10: 0000000000000006 R11: 0000000000000246 R12: 0000000000000005
 R13: 0000000000000005 R14: 0000000000000000 R15: 0000000000000000
 Code: 48 83 ec 30 65 48 8b 04 25 28 00 00 00 48 89 45 e8 31 c0 e8 c9 ce 27 00 48 85 db 74 2f 48 83 7b 48 00 74 28 48 83 7b 50 00 74 21 <f0> ff 43 14 be fe ff ff ff 48 89 df e8 c5 ea ff ff e8 a0 ce 27 
 RIP: usb_kill_urb+0x3a/0xc0 RSP: ffffb5e0859e7d38
 CR2: ffff9da25b513554
 ---[ end trace e3350ea79f55d69f ]---
 
Package: linux-image-4.15.0-108-generic 4.15.0-108.109
SourcePackage: linux
Tags: kernel-oops
Uname: Linux 4.15.0-108-generic x86_64

For 2-Serial Ports /dev/ttyACM0 (Teensy) or /dev/ttyACM0 (Teensy) gave the same response.

For 3-discovery.debug=true, the IDE response was

Code:

Arduino: 1.8.12 (Linux), TD: 1.52, Board: "Teensy 3.6, Serial, 180 MHz, Faster, US English"

Opening Teensy Loader...
Sketch uses 14056 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4948 bytes (1%) of dynamic memory, leaving 257196 bytes for local variables. Maximum is 262144 bytes.
/home/bob/arduino-1.8.12/hardware/teensy/../tools/teensy_post_compile -file=TestLoader.ino -path=/tmp/arduino_build_580551 -tools=/home/bob/arduino-1.8.12/hardware/teensy/../tools -board=TEENSY36 -reboot -port=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10 -portlabel=/dev/ttyACM0 Serial -portprotocol=Teensy 
An error occurred while uploading the sketch

And again Loader crashed and is non-responsive.

I hope this is helpful in seeing a direction to head. Bob

**Bob Larkin** · 07-05-2020, 08:13 PM

Correction, in item 2, it should be or /dev/ttyACM0 Serial (Teensy3.6)

**Bob Larkin** · 07-06-2020, 06:35 PM

Another update. The error messages with "discovery.debug=true" are as shown in #6, above, when the loader crashes. For reference, when the loader does not crash there is something to see:

Code:

Arduino: 1.8.12 (Linux), TD: 1.52, Board: "Teensy 3.6, Serial, 180 MHz, Faster, US English"

Opening Teensy Loader...
Sketch uses 14056 bytes (1%) of program storage space. Maximum is 1048576 bytes.
Global variables use 4948 bytes (1%) of dynamic memory, leaving 257196 bytes for local variables. Maximum is 262144 bytes.
/home/bob/arduino-1.8.12/hardware/teensy/../tools/teensy_post_compile -file=TestLoader.ino -path=/tmp/arduino_build_842652 -tools=/home/bob/arduino-1.8.12/hardware/teensy/../tools -board=TEENSY36 -reboot -port=/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10 -portlabel=/dev/ttyACM0 Serial -portprotocol=Teensy 
An error occurred while uploading the sketch
teensy: Received json: {"eventType":"add","port":{"address":"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10","protocol":"Teensy","protocolLabel":"Teensy Ports","boardName":"Teensy 3.6","label":"/dev/bus/usb/003/005 Bootloader","identificationPrefs":{},"prefs":{"vendorId":"16C0","productId":"0478","serialNumber":"0"},"online":"true"}}
teensy: Received json: {"eventType":"add","port":{"address":"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10","protocol":"Teensy","protocolLabel":"Teensy Ports","boardName":"Teensy 3.6","label":"/dev/bus/usb/003/005 Bootloader","identificationPrefs":{},"prefs":{"vendorId":"16C0","productId":"0478","serialNumber":"0"},"online":"true"}}
teensy: Received json: {"eventType":"add","port":{"address":"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10","protocol":"Teensy","protocolLabel":"Teensy Ports","boardName":"Teensy 3.6","label":"/dev/bus/usb/003/005 Bootloader","identificationPrefs":{},"prefs":{"vendorId":"16C0","productId":"0478","serialNumber":"0"},"online":"true"}}
teensy: Received json: {"eventType":"add","port":{"address":"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10","protocol":"Teensy","protocolLabel":"Teensy Ports","boardName":"Teensy 3.6","label":"/dev/bus/usb/003/005 Bootloader","identificationPrefs":{},"prefs":{"vendorId":"16C0","productId":"0478","serialNumber":"0"},"online":"true"}}
teensy: Received json: {"eventType":"add","port":{"address":"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10","protocol":"Teensy","protocolLabel":"Teensy Ports","boardName":"Teensy 3.6","label":"/dev/bus/usb/003/006 Serial","identificationPrefs":{},"prefs":{"vendorId":"16C0","productId":"0483","serialNumber":"0"},"online":"true"}}
teensy: Received json: {"eventType":"add","port":{"address":"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10","protocol":"Teensy","protocolLabel":"Teensy Ports","boardName":"Teensy 3.6","label":"/dev/bus/usb/003/006 Serial","identificationPrefs":{},"prefs":{"vendorId":"16C0","productId":"0483","serialNumber":"0"},"online":"true"}}
teensy: Received json: {"eventType":"add","port":{"address":"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10","protocol":"Teensy","protocolLabel":"Teensy Ports","boardName":"Teensy 3.6","label":"/dev/bus/usb/003/006 Serial","identificationPrefs":{},"prefs":{"vendorId":"16C0","productId":"0483","serialNumber":"0"},"online":"true"}}
teensy: Received json: {"eventType":"add","port":{"address":"/sys/devices/pci0000:00/0000:00:14.0/usb3/3-10","protocol":"Teensy","protocolLabel":"Teensy Ports","boardName":"Teensy 3.6","label":"/dev/ttyACM0 Serial","identificationPrefs":{},"prefs":{"vendorId":"16C0","productId":"0483","serialNumber":"0"},"online":"true"}}

Also, the fact that the crashes can sometimes cease and only be brought back by loading T4.0 says that I have NOT isolated a fully repeatable condition to create the bug. I am pursuing that now, but it is slow going with lots of PC reboots. More when I am sure. Bob

**mstiller** · 07-06-2020, 06:46 PM

If you ask me, looking at the kernel oops, this might be a bug in the cdc_acm driver, any chance that you update the kernel and try again?

There might be a 5.x kernel available on 18.04, i think

**Bob Larkin** · 07-06-2020, 08:00 PM

OK, here is an INO that has consistently created the crash of the Loader and of Linux, listed above. Creating this problem, for me, only needs the Teensy3.6. It is the previous INO with a small amount of Teensy Audio:

Code:

#include <Audio.h>

AudioSynthWaveformSine sine1;
AudioOutputI2S         i2sOut;
AudioConnection        patchCord1(sine1, 0, i2sOut, 0);
AudioConnection        patchCord2(sine1, 0, i2sOut, 1);
AudioControlSGTL5000   sgtl5000_1;

void setup(void) {
  Serial.begin(1);   delay(1000);
  Serial.println("Teensy Audio, Test Loader"); 
 
  AudioMemory(10);
  sgtl5000_1.enable();
  sine1.frequency(300.0);
  sine1.amplitude(0.005f);
} 

void loop() {
}

The sequence I have been using
1-Reboot Linux 2+ times
2-Plug in T3.6 to US
3-Open the Arduino IDE with the INO above.
4-Check Tools: Teensy 3.6 and /dev/ttyACM0 Serial(Teensy 3.6)
5-Sketch/Upload many time to confirm consistent good loads, It is always good at this point.
6-Close Serial Monitor window.
7-Sketch/Upload 2 to 4 times to cause the Teensy Loader to lock up and for Linux to "crash report" and refuse to "Shut Down" or "Reboot"

That has been consistent for 5 full 1-to-7 sequences, so I believe it will continue! The number of tries in step 7 is not always the same for some reason. This difficulty seems to be sensitive to the INO content, somehow, and as near as I can tell always requires the Monitor window to be closed. The latter provides a work-around. Strange bug. Even stranger if I'm the only one that gets it...

Also, I have never seen any Linux crash behavior from other programs, as I recollect. If any, it wold have been an isolated incident. I have been with Ubuntu 18.04 for a couple of years.

Thanks, Bob

**mstiller** · 07-06-2020, 09:12 PM

If the other programs don't use the AMA driver they will not crash if there is a race condition or bug in this driver. If you google for kernel oops cdc_ama you find some issues, so upgrading to a kernel > 4.15 might help if it is not a big issue for you.

My opinion is, a user level program should not be able to cause a kernel oops, if it does likely the driver is to blame.

**manitou** · 07-06-2020, 09:32 PM

it looks like you are running ModemManager. try getting rid of that. sudo apt-get purge modemmanager

**Bob Larkin** · 07-07-2020, 05:07 AM

Thanks much, I needed things to try. I first deleted modemmanager. No change that I could see, in loading.

Then after a full backup, I updated to kernel 5.3 with no obvious issues. No change that I could see in loading.

So, I am still seeing the results for steps 1 to 7 of post #10 above. It seems to be 100% repeatable as described.

More tomorrow.

**Bob Larkin** · 07-08-2020, 04:19 AM

It would appear that this crashing issue relates to the timing of constructors for at least the AudioOutputI2S (possibly others). Here is the observation. Steps 1 to 7 of post #10 are consistent and repeatable for me. BUT, if I make one change to the AudioOutputI2S class, namely adding delays on either side of begin():

Code:

	AudioOutputI2S(void) : AudioStream(2, inputQueueArray) //  WAS { begin(); }
	{
	  uint32_t xx = 0;
	  for(uint32_t ii=0; ii<10000; ii++) 
	    xx = xx + ii;
	  begin();
	  for(uint32_t ii=0; ii<10000; ii++) 
	    xx = xx + ii;
	}

the problem seems to go away. As least in several tries it did not appear. I did not try to minimize the cure---maybe one small delay would do it.

I discovered this while building a different, but similar class. It showed the same cure.

I need to test this more, but I am going to be away tomorrow and wanted to toss this out while it is fresh. Does any of this make sense? Thoughts?

Bob

**PaulStoffregen** · 07-08-2020, 12:43 PM

Wow, you don't see a Kernel Opps very often in these modern times of Linux! This is extremely unusual. We hear all sorts of problems with Linux which almost always turn out to be udev rules or permissions or other misconfiguration or buggy ModemManager, but pretty much never a kernel-level crash.

Something is going horribly wrong on your PC. It might be USB hardware. It might be a corrupted kernel module. Just to be clear, nothing Teensy does should ever be able to cause a Kernel opps. We never install any kernel modules. By following the normal way of installation, absolutely everything we install runs without root permission, using only the drivers that come with the Linux kernel. The udev rules are the only part installed with root permission, and it's just a text file that tells udev how to handle Teensy and (hopefully) get ModemManager to not interfere.

I know you're interested focusing on Teensy here, and for pretty much any other problem I would agree. But a kernel opps means something is very wrong with either your PC hardware or its Linux installation. That's where you should focus your attention, rather than the specific code on the Teensy side which triggers this crash.

With that in mind, I have 2 quick suggestions of things to try...

1: Add a USB hub between your PC and Teensy. A hub will change 2 things. First, detection of USB connect and disconnect is handled by the hub rather than the USB controller in your PC. Second, for 12 MBit USB devices like Teensy 3.6, your PC actually communicates at 480 Mbit using split transactions to the transaction translator inside the hub, which in turn communicates with Teensy at 12 Mbit. If the hub solves this problem, odds are strong your PC's USB controller (or its kernel driver) has a serious problem.

2: In Arduino, change Tools > USB Type to any of the non-Serial options. RawHID is a probably a good choice. Your kernel log seems to suggest the crash may be happening within the cdc_acm driver. Using RawHID will avoid all use of that driver. If the hub makes no difference but this solves everything, odds are strong your cdc_acm driver module file is corrupted. Or maybe you've discovered a kernel bug, but that seems pretty unlikely for such a well established and widely used driver.

Just to clearly repeat, we pretty much never hear reports of kernel crashes on Linux. Whatever is going so horribly wrong on your machine is absolutely not normal. We do hear lots of Linux issues involving config & ModemManager, but almost never this.

(however, a few years ago Apple shipped a buggy driver and we did hear lots of reports of MacOS kernel crashes around the El Capitan era)

**Bob Larkin** · 07-09-2020, 07:42 PM

Thanks Paul. Your "big picture" thinking was right on.

When I inserted a x4 USB 2.0 hub, the crashes went away. This is not just for the test INO, but a two of others that had been problems. Also, it held true for T4.0 which had been every bit as much an issue. I will get back to Teensy programming and report back if I see anything else. For now, the message to anyone else seeing Loader crashes under Linux, try a USB expander hub!

Background:
First, I found from lsusb that whether I used a blue USB 3 socket or a USB 2.0 socket, the driver was always xhci_hcd/14p at the internal hub level and cdc_acm at the device level. lspci shows the hardware controller is always "USB controller: Intel Corporation 9 Series Chipset Family USB xHCI Controller". This holds for T3.6 and T4.0, but with the different speeds indicated.

Second, several days ago, post #13, I installed kernel 5.3 replacing 4.15. This should have cleared corrupted kernel drivers, if any.

Third, Paul, your comment, "If the hub solves this problem, odds are strong your PC's USB controller (or its kernel driver) has a serious problem." is concerning. Wouldn't the kernel update make driver issues unlikely? I have not seen other issues with the USB. Internet search on the Intel chip set does not suggest any issues, not surprisingly.

For reference, here is the relevant portion of lsusb -t for no hub, T3.6:

Code:

/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/14p, 480M
    |__ Port 9: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 2: Dev 4, If 0, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 4, If 1, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 4, If 2, Class=Human Interface Device, Driver=usbhid, 12M
    |__ Port 10: Dev 10, If 0, Class=Communications, Driver=cdc_acm, 12M    <<<<<<<<<<<<<<<
    |__ Port 10: Dev 10, If 1, Class=CDC Data, Driver=cdc_acm, 12M         <<<<<<<<<<<<<<

and with the hub, T3.6:

Code:

/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/14p, 480M
    |__ Port 9: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 2: Dev 4, If 0, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 4, If 1, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 4, If 2, Class=Human Interface Device, Driver=usbhid, 12M
    |__ Port 10: Dev 11, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 1: Dev 12, If 1, Class=CDC Data, Driver=cdc_acm, 12M     <<<<<<<<<<<<<<<
        |__ Port 1: Dev 12, If 0, Class=Communications, Driver=cdc_acm, 12M  <<<<<<<<<<<<

and with the hub for T4.0:

Code:

/:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/14p, 480M
    |__ Port 9: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 2: Dev 4, If 0, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 4, If 1, Class=Human Interface Device, Driver=usbhid, 12M
        |__ Port 2: Dev 4, If 2, Class=Human Interface Device, Driver=usbhid, 12M
    |__ Port 10: Dev 11, If 0, Class=Hub, Driver=hub/4p, 480M
        |__ Port 1: Dev 47, If 1, Class=CDC Data, Driver=cdc_acm, 480M      <<<<<<<<<<
        |__ Port 1: Dev 47, If 0, Class=Communications, Driver=cdc_acm, 480M   <<<<<<<<<

**mstiller** · 07-09-2020, 08:14 PM

Good to hear that the issues are solved now.

**Bob Larkin** · 07-10-2020, 12:58 AM

The celebration was fun! But brief :-(

When I went back to playing with a getting the OutputI2S class working with F32 and Teensy 4.0, and made more code changes, the crash problem came back. The code works, but only with some added delays on the constructor. There is no point in showing details until I work it down to a minimal complexity that still retains the crash. This testing was with the 4x hub in the USB path. One observation, relative to Paul's experiments, is that I moved the Tools/USB Type to "Raw HID" and after a bit of playing got Serial Port communications, "/dev/hidraw4RawHID (Teensy 4.0)" and the crash was still there. Bob

**PaulStoffregen** · 07-10-2020, 01:14 AM

I use Linux for nearly all Teensy development. While Frank and others have made some very substantial contributions, I've uploaded the audio library many thousands of times while developing most of its code over the years, all from Ubuntu 14, 16, 18. I've never experienced a Linux kernel opps while developing the audio library. I also developed all the USB device stack code, on Teensy 2, 3/LC and 4 - where I have uploaded very wrong USB implementations over and over (in the earliest versions using non-USB ways since I wrote all the USB code from scratch). I've done so many USB things wrong in the course of developing Teensy's core lib. Years ago I did encounter bugs in the Linux drivers requiring a reboot (it's very rare), but never a kernel opps.

We also don't generally get reports of Linux kernel problems from the thousands of people who've used this forum. And indeed we have heard from many Linux users, so it's not a case of everyone using Windows & Macintosh. Problems from not installing the udev rules or having buggy ModemManager interfere have come up over and over. But not Linux kernel opps.

My point is a Linux kernel opps is a very serious problem which we just don't see here. It's unique to you. I'm pretty sure something is very wrong on your machine.

**Bob Larkin** · 07-10-2020, 09:48 PM

Thanks, Paul. I am continuing to pursue an explanation for what I am seeing and when the data is totally solid, I will report back. I don't mean to add noise here :-) Bob

**Bob Larkin** · 07-29-2020, 11:38 PM

Originally Posted by Bob Larkin

.... when the data is totally solid, I will report back. I don't mean to add noise here :-)

OK, I've been able to narrow down a specific set of conditions that is consistent for me in creating the problem. And have also been able to isolate the area in the loading/booting process where things seem to go wrong.

First, I am able to duplicate the problem on two different sets of USB hardware in my regular PC, and more importantly, could duplicate this on an old 32-bit Ubuntu 18.04 PC.

My problems with Teensy 3.6 were the result of first breaking something in Linux by running Teensy 4.0 and later having the problem with 3.6. At this point, I never see it on Teensy 3.6 after cold booting the PC,

I have only been able to create the problem with one specific Class, and it is NOT from the Teensy library. It is a floating point audio I2S output class, made by taking the Teensy I16 output_i2s.h and .cpp and gluing on the OpenAudio F32 read of a data block, followed by conversion to I16 integer. The obvious thing to say at this point is that there is a bug in my code. But, it compiles and links without error, but of course it may not run without error. The details of the experiment are at https://github.com/boblark/TestLoadT The difference between good and bad is the timing of the I2S, interrupt and DMA startup. The bad timing is the same as used by Teensy output_i2s.

I have piles of data, and would be happy to share any, but probably more useful now is to show the Loader verbose output when faiiling:

Code:

09:48:00.405 (loader): remote connection 8 closed
09:48:01.353 (loader): file changed
09:48:01.362 (loader): File "TL_TestOutput_float.ino.hex". 29308 bytes, 1% used
09:48:01.378 (post_compile 12): Begin, version=1.53
09:48:01.411 (loader): remote connection 8 opened
09:48:01.411 (post_compile 12): Sending command: comment: Teensyduino 1.53 - LINUX64 (teensy_post_compile)
09:48:01.412 (loader): remote cmd from 8: "comment: Teensyduino 1.53 - LINUX64 (teensy_post_compile)"
09:48:01.412 (loader): remote cmd from 8: "status"
09:48:01.457 (post_compile 12): Status: 1, 1, 0, 2, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:01.457 (post_compile 12): Disconnect
09:48:01.467 (loader): remote connection 8 closed
09:48:01.473 (post_compile 13): Begin, version=1.53
09:48:01.473 (loader): remote connection 8 opened
09:48:01.473 (post_compile 13): Sending command: comment: Teensyduino 1.53 - LINUX64 (teensy_post_compile)
09:48:01.473 (loader): remote cmd from 8: "comment: Teensyduino 1.53 - LINUX64 (teensy_post_compile)"
09:48:01.473 (loader): remote cmd from 8: "status"
09:48:01.520 (post_compile 13): Status: 1, 1, 0, 2, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:01.520 (post_compile 13): Disconnect
09:48:01.530 (post_compile 14): Running teensy_reboot: /home/bob/arduino-1.8.13/hardware/teensy/../tools/teensy_reboot
09:48:01.531 (loader): remote connection 8 closed
09:48:01.531 (loader): remote connection 8 opened
09:48:01.531 (loader): remote connection 8 closed
09:48:01.531 (reboot 15): Begin, version=1.53
09:48:01.531 (reboot 15): location = /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:01.531 (reboot 15): portlabel = /dev/bus/usb/005/031 Bootloader
09:48:01.531 (reboot 15): portprotocol = Teensy
09:48:01.531 (reboot 15): Only location /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1 will be tried
09:48:01.542 (loader): remote connection 8 opened
09:48:01.545 (reboot 15): add device: subsys=usb, type=usb_device, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:01.545 (reboot 15):   devnode=/dev/bus/usb/005/032, subsystem=usb, ifacenum=-1
09:48:01.545 (reboot 15): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
09:48:01.545 (reboot 15):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:01.545 (reboot 15):   model=36 (Teensy 4.0)
09:48:01.545 (reboot 15): add child:  subsys=tty, type=(null), location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/tty/ttyACM0
09:48:01.545 (reboot 15):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:01.545 (reboot 15):   devnode=/dev/ttyACM0, subsystem=tty, ifacenum=0
09:48:01.545 (reboot 15): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.1
09:48:01.545 (reboot 15):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:01.552 (reboot 15): found Teensy Loader, version 1.53
09:48:01.552 (reboot 15): Sending command: show:arduino_attempt_reboot
09:48:01.587 (loader): remote cmd from 8: "show:arduino_attempt_reboot"
09:48:01.587 (loader): got request to show arduino rebooting message
09:48:01.589 (reboot 15): Sending command: comment: Teensyduino 1.53 - LINUX64 (teensy_reboot)
09:48:01.590 (loader): remote cmd from 8: "comment: Teensyduino 1.53 - LINUX64 (teensy_reboot)"
09:48:01.590 (loader): remote cmd from 8: "status"
09:48:01.637 (reboot 15): Status: 1, 1, 0, 2, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:01.637 (reboot 15): do_reset (serial) /dev/ttyACM0
09:48:01.663 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/tty/ttyACM0
09:48:01.663 (ports 5):   devnode=/dev/bus/usb/005/032, subsystem=usb, ifacenum=-1
09:48:01.663 (ports 5): unknown action: unbind
09:48:01.663 (ports 5): unknown action: unbind
09:48:01.664 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.1
09:48:01.664 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
09:48:01.665 (ports 5): unknown action: unbind
09:48:01.665 (ports 5): del device: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:01.681 (loader): remote cmd from 8: "status"
09:48:01.724 (reboot 15): Status: 1, 1, 0, 2, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:01.724 (reboot 15): status read, retry 0
09:48:01.824 (loader): remote cmd from 8: "status"
09:48:01.872 (reboot 15): Status: 1, 1, 0, 2, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:01.872 (reboot 15): status read, retry 1
09:48:01.972 (loader): remote cmd from 8: "status"
09:48:02.021 (reboot 15): Status: 1, 1, 0, 2, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:02.021 (reboot 15): status read, retry 2
09:48:02.121 (loader): remote cmd from 8: "status"
09:48:02.171 (reboot 15): Status: 1, 1, 0, 2, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:02.171 (reboot 15): status read, retry 3
09:48:02.271 (loader): remote cmd from 8: "status"
09:48:02.296 (ports 5): add device: subsys=usb, type=usb_device, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:02.296 (ports 5):   devnode=/dev/bus/usb/005/033, subsystem=usb, ifacenum=-1
09:48:02.296 (ports 5): usb_add: /dev/bus/usb/005/033 (Teensy 4.0) Bootloader
09:48:02.297 (ports 5): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
09:48:02.297 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:02.297 (ports 5): usb_add: /dev/bus/usb/005/033 (Teensy 4.0) Bootloader
09:48:02.298 (ports 5): add child:  subsys=hid, type=(null), location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0013
09:48:02.298 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:02.298 (ports 5):   model=36 (Teensy 4.0)
09:48:02.298 (ports 5): usb_add: /dev/bus/usb/005/033 (Teensy 4.0) Bootloader
09:48:02.299 (ports 5): add child:  subsys=hidraw, type=(null), location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0013/hidraw/hidraw3
09:48:02.299 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:02.299 (ports 5): usb_add: /dev/bus/usb/005/033 (Teensy 4.0) Bootloader
09:48:02.300 (ports 5): unknown action: bind
09:48:02.300 (ports 5): unknown action: bind
09:48:02.301 (ports 5): unknown action: bind
09:48:02.325 (reboot 15): Status: 1, 1, 0, 2, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:02.325 (reboot 15): status read, retry 4
09:48:02.470 (loader): Device came online, code_size = 2031616
09:48:02.470 (loader): Board is: Teensy 4.0 (IMXRT1062), version 1.05
09:48:02.471 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0013/hidraw/hidraw3
09:48:02.471 (ports 5): unknown action: unbind
09:48:02.472 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0013
09:48:02.472 (ports 5): unknown action: unbind
09:48:02.478 (loader): File "TL_TestOutput_float.ino.hex". 29308 bytes, 1% used
09:48:02.481 (loader): set background IMG_ONLINE
09:48:02.491 (loader): File "TL_TestOutput_float.ino.hex". 29308 bytes, 1% used
09:48:02.495 (loader): elf appears to be for Teensy 4.0 (IMXRT1062) (2031616 bytes)
09:48:02.495 (loader): elf binary data matches hex file
09:48:02.495 (loader): elf file is for Teensy 4.0 (IMXRT1062)
09:48:02.498 (loader): begin operation
09:48:02.502 (loader): remote cmd from 8: "status"
09:48:02.502 (reboot 15): Status: 1, 1, 1, 3, 0, 1, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:02.502 (loader): flash, block=0, bs=1024, auto=1
09:48:02.502 (loader):  gauge old value = 0
09:48:02.503 (loader): flash, block=1, bs=1024, auto=1
09:48:02.723 (loader):  gauge old value = 1
09:48:02.724 (loader): remote cmd from 8: "status"
09:48:02.724 (reboot 15): Status: 1, 1, 1, 3, 0, 1, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:02.724 (loader): flash, block=2, bs=1024, auto=1
09:48:02.724 (loader):  gauge old value = 2
09:48:02.725 (loader): flash, block=3, bs=1024, auto=1
09:48:02.725 (loader):  gauge old value = 3
09:48:02.726 (loader): flash, block=4, bs=1024, auto=1
09:48:02.726 (loader):  gauge old value = 4
09:48:02.729 (loader): flash, block=5, bs=1024, auto=1
09:48:02.730 (loader):  gauge old value = 5
09:48:02.731 (loader): flash, block=6, bs=1024, auto=1
09:48:02.731 (loader):  gauge old value = 6
09:48:02.732 (loader): flash, block=7, bs=1024, auto=1
09:48:02.733 (loader):  gauge old value = 7
09:48:02.734 (loader): flash, block=8, bs=1024, auto=1
09:48:02.735 (loader):  gauge old value = 8
09:48:02.735 (loader): flash, block=9, bs=1024, auto=1
09:48:02.736 (loader):  gauge old value = 9
09:48:02.737 (loader): flash, block=10, bs=1024, auto=1
09:48:02.738 (loader):  gauge old value = 10
09:48:02.739 (loader): flash, block=11, bs=1024, auto=1
09:48:02.740 (loader):  gauge old value = 11
09:48:02.740 (loader): flash, block=12, bs=1024, auto=1
09:48:02.741 (loader):  gauge old value = 12
09:48:02.742 (loader): flash, block=13, bs=1024, auto=1
09:48:02.743 (loader):  gauge old value = 13
09:48:02.743 (loader): flash, block=14, bs=1024, auto=1
09:48:02.744 (loader):  gauge old value = 14
09:48:02.745 (loader): flash, block=15, bs=1024, auto=1
09:48:02.746 (loader):  gauge old value = 15
09:48:02.747 (loader): flash, block=16, bs=1024, auto=1
09:48:02.748 (loader):  gauge old value = 16
09:48:02.748 (loader): flash, block=17, bs=1024, auto=1
09:48:02.749 (loader):  gauge old value = 17
09:48:02.750 (loader): flash, block=18, bs=1024, auto=1
09:48:02.751 (loader):  gauge old value = 18
09:48:02.752 (loader): flash, block=19, bs=1024, auto=1
09:48:02.753 (loader):  gauge old value = 19
09:48:02.753 (loader): flash, block=20, bs=1024, auto=1
09:48:02.754 (loader):  gauge old value = 20
09:48:02.755 (loader): flash, block=21, bs=1024, auto=1
09:48:02.756 (loader):  gauge old value = 21
09:48:02.756 (loader): flash, block=22, bs=1024, auto=1
09:48:02.758 (loader):  gauge old value = 22
09:48:02.758 (loader): flash, block=23, bs=1024, auto=1
09:48:02.759 (loader):  gauge old value = 23
09:48:02.760 (loader): flash, block=24, bs=1024, auto=1
09:48:02.761 (loader):  gauge old value = 24
09:48:02.761 (loader): flash, block=25, bs=1024, auto=1
09:48:02.762 (loader):  gauge old value = 25
09:48:02.763 (loader): flash, block=26, bs=1024, auto=1
09:48:02.764 (loader):  gauge old value = 26
09:48:02.765 (loader): flash, block=27, bs=1024, auto=1
09:48:02.766 (loader):  gauge old value = 27
09:48:02.766 (loader): flash, block=28, bs=1024, auto=1
09:48:02.767 (loader):  gauge old value = 28
09:48:02.769 (loader): sending reboot
09:48:02.770 (loader): begin wait_until_offline
09:48:02.773 (ports 5): unknown action: unbind
09:48:02.773 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
09:48:02.774 (ports 5): unknown action: unbind
09:48:02.775 (ports 5): del device: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:02.820 (loader): HID/linux: something changed, try reading a descriptor
09:48:02.820 (loader): HID/linux: Device was just disconnected
09:48:02.820 (loader): offline, waited 1
09:48:02.820 (loader): end operation, total time = 0.322 seconds
09:48:02.820 (loader): set background IMG_REBOOT_OK
09:48:02.823 (loader): redraw timer set, image 14 to show for 1200 ms
09:48:02.824 (loader): remote cmd from 8: "status"
09:48:02.870 (reboot 15): Status: 1, 1, 0, 3, 0, 0, /tmp/arduino_build_728953/, TL_TestOutput_float.ino.hex
09:48:02.870 (reboot 15): status read, retry 5
09:48:02.870 (reboot 15): Success
09:48:02.870 (reboot 15): Disconnect
09:48:02.880 (loader): remote connection 8 closed
09:48:02.884 (serialmon 16): Begin, version=1.53
09:48:02.884 (serialmon 16): listening for location: /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:48:02.895 (loader): remote connection 8 opened
09:48:03.576 (ports 5): purge, name=/dev/bus/usb/005/033 (Teensy 4.0) Bootloader, loc=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1, age=0.801
09:48:03.897 (loader): remote connection 8 closed
09:48:04.025 (loader): redraw, image 9
09:49:05.541 (ports 5): add device: subsys=usb, type=usb_device, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:49:05.541 (ports 5):   devnode=/dev/bus/usb/005/038, subsystem=usb, ifacenum=-1
09:49:05.541 (ports 5): usb_add: /dev/bus/usb/005/038 (Teensy) Bootloader
09:49:05.542 (ports 5): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
09:49:05.542 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:49:05.542 (ports 5): usb_add: /dev/bus/usb/005/038 (Teensy) Bootloader
09:49:05.544 (ports 5): add child:  subsys=hid, type=(null), location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0014
09:49:05.544 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:49:05.544 (ports 5):   model=36 (Teensy 4.0)
09:49:05.544 (ports 5): usb_add: /dev/bus/usb/005/038 (Teensy 4.0) Bootloader
09:49:05.545 (ports 5): add child:  subsys=hidraw, type=(null), location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0014/hidraw/hidraw3
09:49:05.545 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:49:05.545 (ports 5): usb_add: /dev/bus/usb/005/038 (Teensy 4.0) Bootloader
09:49:05.546 (ports 5): unknown action: bind
09:49:05.547 (ports 5): unknown action: bind
09:49:05.548 (ports 5): unknown action: bind
09:49:05.708 (loader): Device came online, code_size = 2031616
09:49:05.708 (loader): Board is: Teensy 4.0 (IMXRT1062), version 1.05
09:49:05.709 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0014/hidraw/hidraw3
09:49:05.710 (ports 5): unknown action: unbind
09:49:05.711 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0014
09:49:05.711 (ports 5): unknown action: unbind
09:49:05.717 (loader): File "TL_TestOutput_float.ino.hex". 29308 bytes, 1% used
09:49:05.720 (loader): set background IMG_ONLINE
09:49:05.730 (loader): File "TL_TestOutput_float.ino.hex". 29308 bytes, 1% used
09:49:05.733 (loader): elf appears to be for Teensy 4.0 (IMXRT1062) (2031616 bytes)
09:49:05.733 (loader): elf binary data matches hex file
09:49:05.733 (loader): elf file is for Teensy 4.0 (IMXRT1062)
09:49:05.737 (loader): begin operation
09:49:05.739 (loader): flash, block=0, bs=1024, auto=1
09:49:05.739 (loader):  gauge old value = 0
09:49:05.740 (loader): flash, block=1, bs=1024, auto=1
09:49:05.958 (loader):  gauge old value = 1
09:49:05.959 (loader): flash, block=2, bs=1024, auto=1
09:49:05.960 (loader):  gauge old value = 2
09:49:05.960 (loader): flash, block=3, bs=1024, auto=1
09:49:05.960 (loader):  gauge old value = 3
09:49:05.961 (loader): flash, block=4, bs=1024, auto=1
09:49:05.961 (loader):  gauge old value = 4
09:49:05.966 (loader): flash, block=5, bs=1024, auto=1
09:49:05.966 (loader):  gauge old value = 5
09:49:05.968 (loader): flash, block=6, bs=1024, auto=1
09:49:05.968 (loader):  gauge old value = 6
09:49:05.970 (loader): flash, block=7, bs=1024, auto=1
09:49:05.970 (loader):  gauge old value = 7
09:49:05.972 (loader): flash, block=8, bs=1024, auto=1
09:49:05.972 (loader):  gauge old value = 8
09:49:05.973 (loader): flash, block=9, bs=1024, auto=1
09:49:05.974 (loader):  gauge old value = 9
09:49:05.975 (loader): flash, block=10, bs=1024, auto=1
09:49:05.975 (loader):  gauge old value = 10
09:49:05.976 (loader): flash, block=11, bs=1024, auto=1
09:49:05.977 (loader):  gauge old value = 11
09:49:05.977 (loader): flash, block=12, bs=1024, auto=1
09:49:05.978 (loader):  gauge old value = 12
09:49:05.979 (loader): flash, block=13, bs=1024, auto=1
09:49:05.980 (loader):  gauge old value = 13
09:49:05.981 (loader): flash, block=14, bs=1024, auto=1
09:49:05.982 (loader):  gauge old value = 14
09:49:05.982 (loader): flash, block=15, bs=1024, auto=1
09:49:05.983 (loader):  gauge old value = 15
09:49:05.984 (loader): flash, block=16, bs=1024, auto=1
09:49:05.985 (loader):  gauge old value = 16
09:49:05.985 (loader): flash, block=17, bs=1024, auto=1
09:49:05.987 (loader):  gauge old value = 17
09:49:05.987 (loader): flash, block=18, bs=1024, auto=1
09:49:05.988 (loader):  gauge old value = 18
09:49:05.989 (loader): flash, block=19, bs=1024, auto=1
09:49:05.990 (loader):  gauge old value = 19
09:49:05.990 (loader): flash, block=20, bs=1024, auto=1
09:49:05.992 (loader):  gauge old value = 20
09:49:05.992 (loader): flash, block=21, bs=1024, auto=1
09:49:05.993 (loader):  gauge old value = 21
09:49:05.994 (loader): flash, block=22, bs=1024, auto=1
09:49:05.995 (loader):  gauge old value = 22
09:49:05.995 (loader): flash, block=23, bs=1024, auto=1
09:49:05.996 (loader):  gauge old value = 23
09:49:05.997 (loader): flash, block=24, bs=1024, auto=1
09:49:05.998 (loader):  gauge old value = 24
09:49:05.999 (loader): flash, block=25, bs=1024, auto=1
09:49:06.000 (loader):  gauge old value = 25
09:49:06.000 (loader): flash, block=26, bs=1024, auto=1
09:49:06.001 (loader):  gauge old value = 26
09:49:06.002 (loader): flash, block=27, bs=1024, auto=1
09:49:06.003 (loader):  gauge old value = 27
09:49:06.003 (loader): flash, block=28, bs=1024, auto=1
09:49:06.005 (loader):  gauge old value = 28
09:49:06.006 (loader): sending reboot
09:49:06.007 (loader): begin wait_until_offline
09:49:06.010 (ports 5): unknown action: unbind
09:49:06.010 (ports 5): del child: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
09:49:06.011 (ports 5): unknown action: unbind
09:49:06.012 (ports 5): del device: location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:49:06.057 (loader): HID/linux: something changed, try reading a descriptor
09:49:06.057 (loader): HID/linux: Device was just disconnected
09:49:06.057 (loader): offline, waited 1
09:49:06.057 (loader): end operation, total time = 0.320 seconds
09:49:06.057 (loader): set background IMG_REBOOT_OK
09:49:06.060 (loader): redraw timer set, image 14 to show for 1200 ms    *** Continued below ***

**********EXAMPLE OF GOOD LOAD/REBOOT AT THIS POINT, JUST AFTER DATA TRANSFER:   ************
09:41:36.879 (ports 5): add device: subsys=usb, type=usb_device, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:41:36.879 (ports 5):   devnode=/dev/bus/usb/005/030, subsystem=usb, ifacenum=-1
09:41:36.879 (ports 5): usb_add: /dev/bus/usb/005/030 (Teensy 4.0) Serial
09:41:36.882 (ports 5): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
09:41:36.882 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:41:36.882 (ports 5):   model=36 (Teensy 4.0)
09:41:36.882 (ports 5): usb_add: /dev/bus/usb/005/030 (Teensy 4.0) Serial
09:41:36.883 (ports 5): add child:  subsys=usb, type=usb_interface, location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.1
09:41:36.883 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:41:36.883 (ports 5): usb_add: /dev/bus/usb/005/030 (Teensy 4.0) Serial
09:41:36.883 (ports 5): unknown action: bind
09:41:36.885 (ports 5): add child:  subsys=tty, type=(null), location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/tty/ttyACM0
09:41:36.885 (ports 5):   parent location=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:41:36.885 (ports 5):   devnode=/dev/ttyACM0, subsystem=tty, ifacenum=0
09:41:36.885 (ports 5): usb_add: /dev/ttyACM0 (Teensy 4.0) Serial
09:41:36.886 (ports 5): unknown action: bind
09:41:36.887 (ports 5): unknown action: bind
09:41:37.422 (loader): redraw, image 9
*************************************************** END OF GOOD LOAD/REBOOT EXAMPLE *****************************************

************ Back to Loader output for Bad Load/Reboot:     ********
09:49:06.448 (serialmon 17): Begin, version=1.53
09:49:06.448 (serialmon 17): listening for location: /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
09:49:06.501 (loader): remote connection 8 opened
09:49:06.813 (ports 5): purge, name=/dev/bus/usb/005/038 (Teensy 4.0) Bootloader, loc=/sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1, age=0.801
09:49:07.261 (loader): redraw, image 9
09:49:07.446 (loader): remote connection 8 closed
09:49:53.790 (loader): Verbose Info event

Can somebody tell me if the Loader entry
"09:49:06.006 (loader): sending reboot"
resulted in a reboot, and therefore the running of my Teensy code with the possibility of overwriting something? That "overwrite" might stop the Teensy from doing USB serial? Or is there something else happening that can be deduced? I'm overwhelmed!!

For further reference, here is the Linux /var/log/syslog for the same time period

Code:

Jul 29 09:48:01 bob-desktop kernel: [ 4964.779055] usb 5-1: USB disconnect, device number 32
Jul 29 09:48:01 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.1
Jul 29 09:48:01 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
Jul 29 09:48:01 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
Jul 29 09:48:01 bob-desktop kernel: [ 4964.996708] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:48:02 bob-desktop kernel: [ 4965.192564] usb 5-1: new high-speed USB device number 33 using xhci_hcd
Jul 29 09:48:02 bob-desktop kernel: [ 4965.408779] usb 5-1: New USB device found, idVendor=16c0, idProduct=0478, bcdDevice= 1.05
Jul 29 09:48:02 bob-desktop kernel: [ 4965.408780] usb 5-1: New USB device strings: Mfr=0, Product=0, SerialNumber=1
Jul 29 09:48:02 bob-desktop kernel: [ 4965.408781] usb 5-1: SerialNumber: 00097D96
Jul 29 09:48:02 bob-desktop kernel: [ 4965.412514] hid-generic 0003:16C0:0478.0013: hidraw3: USB HID v1.11 Device [HID 16c0:0478] on usb-0000:09:00.0-1/input0
Jul 29 09:48:02 bob-desktop upowerd[1065]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0013
Jul 29 09:48:02 bob-desktop upowerd[1065]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
Jul 29 09:48:02 bob-desktop upowerd[1065]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
Jul 29 09:48:02 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0013
Jul 29 09:48:02 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
Jul 29 09:48:02 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
Jul 29 09:48:02 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
Jul 29 09:48:02 bob-desktop kernel: [ 4965.888834] usb 5-1: USB disconnect, device number 33
Jul 29 09:48:03 bob-desktop kernel: [ 4966.140724] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:48:03 bob-desktop kernel: [ 4966.340577] usb 5-1: new high-speed USB device number 34 using xhci_hcd
Jul 29 09:48:08 bob-desktop kernel: [ 4971.676676] usb 5-1: device descriptor read/64, error -110
Jul 29 09:48:24 bob-desktop kernel: [ 4987.292782] usb 5-1: device descriptor read/64, error -110
Jul 29 09:48:24 bob-desktop kernel: [ 4987.401220] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:48:24 bob-desktop kernel: [ 4987.596694] usb 5-1: new high-speed USB device number 35 using xhci_hcd
Jul 29 09:48:29 bob-desktop kernel: [ 4992.924786] usb 5-1: device descriptor read/64, error -110
Jul 29 09:48:45 bob-desktop kernel: [ 5008.540880] usb 5-1: device descriptor read/64, error -110
Jul 29 09:48:45 bob-desktop kernel: [ 5008.648809] usb usb5-port1: attempt power cycle
Jul 29 09:48:45 bob-desktop kernel: [ 5008.964980] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:48:46 bob-desktop kernel: [ 5009.368810] usb 5-1: new high-speed USB device number 36 using xhci_hcd
Jul 29 09:48:54 bob-desktop kernel: [ 5017.562110] usb 5-1: Device not responding to setup address.
Jul 29 09:48:54 bob-desktop kernel: [ 5017.562545] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:02 bob-desktop kernel: [ 5025.962072] usb 5-1: Device not responding to setup address.
Jul 29 09:49:02 bob-desktop kernel: [ 5025.962481] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:03 bob-desktop kernel: [ 5026.168911] usb 5-1: device not accepting address 36, error -71
Jul 29 09:49:03 bob-desktop kernel: [ 5026.169373] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:03 bob-desktop kernel: [ 5026.364908] usb 5-1: new high-speed USB device number 37 using xhci_hcd
Jul 29 09:49:04 bob-desktop kernel: [ 5027.680771] usb 5-1: Device not responding to setup address.
Jul 29 09:49:04 bob-desktop kernel: [ 5027.681213] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:04 bob-desktop kernel: [ 5027.889104] usb 5-1: Device not responding to setup address.
Jul 29 09:49:04 bob-desktop kernel: [ 5027.889542] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:04 bob-desktop kernel: [ 5028.096921] usb 5-1: device not accepting address 37, error -71
Jul 29 09:49:04 bob-desktop kernel: [ 5028.096946] usb usb5-port1: unable to enumerate USB device
Jul 29 09:49:05 bob-desktop kernel: [ 5028.241143] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:05 bob-desktop kernel: [ 5028.436924] usb 5-1: new high-speed USB device number 38 using xhci_hcd
Jul 29 09:49:05 bob-desktop kernel: [ 5028.653302] usb 5-1: New USB device found, idVendor=16c0, idProduct=0478, bcdDevice= 1.05
Jul 29 09:49:05 bob-desktop kernel: [ 5028.653304] usb 5-1: New USB device strings: Mfr=0, Product=0, SerialNumber=1
Jul 29 09:49:05 bob-desktop kernel: [ 5028.653305] usb 5-1: SerialNumber: 00097D96
Jul 29 09:49:05 bob-desktop kernel: [ 5028.657170] hid-generic 0003:16C0:0478.0014: hidraw3: USB HID v1.11 Device [HID 16c0:0478] on usb-0000:09:00.0-1/input0
Jul 29 09:49:05 bob-desktop upowerd[1065]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0014
Jul 29 09:49:05 bob-desktop upowerd[1065]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
Jul 29 09:49:05 bob-desktop upowerd[1065]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
Jul 29 09:49:05 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0/0003:16C0:0478.0014
Jul 29 09:49:05 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
Jul 29 09:49:06 bob-desktop kernel: [ 5029.126341] usb 5-1: USB disconnect, device number 38
Jul 29 09:49:06 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1/5-1:1.0
Jul 29 09:49:06 bob-desktop upowerd[1065]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:1c.6/0000:09:00.0/usb5/5-1
Jul 29 09:49:06 bob-desktop kernel: [ 5029.377100] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:06 bob-desktop kernel: [ 5029.572907] usb 5-1: new high-speed USB device number 39 using xhci_hcd
Jul 29 09:49:11 bob-desktop kernel: [ 5034.909049] usb 5-1: device descriptor read/64, error -110
Jul 29 09:49:27 bob-desktop kernel: [ 5050.525200] usb 5-1: device descriptor read/64, error -110
Jul 29 09:49:27 bob-desktop kernel: [ 5050.633645] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:27 bob-desktop kernel: [ 5050.829101] usb 5-1: new high-speed USB device number 40 using xhci_hcd
Jul 29 09:49:33 bob-desktop kernel: [ 5056.157202] usb 5-1: device descriptor read/64, error -110
Jul 29 09:49:48 bob-desktop kernel: [ 5071.773375] usb 5-1: device descriptor read/64, error -110
Jul 29 09:49:48 bob-desktop kernel: [ 5071.881317] usb usb5-port1: attempt power cycle
Jul 29 09:49:49 bob-desktop kernel: [ 5072.197545] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:49:49 bob-desktop kernel: [ 5072.601272] usb 5-1: new high-speed USB device number 41 using xhci_hcd
Jul 29 09:49:57 bob-desktop kernel: [ 5080.794585] usb 5-1: Device not responding to setup address.
Jul 29 09:49:57 bob-desktop kernel: [ 5080.795010] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:50:06 bob-desktop kernel: [ 5089.194549] usb 5-1: Device not responding to setup address.
Jul 29 09:50:06 bob-desktop kernel: [ 5089.194985] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:50:06 bob-desktop kernel: [ 5089.401421] usb 5-1: device not accepting address 41, error -71
Jul 29 09:50:06 bob-desktop kernel: [ 5089.401916] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:50:06 bob-desktop kernel: [ 5089.597430] usb 5-1: new high-speed USB device number 42 using xhci_hcd
Jul 29 09:50:14 bob-desktop kernel: [ 5097.790659] usb 5-1: Device not responding to setup address.
Jul 29 09:50:14 bob-desktop kernel: [ 5097.791079] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:50:23 bob-desktop kernel: [ 5106.190757] usb 5-1: Device not responding to setup address.
Jul 29 09:50:23 bob-desktop kernel: [ 5106.191204] debugfs: Directory '02' with parent 'devices' already present!
Jul 29 09:50:23 bob-desktop kernel: [ 5106.397584] usb 5-1: device not accepting address 42, error -71
Jul 29 09:50:23 bob-desktop kernel: [ 5106.397609] usb usb5-port1: unable to enumerate USB device

One other clue, is that there have been Linux error messages, at times, that have suggested the Linux Oops of previous posts in this thread was related to a process taking over a CPU for some number of seconds. I am no longer getting Oops messages, but Linux is showing serious problems with very messy shutdowns and reboots, only after the Load/Boot problem.

Sorry I can't seem to make this simple.

Bob

**PaulStoffregen** · 07-30-2020, 01:24 AM

Wow, maybe this is a previously unknown & elusive bug?!

Can I talk you into sharing the compiled .elf and .hex files for both the Teensy 4.0 and Teensy 3.6? That will let me try it here on Ubuntu 18 using the exact same data.

You'll probably need to put all 4 into a zip file to attach them to a message here on the forum. If using the Quick Reply editor, click "Go Advanced" to get to the full editor which lets you attach a zip file.

**Nominal Animal** · 07-30-2020, 03:28 AM

To me, it looks like an actual Linux kernel bug, that occurs when an USB URB is canceled (because the device reset or vanishes).

There is a relatively recent possibly related bug report on the linux-usb mailing list.

However, an even more recent thread points out – in my opinion, the underlying cause of this particular crash/oops! – a race condition in this exact situation that would produce pretty much exactly this kind of oops, if there was a reliable pattern to reproduce the timing.

In my opinion, Teensy just happens to hit that window when programming it, on some hardware.

It might be useful to post an email to the linux-usb mailing list (info) with a crash dump (preferably on different machines, if you can duplicate it), asking if this is a related issue. (I believe it is, because it fits the pattern. But I am not a paid kernel developer, and I could be quite wrong.)

**Bob Larkin** · 07-30-2020, 04:54 AM

Here are 2 .hex and 2 .elf for T3.6 andT4.0, both sets with the begin() function in the constructor problematic spot. The code is unchanged, only the selection of a Teensy target is changed. The file names start with TL36 or TL40 to keep them straight.
Good luck!

**PaulStoffregen** · 07-30-2020, 05:51 AM

Thanks. I've put this on my high priority issue list. Hope to look into it this weekend.

Thread: Loader crashes, Monitor closed, Linux

Thread Tools

Search Thread

Display

Loader crashes, Monitor closed, Linux

Posting Permissions