improve logging, allow easier to turn off usbd, driver logging

can be useful when focusing on let's say usbh
This commit is contained in:
hathach
2023-07-20 17:06:57 +07:00
parent 6c7c9f2ef5
commit 77495cf119
5 changed files with 97 additions and 91 deletions

View File

@@ -43,9 +43,6 @@
#define CFG_TUD_TASK_QUEUE_SZ 16
#endif
// Debug level of USBD
#define USBD_DBG 2
//--------------------------------------------------------------------+
// Device Data
//--------------------------------------------------------------------+
@@ -81,7 +78,7 @@ tu_static usbd_device_t _usbd_dev;
//--------------------------------------------------------------------+
// Class Driver
//--------------------------------------------------------------------+
#if CFG_TUSB_DEBUG >= 2
#if CFG_TUSB_DEBUG >= CFG_TUD_LOG_LEVEL
#define DRIVER_NAME(_name) .name = _name,
#else
#define DRIVER_NAME(_name)
@@ -308,7 +305,7 @@ bool usbd_control_xfer_cb (uint8_t rhport, uint8_t ep_addr, xfer_result_t event,
//--------------------------------------------------------------------+
// Debug
//--------------------------------------------------------------------+
#if CFG_TUSB_DEBUG >= 2
#if CFG_TUSB_DEBUG >= CFG_TUD_LOG_LEVEL
tu_static char const* const _usbd_event_str[DCD_EVENT_COUNT] =
{
"Invalid" ,
@@ -330,7 +327,7 @@ void usbd_driver_print_control_complete_name(usbd_control_xfer_cb_t callback)
usbd_class_driver_t const * driver = get_driver(i);
if ( driver && driver->control_xfer_cb == callback )
{
TU_LOG(USBD_DBG, " %s control complete\r\n", driver->name);
TU_LOG_USBD(" %s control complete\r\n", driver->name);
return;
}
}
@@ -396,10 +393,10 @@ bool tud_init (uint8_t rhport)
// skip if already initialized
if ( tud_inited() ) return true;
TU_LOG(USBD_DBG, "USBD init on controller %u\r\n", rhport);
TU_LOG_INT(USBD_DBG, sizeof(usbd_device_t));
TU_LOG_INT(USBD_DBG, sizeof(tu_fifo_t));
TU_LOG_INT(USBD_DBG, sizeof(tu_edpt_stream_t));
TU_LOG_USBD("USBD init on controller %u\r\n", rhport);
TU_LOG_INT(CFG_TUD_LOG_LEVEL, sizeof(usbd_device_t));
TU_LOG_INT(CFG_TUD_LOG_LEVEL, sizeof(tu_fifo_t));
TU_LOG_INT(CFG_TUD_LOG_LEVEL, sizeof(tu_edpt_stream_t));
tu_varclr(&_usbd_dev);
@@ -424,7 +421,7 @@ bool tud_init (uint8_t rhport)
{
usbd_class_driver_t const * driver = get_driver(i);
TU_ASSERT(driver);
TU_LOG(USBD_DBG, "%s init\r\n", driver->name);
TU_LOG_USBD("%s init\r\n", driver->name);
driver->init();
}
@@ -496,21 +493,21 @@ void tud_task_ext(uint32_t timeout_ms, bool in_isr)
dcd_event_t event;
if ( !osal_queue_receive(_usbd_q, &event, timeout_ms) ) return;
#if CFG_TUSB_DEBUG >= 2
if (event.event_id == DCD_EVENT_SETUP_RECEIVED) TU_LOG(USBD_DBG, "\r\n"); // extra line for setup
TU_LOG(USBD_DBG, "USBD %s ", event.event_id < DCD_EVENT_COUNT ? _usbd_event_str[event.event_id] : "CORRUPTED");
#if CFG_TUSB_DEBUG >= CFG_TUD_LOG_LEVEL
if (event.event_id == DCD_EVENT_SETUP_RECEIVED) TU_LOG_USBD("\r\n"); // extra line for setup
TU_LOG_USBD("USBD %s ", event.event_id < DCD_EVENT_COUNT ? _usbd_event_str[event.event_id] : "CORRUPTED");
#endif
switch ( event.event_id )
{
case DCD_EVENT_BUS_RESET:
TU_LOG(USBD_DBG, ": %s Speed\r\n", tu_str_speed[event.bus_reset.speed]);
TU_LOG_USBD(": %s Speed\r\n", tu_str_speed[event.bus_reset.speed]);
usbd_reset(event.rhport);
_usbd_dev.speed = event.bus_reset.speed;
break;
case DCD_EVENT_UNPLUGGED:
TU_LOG(USBD_DBG, "\r\n");
TU_LOG_USBD("\r\n");
usbd_reset(event.rhport);
// invoke callback
@@ -518,8 +515,8 @@ void tud_task_ext(uint32_t timeout_ms, bool in_isr)
break;
case DCD_EVENT_SETUP_RECEIVED:
TU_LOG_PTR(USBD_DBG, &event.setup_received);
TU_LOG(USBD_DBG, "\r\n");
TU_LOG_PTR(CFG_TUD_LOG_LEVEL, &event.setup_received);
TU_LOG_USBD("\r\n");
// Mark as connected after receiving 1st setup packet.
// But it is easier to set it every time instead of wasting time to check then set
@@ -534,7 +531,7 @@ void tud_task_ext(uint32_t timeout_ms, bool in_isr)
// Process control request
if ( !process_control_request(event.rhport, &event.setup_received) )
{
TU_LOG(USBD_DBG, " Stall EP0\r\n");
TU_LOG_USBD(" Stall EP0\r\n");
// Failed -> stall both control endpoint IN and OUT
dcd_edpt_stall(event.rhport, 0);
dcd_edpt_stall(event.rhport, 0 | TUSB_DIR_IN_MASK);
@@ -548,7 +545,7 @@ void tud_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(USBD_DBG, "on EP %02X with %u bytes\r\n", ep_addr, (unsigned int) event.xfer_complete.len);
TU_LOG_USBD("on EP %02X with %u bytes\r\n", ep_addr, (unsigned int) event.xfer_complete.len);
_usbd_dev.ep_status[epnum][ep_dir].busy = 0;
_usbd_dev.ep_status[epnum][ep_dir].claimed = 0;
@@ -563,7 +560,7 @@ void tud_task_ext(uint32_t timeout_ms, bool in_isr)
usbd_class_driver_t const * driver = get_driver( _usbd_dev.ep2drv[epnum][ep_dir] );
TU_ASSERT(driver, );
TU_LOG(USBD_DBG, " %s xfer callback\r\n", driver->name);
TU_LOG_USBD(" %s xfer callback\r\n", driver->name);
driver->xfer_cb(event.rhport, ep_addr, (xfer_result_t) event.xfer_complete.result, event.xfer_complete.len);
}
}
@@ -575,27 +572,27 @@ void tud_task_ext(uint32_t timeout_ms, bool in_isr)
// e.g suspend -> resume -> unplug/plug. Skip suspend/resume if not connected
if ( _usbd_dev.connected )
{
TU_LOG(USBD_DBG, ": Remote Wakeup = %u\r\n", _usbd_dev.remote_wakeup_en);
TU_LOG_USBD(": Remote Wakeup = %u\r\n", _usbd_dev.remote_wakeup_en);
if (tud_suspend_cb) tud_suspend_cb(_usbd_dev.remote_wakeup_en);
}else
{
TU_LOG(USBD_DBG, " Skipped\r\n");
TU_LOG_USBD(" Skipped\r\n");
}
break;
case DCD_EVENT_RESUME:
if ( _usbd_dev.connected )
{
TU_LOG(USBD_DBG, "\r\n");
TU_LOG_USBD("\r\n");
if (tud_resume_cb) tud_resume_cb();
}else
{
TU_LOG(USBD_DBG, " Skipped\r\n");
TU_LOG_USBD(" Skipped\r\n");
}
break;
case USBD_EVENT_FUNC_CALL:
TU_LOG(USBD_DBG, "\r\n");
TU_LOG_USBD("\r\n");
if ( event.func_call.func ) event.func_call.func(event.func_call.param);
break;
@@ -620,7 +617,7 @@ void tud_task_ext(uint32_t timeout_ms, bool in_isr)
static bool invoke_class_control(uint8_t rhport, usbd_class_driver_t const * driver, tusb_control_request_t const * request)
{
usbd_control_set_complete_callback(driver->control_xfer_cb);
TU_LOG(USBD_DBG, " %s control request\r\n", driver->name);
TU_LOG_USBD(" %s control request\r\n", driver->name);
return driver->control_xfer_cb(rhport, CONTROL_STAGE_SETUP, request);
}
@@ -641,11 +638,11 @@ static bool process_control_request(uint8_t rhport, tusb_control_request_t const
return tud_vendor_control_xfer_cb(rhport, CONTROL_STAGE_SETUP, p_request);
}
#if CFG_TUSB_DEBUG >= 2
#if CFG_TUSB_DEBUG >= CFG_TUD_LOG_LEVEL
if (TUSB_REQ_TYPE_STANDARD == p_request->bmRequestType_bit.type && p_request->bRequest <= TUSB_REQ_SYNCH_FRAME)
{
TU_LOG(USBD_DBG, " %s", tu_str_std_request[p_request->bRequest]);
if (TUSB_REQ_GET_DESCRIPTOR != p_request->bRequest) TU_LOG(USBD_DBG, "\r\n");
TU_LOG_USBD(" %s", tu_str_std_request[p_request->bRequest]);
if (TUSB_REQ_GET_DESCRIPTOR != p_request->bRequest) TU_LOG_USBD("\r\n");
}
#endif
@@ -701,7 +698,7 @@ static bool process_control_request(uint8_t rhport, tusb_control_request_t const
if ( _usbd_dev.cfg_num )
{
// already configured: need to clear all endpoints and driver first
TU_LOG(USBD_DBG, " Clear current Configuration (%u) before switching\r\n", _usbd_dev.cfg_num);
TU_LOG_USBD(" Clear current Configuration (%u) before switching\r\n", _usbd_dev.cfg_num);
// close all non-control endpoints, cancel all pending transfers if any
dcd_edpt_close_all(rhport);
@@ -730,7 +727,7 @@ static bool process_control_request(uint8_t rhport, tusb_control_request_t const
// Only support remote wakeup for device feature
TU_VERIFY(TUSB_REQ_FEATURE_REMOTE_WAKEUP == p_request->wValue);
TU_LOG(USBD_DBG, " Enable Remote Wakeup\r\n");
TU_LOG_USBD(" Enable Remote Wakeup\r\n");
// Host may enable remote wake up before suspending especially HID device
_usbd_dev.remote_wakeup_en = true;
@@ -741,7 +738,7 @@ static bool process_control_request(uint8_t rhport, tusb_control_request_t const
// Only support remote wakeup for device feature
TU_VERIFY(TUSB_REQ_FEATURE_REMOTE_WAKEUP == p_request->wValue);
TU_LOG(USBD_DBG, " Disable Remote Wakeup\r\n");
TU_LOG_USBD(" Disable Remote Wakeup\r\n");
// Host may disable remote wake up after resuming
_usbd_dev.remote_wakeup_en = false;
@@ -924,7 +921,7 @@ static bool process_set_config(uint8_t rhport, uint8_t cfg_num)
if ( (sizeof(tusb_desc_interface_t) <= drv_len) && (drv_len <= remaining_len) )
{
// Open successfully
TU_LOG(USBD_DBG, " %s opened\r\n", driver->name);
TU_LOG_USBD(" %s opened\r\n", driver->name);
// Some drivers use 2 or more interfaces but may not have IAD e.g MIDI (always) or
// BTH (even CDC) with class in device descriptor (single interface)
@@ -983,7 +980,7 @@ static bool process_get_descriptor(uint8_t rhport, tusb_control_request_t const
{
case TUSB_DESC_DEVICE:
{
TU_LOG(USBD_DBG, " Device\r\n");
TU_LOG_USBD(" Device\r\n");
void* desc_device = (void*) (uintptr_t) tud_descriptor_device_cb();
@@ -1007,7 +1004,7 @@ static bool process_get_descriptor(uint8_t rhport, tusb_control_request_t const
case TUSB_DESC_BOS:
{
TU_LOG(USBD_DBG, " BOS\r\n");
TU_LOG_USBD(" BOS\r\n");
// requested by host if USB > 2.0 ( i.e 2.1 or 3.x )
if (!tud_descriptor_bos_cb) return false;
@@ -1029,12 +1026,12 @@ static bool process_get_descriptor(uint8_t rhport, tusb_control_request_t const
if ( desc_type == TUSB_DESC_CONFIGURATION )
{
TU_LOG(USBD_DBG, " Configuration[%u]\r\n", desc_index);
TU_LOG_USBD(" Configuration[%u]\r\n", desc_index);
desc_config = (uintptr_t) tud_descriptor_configuration_cb(desc_index);
}else
{
// Host only request this after getting Device Qualifier descriptor
TU_LOG(USBD_DBG, " Other Speed Configuration\r\n");
TU_LOG_USBD(" Other Speed Configuration\r\n");
TU_VERIFY( tud_descriptor_other_speed_configuration_cb );
desc_config = (uintptr_t) tud_descriptor_other_speed_configuration_cb(desc_index);
}
@@ -1050,7 +1047,7 @@ static bool process_get_descriptor(uint8_t rhport, tusb_control_request_t const
case TUSB_DESC_STRING:
{
TU_LOG(USBD_DBG, " String[%u]\r\n", desc_index);
TU_LOG_USBD(" String[%u]\r\n", desc_index);
// String Descriptor always uses the desc set from user
uint8_t const* desc_str = (uint8_t const*) tud_descriptor_string_cb(desc_index, tu_le16toh(p_request->wIndex));
@@ -1063,7 +1060,7 @@ static bool process_get_descriptor(uint8_t rhport, tusb_control_request_t const
case TUSB_DESC_DEVICE_QUALIFIER:
{
TU_LOG(USBD_DBG, " Device Qualifier\r\n");
TU_LOG_USBD(" Device Qualifier\r\n");
TU_VERIFY( tud_descriptor_device_qualifier_cb );
@@ -1248,7 +1245,7 @@ bool usbd_edpt_xfer(uint8_t rhport, uint8_t ep_addr, uint8_t * buffer, uint16_t
// TODO skip ready() check for now since enumeration also use this API
// TU_VERIFY(tud_ready());
TU_LOG(USBD_DBG, " Queue EP %02X with %u bytes ...\r\n", ep_addr, total_bytes);
TU_LOG_USBD(" Queue EP %02X with %u bytes ...\r\n", ep_addr, total_bytes);
// Attempt to transfer on a busy endpoint, sound like an race condition !
TU_ASSERT(_usbd_dev.ep_status[epnum][dir].busy == 0);
@@ -1265,7 +1262,7 @@ bool usbd_edpt_xfer(uint8_t rhport, uint8_t ep_addr, uint8_t * buffer, uint16_t
// DCD error, mark endpoint as ready to allow next transfer
_usbd_dev.ep_status[epnum][dir].busy = 0;
_usbd_dev.ep_status[epnum][dir].claimed = 0;
TU_LOG(USBD_DBG, "FAILED\r\n");
TU_LOG_USBD("FAILED\r\n");
TU_BREAKPOINT();
return false;
}
@@ -1282,7 +1279,7 @@ bool usbd_edpt_xfer_fifo(uint8_t rhport, uint8_t ep_addr, tu_fifo_t * ff, uint16
uint8_t const epnum = tu_edpt_number(ep_addr);
uint8_t const dir = tu_edpt_dir(ep_addr);
TU_LOG(USBD_DBG, " Queue ISO EP %02X with %u bytes ... ", ep_addr, total_bytes);
TU_LOG_USBD(" Queue ISO EP %02X with %u bytes ... ", ep_addr, total_bytes);
// Attempt to transfer on a busy endpoint, sound like an race condition !
TU_ASSERT(_usbd_dev.ep_status[epnum][dir].busy == 0);
@@ -1293,14 +1290,14 @@ bool usbd_edpt_xfer_fifo(uint8_t rhport, uint8_t ep_addr, tu_fifo_t * ff, uint16
if (dcd_edpt_xfer_fifo(rhport, ep_addr, ff, total_bytes))
{
TU_LOG(USBD_DBG, "OK\r\n");
TU_LOG_USBD("OK\r\n");
return true;
}else
{
// DCD error, mark endpoint as ready to allow next transfer
_usbd_dev.ep_status[epnum][dir].busy = 0;
_usbd_dev.ep_status[epnum][dir].claimed = 0;
TU_LOG(USBD_DBG, "failed\r\n");
TU_LOG_USBD("failed\r\n");
TU_BREAKPOINT();
return false;
}
@@ -1326,7 +1323,7 @@ void usbd_edpt_stall(uint8_t rhport, uint8_t ep_addr)
// only stalled if currently cleared
if ( !_usbd_dev.ep_status[epnum][dir].stalled )
{
TU_LOG(USBD_DBG, " Stall EP %02X\r\n", ep_addr);
TU_LOG_USBD(" Stall EP %02X\r\n", ep_addr);
dcd_edpt_stall(rhport, ep_addr);
_usbd_dev.ep_status[epnum][dir].stalled = 1;
_usbd_dev.ep_status[epnum][dir].busy = 1;
@@ -1343,7 +1340,7 @@ void usbd_edpt_clear_stall(uint8_t rhport, uint8_t ep_addr)
// only clear if currently stalled
if ( _usbd_dev.ep_status[epnum][dir].stalled )
{
TU_LOG(USBD_DBG, " Clear Stall EP %02X\r\n", ep_addr);
TU_LOG_USBD(" Clear Stall EP %02X\r\n", ep_addr);
dcd_edpt_clear_stall(rhport, ep_addr);
_usbd_dev.ep_status[epnum][dir].stalled = 0;
_usbd_dev.ep_status[epnum][dir].busy = 0;
@@ -1371,7 +1368,7 @@ void usbd_edpt_close(uint8_t rhport, uint8_t ep_addr)
rhport = _usbd_rhport;
TU_ASSERT(dcd_edpt_close, /**/);
TU_LOG(USBD_DBG, " CLOSING Endpoint: 0x%02X\r\n", ep_addr);
TU_LOG_USBD(" CLOSING Endpoint: 0x%02X\r\n", ep_addr);
uint8_t const epnum = tu_edpt_number(ep_addr);
uint8_t const dir = tu_edpt_dir(ep_addr);