Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NRF: USB Disconnect / Reconnect / Enumeration fails during sleep #2855

Closed
xobs opened this issue May 5, 2020 · 16 comments
Closed

NRF: USB Disconnect / Reconnect / Enumeration fails during sleep #2855

xobs opened this issue May 5, 2020 · 16 comments

Comments

@xobs
Copy link
Collaborator

xobs commented May 5, 2020

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
Copy link
Collaborator Author

xobs commented May 5, 2020

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
Copy link
Collaborator Author

xobs commented May 5, 2020

image

@tannewt
Copy link
Member

tannewt commented May 5, 2020

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

@hathach
Copy link
Member

hathach commented May 5, 2020

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
Copy link
Collaborator Author

xobs commented May 6, 2020

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
Copy link
Member

tannewt commented May 6, 2020

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
Copy link
Collaborator Author

xobs commented May 7, 2020

It does work if the WFI call is commented out.

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

@xobs
Copy link
Collaborator Author

xobs commented May 7, 2020

@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
Copy link
Collaborator Author

xobs commented May 7, 2020

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
Copy link
Collaborator Author

xobs commented May 8, 2020

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
Copy link
Collaborator Author

xobs commented May 8, 2020

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.

@xobs
Copy link
Collaborator Author

xobs commented May 8, 2020

Looks like it's not possible to run tud_task() with interrupts disabled.

@hathach do you have any suggestions for how we could do this?

@xobs
Copy link
Collaborator Author

xobs commented May 8, 2020

I've applied this patch to my local copy of tinyusb, which causes it to poll the interrupt handler if interrupts are disabled. This seems to prevent the deadlock:

diff --git a/src/portable/nordic/nrf5x/dcd_nrf5x.c b/src/portable/nordic/nrf5x/dcd_nrf5x.c
index 12435ea2..acc1af58 100644
--- a/src/portable/nordic/nrf5x/dcd_nrf5x.c
+++ b/src/portable/nordic/nrf5x/dcd_nrf5x.c
@@ -101,7 +101,11 @@ static void edpt_dma_start(volatile uint32_t* reg_startep)
     else
     {
       // Otherwise simply block wait
-      while ( _dcd.dma_running )  { }
+      while ( _dcd.dma_running )  {
+        // Manually poll the handler if interrupts are disabled
+        if (!__get_PRIMASK())
+          dcd_int_handler(0);
+      }
     }
   }

@xobs
Copy link
Collaborator Author

xobs commented May 8, 2020

I submitted a PR for this here: hathach/tinyusb#396

I've also found additional places where RUN_BACKGROUND_TASKS assumes interrupts are enabled, These have been rolled into #2868

xobs added a commit to simmel-project/circuitpython that referenced this issue May 8, 2020
Also, run background tasks with interrupts disabled.  This ensures
that any buffers are drained, and if an interrupt arrives after
buffers are drained but before the WFI is executed then the WFI
instruction will return immediately.

This fixes adafruit#2855 on NRF.

Signed-off-by: Sean Cross <sean@xobs.io>
@tannewt
Copy link
Member

tannewt commented May 8, 2020

Is the cause for this a race between the last background task run and the wfi call? WFI should work fine with interrupts enabled but for TinyUSB that means work may have been queued but not done.

@xobs
Copy link
Collaborator Author

xobs commented May 9, 2020

WFI does work fine if interrupts are enabled, but without disabling interrupts you can never be sure that there isn't pending data before issuing WFI For example:

sleep_until_time:
       ; ... do some prep involving the RTC
       bl         usb_background
       wfi

usb_background:
       ; ... service USB buffers
       bx lr

Even though usb_background() drains the buffer, you still could have an interrupt arrive between the bx lr and the wfi instruction. If interrupts are enabled, then that will get serviced and there will be data waiting in the queue. If that is a packet from the host, then you will go to sleep without responding to that packet and the host will time out the device.

The solution is to disable interrupts, flush buffers, and issue wfi. If there's a pending interrupt it will return immediately, allowing you to re-enable interrupts and have it serviced.

xobs added a commit to simmel-project/circuitpython that referenced this issue May 14, 2020
Also, run background tasks with interrupts disabled.  This ensures
that any buffers are drained, and if an interrupt arrives after
buffers are drained but before the WFI is executed then the WFI
instruction will return immediately.

This fixes adafruit#2855 on NRF.

Signed-off-by: Sean Cross <sean@xobs.io>
xobs added a commit to simmel-project/circuitpython that referenced this issue May 15, 2020
Also, run background tasks with interrupts disabled.  This ensures
that any buffers are drained, and if an interrupt arrives after
buffers are drained but before the WFI is executed then the WFI
instruction will return immediately.

This fixes adafruit#2855 on NRF.

Signed-off-by: Sean Cross <sean@xobs.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants