NRF: USB Disconnect / Reconnect / Enumeration fails during sleep

[xobs]

With the most recent patches, issuing time.sleep(x) issues a wfi instruction. This aggressively puts the CPU to sleep. However, this appears to cause USB to no longer enumerate. While this is not an issue with a device that's powered off of USB, if a device has its own battery, then this will prevent the device from enumerating during sleep.

Steps to reproduce

The following code.py should trigger this bug:

from time import sleep
sleep(60)

[xobs]

I believe at least part of the problem is due to the fact that there doesn't seem to be anything listening to the USBDETECTED and USBREMOVED events. This patch adds that in:

diff --git a/ports/nrf/supervisor/port.c b/ports/nrf/supervisor/port.c
index 539a9cf90..24a0c4bdd 100644
--- a/ports/nrf/supervisor/port.c
+++ b/ports/nrf/supervisor/port.c
@@ -67,6 +67,10 @@ static void power_warning_handler(void) {

 const nrfx_rtc_t rtc_instance = NRFX_RTC_INSTANCE(2);

+#if NRF_POWER_HAS_USBREG
+extern void tusb_hal_nrf_power_event(uint32_t event);
+#endif
+
 const nrfx_rtc_config_t rtc_config = {
     .prescaler = RTC_FREQ_TO_PRESCALER(0x8000),
     .reliable = 0,
@@ -115,6 +119,12 @@ safe_mode_t port_init(void) {
     nrfx_power_pof_init(&power_failure_config);
     nrfx_power_pof_enable(&power_failure_config);

+    #if NRF_POWER_HAS_USBREG
+    const nrfx_power_usbevt_config_t usbevt_config = { .handler = ((nrfx_power_usb_event_handler_t) tusb_hal_nrf_power_event) };
+    nrfx_power_usbevt_init(&usbevt_config);
+    nrfx_power_usbevt_enable();
+    #endif
+
     nrf_peripherals_enable_cache();

     // Configure millisecond timer initialization.

That at least gets it part of the way there. However, it still appears as though the device isn't responding to USB properly. In particular, while the config descriptor and initial string descriptor get transferred, the device doesn't appear to be acknowledging them.
enumerate-with-wfi.zip

[xobs]

[tannewt]

@hathach Does tinyusb use interrupts for these USB events? Sleep will wake and call tud_task after any interrupt.

[hathach]

TinyUSB requires application to call tusb_hal_nrf_power_event() within the power handler.
https://github.com/hathach/tinyusb/blob/master/src/portable/nordic/nrf5x/dcd_nrf5x.c#L630

The power IRQHandler is used and shared with SoftDevice therefore it cannot be actively handled when SD is enabled. The above modification by @xobs is part of the initial init_usb_hardware() when enabling USB (with SD not enabled yet). I am not sure how WFI() affect the power peripheral, but in case it does, re-init is probably needed.

[xobs]

I thought it was odd that it seemed to somewhat work even without that patch.

The strange part is I can see the events fire, and I see the tusb_hal_nrf_power_event() function fire with all three kinds of events, but it still just does not work. Do we need to be calling tusb_task() more often now? Should WFI be disabled when not connected to VUSB?

[tannewt]

I thought it was odd that it seemed to somewhat work even without that patch.

The strange part is I can see the events fire, and I see the tusb_hal_nrf_power_event() function fire with all three kinds of events, but it still just does not work. Do we need to be calling tusb_task() more often now?

My guess is that there is an interrupt we need to enable so that it wakes up from WFI. Did you confirm that it works when the actual WFI call is commented out? This looks very similar to the SAMD21 issue where a SETUP packet interrupt is piggybacking on a OUT interrupt. It still failed when WFI was commented out because it was a timing issue.

Should WFI be disabled when not connected to VUSB?

Definitely not. It's only really useful when on battery. When on USB you have an external power supply.

[xobs]

It does work if the WFI call is commented out.

Let me look through the USB interrupts and see what's going on.

[xobs]

@hathach You're right, I didn't see that the event was already being hooked. So the patch I made probably doesn't seem necessary.

However, it does appear as though the OUT data isn't getting ACKed for whatever reason. And it's always the same descriptor. At least it's consistent.

The contents of the USBD_INTEN register prior to unplugging:

(gdb) x 0x40027300
0x40027300:     0x0185d57d
(gdb)

And after plugging back in, while the host is waiting for the device to ACK the 5th SETUP packet:

(gdb) x 0x40027300
0x40027300:     0x01801405
(gdb)

[xobs]

When I connect it when it's in this state, this is the output I receive:

USBD Unplugged



USBD Bus Reset
USBD Setup Received 80 06 00 01 00 00 40 00
  Get Descriptor Device
  Queue EP 80 with 18 bytes
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Bus Reset
USBD Setup Received 80 06 00 01 00 00 12 00
  Get Descriptor Device
  Queue EP 80 with 18 bytes
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 00 02 00 00 FF 00
  Get Descriptor Configuration[0]
  Queue EP 80 with 64 bytes
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 64 bytes
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 64 bytes
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 26 bytes
USBD Xfer Complete on EP 80 with 26 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 01 03 09 04 FF 00
  Get Descriptor String[1]
  Queue EP 80 with 34 bytes
USBD Xfer Complete on EP 80 with 34 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 00 03 00 00 FF 00
  Get Descriptor String[0]
  Queue EP 80 with 4 bytes
USBD Xfer Complete on EP 80 with 4 bytes






USBD Setup Received 80 06 00 02 00 00 DA 00
  Get Descriptor Configuration[0]
  Queue EP 80 with 64 bytes
USBD Bus Reset
USBD Setup Received 80 06 00 01 00 00 40 00
  Get Descriptor Device
  Queue EP 80 with 18 bytes
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Bus Reset
USBD Setup Received 80 06 00 01 00 00 12 00
  Get Descriptor Device
  Queue EP 80 with 18 bytes
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 00 01 00 00 12 00
  Get Descriptor Device
  Queue EP 80 with 18 bytes
USBD Xfer Complete on EP 80 with 18 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 00 02 00 00 09 00
  Get Descriptor Configuration[0]
  Queue EP 80 with 9 bytes
USBD Xfer Complete on EP 80 with 9 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes









USBD Setup Received 80 06 00 02 00 00 DA 00
  Get Descriptor Configuration[0]
  Queue EP 80 with 64 bytes
USBD Setup Received 80 06 00 02 00 00 09 00
  Get Descriptor Configuration[0]
  Queue EP 80 with 9 bytes
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 64 bytes
USBD Setup Received 80 06 00 02 00 00 09 00
  Get Descriptor Configuration[0]
  Queue EP 80 with 9 bytes
USBD Xfer Complete on EP 80 with 9 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 00 02 00 00 DA 00
  Get Descriptor Configuration[0]
  Queue EP 80 with 64 bytes
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 64 bytes
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 64 bytes
USBD Xfer Complete on EP 80 with 64 bytes
  Queue EP 80 with 26 bytes
USBD Xfer Complete on EP 80 with 26 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 00 09 01 00 00 00 00 00
  Set Configuration










USBD Xfer Complete on EP 80 with 4 bytes
  Queue EP 00 with zlp Status
USBD Setup Received 00 01 01 00 00 00 00 00
  Clear Feature
  Queue EP 80 with zlp Status
USBD Xfer Complete on EP 80 with 0 bytes
USBD Setup Received 80 06 06 03 09 04 04 00
  Get Descriptor String[6]
  Queue EP 80 with 4 bytes
USBD Xfer Complete on EP 80 with 4 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 06 03 09 04 36 00
  Get Descriptor String[6]
  Queue EP 80 with 54 bytes
USBD Xfer Complete on EP 80 with 54 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 07 03 09 04 04 00
  Get Descriptor String[7]
  Queue EP 80 with 4 bytes
USBD Xfer Complete on EP 80 with 4 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 07 03 09 04 24 00
  Get Descriptor String[7]
  Queue EP 80 with 36 bytes
USBD Xfer Complete on EP 80 with 36 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 0B 03 09 04 04 00
  Get Descriptor String[11]
  Queue EP 80 with 4 bytes
USBD Xfer Complete on EP 80 with 4 bytes
  80







USBD Xfer Complete on EP 80 with 2 bytes
  Queue EP 00 with zlp Status
USBD Setup Received 80 06 00 03 00 00 02 00
  Get Descriptor String[0]
  Queue EP 80 with 2 bytes
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 00 03 00 00 02 00
  Get Descriptor String[0]
  Queue EP 80 with 2 bytes
USBD Xfer Complete on EP 80 with 2 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 00 03 00 00 04 00
  Get Descriptor String[0]
  Queue EP 80 with 4 bytes
USBD Xfer Complete on EP 80 with 4 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes







USBD Setup Received 80 06 01 03 09 04 02 00
  Get Descriptor String[1]
  Queue EP 80 with 2 bytes
USBD Setup Received 80 06 01 03 09 04 02 00
  Get Descriptor String[1]
  Queue EP 80 with 2 bytes
USBD Xfer Complete on EP 80 with 2 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received 80 06 01 03 09 04 22 00
  Get Descriptor String[1]
  Queue EP 80 with 34 bytes
USBD Xfer Complete on EP 80 with 34 bytes
  Queue EP 00 with zlp Status
USBD Xfer Complete on EP 00 with 0 bytes
USBD Setup Received A1 FE 00 00 02 00 01 00
  MSC control request
  Queue EP 80 with 1 bytes

I have placed multiple "\n" entries where the host is waiting for the device to ACK an IN packet.

Note that this board is being debugged by bit-banging SWD on a raspberry pi, so I needed to hack in rtt support. I think this is accurate, though.

Also, my USB Beagle is in need of a new inductor. It is incredibly flaky right now, making it hard to get reliable measurements, particularly when it involves a lot of unplugging and plugging in.

[xobs]

In looking at https://github.com/hathach/tinyusb/blob/master/src/portable/nordic/nrf5x/dcd_nrf5x.c#L292-L297 it almost seems as though this isn't actually firing.

One thing I can see is that the _usbd_q is getting written to but not read from. If I break into the debugger while it's doing wfi, I see that wr_idx != rd_idx:

(gdb) p *_usbd_q
$10 = {
  role = 1 '\001',
  ff = {
    buffer = 0x2000b740 <_usbd_qdef_buf> "",
    depth = 16,
    item_size = 12,
    overwritable = false,
    count = 1,
    wr_idx = 7,
    rd_idx = 6
  }
}
(gdb)

[xobs]

The issue is that interrupts were still enabled while calling wfi.

This PR adds a patch to disable interrupts (and run background tasks with interrupts disabled to ensure buffers are drained) on the nrf platform: #2868

I suspect other platforms will have similar subtle issues.