USB timeout problem with the current snapshot

[ithinu]

Arduino 2.3.2
Adafruit LSM6DS 4.7.3
DIO2 1.6.0
MIDI Library latest snapshot (5.0.2 causes compilation error)
ResponsiveAnalogRead 1.2.1
SensorFusion 1.0.6
Adafruit BusIO 1.16.1
Sparkfun LSM6DS Breakout 1.0.1

After upload, everything seems to work fine but each time the device connects it takes a while and a -110 timeout is signaled:

Jun  1 00:47:24  kernel: [15311.823169] usb 5-1: new full-speed USB device number 55 using xhci_hcd
Jun  1 00:47:39  kernel: [15327.251092] usb 5-1: device descriptor read/64, error -110
Jun  1 00:47:40  kernel: [15327.531830] usb 5-1: New USB device found, idVendor=239a, idProduct=8053, bcdDevice= 1.00
Jun  1 00:47:40  kernel: [15327.531839] usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jun  1 00:47:40  kernel: [15327.531843] usb 5-1: Product: WARBL
Jun  1 00:47:40  kernel: [15327.531846] usb 5-1: Manufacturer: Mowry Stringed Instruments
Jun  1 00:47:40  kernel: [15327.531849] usb 5-1: SerialNumber: 7353A2E96268DDD2
Jun  1 00:47:40  kernel: [15327.542832] usb 5-1: Quirk or no altest; falling back to MIDI 1.0

After reinstalling the official firmware 4.1, the problem is gone, the device connects immediately:

Jun  1 01:04:27  kernel: [16334.787091] usb 5-1: new full-speed USB device number 63 using xhci_hcd
Jun  1 01:04:27  kernel: [16335.156207] usb 5-1: New USB device found, idVendor=239a, idProduct=8053, bcdDevice= 1.00
Jun  1 01:04:27  kernel: [16335.156214] usb 5-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jun  1 01:04:27  kernel: [16335.156217] usb 5-1: Product: WARBL
Jun  1 01:04:27  kernel: [16335.156219] usb 5-1: Manufacturer: Mowry Stringed Instruments
Jun  1 01:04:27  kernel: [16335.156222] usb 5-1: SerialNumber: 7353A2E96268DDD2
Jun  1 01:04:27  kernel: [16335.167209] usb 5-1: Quirk or no altest; falling back to MIDI 1.0

[amowry]

My IDE and all my libraries are the same versions, with one exception-- I'm using v. 5.0.2 of the MIDI library, without any issues compiling. Do you have the #define RELEASE line commented out? If so, you may need to have a driver installed. I'm not sure what the -110 error means exactly, but it sounds like it can be related to drivers.

What compilation error do you get with 5.0.2 of the MIDI library? I remember issues with previous releases but this one seems to work for me.

[ithinu]

I attach the compiler output at the end of this post (there is also a more completed list of library versions). It is about this fragment in serialMIDI.h:

        // Initialise the Serial port
        #if defined(AVR_CAKE)
            mSerial. template open<Settings::BaudRate>();
        #else
            mSerial.begin(Settings::BaudRate);
        #endif
        }

Compiling sketch...
/home/.arduino15/packages/adafruit/tools/arm-none-eabi-gcc/9-2019q4/bin/arm-none-eabi-g++ -mcpu=cortex-m4 -mthumb -c -g -Werror=return-type -mfloat-abi=hard -mfpu=fpv4-sp-d16 -u _printf_float -std=gnu++11 -ffunction-sections -fdata-sections -fno-threadsafe-statics -nostdlib --param max-inline-insns-single=500 -fno-rtti -fno-exceptions -MMD -DF_CPU=64000000 -DARDUINO=10607 -DARDUINO_NRF52840_ITSYBITSY -DARDUINO_NRF52_ITSYBITSY -DARDUINO_ARCH_NRF52 "-DARDUINO_BSP_VERSION=\"1.6.1\"" -DNRF52840_XXAA -DUSBCON -DUSE_TINYUSB -DUSB_VID=0x239A -DUSB_PID=0x8053 "-DUSB_MANUFACTURER=\"Mowry Stringed Instruments\"" "-DUSB_PRODUCT=\"WARBL\"" -DSOFTDEVICE_PRESENT -DARDUINO_NRF52_ADAFRUIT -DNRF52_SERIES -DDX_CC_TEE -DLFS_NAME_MAX=64 -Ofast -DCFG_DEBUG=0 -DCFG_LOGGER=0 -DCFG_SYSVIEW=0 -I/home/.arduino15/packages/adafruit/tools/CMSIS/5.7.0/CMSIS/Core/Include/ -I/home/.arduino15/packages/adafruit/tools/CMSIS/5.7.0/CMSIS/DSP/Include/ -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic/nrfx -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic/nrfx/hal -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic/nrfx/mdk -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic/nrfx/soc -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic/nrfx/drivers/include -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic/nrfx/drivers/src -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic/softdevice/s140_nrf52_6.1.1_API/include -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/nordic/softdevice/s140_nrf52_6.1.1_API/include/nrf52 -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/Source/include -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/config -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/portable/GCC/nrf52 -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/freertos/portable/CMSIS/nrf52 -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/sysview/SEGGER -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5/sysview/Config -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_TinyUSB_Arduino/src/arduino -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/cores/nRF5 -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/variants/itsybitsy_nrf52840_express -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Bluefruit52Lib/src -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_nRFCrypto/src -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_TinyUSB_Arduino/src -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/SPI -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Wire -I/home/Arduino/libraries/MIDI_Library/src -I/home/Arduino/libraries/Adafruit_LSM6DS -I/home/Arduino/libraries/Adafruit_BusIO -I/home/Arduino/libraries/Adafruit_Unified_Sensor -I/home/Arduino/libraries/SensorFusion/src -I/home/Arduino/libraries/ResponsiveAnalogRead/src -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_LittleFS/src -I/home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/InternalFileSytem/src /tmp/arduino/sketches/7941F34557B3DA7F31EF589CB4FC003B/sketch/warbl2_firmware.ino.cpp -o /tmp/arduino/sketches/7941F34557B3DA7F31EF589CB4FC003B/sketch/warbl2_firmware.ino.cpp.o
In file included from /home/Arduino/libraries/MIDI_Library/src/MIDI.h:35,
                 from /home/src/WARBL2-main/warbl2_firmware/warbl2_firmware.ino:46:
/home/Arduino/libraries/MIDI_Library/src/serialMIDI.h: In instantiation of 'void midi::SerialMIDI<SerialPort, _Settings>::begin() [with SerialPort = Adafruit_USBD_MIDI; _Settings = MySettings]':
/home/Arduino/libraries/MIDI_Library/src/MIDI.hpp:75:5:   required from 'void midi::MidiInterface<Transport, _Settings, _Platform>::begin(midi::Channel) [with Transport = midi::SerialMIDI<Adafruit_USBD_MIDI, MySettings>; _Settings = midi::DefaultSettings; _Platform = midi::DefaultPlatform; midi::Channel = unsigned char]'
/home/src/WARBL2-main/warbl2_firmware/warbl2_firmware.ino:378:33:   required from here
/home/Arduino/libraries/MIDI_Library/src/serialMIDI.h:62:13: error: 'BaudRate' is not a member of 'midi::SerialMIDI<Adafruit_USBD_MIDI, MySettings>::Settings' {aka 'MySettings'}
   62 |             mSerial.begin(Settings::BaudRate);
      |             ^~~~~~~
/home/Arduino/libraries/MIDI_Library/src/serialMIDI.h: In instantiation of 'void midi::SerialMIDI<SerialPort, _Settings>::begin() [with SerialPort = BLEMidi; _Settings = MySettings]':
/home/Arduino/libraries/MIDI_Library/src/MIDI.hpp:75:5:   required from 'void midi::MidiInterface<Transport, _Settings, _Platform>::begin(midi::Channel) [with Transport = midi::SerialMIDI<BLEMidi, MySettings>; _Settings = midi::DefaultSettings; _Platform = midi::DefaultPlatform; midi::Channel = unsigned char]'
/home/src/WARBL2-main/warbl2_firmware/warbl2_firmware.ino:410:36:   required from here
/home/Arduino/libraries/MIDI_Library/src/serialMIDI.h:62:13: error: 'BaudRate' is not a member of 'midi::SerialMIDI<BLEMidi, MySettings>::Settings' {aka 'MySettings'}
Using library Adafruit Bluefruit nRF52 Libraries at version 0.21.0 in folder: /home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Bluefruit52Lib 
Using library Adafruit nRFCrypto at version 0.1.2 in folder: /home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_nRFCrypto 
Using library Adafruit TinyUSB Library at version 3.1.3 in folder: /home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_TinyUSB_Arduino 
Using library SPI at version 1.0 in folder: /home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/SPI 
Using library Wire at version 1.0 in folder: /home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Wire 
Using library MIDI Library at version 5.0.2 in folder: /home/Arduino/libraries/MIDI_Library 
Using library Adafruit LSM6DS at version 4.7.3 in folder: /home/Arduino/libraries/Adafruit_LSM6DS 
Using library Adafruit BusIO at version 1.16.1 in folder: /home/Arduino/libraries/Adafruit_BusIO 
Using library Adafruit Unified Sensor at version 1.1.14 in folder: /home/Arduino/libraries/Adafruit_Unified_Sensor 
Using library SensorFusion at version 1.0.6 in folder: /home/Arduino/libraries/SensorFusion 
Using library ResponsiveAnalogRead at version 1.2.1 in folder: /home/Arduino/libraries/ResponsiveAnalogRead 
Using library Adafruit Little File System Libraries at version 0.11.0 in folder: /home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/Adafruit_LittleFS 
Using library Adafruit Internal File System on Bluefruit nRF52 at version 0.11.0 in folder: /home/.arduino15/packages/adafruit/hardware/nrf52/1.6.1/libraries/InternalFileSytem 
exit status 1

Compilation error: exit status 1

[ithinu]

I narrowed down the problem. First of all, WARBL2_firmware_4.1.uf2 and the snapshot's flash.uf2 are identical. It's a bit strange because I commented out #define RELEASE and as I said, I use the MIDI library from the snapshot.

Anyways, I uploaded flash.uf2 manually using the copy to drive method from the manual. No more -110 errors, WARBL connects instantly. I repeated it several times and it was always the same: uploading via Arduino IDE results in the -110 error when connecting, copying exactly the same binary file to the drive doesn't.

[amowry]

The IDE doesn't create a UF2 file when you compile the binary, so you may still be looking at the UF2 file that I created?

It turned out that my board package was outdated. I was running 1.3.0. When I upgrade to 1.6.1 I see some strange behavior-- I'm not getting an error on Windows, but there seems to be a delay before the WARBL connects by USB. When I downgrade the board to 1.6.0 that behavior seems to go away. You might try that and see if the error disappears. I'll need to look at the changes Adafruit made and possibly ask them about this. I suspect it's something with TinyUSB.

[ithinu]

Yes, in that case I did in fact use your release UF2.

As of the connection delay, I downgraded to 1.6.0 and it is gone in Linux as well. Thanks.

[amowry]

Okay, thanks. I'm not sure how to track down the issue with TinyUSB but for now I'll make a note in the ReadMe here to use the 1.6.0 package.

[MrMep]

Just an update of my findings (no solution yet):

1. The problem is confirmed on MacOs too. Here's a log extract, if it might help:

default	00:04:29.911737+0200	kernel	usb-drd0-port-hs@00100000: AppleUSBHostPort::enumerateDeviceComplete_block_invoke: enumeration failed
default	00:04:29.911767+0200	kernel	usb-drd0-port-hs@00100000: AppleUSBHostPort::terminateDevice: destroying 0x0000/0000/0000 (IOUSBHostDevice): enumeration failure
default	00:04:29.912853+0200	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Client <private> is requesting 150mA wake and 0mA sleep for port 1
default	00:04:29.912870+0200	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Client <private> port 1 has EDT current overrides of 3000mA wake and 3000mA sleep
default	00:04:29.912878+0200	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Granting 150mA wake and 0mA sleep based on override for port 1
default	00:04:31.066626+0200	kernel	usb-drd0-port-hs@00100000: AppleUSBHostPort::enumerateDeviceComplete_block_invoke: enumerated 0x239a/8051/0100 (ItsyBitsy nRF52840 Express / 1) at 12 Mbps
default	00:04:31.073056+0200	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Client <private> is requesting 150mA wake and 0mA sleep for port 1
default	00:04:31.073093+0200	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Client <private> port 1 has EDT current overrides of 3000mA wake and 3000mA sleep
default	00:04:31.073101+0200	kernel	AppleUSBHostResourcesTypeC@(null): AppleUSBHostResourcesTypeC::allocateDownstreamBusCurrentGated: Granting 150mA wake and 0mA sleep based on override for port 1

2. I couldn't find much about this bug. The only hint was the order of initialization between Midi.usb and BLe.Midi. I tried to invert them, but nothing changed.
3. Interestingly enough, I tried to put a delay right after MIDI.begin block: it worsened the situation and the device was not recognized anymore. I think this might be the right track: timing.
4. I compared the two TinyUSB packages (between 1.6.0 and 1.6.1) and in fact it looks like they changed a lot in the enumeration procedure.
5. I installed the 1.6.1 package and manually updated Tiny_USB to the latest release (3.3.1): it compiles fine, but the issue remains.
6. I tried to install a version prior to 3.1.3 (included in the package) but it doesn't compile.

Although it looks very probable, unfortunately we still lack confirmation that the problem is in TinyUSB. I suspect something in the MIDI library and the timing in our firmware: this would account for the lack of acknowledgement of this problem by others.

[MrMep]

I attach the compiler output at the end of this post (there is also a more completed list of library versions). It is about this fragment in serialMIDI.h:

        // Initialise the Serial port
        #if defined(AVR_CAKE)
            mSerial. template open<Settings::BaudRate>();
        #else
            mSerial.begin(Settings::BaudRate);
        #endif
        }

I successfully compiled with MIDI_Library 5.0.2, but it needs to be manually patched (the repo is stuck at 2020):

         // Initialise the Serial port
         #if defined(AVR_CAKE)
             mSerial. template open<Settings::BaudRate>();
         #else
             mSerial.begin(31250);
         #endif
         }

I'll test it in the next days and report here.

[amowry]

Thanks @MrMep! I tried some similar things when I was trying to tack this down, with similar results. However, I was able to install earlier versions of TinyUSB and have them compile. I installed the latest board package, then installed TinyUSB v. 3.1.1 in the IDE and selected "install without dependencies" so I was using the same version of the MIDI llibrary (5.0.2) for all of this. The enumeration works fine with TinyUSB 3.1.1, so to me it seemed like it was the changes between 3.1.1 and 3.1.3 that caused the issue, but I didn't progress and further in tracking it down.

I also came to the conclusion that it's some sort of timing issue in setup() because I did similar experiments and the issue seemed to gradually improve when I removed various items from setup(). However, I couldn't pinpoint a single line that was causing this by itself.

Incidentally, the way I can tell when the issue arises is because the WARBL starts trying to charge for a second or two because it thinks it has USB power but no USB host connection (I have "charge from USB hosts" turned off in the Config Tool).

If it's helpful, these are all my library versions:

Using library Adafruit Bluefruit nRF52 Libraries at version 0.21.0 in folder: C:\Users\Andrew\AppData\Local\Arduino15\packages\adafruit\hardware\nrf52\1.6.1\libraries\Bluefruit52Lib Using library Adafruit nRFCrypto at version 0.1.2 in folder: C:\Users\Andrew\AppData\Local\Arduino15\packages\adafruit\hardware\nrf52\1.6.1\libraries\Adafruit_nRFCrypto Using library Adafruit TinyUSB Library at version 3.1.1 in folder: C:\Users\Andrew\Documents\Arduino\libraries\Adafruit_TinyUSB_Library Using library SPI at version 1.0 in folder: C:\Users\Andrew\AppData\Local\Arduino15\packages\adafruit\hardware\nrf52\1.6.1\libraries\SPI Using library Wire at version 1.0 in folder: C:\Users\Andrew\AppData\Local\Arduino15\packages\adafruit\hardware\nrf52\1.6.1\libraries\Wire Using library MIDI Library at version 5.0.2 in folder: C:\Users\Andrew\Documents\Arduino\libraries\MIDI_Library Using library Adafruit LSM6DS at version 4.7.3 in folder: C:\Users\Andrew\Documents\Arduino\libraries\Adafruit_LSM6DS Using library Adafruit BusIO at version 1.16.1 in folder: C:\Users\Andrew\Documents\Arduino\libraries\Adafruit_BusIO Using library Adafruit Unified Sensor at version 1.1.14 in folder: C:\Users\Andrew\Documents\Arduino\libraries\Adafruit_Unified_Sensor Using library SensorFusion at version 1.0.6 in folder: C:\Users\Andrew\Documents\Arduino\libraries\SensorFusion Using library ResponsiveAnalogRead at version 1.2.1 in folder: C:\Users\Andrew\Documents\Arduino\libraries\ResponsiveAnalogRead Using library Adafruit Little File System Libraries at version 0.11.0 in folder: C:\Users\Andrew\AppData\Local\Arduino15\packages\adafruit\hardware\nrf52\1.6.1\libraries\Adafruit_LittleFS Using library Adafruit Internal File System on Bluefruit nRF52 at version 0.11.0 in folder: C:\Users\Andrew\AppData\Local\Arduino15\packages\adafruit\hardware\nrf52\1.6.1\libraries\InternalFileSytem

[MrMep]

I think I found the bug:

https://github.com/adafruit/Adafruit_TinyUSB_Arduino/blob/e0345385707c774f658d7312bb47c67e434166a2/src/device/usbd.c#L560

      case DCD_EVENT_SETUP_RECEIVED:
        _usbd_dev.setup_count--;
        TU_LOG_BUF(CFG_TUD_LOG_LEVEL, &event.setup_received, 8);
        if (_usbd_dev.setup_count) {
          TU_LOG_USBD("  Skipped since there is other SETUP in queue\r\n");
          break;
        }

For some still unknown reasons, setup_count is > 0 when the timeout occurs. I suspect the first setup request fails later in the code and a second one is sent, but the lines above stop it. This is actually a new check introduced in 3.3.2/3.
I suspect the reason for the multiple setup requests is in our code (or related libraries): the old TinyUSB versions didn't have that check, so eventually the usb setup succeed.

It is enough to comment out thebreak; above to have everything working normally.

[amowry]

Amazing, thanks! I guess the next question is: Is it something that I did wrong, or something in a library that causes this?

[MrMep]

PR 16 should solve the other issue with MIDI Library 5.0.2.

[MrMep]

Amazing, thanks! I guess the next question is: Is it something that I did wrong, or something in a library that causes this?

Good question... There's no mention in my PC logs of a setup request gone wrong, so it's still mysterious...
I doubt it is something new in the TinyUSB Library, at least not from 3.1.1 to 3.1.3.
Maybe it was always there but it didn't cause visible problems. There seems to be a race condition in the USB setup request, but a volatile var (setup_count) doesn't cut it (does it remember anything to you? ;)
I haven't given up yet...