From cb2af4c0bc096e57c3486945eda43dbc26b3829a Mon Sep 17 00:00:00 2001 From: hathach Date: Wed, 21 Dec 2022 11:46:58 +0700 Subject: [PATCH] minor debug log --- src/class/cdc/cdc_host.c | 8 ++++ src/class/msc/msc_host.c | 13 ++++-- src/host/usbh.c | 85 ++++++++++++++++++++++------------------ 3 files changed, 63 insertions(+), 43 deletions(-) diff --git a/src/class/cdc/cdc_host.c b/src/class/cdc/cdc_host.c index 5aec41cbc..83c623884 100644 --- a/src/class/cdc/cdc_host.c +++ b/src/class/cdc/cdc_host.c @@ -33,6 +33,12 @@ #include "cdc_host.h" + +// 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__) + //--------------------------------------------------------------------+ // MACRO CONSTANT TYPEDEF //--------------------------------------------------------------------+ @@ -348,6 +354,8 @@ bool tuh_cdc_set_control_line_state(uint8_t idx, uint16_t line_state, tuh_xfer_c cdch_interface_t* p_cdc = get_itf(idx); TU_VERIFY(p_cdc && p_cdc->acm_capability.support_line_request); + TU_LOG_CDCH("CDC Set Control Line State\r\n"); + tusb_control_request_t const request = { .bmRequestType_bit = diff --git a/src/class/msc/msc_host.c b/src/class/msc/msc_host.c index 32f75a84b..6724e486c 100644 --- a/src/class/msc/msc_host.c +++ b/src/class/msc/msc_host.c @@ -33,6 +33,11 @@ #include "msc_host.h" +// 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__) + //--------------------------------------------------------------------+ // MACRO CONSTANT TYPEDEF //--------------------------------------------------------------------+ @@ -417,7 +422,7 @@ bool msch_set_config(uint8_t dev_addr, uint8_t itf_num) p_msc->configured = true; //------------- Get Max Lun -------------// - TU_LOG2("MSC Get Max Lun\r\n"); + TU_LOG_MSCH("MSC Get Max Lun\r\n"); tusb_control_request_t const request = { .bmRequestType_bit = @@ -456,7 +461,7 @@ static void config_get_maxlun_complete (tuh_xfer_t* xfer) p_msc->max_lun++; // MAX LUN is minus 1 by specs // TODO multiple LUN support - TU_LOG2("SCSI Test Unit Ready\r\n"); + TU_LOG_MSCH("SCSI Test Unit Ready\r\n"); uint8_t const lun = 0; tuh_msc_test_unit_ready(daddr, lun, config_test_unit_ready_complete, 0); } @@ -469,14 +474,14 @@ static bool config_test_unit_ready_complete(uint8_t dev_addr, tuh_msc_complete_d if (csw->status == 0) { // Unit is ready, read its capacity - TU_LOG2("SCSI Read Capacity\r\n"); + TU_LOG_MSCH("SCSI Read Capacity\r\n"); tuh_msc_read_capacity(dev_addr, cbw->lun, (scsi_read_capacity10_resp_t*) ((void*) _msch_buffer), config_read_capacity_complete, 0); }else { // Note: During enumeration, some device fails Test Unit Ready and require a few retries // with Request Sense to start working !! // TODO limit number of retries - TU_LOG2("SCSI Request Sense\r\n"); + TU_LOG_MSCH("SCSI Request Sense\r\n"); TU_ASSERT(tuh_msc_request_sense(dev_addr, cbw->lun, _msch_buffer, config_request_sense_complete, 0)); } diff --git a/src/host/usbh.c b/src/host/usbh.c index 59b1c3280..36fc5fded 100644 --- a/src/host/usbh.c +++ b/src/host/usbh.c @@ -46,8 +46,10 @@ #define CFG_TUH_INTERFACE_MAX 8 #endif -// Debug level of USBD -#define USBH_DBG_LVL 2 +// Debug level, TUSB_CFG_DEBUG must be at least this level for debug message +#define USBH_DEBUG 2 + +#define TU_LOG_USBH(...) TU_LOG(USBH_DEBUG, __VA_ARGS__) //--------------------------------------------------------------------+ // USBH-HCD common data structure @@ -324,11 +326,11 @@ bool tuh_init(uint8_t controller_id) // skip if already initialized if ( tuh_inited() ) return true; - TU_LOG2("USBH init on controller %u\r\n", controller_id); - TU_LOG2_INT(sizeof(usbh_device_t)); - TU_LOG2_INT(sizeof(hcd_event_t)); - TU_LOG2_INT(sizeof(_ctrl_xfer)); - TU_LOG2_INT(sizeof(tuh_xfer_t)); + TU_LOG_USBH("USBH init on controller %u\r\n", controller_id); + TU_LOG_INT(USBH_DEBUG, sizeof(usbh_device_t)); + TU_LOG_INT(USBH_DEBUG, sizeof(hcd_event_t)); + TU_LOG_INT(USBH_DEBUG, sizeof(_ctrl_xfer)); + TU_LOG_INT(USBH_DEBUG, sizeof(tuh_xfer_t)); // Event queue _usbh_q = osal_queue_create( &_usbh_qdef ); @@ -353,7 +355,7 @@ bool tuh_init(uint8_t controller_id) // Class drivers for (uint8_t drv_id = 0; drv_id < USBH_CLASS_DRIVER_COUNT; drv_id++) { - TU_LOG2("%s init\r\n", usbh_class_drivers[drv_id].name); + TU_LOG_USBH("%s init\r\n", usbh_class_drivers[drv_id].name); usbh_class_drivers[drv_id].init(); } @@ -401,12 +403,12 @@ void tuh_task_ext(uint32_t timeout_ms, bool in_isr) case HCD_EVENT_DEVICE_ATTACH: // TODO due to the shared _usbh_ctrl_buf, we must complete enumerating // one device before enumerating another one. - TU_LOG2("[%u:] USBH DEVICE ATTACH\r\n", event.rhport); + TU_LOG_USBH("[%u:] USBH DEVICE ATTACH\r\n", event.rhport); enum_new_device(&event); break; case HCD_EVENT_DEVICE_REMOVE: - TU_LOG2("[%u:%u:%u] USBH DEVICE REMOVED\r\n", event.rhport, event.connection.hub_addr, event.connection.hub_port); + TU_LOG_USBH("[%u:%u:%u] USBH DEVICE REMOVED\r\n", event.rhport, event.connection.hub_addr, event.connection.hub_port); process_device_unplugged(event.rhport, event.connection.hub_addr, event.connection.hub_port); #if CFG_TUH_HUB @@ -425,7 +427,7 @@ 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_LOG2("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\r\n", ep_addr, (unsigned int) event.xfer_complete.len); if (event.dev_addr == 0) { @@ -449,7 +451,7 @@ void tuh_task_ext(uint32_t timeout_ms, bool in_isr) uint8_t drv_id = dev->ep2drv[epnum][ep_dir]; if(drv_id < USBH_CLASS_DRIVER_COUNT) { - TU_LOG2("%s xfer callback\r\n", usbh_class_drivers[drv_id].name); + TU_LOG_USBH("%s xfer callback\r\n", usbh_class_drivers[drv_id].name); usbh_class_drivers[drv_id].xfer_cb(event.dev_addr, ep_addr, event.xfer_complete.result, event.xfer_complete.len); } else @@ -539,9 +541,11 @@ bool tuh_control_xfer (tuh_xfer_t* xfer) TU_VERIFY(is_idle); const uint8_t rhport = usbh_get_rhport(daddr); - TU_LOG2("[%u:%u] %s: ", rhport, daddr, xfer->setup->bRequest <= TUSB_REQ_SYNCH_FRAME ? tu_str_std_request[xfer->setup->bRequest] : "Unknown Request"); - TU_LOG2_PTR(xfer->setup); - TU_LOG2("\r\n"); + TU_LOG_USBH("[%u:%u] %s: ", rhport, daddr, + (xfer->setup->bmRequestType_bit.type == TUSB_REQ_TYPE_STANDARD && xfer->setup->bRequest <= TUSB_REQ_SYNCH_FRAME) ? + tu_str_std_request[xfer->setup->bRequest] : "Class Request"); + TU_LOG_PTR(USBH_DEBUG, xfer->setup); + TU_LOG_USBH("\r\n"); if (xfer->complete_cb) { @@ -585,7 +589,7 @@ TU_ATTR_ALWAYS_INLINE static inline void _set_control_xfer_stage(uint8_t stage) static void _xfer_complete(uint8_t daddr, xfer_result_t result) { - TU_LOG2("\r\n"); + TU_LOG_USBH("\r\n"); // duplicate xfer since user can execute control transfer within callback tusb_control_request_t const request = _ctrl_xfer.request; @@ -643,8 +647,8 @@ static bool usbh_control_xfer_cb (uint8_t dev_addr, uint8_t ep_addr, xfer_result case CONTROL_STAGE_DATA: if (request->wLength) { - TU_LOG2("[%u:%u] Control data:\r\n", rhport, dev_addr); - TU_LOG2_MEM(_ctrl_xfer.buffer, xferred_bytes, 2); + TU_LOG_USBH("[%u:%u] Control data:\r\n", rhport, dev_addr); + TU_LOG_MEM(USBH_DEBUG, _ctrl_xfer.buffer, xferred_bytes, 2); } _ctrl_xfer.actual_len = (uint16_t) xferred_bytes; @@ -760,7 +764,7 @@ bool usbh_edpt_xfer_with_callback(uint8_t dev_addr, uint8_t ep_addr, uint8_t * b uint8_t const dir = tu_edpt_dir(ep_addr); tu_edpt_state_t* ep_state = &dev->ep_status[epnum][dir]; - TU_LOG2(" Queue EP %02X with %u bytes ... ", ep_addr, total_bytes); + TU_LOG_USBH(" Queue EP %02X with %u bytes ... ", ep_addr, total_bytes); // Attempt to transfer on a busy endpoint, sound like an race condition ! TU_ASSERT(ep_state->busy == 0); @@ -776,7 +780,7 @@ bool usbh_edpt_xfer_with_callback(uint8_t dev_addr, uint8_t ep_addr, uint8_t * b if ( hcd_edpt_xfer(dev->rhport, dev_addr, ep_addr, buffer, total_bytes) ) { - TU_LOG2("OK\r\n"); + TU_LOG_USBH("OK\r\n"); return true; }else { @@ -791,7 +795,7 @@ bool usbh_edpt_xfer_with_callback(uint8_t dev_addr, uint8_t ep_addr, uint8_t * b static bool usbh_edpt_control_open(uint8_t dev_addr, uint8_t max_packet_size) { - TU_LOG2("[%u:%u] Open EP0 with Size = %u\r\n", usbh_get_rhport(dev_addr), dev_addr, max_packet_size); + TU_LOG_USBH("[%u:%u] Open EP0 with Size = %u\r\n", usbh_get_rhport(dev_addr), dev_addr, max_packet_size); tusb_desc_endpoint_t ep0_desc = { @@ -960,7 +964,7 @@ bool tuh_descriptor_get_serial_string(uint8_t daddr, uint16_t language_id, void* bool tuh_descriptor_get_hid_report(uint8_t daddr, uint8_t itf_num, uint8_t desc_type, uint8_t index, void* buffer, uint16_t len, tuh_xfer_cb_t complete_cb, uintptr_t user_data) { - TU_LOG2("HID Get Report Descriptor\r\n"); + TU_LOG_USBH("HID Get Report Descriptor\r\n"); tusb_control_request_t const request = { .bmRequestType_bit = @@ -999,7 +1003,7 @@ bool tuh_descriptor_get_hid_report(uint8_t daddr, uint8_t itf_num, uint8_t desc_ bool tuh_configuration_set(uint8_t daddr, uint8_t config_num, tuh_xfer_cb_t complete_cb, uintptr_t user_data) { - TU_LOG2("Set Configuration = %d\r\n", config_num); + TU_LOG_USBH("Set Configuration = %d\r\n", config_num); tusb_control_request_t const request = { @@ -1103,11 +1107,11 @@ static void process_device_unplugged(uint8_t rhport, uint8_t hub_addr, uint8_t h (hub_port == 0 || dev->hub_port == hub_port) && // hub_port = 0 means all devices of downstream hub dev->connected) { - TU_LOG2(" Address = %u\r\n", dev_addr); + TU_LOG_USBH(" Address = %u\r\n", dev_addr); if (is_hub_addr(dev_addr)) { - TU_LOG(USBH_DBG_LVL, "HUB address = %u is unmounted\r\n", dev_addr); + TU_LOG(USBH_DEBUG, "HUB address = %u is unmounted\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); @@ -1120,7 +1124,7 @@ static void process_device_unplugged(uint8_t rhport, uint8_t hub_addr, uint8_t h // Close class driver for (uint8_t drv_id = 0; drv_id < USBH_CLASS_DRIVER_COUNT; drv_id++) { - TU_LOG2("%s close\r\n", usbh_class_drivers[drv_id].name); + TU_LOG_USBH("%s close\r\n", usbh_class_drivers[drv_id].name); usbh_class_drivers[drv_id].close(dev_addr); } @@ -1245,7 +1249,7 @@ static void process_enumeration(tuh_xfer_t* xfer) TU_ASSERT( usbh_edpt_control_open(addr0, 8), ); // Get first 8 bytes of device descriptor for Control Endpoint size - TU_LOG2("Get 8 byte of Device Descriptor\r\n"); + TU_LOG_USBH("Get 8 byte of Device Descriptor\r\n"); TU_ASSERT(tuh_descriptor_get_device(addr0, _usbh_ctrl_buf, 8, process_enumeration, ENUM_SET_ADDR), ); } break; @@ -1254,7 +1258,7 @@ static void process_enumeration(tuh_xfer_t* xfer) case ENUM_RESET_2: // TODO not used by now, but may be needed for some devices !? // Reset device again before Set Address - TU_LOG2("Port reset2 \r\n"); + TU_LOG_USBH("Port reset2 \r\n"); if (_dev0.hub_addr == 0) { // connected directly to roothub @@ -1294,7 +1298,7 @@ static void process_enumeration(tuh_xfer_t* xfer) TU_ASSERT( usbh_edpt_control_open(new_addr, new_dev->ep0_size), ); // Get full device descriptor - TU_LOG2("Get Device Descriptor\r\n"); + TU_LOG_USBH("Get Device Descriptor\r\n"); TU_ASSERT(tuh_descriptor_get_device(new_addr, _usbh_ctrl_buf, sizeof(tusb_desc_device_t), process_enumeration, ENUM_GET_9BYTE_CONFIG_DESC), ); } break; @@ -1315,7 +1319,7 @@ static void process_enumeration(tuh_xfer_t* xfer) // Get 9-byte for total length uint8_t const config_idx = CONFIG_NUM - 1; - TU_LOG2("Get Configuration[0] Descriptor (9 bytes)\r\n"); + TU_LOG_USBH("Get Configuration[0] Descriptor (9 bytes)\r\n"); TU_ASSERT( tuh_descriptor_get_configuration(daddr, config_idx, _usbh_ctrl_buf, 9, process_enumeration, ENUM_GET_FULL_CONFIG_DESC), ); } break; @@ -1332,7 +1336,7 @@ static void process_enumeration(tuh_xfer_t* xfer) // Get full configuration descriptor uint8_t const config_idx = CONFIG_NUM - 1; - TU_LOG2("Get Configuration[0] Descriptor\r\n"); + TU_LOG_USBH("Get Configuration[0] Descriptor\r\n"); TU_ASSERT( tuh_descriptor_get_configuration(daddr, config_idx, _usbh_ctrl_buf, total_len, process_enumeration, ENUM_SET_CONFIG), ); } break; @@ -1347,7 +1351,7 @@ static void process_enumeration(tuh_xfer_t* xfer) case ENUM_CONFIG_DRIVER: { - TU_LOG2("Device configured\r\n"); + TU_LOG_USBH("Device configured\r\n"); usbh_device_t* dev = get_device(daddr); TU_ASSERT(dev, ); @@ -1387,7 +1391,7 @@ static bool enum_new_device(hcd_event_t* event) if ( !hcd_port_connect_status(_dev0.rhport) ) return true; _dev0.speed = hcd_port_speed_get(_dev0.rhport ); - TU_LOG2("%s Speed\r\n", tu_str_speed[_dev0.speed]); + TU_LOG_USBH("%s Speed\r\n", tu_str_speed[_dev0.speed]); // fake transfer to kick-off the enumeration process tuh_xfer_t xfer; @@ -1444,7 +1448,7 @@ static bool enum_request_set_addr(void) uint8_t const new_addr = get_new_address(desc_device->bDeviceClass == TUSB_CLASS_HUB); TU_ASSERT(new_addr != 0); - TU_LOG2("Set Address = %d\r\n", new_addr); + TU_LOG_USBH("Set Address = %d\r\n", new_addr); usbh_device_t* new_dev = get_device(new_addr); @@ -1488,9 +1492,12 @@ static bool _parse_configuration_descriptor(uint8_t dev_addr, tusb_desc_configur { usbh_device_t* dev = get_device(dev_addr); - uint8_t const* desc_end = ((uint8_t const*) desc_cfg) + tu_le16toh(desc_cfg->wTotalLength); + uint16_t const total_len = tu_le16toh(desc_cfg->wTotalLength); + uint8_t const* desc_end = ((uint8_t const*) desc_cfg) + total_len; uint8_t const* p_desc = tu_desc_next(desc_cfg); + TU_LOG_USBH("Parsing Configuration descriptor (wTotalLength = %u)\r\n", total_len); + // parse each interfaces while( p_desc < desc_end ) { @@ -1535,7 +1542,7 @@ static bool _parse_configuration_descriptor(uint8_t dev_addr, tusb_desc_configur if ( driver->open(dev->rhport, dev_addr, desc_itf, drv_len) ) { // open successfully - TU_LOG2(" %s opened\r\n", driver->name); + TU_LOG_USBH(" %s opened\r\n", driver->name); // bind (associated) interfaces to found driver for(uint8_t i=0; i= USBH_CLASS_DRIVER_COUNT ) { - TU_LOG(USBH_DBG_LVL, "Interface %u: class = %u subclass = %u protocol = %u is not supported\r\n", + TU_LOG(USBH_DEBUG, "Interface %u: class = %u subclass = %u protocol = %u is not supported\r\n", desc_itf->bInterfaceNumber, desc_itf->bInterfaceClass, desc_itf->bInterfaceSubClass, desc_itf->bInterfaceProtocol); } } @@ -1580,7 +1587,7 @@ void usbh_driver_set_config_complete(uint8_t dev_addr, uint8_t itf_num) if (drv_id != DRVID_INVALID) { usbh_class_driver_t const * driver = &usbh_class_drivers[drv_id]; - TU_LOG2("%s set config: itf = %u\r\n", driver->name, itf_num); + TU_LOG_USBH("%s set config: itf = %u\r\n", driver->name, itf_num); driver->set_config(dev_addr, itf_num); break; } @@ -1593,7 +1600,7 @@ void usbh_driver_set_config_complete(uint8_t dev_addr, uint8_t itf_num) if (is_hub_addr(dev_addr)) { - TU_LOG(USBH_DBG_LVL, "HUB address = %u is mounted\r\n", dev_addr); + TU_LOG(USBH_DEBUG, "HUB address = %u is mounted\r\n", dev_addr); }else { // Invoke callback if available