Teensy 3.1: "Teensy did not respond to a USB-based request to enter program mode."

Status
Not open for further replies.

gwideman

Well-known member
Teensy 3.1: "Teensy did not respond to a USB-based request to enter program mode."

I have seen a few previous threads on this subject, but none seem to quite apply.

The main symptoms:

Using:
-- Computer A as host, Windows 10 Pro
-- Teensy 3.1
-- from the Arduino 1.8.13 environment
-- Teensyduino 1.5.3

Steps:
1. I hit the Upload button, and after compiling...

2. the Teensy loader window hangs at "Arduino is attempting to put Teensy into Program Mode", for about 5 or 6 seconds. Then

3. The Arduino message window displays "Teensy did not respond to a USB-based request to enter program mode." in orange, and "Please press the PROGRAM MODE BUTTON..."

4. As soon as step 3 takes placem the Teensy 3.1 reboots and runs the new code. (Ie: without pressing the button!). The Teensy loader window flashes a progression of two or more different messages, including, briefly, "Reboot OK", then "Press Button on Teensy..."

The net result is that the upload appears on screen to have failed, though it actually succeeded. (But in repeated use, leaves you wondering if it did or not.)

I did try different USB socket on the computer, and tried removing all installed USB devices (using Nirsoft USBDeview), no change in symptoms.

Comparison cases

Different Teensy, same computer:
If I swap out the 3.1 and use a 3.6 instead, at step 2 the reboot happens immediately, and Teensy loader immediately reports Reboot OK (and no orange message in the Arduino IDE). So everything on screen indicates success.

Same 3.1 Teensy, different computer:
I ran the same test with the same Teensy 3.1 on Computer B
-- Win 10 Pro
-- Arduino 1.8.1
-- Teensyduino 1.5
Works fine.

(... and then my Teensy 3.1 fell off the desk, and yanked the USB connector off the board. Sigh. Two 3.2's now on order. So I didn't get to try with updated Arduino and Teensyduino on Computer B)

Any ideas?
 
Best of luck with the T_3.2's working like the T_3.6 - bummer on the gravity event taking the connector off :(

If the questionable upload problem recurs, in the Teensy Loader app is : Help / Verbose info

Posting that would give the processing and events as seen during the upload and after that might point out the timing and nature of the reported failure.
 
...the Teensy Loader app is : Help / Verbose info ...

All these years and somehow I never knew about that feature! Thanks!

As it happens, Teensy Loader was still open, so here's an excerpt showing an attempt to program the Teensy 3.1. The key aspect is the sequence of "status read, retry" messages, 49 of them, before the message "Teensy did not respond to a USB-based request to automatically reboot." , after which programming was actually able to continue.

Code:
14:30:37.065 (post_compile 6): Begin, version=1.53, high-res time
14:30:37.067 (loader): remote connection 1256 opened
14:30:37.067 (loader): remote cmd from 1256: "comment: Teensyduino 1.53 - WINDOWS (teensy_post_compile)"
14:30:37.067 (loader): remote cmd from 1256: "status"
14:30:37.067 (loader): file changed
14:30:37.067 (post_compile 6): Sending command: comment: Teensyduino 1.53 - WINDOWS (teensy_post_compile)
14:30:37.076 (loader): File "BlinkTest.ino.hex". 8156 bytes, 3% used
14:30:37.081 (post_compile 6): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:37.081 (post_compile 6): Sending command: dir:C:\Users\graham\AppData\Local\Temp\arduino_build_728389\
14:30:37.083 (loader): remote cmd from 1256: "dir:C:\Users\graham\AppData\Local\Temp\arduino_build_728389\"
14:30:37.083 (post_compile 6): Sending command: file:BlinkTest.ino.hex
14:30:37.084 (loader): remote cmd from 1256: "file:BlinkTest.ino.hex"
14:30:37.092 (loader): File "BlinkTest.ino.hex". 8156 bytes, 3% used
14:30:37.098 (loader): remote cmd from 1256: "status"
14:30:37.099 (post_compile 6): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:37.099 (post_compile 6): Disconnect
14:30:37.109 (loader): remote connection 1256 closed
14:30:41.405 (post_compile 7): Begin, version=1.53, high-res time
14:30:41.406 (loader): remote connection 1568 opened
14:30:41.407 (loader): remote cmd from 1568: "comment: Teensyduino 1.53 - WINDOWS (teensy_post_compile)"
14:30:41.407 (loader): remote cmd from 1568: "status"
14:30:41.407 (loader): file changed
14:30:41.407 (post_compile 7): Sending command: comment: Teensyduino 1.53 - WINDOWS (teensy_post_compile)
14:30:41.415 (loader): File "BlinkTest.ino.hex". 8156 bytes, 3% used
14:30:41.420 (post_compile 7): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.420 (post_compile 7): Sending command: dir:C:\Users\graham\AppData\Local\Temp\arduino_build_728389\
14:30:41.423 (loader): remote cmd from 1568: "dir:C:\Users\graham\AppData\Local\Temp\arduino_build_728389\"
14:30:41.423 (loader): remote cmd from 1568: "file:BlinkTest.ino.hex"
14:30:41.423 (post_compile 7): Sending command: file:BlinkTest.ino.hex
14:30:41.432 (loader): File "BlinkTest.ino.hex". 8156 bytes, 3% used
14:30:41.437 (loader): remote cmd from 1568: "status"
14:30:41.439 (post_compile 7): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.439 (post_compile 7): Disconnect
14:30:41.450 (loader): remote connection 1568 closed
14:30:41.510 (post_compile 8): Begin, version=1.53, high-res time
14:30:41.512 (loader): remote connection 1568 opened
14:30:41.512 (loader): remote cmd from 1568: "comment: Teensyduino 1.53 - WINDOWS (teensy_post_compile)"
14:30:41.512 (post_compile 8): Sending command: comment: Teensyduino 1.53 - WINDOWS (teensy_post_compile)
14:30:41.513 (loader): remote cmd from 1568: "status"
14:30:41.514 (post_compile 8): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.514 (post_compile 8): Sending command: dir:C:\Users\graham\AppData\Local\Temp\arduino_build_728389\
14:30:41.514 (loader): remote cmd from 1568: "dir:C:\Users\graham\AppData\Local\Temp\arduino_build_728389\"
14:30:41.514 (loader): remote cmd from 1568: "file:BlinkTest.ino.hex"
14:30:41.514 (post_compile 8): Sending command: file:BlinkTest.ino.hex
14:30:41.522 (loader): File "BlinkTest.ino.hex". 8156 bytes, 3% used
14:30:41.528 (loader): remote cmd from 1568: "status"
14:30:41.529 (post_compile 8): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.529 (post_compile 8): Disconnect
14:30:41.539 (loader): remote connection 1568 closed
14:30:41.539 (loader): remote connection 1572 opened
14:30:41.540 (post_compile 9): Running teensy_reboot: "C:\Program Files (x86)\Arduino\hardware\teensy\..\tools\teensy_reboot.exe" teensy_reboot.exe "-board=TEENSY32" "-port=usb:0/140000/0/1" "-portlabel=(null)" "-portprotocol=(null)"
14:30:41.552 (reboot 10): Begin, version=1.53, high-res time
14:30:41.552 (reboot 10): location = usb:0/140000/0/1
14:30:41.552 (reboot 10): portlabel = (null)
14:30:41.552 (reboot 10): portprotocol = (null)
14:30:41.552 (reboot 10): LoadLibrary cfgmgr32 ok
14:30:41.552 (reboot 10): LoadLibrary ntdll ok
14:30:41.552 (reboot 10): found_usb_device, id=\\?\usb#vid_16c0&pid_0483#614240#{a5dcbf10-6530-11d2-901f-00c04fb951ed}
14:30:41.552 (reboot 10): found_usb_device, loc=usb:0/140000/0/1    Port_#0001.Hub_#0001
14:30:41.552 (reboot 10): found_usb_device, hwid=USB\VID_16C0&PID_0483&REV_0275
14:30:41.552 (reboot 10): found_usb_device, devinst=00000003
14:30:41.552 (reboot 10): add: loc=usb:0/140000/0/1, class=Ports, vid=16C0, pid=0483, ver=0275, serial=614240, dev=\\?\usb#vid_16c0&pid_0483#614240#{a5dcbf10-6530-11d2-901f-00c04fb951ed}
14:30:41.552 (reboot 10):   comport_from_devinst_list attempt
14:30:41.552 (reboot 10):   found Ports in classguid_list at index=0
14:30:41.552 (reboot 10):   port COM5 found from devnode
14:30:41.552 (reboot 10): found_usb_device complete
14:30:41.554 (loader): remote connection 1400 opened
14:30:41.555 (loader): remote cmd from 1400: "show:arduino_attempt_reboot"
14:30:41.555 (loader): got request to show arduino rebooting message
14:30:41.555 (reboot 10): found Teensy Loader, version 1.53
14:30:41.555 (reboot 10): Sending command: show:arduino_attempt_reboot
14:30:41.557 (loader): remote cmd from 1400: "comment: Teensyduino 1.53 - WINDOWS (teensy_reboot)"
14:30:41.557 (loader): remote cmd from 1400: "status"
14:30:41.558 (reboot 10): Sending command: comment: Teensyduino 1.53 - WINDOWS (teensy_reboot)
14:30:41.559 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.559 (reboot 10): do_reset (serial) COM5
14:30:41.562 (loader): remote cmd from 1400: "status"
14:30:41.563 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.563 (reboot 10): status read, retry 0
14:30:41.663 (loader): remote cmd from 1400: "status"
14:30:41.665 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.665 (reboot 10): status read, retry 1
14:30:41.717 (ports 5): WM_DEVICECHANGE DBT_DEVICEREMOVECOMPLETE
14:30:41.717 (ports 5): remove: loc=usb:0/140000/0/1
14:30:41.717 (ports 5): usb_remove: usb:0/140000/0/1
14:30:41.717 (ports 5): nothing new, skipping HID & Ports enum
14:30:41.727 (ports 5): WM_DEVICECHANGE DBT_DEVNODES_CHANGED
14:30:41.727 (ports 5): nothing new, skipping HID & Ports enum
14:30:41.760 (ports 5): WM_DEVICECHANGE DBT_DEVICEREMOVECOMPLETE
14:30:41.761 (ports 5): nothing new, skipping HID & Ports enum
14:30:41.765 (loader): remote cmd from 1400: "status"
14:30:41.766 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.766 (reboot 10): status read, retry 2
14:30:41.867 (loader): remote cmd from 1400: "status"
14:30:41.869 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.869 (reboot 10): status read, retry 3
14:30:41.969 (loader): remote cmd from 1400: "status"
14:30:41.971 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:41.971 (reboot 10): status read, retry 4
14:30:42.071 (loader): remote cmd from 1400: "status"
14:30:42.072 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.072 (reboot 10): status read, retry 5
14:30:42.116 (ports 5): WM_DEVICECHANGE DBT_DEVNODES_CHANGED
14:30:42.116 (ports 5): nothing new, skipping HID & Ports enum
14:30:42.172 (loader): remote cmd from 1400: "status"
14:30:42.173 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.173 (reboot 10): status read, retry 6
14:30:42.274 (loader): remote cmd from 1400: "status"
14:30:42.280 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.280 (reboot 10): status read, retry 7
14:30:42.381 (loader): remote cmd from 1400: "status"
14:30:42.383 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.383 (reboot 10): status read, retry 8
14:30:42.484 (loader): remote cmd from 1400: "status"
14:30:42.485 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.485 (reboot 10): status read, retry 9
14:30:42.586 (loader): remote cmd from 1400: "status"
14:30:42.587 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.587 (reboot 10): status read, retry 10
14:30:42.687 (loader): remote cmd from 1400: "status"
14:30:42.689 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.689 (reboot 10): status read, retry 11
14:30:42.789 (loader): remote cmd from 1400: "status"
14:30:42.790 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.790 (reboot 10): status read, retry 12
14:30:42.891 (loader): remote cmd from 1400: "status"
14:30:42.892 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.892 (reboot 10): status read, retry 13
14:30:42.993 (loader): remote cmd from 1400: "status"
14:30:42.995 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:42.995 (reboot 10): status read, retry 14
14:30:43.095 (loader): remote cmd from 1400: "status"
14:30:43.097 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.097 (reboot 10): status read, retry 15
14:30:43.197 (loader): remote cmd from 1400: "status"
14:30:43.199 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.199 (reboot 10): status read, retry 16
14:30:43.300 (loader): remote cmd from 1400: "status"
14:30:43.301 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.301 (reboot 10): status read, retry 17
14:30:43.324 (ports 5): purge, name=COM5 (Teensy 3.2) Serial, loc=usb:0/140000/0/1, age=1.606 sec
14:30:43.401 (loader): remote cmd from 1400: "status"
14:30:43.402 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.402 (reboot 10): status read, retry 18
14:30:43.503 (loader): remote cmd from 1400: "status"
14:30:43.504 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.504 (reboot 10): status read, retry 19
14:30:43.604 (loader): remote cmd from 1400: "status"
14:30:43.605 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.605 (reboot 10): status read, retry 20
14:30:43.706 (loader): remote cmd from 1400: "status"
14:30:43.707 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.707 (reboot 10): status read, retry 21
14:30:43.807 (loader): remote cmd from 1400: "status"
14:30:43.809 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.809 (reboot 10): status read, retry 22
14:30:43.909 (loader): remote cmd from 1400: "status"
14:30:43.911 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:43.911 (reboot 10): status read, retry 23
14:30:44.011 (loader): remote cmd from 1400: "status"
14:30:44.012 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.012 (reboot 10): status read, retry 24
14:30:44.113 (loader): remote cmd from 1400: "status"
14:30:44.115 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.115 (reboot 10): status read, retry 25
14:30:44.216 (loader): remote cmd from 1400: "status"
14:30:44.218 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.218 (reboot 10): status read, retry 26
14:30:44.319 (loader): remote cmd from 1400: "status"
14:30:44.320 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.320 (reboot 10): status read, retry 27
14:30:44.421 (loader): remote cmd from 1400: "status"
14:30:44.423 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.423 (reboot 10): status read, retry 28
14:30:44.524 (loader): remote cmd from 1400: "status"
14:30:44.526 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.526 (reboot 10): status read, retry 29
14:30:44.627 (loader): remote cmd from 1400: "status"
14:30:44.628 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.628 (reboot 10): status read, retry 30
14:30:44.729 (loader): remote cmd from 1400: "status"
14:30:44.730 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.730 (reboot 10): status read, retry 31
14:30:44.831 (loader): remote cmd from 1400: "status"
14:30:44.832 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.832 (reboot 10): status read, retry 32
14:30:44.933 (loader): remote cmd from 1400: "status"
14:30:44.934 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:44.934 (reboot 10): status read, retry 33
14:30:45.035 (loader): remote cmd from 1400: "status"
14:30:45.036 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.036 (reboot 10): status read, retry 34
14:30:45.136 (loader): remote cmd from 1400: "status"
14:30:45.137 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.137 (reboot 10): status read, retry 35
14:30:45.238 (loader): remote cmd from 1400: "status"
14:30:45.239 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.239 (reboot 10): status read, retry 36
14:30:45.340 (loader): remote cmd from 1400: "status"
14:30:45.341 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.341 (reboot 10): status read, retry 37
14:30:45.442 (loader): remote cmd from 1400: "status"
14:30:45.443 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.443 (reboot 10): status read, retry 38
14:30:45.543 (loader): remote cmd from 1400: "status"
14:30:45.544 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.544 (reboot 10): status read, retry 39
14:30:45.645 (loader): remote cmd from 1400: "status"
14:30:45.647 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.647 (reboot 10): status read, retry 40
14:30:45.747 (loader): remote cmd from 1400: "status"
14:30:45.748 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.748 (reboot 10): status read, retry 41
14:30:45.849 (loader): remote cmd from 1400: "status"
14:30:45.850 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.850 (reboot 10): status read, retry 42
14:30:45.950 (loader): remote cmd from 1400: "status"
14:30:45.951 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:45.951 (reboot 10): status read, retry 43
14:30:46.052 (loader): remote cmd from 1400: "status"
14:30:46.053 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:46.053 (reboot 10): status read, retry 44
14:30:46.153 (loader): remote cmd from 1400: "status"
14:30:46.154 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:46.154 (reboot 10): status read, retry 45
14:30:46.255 (loader): remote cmd from 1400: "status"
14:30:46.256 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:46.256 (reboot 10): status read, retry 46
14:30:46.356 (loader): remote cmd from 1400: "status"
14:30:46.357 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:46.357 (reboot 10): status read, retry 47
14:30:46.458 (loader): remote cmd from 1400: "status"
14:30:46.459 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:46.459 (reboot 10): status read, retry 48
14:30:46.560 (loader): remote cmd from 1400: "status"
14:30:46.561 (reboot 10): Status: 1, 1, 0, 1, 0, 0, C:\Users\graham\AppData\Local\Temp\arduino_build_728389\, BlinkTest.ino.hex
14:30:46.561 (reboot 10): status read, retry 49
14:30:46.662 (reboot 10): Teensy did not respond to a USB-based request to automatically reboot.
14:30:46.664 (loader): remote connection 1400 closed
14:30:46.667 (loader): remote connection 1572 closed
14:30:47.114 (ports 5): WM_DEVICECHANGE DBT_DEVICEARRIVAL
14:30:47.115 (ports 5): found_usb_device, id=\\?\usb#vid_16c0&pid_0478#0000eff0#{a5dcbf10-6530-11d2-901f-00c04fb951ed}
14:30:47.115 (ports 5): found_usb_device, loc=usb:0/140000/0/1    Port_#0001.Hub_#0001
14:30:47.115 (ports 5): found_usb_device, hwid=USB\VID_16C0&PID_0478&REV_0103
14:30:47.115 (ports 5): found_usb_device, devinst=00000010
14:30:47.115 (ports 5): add: loc=usb:0/140000/0/1, class=HID, vid=16C0, pid=0478, ver=0103, serial=0000eff0, dev=\\?\usb#vid_16c0&pid_0478#0000eff0#{a5dcbf10-6530-11d2-901f-00c04fb951ed}
14:30:47.115 (ports 5): hiddev_from_devinst_list: iface=0
14:30:47.116 (ports 5): found_usb_device complete
14:30:47.116 (ports 5): usb_add: usb:0/140000/0/1  [no_device] (Teensy) Bootloader
14:30:47.196 (loader): Device came online, code_size = 262144
14:30:47.196 (loader): Board is: Teensy 3.1 (MK20DX256), version 1.03
14:30:47.209 (loader): File "BlinkTest.ino.hex". 8156 bytes, 3% used
14:30:47.216 (loader): set background IMG_ONLINE
14:30:47.232 (loader): File "BlinkTest.ino.hex". 8156 bytes, 3% used
14:30:47.238 (loader): elf appears to be for Teensy 3.2 (MK20DX256) (262144 bytes)
14:30:47.238 (loader): elf binary data matches hex file
14:30:47.238 (loader): elf file is for Teensy 3.2 (MK20DX256)
14:30:47.241 (loader): begin operation
14:30:47.257 (loader): flash, block=0, bs=1024, auto=1
14:30:47.258 (loader):  gauge old value = 0
14:30:47.258 (loader): flash, block=1, bs=1024, auto=1
14:30:47.259 (loader):  gauge old value = 1
14:30:47.260 (loader): flash, block=2, bs=1024, auto=1
14:30:47.261 (loader):  gauge old value = 2
14:30:47.262 (loader): flash, block=3, bs=1024, auto=1
14:30:47.343 (loader):  gauge old value = 3
14:30:47.343 (loader): flash, block=4, bs=1024, auto=1
14:30:47.344 (loader):  gauge old value = 4
14:30:47.349 (loader): flash, block=5, bs=1024, auto=1
14:30:47.350 (loader):  gauge old value = 5
14:30:47.352 (loader): flash, block=6, bs=1024, auto=1
14:30:47.370 (loader):  gauge old value = 6
14:30:47.371 (loader): flash, block=7, bs=1024, auto=1
14:30:47.372 (loader):  gauge old value = 7
14:30:47.374 (loader): sending reboot
14:30:47.391 (loader): begin wait_until_offline
14:30:47.510 (ports 5): WM_DEVICECHANGE DBT_DEVICEREMOVECOMPLETE
14:30:47.510 (ports 5): remove: loc=usb:0/140000/0/1
14:30:47.510 (ports 5): usb_remove: usb:0/140000/0/1
14:30:47.510 (ports 5): nothing new, skipping HID & Ports enum
14:30:47.544 (loader): offline, waited 3
14:30:47.544 (loader): end operation, total time = 0.303 seconds
14:30:47.546 (loader): set background IMG_REBOOT_OK
14:30:47.549 (loader): redraw timer set, image 14 to show for 1200 ms
14:30:47.569 (loader): HID/win32:  vid:320F pid:500D ver:0100
14:30:47.569 (loader): HID/win32:  vid:320F pid:500D ver:0100
14:30:47.569 (loader): HID/win32:  vid:320F pid:500D ver:0100
14:30:47.569 (loader): HID/win32:  vid:BEEF pid:046D ver:0101
14:30:47.571 (ports 5): WM_DEVICECHANGE DBT_DEVNODES_CHANGED
14:30:47.571 (ports 5): nothing new, skipping HID & Ports enum
14:30:47.829 (ports 5): WM_DEVICECHANGE DBT_DEVICEARRIVAL
14:30:47.830 (ports 5): found_usb_device, id=\\?\usb#vid_16c0&pid_0483#614240#{a5dcbf10-6530-11d2-901f-00c04fb951ed}
14:30:47.830 (ports 5): found_usb_device, loc=usb:0/140000/0/1    Port_#0001.Hub_#0001
14:30:47.830 (ports 5): found_usb_device, hwid=USB\VID_16C0&PID_0483&REV_0275
14:30:47.830 (ports 5): found_usb_device, devinst=00000003
14:30:47.830 (ports 5): add: loc=usb:0/140000/0/1, class=Ports, vid=16C0, pid=0483, ver=0275, serial=614240, dev=\\?\usb#vid_16c0&pid_0483#614240#{a5dcbf10-6530-11d2-901f-00c04fb951ed}
14:30:47.830 (ports 5):   comport_from_devinst_list attempt
14:30:47.830 (ports 5):   found Ports in classguid_list at index=0
14:30:47.830 (ports 5):   port COM5 found from devnode
14:30:47.830 (ports 5): found_usb_device complete
14:30:47.830 (ports 5): usb_add: usb:0/140000/0/1  COM5 (Teensy 3.2) Serial
14:30:47.837 (ports 5): WM_DEVICECHANGE DBT_DEVICEARRIVAL
14:30:47.837 (ports 5): nothing new, skipping HID & Ports enum
14:30:47.871 (ports 5): WM_DEVICECHANGE DBT_DEVNODES_CHANGED
14:30:47.872 (ports 5): nothing new, skipping HID & Ports enum
14:30:48.743 (loader): redraw, image 9
 
Glad you found that logged info still present in time!

@PaulStoffregen looking at that should quickly get some idea of indicated issues and why it left the IDE confused.
 
@PaulStoffregen looking at that should quickly get some idea of indicated issues and why it left the IDE confused.

Sadly not. This verbose info only tells us *what* happened but not *why* it happened. Clearly Windows waited 5 seconds before detecting the freshly rebooted Teensy 3.1. These 3 things are pretty clear from the log:

At 14:30:41.717 - Device disconnects, we get DBT_DEVICEREMOVECOMPLETE notification from Windows.


(0.399 seconds elapse...)

At 14:30:42.116 - Something unknown happens, we get DBT_DEVNODES_CHANGED notification from Windows, but Setup API shows nothing new. This is probably where Teensy 3.1 has started running the bootloader and USB enumeration has happened. But Windows hasn't created any instances we can find by Setup API. Why it's bothering to send us a DBT_DEVNODES_CHANGED event is beyond me!

(4.998 seconds elapse...)

At 14:30:47.114 - HID drivers are finally loaded, we get DBT_DEVICEARRIVAL notification from Windows. Setup API shows we now have the "\\?\usb#vid_16c0&pid_0478#0000eff0#{a5dcbf10-6530-11d2-901f-00c04fb951ed}" device to access.

0.4 seconds is the normal amount of time for USB disconnect and reconnect and enumeration to happen. We assume the whole process should not ever take as long as 5 seconds. Maybe I should lengthen the timeout to 6 seconds??

We get no insight as to *why* Windows took another 4.998 seconds from the time USB enumeration (probably) happened until it loaded the HID driver, made the device file available and sent the DBT_DEVICEARRIVAL notification to the Teensy Loader application.

Windows 7 had these strange delays in loading HID drivers, which were small when Teensy implemented 1 or 2 HID interfaces, but grew much longer when we had more. The USB "everything" experiment could take a minute or more to fully create all interfaces on Windows 7. But that doesn't really explain this, since you're using Windows 10 and we have only a single HID interface in bootloader mode.

My best guess is this other computer might have some combination of other HID stuff, or maybe even non-HID stuff, or perhaps not even devices but software that's somehow stalling detection and creating of HID interfaces? The sad reality is Windows doesn't tell us why it waited so long. In the Widows 7 days I tried so many things to query Windows during those several mysterious seconds, but I never found any way from ordinary user program APIs to discover what Windows was actually doing. I also spent a lot of work capturing USB communication. All those delays were completely on the Windows side. Teensy quickly replied to every USB descriptor query and all other USB setup packets, but for reasons unknown Windows would just wait for seconds before loading drivers (which then do a few more USB setup transfers, which Teensy answers quickly).

I wish I knew how to get that info, but I don't know of any way to get more from Windows Setup API and Configuration Manager API which Teensy Loader uses.

These strange USB delays between the first part of enumeration and the drivers completing their part of enumeration are unique to Windows. I've also spent a lot of time analyzing USB enumeration on Linux and Macintosh, which never do this. Windows 7 was very bad. Windows 10 seems to be much better, but apparently it still happens on some machines. I have no idea why. This is one of the many things I really don't like about Windows!!!
 
Last edited:
Sadly not. This verbose info only tells us *what* happened but not *why* it happened. Clearly Windows waited 5 seconds before detecting the freshly rebooted Teensy 3.1. These 3 things are pretty clear from the log:

Paul -- thanks for your detailed commentary!

Question: Is there some doc for the list of values in the reboot Status message?

It's so odd that, as I reported, on the same machine (Computer A), just minutes apart, a Teensy 3.6 behaves just fine (no appreciable delay to complete the reboot). I exchanged the 3.1 and the 3.6 several times, and tested upload several times on each exchange, and the symptoms were consistent.

Anyhow, in my case it's moot because the 3.1 is now out of commission, at least temporarily. We'll see what happens when a couple of 3.2's arrive tomorrow.

Graham
 
And on a little more thinking, I remembered this post of mine regarding USB issues:

https://forum.pjrc.com/threads/23566-Teensyduino-USB-Joystick-no-data-driver-problem-workaround?highlight=gwideman


... and noted that I have been misled once before into thinking that USBDeview deletes all info that the registry knows about previous encounters with USB devices, when actually it does not (or at least, did not back then).

So, in case I encounter this problem again, I'll do the experiment of hunting down and removing references in the registry directly. That is, if it's in less than seven years time and I still remember :).

The theory would be something like: during the boot process, Windows identifies the Teensy 3.1 as some type of device that it once was but is no longer, invokes the wrong driver, and it takes some seconds to see that doesn't work, before trying a different approach that does succeed. Speculation on my part, of course.
 
Probably no big surprise, but the fresh Teensy 3.2's work fine. No complaint of not responding to USB request to enter program mode.
 
I added 1.2 seconds to the time teensy_reboot waits before concluding Teensy didn't respond. I still have no idea why there was a 5 second delay with Windows using this particular Teensy. But if it's a thing that happens again for you or others, hopefully the slightly longer delay in future software will help.
 
Hi Paul,

For my part, I made a backpack board specifically to be able to reattach the broken-off USB connector to this Teensy 3.1, in hopes of tracking down the problem further.
20201026_142449_crop.jpg

When I then used Arduino IDE + Teensy Loader to program this repaired board, it still delayed almost 5 secs, but succeeded in programming most of the time. There was a Windows 10 update in the intervening time since I first reported the problem, so I don't know if that affected anything.

I then proceeded to clear from the registry all references to PJRC USB VID number and the PID for this board. That did not improve things, in fact at some point it stopped Teensy Loader from programming the board at all. So I then cleared from the registry all entries corresponding to PJRC VID. So in principle, this computer had forgotten all PJRC boards and settings.

After plugging in the board again, and allowing Windows to recognize it, now programming this board works quickly and reliably.

So something remembered in the registry was upsetting the process.

I did take a snapshot of the registry before deleting entries, and then again afterwards, so in principle I could compare what's changed. I'm waiting to build up steam on devising a strategy to do that, as it's not straightforward.
 
Smart move to make a registry backup. Please let me know if you ever learn any more about what might cause this strange delay. If there's something that can be seen in the registry, maybe I can put a check for those registry keys into future versions of the software?
 
Status
Not open for further replies.
Back
Top