From 77495cf119c89c3091e7ab05773ebce19988da86 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 20 Jul 2023 17:06:57 +0700 Subject: improve logging, allow easier to turn off usbd, driver logging can be useful when focusing on let's say usbh --- src/device/usbd.c | 93 +++++++++++++++++++++++------------------------ src/device/usbd_control.c | 9 ++--- src/device/usbd_pvt.h | 9 ++++- 3 files changed, 56 insertions(+), 55 deletions(-) (limited to 'src/device') diff --git a/src/device/usbd.c b/src/device/usbd.c index 44c2530ce..9429cf664 100644 --- a/src/device/usbd.c +++ b/src/device/usbd.c @@ -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); diff --git a/src/device/usbd_control.c b/src/device/usbd_control.c index 2afe967b5..c580e6ecf 100644 --- a/src/device/usbd_control.c +++ b/src/device/usbd_control.c @@ -32,10 +32,7 @@ #include "tusb.h" #include "device/usbd_pvt.h" -// Debug level of USBD Control -#define USBD_CONTROL_DEBUG 2 - -#if CFG_TUSB_DEBUG >= USBD_CONTROL_DEBUG +#if CFG_TUSB_DEBUG >= CFG_TUD_LOG_LEVEL extern void usbd_driver_print_control_complete_name(usbd_control_xfer_cb_t callback); #endif @@ -191,7 +188,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(USBD_CONTROL_DEBUG, _usbd_ctrl_buf, xferred_bytes, 2); + TU_LOG_MEM(CFG_TUD_LOG_LEVEL, _usbd_ctrl_buf, xferred_bytes, 2); } _ctrl_xfer.total_xferred += (uint16_t) xferred_bytes; @@ -208,7 +205,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 >= USBD_CONTROL_DEBUG + #if CFG_TUSB_DEBUG >= CFG_TUD_LOG_LEVEL usbd_driver_print_control_complete_name(_ctrl_xfer.complete_cb); #endif diff --git a/src/device/usbd_pvt.h b/src/device/usbd_pvt.h index 8393d3469..940b2858b 100644 --- a/src/device/usbd_pvt.h +++ b/src/device/usbd_pvt.h @@ -33,13 +33,20 @@ extern "C" { #endif +// Level where CFG_TUSB_DEBUG must be at least for USBD is logged +#ifndef CFG_TUD_LOG_LEVEL +#define CFG_TUD_LOG_LEVEL 2 +#endif + +#define TU_LOG_USBD(...) TU_LOG(CFG_TUD_LOG_LEVEL, __VA_ARGS__) + //--------------------------------------------------------------------+ // Class Driver API //--------------------------------------------------------------------+ typedef struct { - #if CFG_TUSB_DEBUG >= 2 + #if CFG_TUSB_DEBUG >= CFG_TUD_LOG_LEVEL char const* name; #endif -- cgit v1.3.1