correct EHCI reporting failed xfer (instead of stalled) when device is unplugged

9 files changed, 74 insertions, 38 deletions

diff --git a/src/class/cdc/cdc_host.c b/src/class/cdc/cdc_host.c
index fe3691bf4..9ff666ed4 100644
--- a/src/class/cdc/cdc_host.c
+++ b/src/class/cdc/cdc_host.c
@@ -35,8 +35,7 @@
 
 // Debug level, TUSB_CFG_DEBUG must be at least this level for debug message
 #define CDCH_DEBUG   2
-
-#define TU_LOG_CDCH(...)   TU_LOG(CDCH_DEBUG, __VA_ARGS__)
+#define TU_LOG_DRV(...)   TU_LOG(CDCH_DEBUG, __VA_ARGS__)
 
 //--------------------------------------------------------------------+
 // Host CDC Interface
@@ -537,6 +536,8 @@ void cdch_close(uint8_t daddr)
     cdch_interface_t* p_cdc = &cdch_data[idx];
     if (p_cdc->daddr == daddr)
     {
+      TU_LOG_DRV("  CDCh close addr = %u index = %u\r\n", daddr, idx);
+
       // Invoke application callback
       if (tuh_cdc_umount_cb) tuh_cdc_umount_cb(idx);
 
@@ -804,7 +805,7 @@ static void acm_process_config(tuh_xfer_t* xfer)
 
 static bool acm_set_control_line_state(cdch_interface_t* p_cdc, uint16_t line_state, tuh_xfer_cb_t complete_cb, uintptr_t user_data) {
   TU_VERIFY(p_cdc->acm_capability.support_line_request);
-  TU_LOG_CDCH("CDC ACM Set Control Line State\r\n");
+  TU_LOG_DRV("CDC ACM Set Control Line State\r\n");
 
   tusb_control_request_t const request = {
     .bmRequestType_bit = {
@@ -834,7 +835,7 @@ static bool acm_set_control_line_state(cdch_interface_t* p_cdc, uint16_t line_st
 }
 
 static bool acm_set_line_coding(cdch_interface_t* p_cdc, cdc_line_coding_t const* line_coding, tuh_xfer_cb_t complete_cb, uintptr_t user_data) {
-  TU_LOG_CDCH("CDC ACM Set Line Conding\r\n");
+  TU_LOG_DRV("CDC ACM Set Line Conding\r\n");
 
   tusb_control_request_t const request = {
     .bmRequestType_bit = {
@@ -894,7 +895,7 @@ static bool ftdi_open(uint8_t daddr, const tusb_desc_interface_t *itf_desc, uint
   cdch_interface_t * p_cdc = make_new_itf(daddr, itf_desc);
   TU_VERIFY(p_cdc);
 
-  TU_LOG_CDCH("FTDI opened\r\n");
+  TU_LOG_DRV("FTDI opened\r\n");
 
   p_cdc->serial_drid = SERIAL_DRIVER_FTDI;
 
@@ -938,7 +939,7 @@ static bool ftdi_sio_reset(cdch_interface_t* p_cdc, tuh_xfer_cb_t complete_cb, u
 
 static bool ftdi_sio_set_modem_ctrl(cdch_interface_t* p_cdc, uint16_t line_state, tuh_xfer_cb_t complete_cb, uintptr_t user_data)
 {
-  TU_LOG_CDCH("CDC FTDI Set Control Line State\r\n");
+  TU_LOG_DRV("CDC FTDI Set Control Line State\r\n");
   p_cdc->user_control_cb = complete_cb;
   TU_ASSERT(ftdi_sio_set_request(p_cdc, FTDI_SIO_MODEM_CTRL, 0x0300 | line_state,
                                  complete_cb ? cdch_internal_control_complete : NULL, user_data));
@@ -974,7 +975,7 @@ static uint32_t ftdi_232bm_baud_to_divisor(uint32_t baud)
 static bool ftdi_sio_set_baudrate(cdch_interface_t* p_cdc, uint32_t baudrate, tuh_xfer_cb_t complete_cb, uintptr_t user_data)
 {
   uint16_t const divisor = (uint16_t) ftdi_232bm_baud_to_divisor(baudrate);
-  TU_LOG_CDCH("CDC FTDI Set BaudRate = %lu, divisor = 0x%04x\n", baudrate, divisor);
+  TU_LOG_DRV("CDC FTDI Set BaudRate = %lu, divisor = 0x%04x\n", baudrate, divisor);
 
   p_cdc->user_control_cb = complete_cb;
   _ftdi_requested_baud = baudrate;
@@ -1061,7 +1062,7 @@ static bool cp210x_open(uint8_t daddr, tusb_desc_interface_t const *itf_desc, ui
   cdch_interface_t * p_cdc = make_new_itf(daddr, itf_desc);
   TU_VERIFY(p_cdc);
 
-  TU_LOG_CDCH("CP210x opened\r\n");
+  TU_LOG_DRV("CP210x opened\r\n");
   p_cdc->serial_drid = SERIAL_DRIVER_CP210X;
 
   // endpoint pair
@@ -1109,7 +1110,7 @@ static bool cp210x_ifc_enable(cdch_interface_t* p_cdc, uint16_t enabled, tuh_xfe
 }
 
 static bool cp210x_set_baudrate(cdch_interface_t* p_cdc, uint32_t baudrate, tuh_xfer_cb_t complete_cb, uintptr_t user_data) {
-  TU_LOG_CDCH("CDC CP210x Set BaudRate = %lu\n", baudrate);
+  TU_LOG_DRV("CDC CP210x Set BaudRate = %lu\n", baudrate);
   uint32_t baud_le = tu_htole32(baudrate);
   p_cdc->user_control_cb = complete_cb;
   return cp210x_set_request(p_cdc, CP210X_SET_BAUDRATE, 0, (uint8_t *) &baud_le, 4,
@@ -1118,7 +1119,7 @@ static bool cp210x_set_baudrate(cdch_interface_t* p_cdc, uint32_t baudrate, tuh_
 
 static bool cp210x_set_modem_ctrl(cdch_interface_t* p_cdc, uint16_t line_state, tuh_xfer_cb_t complete_cb, uintptr_t user_data)
 {
-  TU_LOG_CDCH("CDC CP210x Set Control Line State\r\n");
+  TU_LOG_DRV("CDC CP210x Set Control Line State\r\n");
   p_cdc->user_control_cb = complete_cb;
   return cp210x_set_request(p_cdc, CP210X_SET_MHS, 0x0300 | line_state, NULL, 0,
                             complete_cb ? cdch_internal_control_complete : NULL, user_data);
diff --git a/src/class/hid/hid_host.c b/src/class/hid/hid_host.c
index d95d3ef35..3a491937a 100644
--- a/src/class/hid/hid_host.c
+++ b/src/class/hid/hid_host.c
@@ -33,6 +33,10 @@
 
 #include "hid_host.h"
 
+// Debug level, TUSB_CFG_DEBUG must be at least this level for debug message
+#define HIDH_DEBUG   2
+#define TU_LOG_DRV(...)   TU_LOG(HIDH_DEBUG, __VA_ARGS__)
+
 //--------------------------------------------------------------------+
 // MACRO CONSTANT TYPEDEF
 //--------------------------------------------------------------------+
@@ -207,7 +211,7 @@ static void set_protocol_complete(tuh_xfer_t* xfer)
 
 static bool _hidh_set_protocol(uint8_t daddr, uint8_t itf_num, uint8_t protocol, tuh_xfer_cb_t complete_cb, uintptr_t user_data)
 {
-  TU_LOG2("HID Set Protocol = %d\r\n", protocol);
+  TU_LOG_DRV("HID Set Protocol = %d\r\n", protocol);
 
   tusb_control_request_t const request =
   {
@@ -246,7 +250,7 @@ bool tuh_hid_set_protocol(uint8_t daddr, uint8_t idx, uint8_t protocol)
 
 static void set_report_complete(tuh_xfer_t* xfer)
 {
-  TU_LOG2("HID Set Report complete\r\n");
+  TU_LOG_DRV("HID Set Report complete\r\n");
 
   if (tuh_hid_set_report_complete_cb)
   {
@@ -266,7 +270,7 @@ bool tuh_hid_set_report(uint8_t daddr, uint8_t idx, uint8_t report_id, uint8_t r
   hidh_interface_t* p_hid = get_hid_itf(daddr, idx);
   TU_VERIFY(p_hid);
 
-  TU_LOG2("HID Set Report: id = %u, type = %u, len = %u\r\n", report_id, report_type, len);
+  TU_LOG_DRV("HID Set Report: id = %u, type = %u, len = %u\r\n", report_id, report_type, len);
 
   tusb_control_request_t const request =
   {
@@ -298,7 +302,7 @@ bool tuh_hid_set_report(uint8_t daddr, uint8_t idx, uint8_t report_id, uint8_t r
 static bool _hidh_set_idle(uint8_t daddr, uint8_t itf_num, uint16_t idle_rate, tuh_xfer_cb_t complete_cb, uintptr_t user_data)
 {
   // SET IDLE request, device can stall if not support this request
-  TU_LOG2("HID Set Idle \r\n");
+  TU_LOG_DRV("HID Set Idle \r\n");
 
   tusb_control_request_t const request =
   {
@@ -367,7 +371,7 @@ bool tuh_hid_send_ready(uint8_t dev_addr, uint8_t idx)
 
 bool tuh_hid_send_report(uint8_t daddr, uint8_t idx, uint8_t report_id, const void* report, uint16_t len)
 {
-  TU_LOG2("HID Send Report %d\r\n", report_id);
+  TU_LOG_DRV("HID Send Report %d\r\n", report_id);
 
   hidh_interface_t* p_hid = get_hid_itf(daddr, idx);
   TU_VERIFY(p_hid);
@@ -430,7 +434,7 @@ bool hidh_xfer_cb(uint8_t daddr, uint8_t ep_addr, xfer_result_t result, uint32_t
 
   if ( dir == TUSB_DIR_IN )
   {
-    TU_LOG2("  Get Report callback (%u, %u)\r\n", daddr, idx);
+    TU_LOG_DRV("  Get Report callback (%u, %u)\r\n", daddr, idx);
     TU_LOG3_MEM(p_hid->epin_buf, xferred_bytes, 2);
     tuh_hid_report_received_cb(daddr, idx, p_hid->epin_buf, (uint16_t) xferred_bytes);
   }else
@@ -448,8 +452,9 @@ void hidh_close(uint8_t daddr)
     hidh_interface_t* p_hid = &_hidh_itf[i];
     if (p_hid->daddr == daddr)
     {
-       if(tuh_hid_umount_cb) tuh_hid_umount_cb(daddr, i);
-       p_hid->daddr = 0;
+      TU_LOG_DRV("  HIDh close addr = %u index = %u\r\n", daddr, i);
+      if(tuh_hid_umount_cb) tuh_hid_umount_cb(daddr, i);
+      p_hid->daddr = 0;
     }
   }
 }
@@ -465,7 +470,7 @@ bool hidh_open(uint8_t rhport, uint8_t daddr, tusb_desc_interface_t const *desc_
 
   TU_VERIFY(TUSB_CLASS_HID == desc_itf->bInterfaceClass);
 
-  TU_LOG2("[%u] HID opening Interface %u\r\n", daddr, desc_itf->bInterfaceNumber);
+  TU_LOG_DRV("[%u] HID opening Interface %u\r\n", daddr, desc_itf->bInterfaceNumber);
 
   // len = interface + hid + n*endpoints
   uint16_t const drv_len = (uint16_t) (sizeof(tusb_desc_interface_t) + sizeof(tusb_hid_descriptor_hid_t) +
@@ -592,7 +597,7 @@ static void process_set_config(tuh_xfer_t* xfer)
       // using usbh enumeration buffer since report descriptor can be very long
       if( p_hid->report_desc_len > CFG_TUH_ENUMERATION_BUFSIZE )
       {
-        TU_LOG2("HID Skip Report Descriptor since it is too large %u bytes\r\n", p_hid->report_desc_len);
+        TU_LOG_DRV("HID Skip Report Descriptor since it is too large %u bytes\r\n", p_hid->report_desc_len);
 
         // Driver is mounted without report descriptor
         config_driver_mount_complete(daddr, idx, NULL, 0);
@@ -763,7 +768,7 @@ uint8_t tuh_hid_parse_report_descriptor(tuh_hid_report_info_t* report_info_arr,
   for ( uint8_t i = 0; i < report_num; i++ )
   {
     info = report_info_arr+i;
-    TU_LOG2("%u: id = %u, usage_page = %u, usage = %u\r\n", i, info->report_id, info->usage_page, info->usage);
+    TU_LOG_DRV("%u: id = %u, usage_page = %u, usage = %u\r\n", i, info->report_id, info->usage_page, info->usage);
   }
 
   return report_num;
diff --git a/src/class/msc/msc_host.c b/src/class/msc/msc_host.c
index 1b48813ec..138443de4 100644
--- a/src/class/msc/msc_host.c
+++ b/src/class/msc/msc_host.c
@@ -35,7 +35,6 @@
 
 // Debug level, TUSB_CFG_DEBUG must be at least this level for debug message
 #define MSCH_DEBUG   2
-
 #define TU_LOG_MSCH(...)   TU_LOG(MSCH_DEBUG, __VA_ARGS__)
 
 //--------------------------------------------------------------------+
@@ -82,6 +81,7 @@ CFG_TUH_MEM_SECTION static msch_interface_t _msch_itf[CFG_TUH_DEVICE_MAX];
 CFG_TUH_MEM_SECTION CFG_TUH_MEM_ALIGN
 static uint8_t _msch_buffer[sizeof(scsi_inquiry_resp_t)];
 
+// FIXME potential nul reference
 TU_ATTR_ALWAYS_INLINE
 static inline msch_interface_t* get_itf(uint8_t dev_addr)
 {
@@ -305,11 +305,15 @@ void msch_init(void)
 void msch_close(uint8_t dev_addr)
 {
   TU_VERIFY(dev_addr <= CFG_TUH_DEVICE_MAX, );
-
   msch_interface_t* p_msc = get_itf(dev_addr);
+  TU_VERIFY(p_msc->configured, );
+
+  TU_LOG_MSCH("  MSCh close addr = %d\r\n", dev_addr);
 
   // invoke Application Callback
-  if (p_msc->mounted && tuh_msc_umount_cb) tuh_msc_umount_cb(dev_addr);
+  if (p_msc->mounted) {
+    if(tuh_msc_umount_cb) tuh_msc_umount_cb(dev_addr);
+  }
 
   tu_memclr(p_msc, sizeof(msch_interface_t));
 }
diff --git a/src/common/tusb_debug.h b/src/common/tusb_debug.h
index 82f682043..36507041f 100644
--- a/src/common/tusb_debug.h
+++ b/src/common/tusb_debug.h
@@ -46,6 +46,7 @@
 #if CFG_TUSB_DEBUG >= 2
 extern char const* const tu_str_speed[];
 extern char const* const tu_str_std_request[];
+extern char const* const tu_str_xfer_result[];
 #endif
 
 void tu_print_mem(void const *buf, uint32_t count, uint8_t indent);
diff --git a/src/device/usbd_control.c b/src/device/usbd_control.c
index ea8eef285..2afe967b5 100644
--- a/src/device/usbd_control.c
+++ b/src/device/usbd_control.c
@@ -32,7 +32,10 @@
 #include "tusb.h"
 #include "device/usbd_pvt.h"
 
-#if CFG_TUSB_DEBUG >= 2
+// Debug level of USBD Control
+#define USBD_CONTROL_DEBUG   2
+
+#if CFG_TUSB_DEBUG >= USBD_CONTROL_DEBUG
 extern void usbd_driver_print_control_complete_name(usbd_control_xfer_cb_t callback);
 #endif
 
@@ -188,7 +191,7 @@ bool usbd_control_xfer_cb (uint8_t rhport, uint8_t ep_addr, xfer_result_t result
   {
     TU_VERIFY(_ctrl_xfer.buffer);
     memcpy(_ctrl_xfer.buffer, _usbd_ctrl_buf, xferred_bytes);
-    TU_LOG_MEM(2, _usbd_ctrl_buf, xferred_bytes, 2);
+    TU_LOG_MEM(USBD_CONTROL_DEBUG, _usbd_ctrl_buf, xferred_bytes, 2);
   }
 
   _ctrl_xfer.total_xferred += (uint16_t) xferred_bytes;
@@ -205,7 +208,7 @@ bool usbd_control_xfer_cb (uint8_t rhport, uint8_t ep_addr, xfer_result_t result
     // callback can still stall control in status phase e.g out data does not make sense
     if ( _ctrl_xfer.complete_cb )
     {
-      #if CFG_TUSB_DEBUG >= 2
+      #if CFG_TUSB_DEBUG >= USBD_CONTROL_DEBUG
       usbd_driver_print_control_complete_name(_ctrl_xfer.complete_cb);
       #endif
 
diff --git a/src/host/hub.c b/src/host/hub.c
index 386ad6aae..85bf22b3e 100644
--- a/src/host/hub.c
+++ b/src/host/hub.c
@@ -33,6 +33,10 @@
 #include "usbh_classdriver.h"
 #include "hub.h"
 
+// Debug level, TUSB_CFG_DEBUG must be at least this level for debug message
+#define HUB_DEBUG   2
+#define TU_LOG_DRV(...)   TU_LOG(HUB_DEBUG, __VA_ARGS__)
+
 //--------------------------------------------------------------------+
 // MACRO CONSTANT TYPEDEF
 //--------------------------------------------------------------------+
@@ -218,7 +222,10 @@ void hub_close(uint8_t dev_addr)
   TU_VERIFY(dev_addr > CFG_TUH_DEVICE_MAX, );
   hub_interface_t* p_hub = get_itf(dev_addr);
 
-  if (p_hub->ep_in) tu_memclr(p_hub, sizeof( hub_interface_t));
+  if (p_hub->ep_in) {
+    TU_LOG_DRV("  HUB close addr = %d\r\n", dev_addr);
+    tu_memclr(p_hub, sizeof( hub_interface_t));
+  }
 }
 
 bool hub_edpt_status_xfer(uint8_t dev_addr)
diff --git a/src/host/usbh.c b/src/host/usbh.c
index 24ce47a7f..4cfc7c5c2 100644
--- a/src/host/usbh.c
+++ b/src/host/usbh.c
@@ -61,6 +61,8 @@ typedef struct
   uint8_t hub_addr;
   uint8_t hub_port;
   uint8_t speed;
+
+  // enumeration is in progress, done when all interfaces are configured
   volatile uint8_t enumerating;
 
 //  struct TU_ATTR_PACKED {
@@ -436,7 +438,8 @@ void tuh_task_ext(uint32_t timeout_ms, bool in_isr)
         uint8_t const epnum   = tu_edpt_number(ep_addr);
         uint8_t const ep_dir  = tu_edpt_dir(ep_addr);
 
-        TU_LOG_USBH("on EP %02X with %u bytes\r\n", ep_addr, (unsigned int) event.xfer_complete.len);
+        TU_LOG_USBH("on EP %02X with %u bytes %s\r\n", ep_addr, (unsigned int) event.xfer_complete.len,
+                    tu_str_xfer_result[event.xfer_complete.result]);
 
         if (event.dev_addr == 0)
         {
@@ -866,6 +869,10 @@ TU_ATTR_FAST_FUNC void hcd_event_handler(hcd_event_t const* event, bool in_isr)
 {
   switch (event->event_id)
   {
+//    case HCD_EVENT_DEVICE_REMOVE:
+//
+//      break;
+
     default:
       osal_queue_send(_usbh_q, event, in_isr);
     break;
@@ -1128,30 +1135,28 @@ static void process_device_unplugged(uint8_t rhport, uint8_t hub_addr, uint8_t h
     usbh_device_t* dev = &_usbh_devices[dev_id];
     uint8_t const dev_addr = dev_id+1;
 
-    // TODO Hub multiple level
     if (dev->rhport == rhport   &&
         (hub_addr == 0 || dev->hub_addr == hub_addr) && // hub_addr = 0 means roothub
         (hub_port == 0 || dev->hub_port == hub_port) && // hub_port = 0 means all devices of downstream hub
         dev->connected)
     {
-      TU_LOG_USBH("  Address = %u\r\n", dev_addr);
+      TU_LOG_USBH("Device unplugged address = %u\r\n", dev_addr);
 
       if (is_hub_addr(dev_addr))
       {
-        TU_LOG(USBH_DEBUG, "HUB address = %u is unmounted\r\n", dev_addr);
+        TU_LOG(USBH_DEBUG, "  is a HUB device\r\n", dev_addr);
         // If the device itself is a usb hub, unplug downstream devices.
         // FIXME un-roll recursive calls to prevent potential stack overflow
         process_device_unplugged(rhport, dev_addr, 0);
       }else
       {
-        // Invoke callback before closing driver
+        // Invoke callback before closing driver (maybe call it later ?)
         if (tuh_umount_cb) tuh_umount_cb(dev_addr);
       }
 
       // Close class driver
       for (uint8_t drv_id = 0; drv_id < USBH_CLASS_DRIVER_COUNT; drv_id++)
       {
-        TU_LOG_USBH("%s close\r\n", usbh_class_drivers[drv_id].name);
         usbh_class_drivers[drv_id].close(dev_addr);
       }
 
@@ -1449,6 +1454,7 @@ static uint8_t get_new_address(bool is_hub)
 {
   uint8_t start;
   uint8_t end;
+
   if ( is_hub )
   {
     start = CFG_TUH_DEVICE_MAX;
@@ -1459,7 +1465,7 @@ static uint8_t get_new_address(bool is_hub)
     end   = start + CFG_TUH_DEVICE_MAX;
   }
 
-  for ( uint8_t idx = start; idx < end; idx++)
+  for (uint8_t idx = start; idx < end; idx++)
   {
     if (!_usbh_devices[idx].connected) return (idx+1);
   }
diff --git a/src/portable/ehci/ehci.c b/src/portable/ehci/ehci.c
index 494e2e50f..69e59ce65 100644
--- a/src/portable/ehci/ehci.c
+++ b/src/portable/ehci/ehci.c
@@ -142,8 +142,11 @@ static inline ehci_qhd_t* qhd_get_from_addr (uint8_t dev_addr, uint8_t ep_addr);
 // determine if a queue head has bus-related error
 static inline bool qhd_has_xact_error (ehci_qhd_t * p_qhd)
 {
-  return (p_qhd->qtd_overlay.buffer_err || p_qhd->qtd_overlay.babble_err || p_qhd->qtd_overlay.xact_err);
-  //p_qhd->qtd_overlay.non_hs_period_missed_uframe || p_qhd->qtd_overlay.pingstate_err TODO split transaction error
+  volatile ehci_qtd_t *qtd_overlay = &p_qhd->qtd_overlay;
+
+  // Error count = 0 often occurs when device disconnected
+  return (qtd_overlay->err_count == 0 || qtd_overlay->buffer_err || qtd_overlay->babble_err || qtd_overlay->xact_err);
+  //qtd_overlay->non_hs_period_missed_uframe || qtd_overlay->pingstate_err TODO split transaction error
 }
 
 static void qhd_init(ehci_qhd_t *p_qhd, uint8_t dev_addr, tusb_desc_endpoint_t const * ep_desc);
@@ -630,7 +633,9 @@ static void qhd_xfer_error_isr(ehci_qhd_t * p_qhd)
 
     p_qhd->total_xferred_bytes += p_qhd->p_qtd_list_head->expected_bytes - p_qhd->p_qtd_list_head->total_bytes;
 
-//    if ( XFER_RESULT_FAILED == error_event )    TU_BREAKPOINT(); // TODO skip unplugged device
+//    if ( XFER_RESULT_FAILED == error_event ) {
+//      TU_BREAKPOINT(); // TODO skip unplugged device
+//    }
 
     p_qhd->p_qtd_list_head->used = 0; // free QTD
     qtd_remove_1st_from_qhd(p_qhd);
diff --git a/src/tusb.c b/src/tusb.c
index 85fe5a3cc..7327db685 100644
--- a/src/tusb.c
+++ b/src/tusb.c
@@ -439,6 +439,10 @@ char const* const tu_str_std_request[] =
   "Synch Frame"
 };
 
+char const* const tu_str_xfer_result[] = {
+    "OK", "Failed", "Stalled", "Timeout"
+};
+
 #endif
 
 static void dump_str_line(uint8_t const* buf, uint16_t count)