Forum Rule: Always post complete source code & details to reproduce any issue!
Results 1 to 11 of 11

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

  1. #1

    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?

  2. #2
    Senior Member+ defragster's Avatar
    Join Date
    Feb 2015
    Posts
    12,710
    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.

  3. #3
    Quote Originally Posted by defragster View Post
    ...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

  4. #4
    Senior Member+ defragster's Avatar
    Join Date
    Feb 2015
    Posts
    12,710
    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.

  5. #5
    Senior Member PaulStoffregen's Avatar
    Join Date
    Nov 2012
    Posts
    23,051
    Quote Originally Posted by defragster View Post
    @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 by PaulStoffregen; 09-09-2020 at 02:47 PM.

  6. #6
    Quote Originally Posted by PaulStoffregen View Post
    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

  7. #7
    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.

  8. #8
    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.

  9. #9
    Senior Member PaulStoffregen's Avatar
    Join Date
    Nov 2012
    Posts
    23,051
    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.

  10. #10
    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.
    Click image for larger version. 

Name:	20201026_142449_crop.jpg 
Views:	5 
Size:	84.9 KB 
ID:	22213

    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.

  11. #11
    Senior Member PaulStoffregen's Avatar
    Join Date
    Nov 2012
    Posts
    23,051
    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?

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •