From 9415f2d30ed91209060208c677312433bfcbf8b2 Mon Sep 17 00:00:00 2001 From: alexrayne Date: Tue, 20 Dec 2016 00:55:58 +0200 Subject: [PATCH 1/6] *usbd:USBD_DEBUG - now accepts numeric verbosity level. * usbd_private.h:USBD_LOGxxx(verbose_level - migrate to new debug printer style + USB_Vxxx - denotes verbosity levels + USB_VCALL,VIO,VSETUP - denotes code sections to log * usbd_log_call - deploy USBD_LOG_CALL to standalone printer routine * usbd_dwc_otg - starts migrate to new logstyle --- lib/usbd/backend/usbd_dwc_otg.c | 36 ++++++++++---------- lib/usbd/usbd.c | 7 ++++ lib/usbd/usbd_private.h | 58 +++++++++++++++++++++++++++++---- 3 files changed, 76 insertions(+), 25 deletions(-) diff --git a/lib/usbd/backend/usbd_dwc_otg.c b/lib/usbd/backend/usbd_dwc_otg.c index ebb42f89..c7adbd30 100644 --- a/lib/usbd/backend/usbd_dwc_otg.c +++ b/lib/usbd/backend/usbd_dwc_otg.c @@ -775,7 +775,7 @@ static void handle_rxflvl_interrupt(usbd_device *dev) [15] = "RESERVED_15" }; - LOGF_LN("GRXSTSP: rxstsp = %s, ep_num = %"PRIu8", bcnt = %"PRIu16, + USBD_LOGF_LN(USB_VIO, "GRXSTSP: rxstsp = %s, ep_num = %"PRIu8", bcnt = %"PRIu16, map_pktsts[DWC_OTG_GRXSTSP_PKTSTS_GET(rxstsp)], ep_num, bcnt); #endif @@ -790,7 +790,7 @@ static void handle_rxflvl_interrupt(usbd_device *dev) } break; case DWC_OTG_GRXSTSP_PKTSTS_SETUP: { if (bcnt != 8) { - LOG_LN("SETUP packet in FIFO not equal to 8"); + USBD_LOG_LN(USB_VSETUP,"SETUP packet in FIFO not equal to 8"); break; } @@ -798,11 +798,13 @@ static void handle_rxflvl_interrupt(usbd_device *dev) uint32_t *io = (void *) setup_data; io[0] = REBASE(DWC_OTG_FIFO, 0); io[1] = REBASE(DWC_OTG_FIFO, 0); - LOGF_LN("bmRequestType: 0x%02"PRIx8, setup_data->bmRequestType); - LOGF_LN("bRequest: 0x%02"PRIx8, setup_data->bRequest); - LOGF_LN("wValue: 0x%04"PRIx16, setup_data->wValue); - LOGF_LN("wIndex: 0x%04"PRIx16, setup_data->wIndex); - LOGF_LN("wLength: %"PRIu16, setup_data->wLength); + USBD_LOGF_LN(USB_VSETUP, "SETUP:reqType 0x%02"PRIx8"; Request 0x%02"PRIx8 + ";Value 0x%04"PRIx16";Index 0x%04"PRIx16 + ";Length: %"PRIu16 + , setup_data->bmRequestType, setup_data->bRequest + , setup_data->wValue, setup_data->wIndex + , setup_data->wLength + ); } break; case DWC_OTG_GRXSTSP_PKTSTS_SETUP_COMP: { /* Enable Interrupt to receive the SETUP packet */ @@ -824,7 +826,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_EPDISD) { REBASE(DWC_OTG_DIEPxINT, ep_num) = DWC_OTG_DIEPINT_EPDISD; - LOGF_LN("Endpoint disabled 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VIO, "ep0x%"PRIx8" disabled", ep_addr); } usbd_urb *urb = usbd_find_active_urb(dev, ep_addr); @@ -832,7 +834,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_XFRC) { REBASE(DWC_OTG_DIEPxINT, ep_num) = DWC_OTG_DIEPINT_XFRC; - LOGF_LN("Transfer Complete: endpoint 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VIO, "Transfer Complete: ep0x%"PRIx8, ep_addr); if (!ep_num && urb != NULL && dev->private_data.ep0tsiz_pktcnt) { /* We are still sending data! */ @@ -871,7 +873,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_TXFE) { /* Send more data */ - LOGF_LN("Sending more data for endpoint 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VIO, "Sending more data for endpoint 0x%"PRIx8, ep_addr); if (urb != NULL) { /* As per doc, before writing to FIFO, we need to write to CTL register. @@ -883,7 +885,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) } if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_ITTXFE) { - LOGF_LN("Data IN Token received when endpoint 0x%"PRIx8" FIFO was empty", + USBD_LOGF_LN(USB_VIO, "Data IN Token received when ep0x%"PRIx8" FIFO was empty", ep_addr); REBASE(DWC_OTG_DIEPxINT, ep_num) = DWC_OTG_DIEPINT_ITTXFE; } @@ -901,13 +903,12 @@ static void process_out_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) const uint8_t ep_addr = ep_num; if (REBASE(DWC_OTG_DOEPxINT, ep_num) & DWC_OTG_DOEPINT_EPDISD) { - LOGF_LN("Endpoint disabled 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VIO, "ep0x%"PRIx8" disabled", ep_addr); REBASE(DWC_OTG_DOEPxINT, ep_num) = DWC_OTG_DOEPINT_EPDISD; } if (REBASE(DWC_OTG_DOEPxINT, ep_num) & DWC_OTG_DOEPINT_BBLERR) { - LOGF_LN("Received more data than expected on endpoint 0x%"PRIx8, - ep_addr); + USBD_LOGF_LN(USB_VIO, "Received more data than expected on ep0x%"PRIx8,ep_addr); usbd_urb *urb = usbd_find_active_urb(dev, ep_addr); REBASE(DWC_OTG_DOEPxINT, ep_num) = DWC_OTG_DOEPINT_BBLERR; premature_urb_complete(dev, urb, USBD_ERR_BABBLE); @@ -916,7 +917,7 @@ static void process_out_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DOEPxINT, ep_num) & DWC_OTG_DOEPINT_XFRC) { REBASE(DWC_OTG_DOEPxINT, ep_num) = DWC_OTG_DOEPINT_XFRC; - LOGF_LN("Transfer Complete: endpoint 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VIO, "Transfer Complete: ep0x%"PRIx8, ep_addr); usbd_urb *urb = usbd_find_active_urb(dev, ep_addr); if (!ep_num && urb != NULL && dev->private_data.ep0tsiz_pktcnt) { @@ -946,7 +947,7 @@ static void process_out_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) } if (REBASE(DWC_OTG_DOEPxINT, ep_num) & DWC_OTG_DOEPINT_STUP) { - LOGF_LN("Setup phase done for endpoint 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VSETUP, "Setup phase done for ep0x%"PRIx8, ep_addr); REBASE(DWC_OTG_DOEPxINT, ep_num) = DWC_OTG_DOEPINT_STUP; REBASE(DWC_OTG_DOEPxTSIZ, ep_num) |= DWC_OTG_DOEPTSIZ_STUPCNT_3; @@ -955,8 +956,7 @@ static void process_out_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DOEPxINT, ep_num) & DWC_OTG_DOEPINT_OTEPDIS) { REBASE(DWC_OTG_DOEPxINT, ep_num) = DWC_OTG_DOEPINT_OTEPDIS; - LOGF_LN("Data OUT Token received when endpoint 0x%"PRIx8" was disable", - ep_addr); + USBD_LOGF_LN(USB_VIO, "Data OUT Token received when ep0x%"PRIx8" was disable", ep_addr); } } diff --git a/lib/usbd/usbd.c b/lib/usbd/usbd.c index cd382b91..8cb7d32d 100644 --- a/lib/usbd/usbd.c +++ b/lib/usbd/usbd.c @@ -210,3 +210,10 @@ usbd_speed usbd_get_speed(usbd_device *dev) /**@}*/ +#if defined(USBD_DEBUG) +void usbd_log_call(const char *fname){ + USBD_LOG(USB_VALL, "inside "); + USBD_LOG_LN(USB_VALL, fname); +} +#endif + diff --git a/lib/usbd/usbd_private.h b/lib/usbd/usbd_private.h index dc6cc74d..82157c87 100644 --- a/lib/usbd/usbd_private.h +++ b/lib/usbd/usbd_private.h @@ -211,23 +211,67 @@ struct usbd_backend { #endif }; +#define USB_VALL 0 +#define USB_VFAIL 1 +#define USB_VINFO 2 +#define USB_VNOTE 3 +#define USB_VDEBUG 4 +#define USB_VTRACE 5 + +#define USB_VCALL USB_VTRACE +#define USB_VIO USB_VTRACE +#define USB_VSETUP USB_VDEBUG + +#if !defined(USBD_DEBUG) +//# define USBD_DEBUG USB_VDEBUG +#endif + +#define NEW_LINE "\n" + #if defined(USBD_DEBUG) extern void usbd_log_puts(const char *arg); extern void usbd_log_printf(const char *fmt, ...) __attribute__((format(printf, 1, 2))); +extern void usbd_log_call(const char *fname); + # include -# define LOG(str) usbd_log_puts(str) -# define LOGF(fmt,...) usbd_log_printf(fmt, ##__VA_ARGS__) +# define USBD_STR(s) s +# define USBD_LOG(level, str) if (level <= USBD_DEBUG) usbd_log_puts(str) +# define USBD_LOGF(level, fmt,...) if (level <= USBD_DEBUG) usbd_log_printf(fmt, ##__VA_ARGS__) + +# define USBD_LOG_LN(level, str) USBD_LOG(level, str); USBD_LOG(level, NEW_LINE ); +//# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, fmt, __VA_ARGS__); USBD_LOG(level, NEW_LINE ); +# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, USBD_STR(fmt)NEW_LINE, __VA_ARGS__); + +# if USBD_DEBUG >= USB_VCALL +# define USBD_LOG_CALL usbd_log_call(__func__) +# else +# define USBD_LOG_CALL +# endif + +//temps for backport +# define LOG(str) USBD_LOG(USB_VALL, str) +# define LOGF(fmt,...) USBD_LOGF(USB_VALL, fmt, __VA_ARGS__) + +# define LOG_LN(str) USBD_LOG_LN(USB_VALL, str) +# define LOGF_LN(fmt,...) USBD_LOGF_LN(USB_VALL, fmt, __VA_ARGS__) + +# define LOG_CALL USBD_LOG_CALL + #else +# define USBD_LOG(level, str) +# define USBD_LOGF(level, fmt,...) +# define USBD_LOG_LN(level, str) +# define USBD_LOGF_LN(level, fmt,...) +# define USBD_LOG_CALL + # define LOG(str) # define LOGF(fmt,...) +# define LOG_LN(str) +# define LOGF_LN(fmt,...) +# define LOG_CALL #endif -#define NEW_LINE "\n" -#define LOG_LN(str) LOG(str); LOG(NEW_LINE) -#define LOGF_LN(fmt,...) LOGF(fmt, __VA_ARGS__); LOG(NEW_LINE) -#define LOG_CALL LOG("inside "); LOG_LN(__func__); - #define IS_URB_ID_INVALID(urb_id) ((urb_id) == USBD_INVALID_URB_ID) #define IS_URB_INVALID(urb) IS_URB_ID_INVALID((urb)->id) From 34e79c4c923a5553d98a6162a402036f808e2802 Mon Sep 17 00:00:00 2001 From: alexrayne Date: Fri, 30 Dec 2016 15:48:55 +0200 Subject: [PATCH 2/6] *usbd:USBD_LOG - continue migrate to USBD_LOG, make messages shorter + USB_VURB,VURBQUE,VURBFAIL,VIO_MSC --- lib/usbd/backend/usbd_dwc_otg.c | 2 +- lib/usbd/class/usbd_msc.c | 8 ++++++- lib/usbd/usbd_private.h | 12 +++++++---- lib/usbd/usbd_transfer.c | 37 ++++++++++++++------------------- 4 files changed, 32 insertions(+), 27 deletions(-) diff --git a/lib/usbd/backend/usbd_dwc_otg.c b/lib/usbd/backend/usbd_dwc_otg.c index c7adbd30..cd419901 100644 --- a/lib/usbd/backend/usbd_dwc_otg.c +++ b/lib/usbd/backend/usbd_dwc_otg.c @@ -727,7 +727,7 @@ static void fifo_to_urb_1pkt(usbd_device *dev, usbd_urb *urb, uint16_t bcnt) if (bcnt < transfer->ep_size) { if (transfer->ep_type == USBD_EP_BULK) { - LOGF_LN("Short packet received for Bulk endpoint 0x%"PRIx8, + USBD_LOGF_LN(USB_VIO, "Short packet received for Bulk endpoint 0x%"PRIx8, transfer->ep_addr); if (transfer->flags & USBD_FLAG_SHORT_PACKET) { diff --git a/lib/usbd/class/usbd_msc.c b/lib/usbd/class/usbd_msc.c index 5b5d7d53..8cca5d90 100644 --- a/lib/usbd/class/usbd_msc.c +++ b/lib/usbd/class/usbd_msc.c @@ -406,6 +406,7 @@ static void scsi_command(usbd_msc *ms, trans->byte_count = 0; } + USBD_LOGF_LN(USB_VIO_MSC, "SCSI:cmd %x", trans->cbw.CBWCB[0]); switch (trans->cbw.CBWCB[0]) { case USB_MSC_SCSI_TEST_UNIT_READY: case USB_MSC_SCSI_SEND_DIAGNOSTIC: @@ -440,6 +441,7 @@ static void scsi_command(usbd_msc *ms, scsi_write_10(ms, trans, event); break; default: + USBD_LOGF_LN(USB_VIO_MSC, "SCSI:cmd %x uncknown", trans->cbw.CBWCB[0]); set_sbc_status(ms, SBC_SENSE_KEY_ILLEGAL_REQUEST, SBC_ASC_INVALID_COMMAND_OPERATION_CODE, SBC_ASCQ_NA); @@ -791,18 +793,22 @@ bool usbd_msc_setup_ep0(usbd_msc *ms, const uint8_t value = USB_REQ_TYPE_CLASS | USB_REQ_TYPE_INTERFACE; if ((setup_data->bmRequestType & mask) == value) { + USBD_LOGF(USB_VSETUP, "USB:MSC:Req %x ", (int)setup_data->bRequest); switch (setup_data->bRequest) { case USB_MSC_REQ_BULK_ONLY_RESET: + USBD_LOG(USB_VSETUP,"BULK_ONLY_RESET\n"); /* Do any special reset code here. */ usbd_ep0_transfer(dev, setup_data, NULL, 0, NULL); return true; case USB_MSC_REQ_GET_MAX_LUN: { + USBD_LOG(USB_VSETUP,"MAX_LUN 0\n"); /* Return the number of LUNs. We use 0. */ static const uint8_t res = 0; usbd_ep0_transfer(dev, setup_data, (void *) &res, sizeof(res), NULL); return true; - }} + } + }//switch (setup_data->bRequest) } return false; diff --git a/lib/usbd/usbd_private.h b/lib/usbd/usbd_private.h index 82157c87..7bc0ebc0 100644 --- a/lib/usbd/usbd_private.h +++ b/lib/usbd/usbd_private.h @@ -219,11 +219,15 @@ struct usbd_backend { #define USB_VTRACE 5 #define USB_VCALL USB_VTRACE -#define USB_VIO USB_VTRACE +#define USB_VIO USB_VDEBUG #define USB_VSETUP USB_VDEBUG +#define USB_VURB USB_VDEBUG +#define USB_VURBQUE USB_VTRACE +#define USB_VURBFAIL USB_VDEBUG +#define USB_VIO_MSC USB_VDEBUG #if !defined(USBD_DEBUG) -//# define USBD_DEBUG USB_VDEBUG +# define USBD_DEBUG USB_VDEBUG #endif #define NEW_LINE "\n" @@ -241,10 +245,10 @@ extern void usbd_log_call(const char *fname); # define USBD_LOG_LN(level, str) USBD_LOG(level, str); USBD_LOG(level, NEW_LINE ); //# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, fmt, __VA_ARGS__); USBD_LOG(level, NEW_LINE ); -# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, USBD_STR(fmt)NEW_LINE, __VA_ARGS__); +# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, USBD_STR(fmt)NEW_LINE, __VA_ARGS__) # if USBD_DEBUG >= USB_VCALL -# define USBD_LOG_CALL usbd_log_call(__func__) +# define USBD_LOG_CALL usbd_log_call(__func__); # else # define USBD_LOG_CALL # endif diff --git a/lib/usbd/usbd_transfer.c b/lib/usbd/usbd_transfer.c index fccc0d22..1e7a7bfa 100644 --- a/lib/usbd/usbd_transfer.c +++ b/lib/usbd/usbd_transfer.c @@ -177,7 +177,7 @@ static void queue_item_append(struct usbd_urb_queue *queue, usbd_urb *urb) queue->tail = urb; } else { /* Problem! */ - LOGF_LN("URB Queue %p corrupt", queue); + USBD_LOGF_LN(USB_VURBFAIL, "URB Queue %p corrupt", queue); queue->head = queue->tail = urb; } } @@ -298,8 +298,7 @@ usbd_urb_id usbd_transfer_submit(usbd_device *dev, if (transfer->ep_type == USBD_EP_CONTROL) { if (!ENDPOINT_NUMBER(transfer->ep_addr) && !ctrl_ep0_size_acceptable(transfer->ep_size)) { - LOGF_LN("Invalid control endpoint size %"PRIu16" for EP0", - transfer->ep_size); + USBD_LOGF_LN(USB_VURBFAIL, "Invalid control endpoint size %"PRIu16" for EP0", transfer->ep_size); TRANSFER_INVALID(dev, transfer); return USBD_INVALID_URB_ID; } @@ -321,6 +320,8 @@ usbd_urb_id usbd_transfer_submit(usbd_device *dev, (dev->last_poll + MS2US(transfer->timeout)) : 0; #endif + bool to_active = !dev->urbs.force_all_new_urb_to_waiting && + try_alloc_ep_for_urb(dev, urb); #if defined(USBD_DEBUG) const char *ep_type_map_str[] = { @@ -330,19 +331,15 @@ usbd_urb_id usbd_transfer_submit(usbd_device *dev, [USBD_EP_BULK] = "Bulk", }; - LOGF_LN("Created URB %"PRIu64": %s %s %"PRIu8": data=%p, length=%u", + USBD_LOGF_LN(USB_VURB, "Created URB %"PRIu64": %s %s %"PRIu8": data=%p, length=%u is %s", urb->id, ep_type_map_str[urb->transfer.ep_type], IS_IN_ENDPOINT(urb->transfer.ep_addr) ? "IN" : "OUT", ENDPOINT_NUMBER(urb->transfer.ep_addr), - urb->transfer.buffer, urb->transfer.length); + urb->transfer.buffer, urb->transfer.length + , ( (to_active) ? "active" : "waiting" ) + ); #endif - bool to_active = !dev->urbs.force_all_new_urb_to_waiting && - try_alloc_ep_for_urb(dev, urb); - - LOGF_LN("[new] URB id=%"PRIu64" is %s", urb->id, - to_active ? "active" : "waiting"); - if (to_active) { mark_ep_as_free(dev, urb->transfer.ep_addr, false); queue_item_append(&dev->urbs.active, urb); @@ -365,7 +362,7 @@ static void urb_callback(usbd_device *dev, usbd_urb *urb, { LOG_CALL - LOGF_LN("URB %"PRIu64" transfer status = %s", urb->id, + USBD_LOGF_LN(USB_VURB, "URB %"PRIu64" transfer status = %s", urb->id, stringify_transfer_status(status)); /* callback provided */ @@ -388,7 +385,7 @@ bool usbd_transfer_cancel(usbd_device *dev, usbd_urb_id urb_id) usbd_urb *urb, *prev; if (IS_URB_ID_INVALID(urb_id)) { - LOG_LN("invalid urb id passed to transfer_cancel"); + USBD_LOG_LN(USB_VURBFAIL, "invalid urb id passed to transfer_cancel"); return false; } @@ -421,7 +418,7 @@ bool usbd_transfer_cancel(usbd_device *dev, usbd_urb_id urb_id) return true; } - LOGF_LN("WARN: urb with id = %"PRIu64" not found", urb_id); + USBD_LOGF_LN(USB_VURBFAIL, "WARN: urb with id = %"PRIu64" not found", urb_id); return false; } @@ -472,7 +469,7 @@ unsigned usbd_transfer_cancel_ep(usbd_device *dev, uint8_t ep_addr) void usbd_urb_schedule(usbd_device *dev) { if (dev->urbs.force_all_new_urb_to_waiting) { - LOG_LN("Could not schedule (force_all_new_urb_to_waiting = true)"); + USBD_LOG_LN(USB_VURBFAIL, "Could not schedule (force_all_new_urb_to_waiting = true)"); return; } @@ -489,7 +486,7 @@ void usbd_urb_schedule(usbd_device *dev) urb = queue_item_detach(&dev->urbs.waiting, prev, tmp); queue_item_append(&dev->urbs.active, tmp); - LOGF_LN("[waiting] URB id=%"PRIu64" is now active", tmp->id); + USBD_LOGF_LN(USB_VURB, "[waiting] URB id=%"PRIu64" is now active", tmp->id); dev->backend->urb_submit(dev, tmp); } } @@ -516,7 +513,7 @@ static void detach_from_active(usbd_device *dev, usbd_urb *item) return; } - LOGF_LN("WARNING: Found not find URB %"PRIu64" in active list to detach it", + USBD_LOGF_LN(USB_VURBFAIL, "WARNING: Found not find URB %"PRIu64" in active list to detach it", urb->id); } @@ -547,8 +544,7 @@ usbd_urb *usbd_find_active_urb(usbd_device *dev, uint8_t ep_addr) { usbd_urb *urb = NULL; - LOGF_LN("Searching for URB which is active and has " - "ep_addr=0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VURBQUE, "Searching URB on ep0x%"PRIx8, ep_addr); for (urb = dev->urbs.active.head; urb != NULL; urb = urb->next) { if (urb->transfer.ep_addr == ep_addr) { @@ -556,8 +552,7 @@ usbd_urb *usbd_find_active_urb(usbd_device *dev, uint8_t ep_addr) } } - LOGF_LN("Unable to find the current processing URB for " - "endpoint 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VURB,"Unable to find the current processing URB for ep0x%"PRIx8, ep_addr); return NULL; } From a0691e91632be0c2860230a8d992947e8edcd2b7 Mon Sep 17 00:00:00 2001 From: alexrayne Date: Wed, 4 Jan 2017 22:25:01 +0200 Subject: [PATCH 3/6] *usbd:log - shorter messages + USB_VIO2 --- lib/usbd/backend/usbd_dwc_otg.c | 10 +++++----- lib/usbd/usbd_private.h | 1 + 2 files changed, 6 insertions(+), 5 deletions(-) diff --git a/lib/usbd/backend/usbd_dwc_otg.c b/lib/usbd/backend/usbd_dwc_otg.c index cd419901..f93202fd 100644 --- a/lib/usbd/backend/usbd_dwc_otg.c +++ b/lib/usbd/backend/usbd_dwc_otg.c @@ -332,7 +332,7 @@ void dwc_otg_set_ep_stall(usbd_device *dev, uint8_t addr, bool stall) { uint8_t num = ENDPOINT_NUMBER(addr); - LOGF_LN("STALL endpoint 0x%"PRIx8" = %s", addr, stall ? "Yes" : "No"); + USBD_LOGF_LN(USB_VIO, "STALL ep0x%"PRIx8" = %s", addr, stall ? "Yes" : "No"); /* DIEP0CTL, DIEPxCTL, DOEP0CTL, DOEPxCTL have same STALL layout */ volatile uint32_t *reg_ptr = IS_IN_ENDPOINT(addr) ? @@ -389,7 +389,7 @@ static void urb_to_fifo_1pkt(usbd_device *dev, usbd_urb *urb) size_t rem_len = transfer->length - transfer->transferred; if (!rem_len) { - LOGF_LN("No more data to send URB %"PRIu64" (endpoint 0x%"PRIx8") " + USBD_LOGF_LN(USB_VURB, "No more data to send URB %"PRIu64" (ep0x%"PRIx8") " "(intending ZLP?)", urb->id, transfer->ep_addr); return; } @@ -775,7 +775,7 @@ static void handle_rxflvl_interrupt(usbd_device *dev) [15] = "RESERVED_15" }; - USBD_LOGF_LN(USB_VIO, "GRXSTSP: rxstsp = %s, ep_num = %"PRIu8", bcnt = %"PRIu16, + USBD_LOGF_LN(USB_VIO, "GRXSTSP: %s, ep%"PRIu8", bcnt = %"PRIu16, map_pktsts[DWC_OTG_GRXSTSP_PKTSTS_GET(rxstsp)], ep_num, bcnt); #endif @@ -873,7 +873,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_TXFE) { /* Send more data */ - USBD_LOGF_LN(USB_VIO, "Sending more data for endpoint 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VIO2, "Sending more data for endpoint 0x%"PRIx8, ep_addr); if (urb != NULL) { /* As per doc, before writing to FIFO, we need to write to CTL register. @@ -885,7 +885,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) } if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_ITTXFE) { - USBD_LOGF_LN(USB_VIO, "Data IN Token received when ep0x%"PRIx8" FIFO was empty", + USBD_LOGF_LN(USB_VIO2, "Data IN Token received when ep0x%"PRIx8" FIFO was empty", ep_addr); REBASE(DWC_OTG_DIEPxINT, ep_num) = DWC_OTG_DIEPINT_ITTXFE; } diff --git a/lib/usbd/usbd_private.h b/lib/usbd/usbd_private.h index 7bc0ebc0..51997925 100644 --- a/lib/usbd/usbd_private.h +++ b/lib/usbd/usbd_private.h @@ -220,6 +220,7 @@ struct usbd_backend { #define USB_VCALL USB_VTRACE #define USB_VIO USB_VDEBUG +#define USB_VIO2 USB_VTRACE #define USB_VSETUP USB_VDEBUG #define USB_VURB USB_VDEBUG #define USB_VURBQUE USB_VTRACE From 2e5756b3943bc3894c50fa9683096c7cabca5133 Mon Sep 17 00:00:00 2001 From: alexrayne Date: Tue, 21 Feb 2017 01:24:55 +0300 Subject: [PATCH 4/6] +usbd:log;urb, io - a bit more verbose log -log - remove defaulted log --- lib/usbd/backend/usbd_dwc_otg.c | 4 ++-- lib/usbd/usbd_private.h | 2 +- lib/usbd/usbd_transfer.c | 2 ++ 3 files changed, 5 insertions(+), 3 deletions(-) diff --git a/lib/usbd/backend/usbd_dwc_otg.c b/lib/usbd/backend/usbd_dwc_otg.c index f93202fd..b5ac7e7c 100644 --- a/lib/usbd/backend/usbd_dwc_otg.c +++ b/lib/usbd/backend/usbd_dwc_otg.c @@ -834,14 +834,13 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_XFRC) { REBASE(DWC_OTG_DIEPxINT, ep_num) = DWC_OTG_DIEPINT_XFRC; - USBD_LOGF_LN(USB_VIO, "Transfer Complete: ep0x%"PRIx8, ep_addr); - if (!ep_num && urb != NULL && dev->private_data.ep0tsiz_pktcnt) { /* We are still sending data! */ size_t rem = urb->transfer.length - urb->transfer.transferred; uint32_t xfrsiz = MIN(urb->transfer.ep_size, rem); dev->private_data.ep0tsiz_pktcnt--; + USBD_LOGF_LN(USB_VIO, "USBD: new frame: ep0x%"PRIx8" len %d\n", ep_addr, xfrsiz); REBASE(DWC_OTG_DIEP0TSIZ) = DWC_OTG_DIEP0TSIZ_PKTCNT_1 | DWC_OTG_DIEP0TSIZ_XFRSIZ(xfrsiz); @@ -862,6 +861,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) /* Disable Interrupt */ REBASE(DWC_OTG_DAINTMSK) &= ~DWC_OTG_DAINTMSK_IEPM(ep_num); + USBD_LOGF_LN(USB_VIO, "USBD: last frame: ep0x%"PRIx8"\n", ep_addr); /* The URB has been processed, do the callback */ if (urb != NULL) { usbd_urb_complete(dev, urb, USBD_SUCCESS); diff --git a/lib/usbd/usbd_private.h b/lib/usbd/usbd_private.h index 51997925..633a95f2 100644 --- a/lib/usbd/usbd_private.h +++ b/lib/usbd/usbd_private.h @@ -228,7 +228,7 @@ struct usbd_backend { #define USB_VIO_MSC USB_VDEBUG #if !defined(USBD_DEBUG) -# define USBD_DEBUG USB_VDEBUG +//# define USBD_DEBUG USB_VDEBUG #endif #define NEW_LINE "\n" diff --git a/lib/usbd/usbd_transfer.c b/lib/usbd/usbd_transfer.c index 1e7a7bfa..95b310c4 100644 --- a/lib/usbd/usbd_transfer.c +++ b/lib/usbd/usbd_transfer.c @@ -527,6 +527,8 @@ static void detach_from_active(usbd_device *dev, usbd_urb *item) void usbd_urb_complete(usbd_device *dev, usbd_urb *urb, usbd_transfer_status status) { + USBD_LOGF_LN(USB_VURB, "URB %"PRIu64" on ep0x%"PRIx8" complete\n" + , urb->id, urb->transfer.ep_addr); detach_from_active(dev, urb); urb_callback(dev, urb, status); unused_push(dev, urb); From 396022af722d988da66d0962abdbfcb968b783a7 Mon Sep 17 00:00:00 2001 From: alexrayne Date: Tue, 14 Mar 2017 22:29:25 +0200 Subject: [PATCH 5/6] +usbd:usbd_log.h - introduce localiser header for debug loggers, that can provide project instrumentation for log + : PRIurb, view_urbid - add this wrapers to adopt log instruments with int64 urb_id. +usbd:log:USB_VIO_INIT - printer for initialisation verbose + USB_MSC --- lib/usbd/backend/usbd_dwc_otg.c | 14 +++- lib/usbd/class/usbd_msc.c | 14 +++- lib/usbd/usbd.c | 3 +- lib/usbd/usbd_ep0.c | 5 +- lib/usbd/usbd_log.h | 110 ++++++++++++++++++++++++++++++++ lib/usbd/usbd_private.h | 66 +------------------ lib/usbd/usbd_transfer.c | 34 +++++----- 7 files changed, 155 insertions(+), 91 deletions(-) create mode 100644 lib/usbd/usbd_log.h diff --git a/lib/usbd/backend/usbd_dwc_otg.c b/lib/usbd/backend/usbd_dwc_otg.c index b5ac7e7c..f0c3ae11 100644 --- a/lib/usbd/backend/usbd_dwc_otg.c +++ b/lib/usbd/backend/usbd_dwc_otg.c @@ -243,6 +243,8 @@ void dwc_otg_ep_prepare(usbd_device *dev, uint8_t addr, if (IS_IN_ENDPOINT(addr)) { /* FIXME: underflow */ dev->private_data.fifo_remaining -= fifo_word; /* IN */ + USBD_LOGF_LN(USB_VIO_INIT, "USBD: EP%dIN avail %x" + , num, REBASE(DWC_OTG_DIEPxTXFSTS, num) ); REBASE(DWC_OTG_DIEPxTXF, num) = DWC_OTG_DIEPTXF_INEPTXFD(fifo_word) | DWC_OTG_DIEPTXF_INEPTXSA(dev->private_data.fifo_remaining); @@ -250,6 +252,10 @@ void dwc_otg_ep_prepare(usbd_device *dev, uint8_t addr, REBASE(DWC_OTG_DIEPxCTL, num) = DWC_OTG_DIEPCTL_SNAK | DWC_OTG_DIEPCTL_SD0PID | eptyp_map[type] | DWC_OTG_DIEPCTL_USBAEP | DWC_OTG_DIEPCTL_TXFNUM(num); + + USBD_LOGF_LN(USB_VIO_INIT, "USBD: EP%dIN assign at %x[%x] avail %x" + , num, dev->private_data.fifo_remaining, fifo_word + , REBASE(DWC_OTG_DIEPxTXFSTS, num) ); } else { if (type == USBD_EP_CONTROL) { dev->private_data.fifo_rx_usage_overall += 13; /* Setup */ @@ -389,8 +395,8 @@ static void urb_to_fifo_1pkt(usbd_device *dev, usbd_urb *urb) size_t rem_len = transfer->length - transfer->transferred; if (!rem_len) { - USBD_LOGF_LN(USB_VURB, "No more data to send URB %"PRIu64" (ep0x%"PRIx8") " - "(intending ZLP?)", urb->id, transfer->ep_addr); + USBD_LOGF_LN(USB_VURB, "No more data to send URB %"PRIurb" (ep0x%"PRIx8") " + "(intending ZLP?)", view_urbid(urb->id), transfer->ep_addr); return; } @@ -917,11 +923,11 @@ static void process_out_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DOEPxINT, ep_num) & DWC_OTG_DOEPINT_XFRC) { REBASE(DWC_OTG_DOEPxINT, ep_num) = DWC_OTG_DOEPINT_XFRC; - USBD_LOGF_LN(USB_VIO, "Transfer Complete: ep0x%"PRIx8, ep_addr); usbd_urb *urb = usbd_find_active_urb(dev, ep_addr); if (!ep_num && urb != NULL && dev->private_data.ep0tsiz_pktcnt) { /* We are still expecting data! */ + USBD_LOGF_LN(USB_VIO, "Transfer chunk Complete: ep0x%"PRIx8, ep_addr); dev->private_data.ep0tsiz_pktcnt--; @@ -931,6 +937,7 @@ static void process_out_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) REBASE(DWC_OTG_DOEP0CTL) |= DWC_OTG_DOEP0CTL_EPENA; } else { + USBD_LOGF_LN(USB_VIO, "Transfer Complete: ep0x%"PRIx8, ep_addr); /* Set NAK on the endpoint */ REBASE(DWC_OTG_DOEPxCTL, ep_num) |= DWC_OTG_DOEPCTL_SNAK; @@ -980,6 +987,7 @@ static inline void alloc_fifo_for_ep0_only(usbd_device *dev) void dwc_otg_poll(usbd_device *dev) { if (REBASE(DWC_OTG_GINTSTS) & DWC_OTG_GINTSTS_ENUMDNE) { + USBD_LOG_LN(USB_VIO_INIT,"USBD:enumerated"); REBASE(DWC_OTG_DCFG) &= ~DWC_OTG_DCFG_DAD_MASK; disable_all_non_ep0(dev); alloc_fifo_for_ep0_only(dev); diff --git a/lib/usbd/class/usbd_msc.c b/lib/usbd/class/usbd_msc.c index 8cca5d90..e67eb703 100644 --- a/lib/usbd/class/usbd_msc.c +++ b/lib/usbd/class/usbd_msc.c @@ -27,6 +27,10 @@ #include #include "../usbd_private.h" +#ifndef USB_VSETUP_MSC +#define USB_VSETUP_MSC USB_VSETUP +#endif + /* * TODO: * - Removable media support @@ -230,6 +234,8 @@ static void scsi_write_10(usbd_msc *ms, trans->current_block = 0; trans->bytes_to_recv = trans->block_count << 9; + USBD_LOGF_LN(USB_MSC, "SCSI: write10 lba%x * %x" + , trans->lba_start, trans->block_count); } } @@ -248,6 +254,8 @@ static void scsi_read_10(usbd_msc *ms, /* both are in terms of 512 byte blocks, so shift by 9 */ trans->bytes_to_send = trans->block_count << 9; + USBD_LOGF_LN(USB_MSC, "SCSI: read10 lba%x * %x" + , trans->lba_start, trans->block_count); set_sbc_status_good(ms); } } @@ -793,15 +801,15 @@ bool usbd_msc_setup_ep0(usbd_msc *ms, const uint8_t value = USB_REQ_TYPE_CLASS | USB_REQ_TYPE_INTERFACE; if ((setup_data->bmRequestType & mask) == value) { - USBD_LOGF(USB_VSETUP, "USB:MSC:Req %x ", (int)setup_data->bRequest); + USBD_LOGF(USB_VSETUP_MSC, "USB:MSC:Req %x ", (int)setup_data->bRequest); switch (setup_data->bRequest) { case USB_MSC_REQ_BULK_ONLY_RESET: - USBD_LOG(USB_VSETUP,"BULK_ONLY_RESET\n"); + USBD_LOG(USB_VSETUP_MSC,"BULK_ONLY_RESET\n"); /* Do any special reset code here. */ usbd_ep0_transfer(dev, setup_data, NULL, 0, NULL); return true; case USB_MSC_REQ_GET_MAX_LUN: { - USBD_LOG(USB_VSETUP,"MAX_LUN 0\n"); + USBD_LOG(USB_VSETUP_MSC,"MAX_LUN 0\n"); /* Return the number of LUNs. We use 0. */ static const uint8_t res = 0; usbd_ep0_transfer(dev, setup_data, (void *) &res, diff --git a/lib/usbd/usbd.c b/lib/usbd/usbd.c index 8cb7d32d..852c4353 100644 --- a/lib/usbd/usbd.c +++ b/lib/usbd/usbd.c @@ -212,8 +212,7 @@ usbd_speed usbd_get_speed(usbd_device *dev) #if defined(USBD_DEBUG) void usbd_log_call(const char *fname){ - USBD_LOG(USB_VALL, "inside "); - USBD_LOG_LN(USB_VALL, fname); + USBD_LOGF_LN(USB_VALL, "inside %s" , fname); } #endif diff --git a/lib/usbd/usbd_ep0.c b/lib/usbd/usbd_ep0.c index 1081f080..55d292d4 100644 --- a/lib/usbd/usbd_ep0.c +++ b/lib/usbd/usbd_ep0.c @@ -790,6 +790,7 @@ standard_request_endpoint(usbd_device *dev, struct usbd_control_arg *arg) case USB_REQ_CLEAR_FEATURE: if (arg->setup->wValue == USB_FEAT_ENDPOINT_HALT) { uint8_t ep_addr = arg->setup->wIndex; + USBD_LOGF_LN(USB_VSETUP,"USBD:CLEAR_FEATURE - halt EP%d", ep_addr); usbd_set_ep_dtog(dev, ep_addr, false); usbd_set_ep_stall(dev, ep_addr, false); return USBD_REQ_HANDLED; @@ -797,7 +798,9 @@ standard_request_endpoint(usbd_device *dev, struct usbd_control_arg *arg) break; case USB_REQ_SET_FEATURE: if (arg->setup->wValue == USB_FEAT_ENDPOINT_HALT) { - usbd_set_ep_stall(dev, arg->setup->wIndex, true); + uint8_t ep_addr = arg->setup->wIndex; + USBD_LOGF_LN(USB_VSETUP,"USBD:SET_FEATURE - halt EP%d", ep_addr); + usbd_set_ep_stall(dev, ep_addr, true); return USBD_REQ_HANDLED; } break; diff --git a/lib/usbd/usbd_log.h b/lib/usbd/usbd_log.h new file mode 100644 index 00000000..306b1957 --- /dev/null +++ b/lib/usbd/usbd_log.h @@ -0,0 +1,110 @@ +/* + * This file is part of the unicore-mx project. + * + * Copyright (C) 2010 Gareth McMullin + * Copyright (C) 2015, 2016 Kuldeep Singh Dhaka + * + * This library is free software: you can redistribute it and/or modify + * it under the terms of the GNU Lesser General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This library is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Lesser General Public License for more details. + * + * You should have received a copy of the GNU Lesser General Public License + * along with this library. If not, see . + */ + +/* + * This file is intended to declare internal debug log printing port + * It can be copyed into target project folder, and modifyed to link with target system + */ + +#ifndef UNICOREMX_USBD_LOG_PRIVATE_H +#define UNICOREMX_USBD_LOG_PRIVATE_H + +#include + +BEGIN_DECLS + + + +#define USB_VALL 0 +#define USB_VFAIL 1 +#define USB_VINFO 2 +#define USB_VNOTE 3 +#define USB_VDEBUG 4 +#define USB_VTRACE 5 + +#define USB_VCALL USB_VTRACE +#define USB_VIO USB_VDEBUG +#define USB_VIO2 USB_VTRACE +#define USB_VIO_INIT USB_VDEBUG +#define USB_VSETUP USB_VDEBUG +#define USB_VSETUP_MSC USB_VDEBUG +#define USB_VURB USB_VDEBUG +#define USB_VURBQUE USB_VTRACE +#define USB_VURBFAIL USB_VDEBUG +#define USB_VIO_MSC USB_VDEBUG +#define USB_MSC USB_VDEBUG + +#if !defined(USBD_DEBUG) +//# define USBD_DEBUG USB_VDEBUG +#endif + +#define NEW_LINE "\n" +#define PRIurb PRIu64 +#define view_urbid(uid) uid + +#if defined(USBD_DEBUG) +extern void usbd_log_puts(const char *arg); +extern void usbd_log_printf(const char *fmt, ...) + __attribute__((format(printf, 1, 2))); +extern void usbd_log_call(const char *fname); + +# include +# define USBD_STR(s) s +# define USBD_LOG(level, str) if (level <= USBD_DEBUG) usbd_log_puts(str) +# define USBD_LOGF(level, fmt,...) if (level <= USBD_DEBUG) usbd_log_printf(fmt, ##__VA_ARGS__) + +# define USBD_LOG_LN(level, str) USBD_LOG(level, USBD_STR(fmt)NEW_LINE); +//# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, fmt, __VA_ARGS__); USBD_LOG(level, NEW_LINE ); +# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, USBD_STR(fmt)NEW_LINE, __VA_ARGS__) + +# if USBD_DEBUG >= USB_VCALL +# define USBD_LOG_CALL usbd_log_call(__func__); +# else +# define USBD_LOG_CALL +# endif + +//temps for backport +# define LOG(str) USBD_LOG(USB_VALL, str) +# define LOGF(fmt,...) USBD_LOGF(USB_VALL, fmt, __VA_ARGS__) + +# define LOG_LN(str) USBD_LOG_LN(USB_VALL, str) +# define LOGF_LN(fmt,...) USBD_LOGF_LN(USB_VALL, fmt, __VA_ARGS__) + +# define LOG_CALL USBD_LOG_CALL + +#else +# define USBD_LOG(level, str) +# define USBD_LOGF(level, fmt,...) +# define USBD_LOG_LN(level, str) +# define USBD_LOGF_LN(level, fmt,...) +# define USBD_LOG_CALL + +# define LOG(str) +# define LOGF(fmt,...) +# define LOG_LN(str) +# define LOGF_LN(fmt,...) +# define LOG_CALL +#endif + + + +END_DECLS + +#endif diff --git a/lib/usbd/usbd_private.h b/lib/usbd/usbd_private.h index 80915c31..2424b83f 100644 --- a/lib/usbd/usbd_private.h +++ b/lib/usbd/usbd_private.h @@ -211,71 +211,7 @@ struct usbd_backend { #endif }; -#define USB_VALL 0 -#define USB_VFAIL 1 -#define USB_VINFO 2 -#define USB_VNOTE 3 -#define USB_VDEBUG 4 -#define USB_VTRACE 5 - -#define USB_VCALL USB_VTRACE -#define USB_VIO USB_VDEBUG -#define USB_VIO2 USB_VTRACE -#define USB_VSETUP USB_VDEBUG -#define USB_VURB USB_VDEBUG -#define USB_VURBQUE USB_VTRACE -#define USB_VURBFAIL USB_VDEBUG -#define USB_VIO_MSC USB_VDEBUG - -#if !defined(USBD_DEBUG) -//# define USBD_DEBUG USB_VDEBUG -#endif - -#define NEW_LINE "\n" - -#if defined(USBD_DEBUG) -extern void usbd_log_puts(const char *arg); -extern void usbd_log_printf(const char *fmt, ...) - __attribute__((format(printf, 1, 2))); -extern void usbd_log_call(const char *fname); - -# include -# define USBD_STR(s) s -# define USBD_LOG(level, str) if (level <= USBD_DEBUG) usbd_log_puts(str) -# define USBD_LOGF(level, fmt,...) if (level <= USBD_DEBUG) usbd_log_printf(fmt, ##__VA_ARGS__) - -# define USBD_LOG_LN(level, str) USBD_LOG(level, str); USBD_LOG(level, NEW_LINE ); -//# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, fmt, __VA_ARGS__); USBD_LOG(level, NEW_LINE ); -# define USBD_LOGF_LN(level, fmt,...) USBD_LOGF(level, USBD_STR(fmt)NEW_LINE, __VA_ARGS__) - -# if USBD_DEBUG >= USB_VCALL -# define USBD_LOG_CALL usbd_log_call(__func__); -# else -# define USBD_LOG_CALL -# endif - -//temps for backport -# define LOG(str) USBD_LOG(USB_VALL, str) -# define LOGF(fmt,...) USBD_LOGF(USB_VALL, fmt, __VA_ARGS__) - -# define LOG_LN(str) USBD_LOG_LN(USB_VALL, str) -# define LOGF_LN(fmt,...) USBD_LOGF_LN(USB_VALL, fmt, __VA_ARGS__) - -# define LOG_CALL USBD_LOG_CALL - -#else -# define USBD_LOG(level, str) -# define USBD_LOGF(level, fmt,...) -# define USBD_LOG_LN(level, str) -# define USBD_LOGF_LN(level, fmt,...) -# define USBD_LOG_CALL - -# define LOG(str) -# define LOGF(fmt,...) -# define LOG_LN(str) -# define LOGF_LN(fmt,...) -# define LOG_CALL -#endif +#include #define IS_URB_ID_INVALID(urb_id) ((urb_id) == USBD_INVALID_URB_ID) #define IS_URB_INVALID(urb) IS_URB_ID_INVALID((urb)->id) diff --git a/lib/usbd/usbd_transfer.c b/lib/usbd/usbd_transfer.c index 95b310c4..ebb134f2 100644 --- a/lib/usbd/usbd_transfer.c +++ b/lib/usbd/usbd_transfer.c @@ -331,8 +331,8 @@ usbd_urb_id usbd_transfer_submit(usbd_device *dev, [USBD_EP_BULK] = "Bulk", }; - USBD_LOGF_LN(USB_VURB, "Created URB %"PRIu64": %s %s %"PRIu8": data=%p, length=%u is %s", - urb->id, ep_type_map_str[urb->transfer.ep_type], + USBD_LOGF_LN(USB_VURB, "Created URB %"PRIurb": %s %s %"PRIu8": data=%p, length=%u is %s", + view_urbid(urb->id), ep_type_map_str[urb->transfer.ep_type], IS_IN_ENDPOINT(urb->transfer.ep_addr) ? "IN" : "OUT", ENDPOINT_NUMBER(urb->transfer.ep_addr), urb->transfer.buffer, urb->transfer.length @@ -362,7 +362,7 @@ static void urb_callback(usbd_device *dev, usbd_urb *urb, { LOG_CALL - USBD_LOGF_LN(USB_VURB, "URB %"PRIu64" transfer status = %s", urb->id, + USBD_LOGF_LN(USB_VURB, "URB %"PRIurb" transfer status = %s", view_urbid(urb->id), stringify_transfer_status(status)); /* callback provided */ @@ -486,7 +486,7 @@ void usbd_urb_schedule(usbd_device *dev) urb = queue_item_detach(&dev->urbs.waiting, prev, tmp); queue_item_append(&dev->urbs.active, tmp); - USBD_LOGF_LN(USB_VURB, "[waiting] URB id=%"PRIu64" is now active", tmp->id); + USBD_LOGF_LN(USB_VURB, "[waiting] URB id=%"PRIurb" is now active", view_urbid(tmp->id) ); dev->backend->urb_submit(dev, tmp); } } @@ -513,8 +513,8 @@ static void detach_from_active(usbd_device *dev, usbd_urb *item) return; } - USBD_LOGF_LN(USB_VURBFAIL, "WARNING: Found not find URB %"PRIu64" in active list to detach it", - urb->id); + USBD_LOGF_LN(USB_VURBFAIL, "WARNING: Found not find URB %"PRIurb" in active list to detach it" + , view_urbid(urb->id) ); } /** @@ -527,8 +527,8 @@ static void detach_from_active(usbd_device *dev, usbd_urb *item) void usbd_urb_complete(usbd_device *dev, usbd_urb *urb, usbd_transfer_status status) { - USBD_LOGF_LN(USB_VURB, "URB %"PRIu64" on ep0x%"PRIx8" complete\n" - , urb->id, urb->transfer.ep_addr); + USBD_LOGF_LN(USB_VURB, "URB %"PRIurb" on ep0x%"PRIx8" complete\n" + , view_urbid(urb->id), urb->transfer.ep_addr); detach_from_active(dev, urb); urb_callback(dev, urb, status); unused_push(dev, urb); @@ -662,8 +662,8 @@ static void _control_status_callback(usbd_device *dev, (void) urb_id; if (status != USBD_SUCCESS) { - LOGF_LN("[Control status stage] Transfer %"PRIu64" failed with " - "status=%s", urb_id, stringify_transfer_status(status)); + USBD_LOGF_LN(USB_VURB, "[Control status stage] Transfer %"PRIurb" failed with status=%s" + , view_urbid(urb_id), stringify_transfer_status(status)); return; } @@ -711,9 +711,9 @@ static void _control_data_callback(usbd_device *dev, (void) urb_id; if (status != USBD_SUCCESS) { - LOGF_LN("[Control data stage] Transfer %"PRIu64" failed with " - "status=%s, not going into status stage", urb_id, - stringify_transfer_status(status)); + USBD_LOGF_LN(USB_VURB, "[Control data stage] Transfer %"PRIurb" failed with " + "status=%s, not going into status stage" + , view_urbid(urb_id), stringify_transfer_status(status)); return; } @@ -825,8 +825,7 @@ void usbd_control_transfer(usbd_device *dev, uint8_t ep_addr, * going to send for data stage. * If our safest bet is to STALL the transaction. */ - LOGF_LN("STALL: User provide less buffer than " - "the host is going to send"); + LOG_LN("STALL: User provide less buffer than the host is going to send"); usbd_set_ep_stall(dev, ep_addr | 0x80, true); usbd_set_ep_stall(dev, ep_addr & 0x7F, true); return; @@ -872,8 +871,9 @@ void *usbd_urb_get_buffer_pointer(usbd_device *dev, usbd_urb *urb, size_t len) #if defined(USBD_DEBUG) if ((transfer->transferred + len) > transfer->length) { - LOGF_LN("URB %"PRIu64" buffer overflow detected! " - "(backend want to %s %"PRIu16" bytes to buffer)", urb->id, + LOGF_LN("URB %"PRIurb" buffer overflow detected! " + "(backend want to %s %"PRIu16" bytes to buffer)" + , view_urbid(urb->id), out ? "write" : "read", len); LOGF_LN("transfer->length: %"PRIu16, transfer->length); LOGF_LN("transfer->transferred: %"PRIu16, transfer->transferred); From 242364f0fb1127106ff2992c37adc96cbd789a04 Mon Sep 17 00:00:00 2001 From: alexrayne Date: Wed, 24 May 2017 12:14:53 +0200 Subject: [PATCH 6/6] *usbd:log - a bit more messages, a bit shorter --- lib/usbd/backend/usbd_dwc_otg.c | 18 ++++++++++++++---- lib/usbd/usbd_ep0.c | 4 ++-- 2 files changed, 16 insertions(+), 6 deletions(-) diff --git a/lib/usbd/backend/usbd_dwc_otg.c b/lib/usbd/backend/usbd_dwc_otg.c index f0c3ae11..1a6815df 100644 --- a/lib/usbd/backend/usbd_dwc_otg.c +++ b/lib/usbd/backend/usbd_dwc_otg.c @@ -169,6 +169,8 @@ static void disable_all_non_ep0(usbd_device *dev) { unsigned i; + USBD_LOG_LN(USB_VIO, "USBD:disable endpoints"); + for (i = 1; i < get_ep_count(dev); i++) { REBASE(DWC_OTG_DOEPxINT, i) = 0xFFFF; @@ -401,6 +403,10 @@ static void urb_to_fifo_1pkt(usbd_device *dev, usbd_urb *urb) } size_t tx_len = MIN(transfer->ep_size, rem_len); + USBD_LOGF_LN(USB_VIO2_URB, "USBD:tx URB%"PRIurb" (%d/%d) + %d" + , view_urbid(urb->id) + , transfer->transferred, transfer->length, tx_len + ); /* TX FIFO has enough space to write "tx_len" of data */ size_t tx_words = DIVIDE_AND_CEIL(tx_len, 4); @@ -553,6 +559,9 @@ static void urb_submit_non_ep0(usbd_device *dev, usbd_urb *urb) DWC_OTG_DIEPCTL_CNAK | DWC_OTG_DIEPCTL_TXFNUM(ep_num) | eptyp_map[transfer->ep_type] | DWC_OTG_DIEPCTL_USBAEP; + USBD_LOGF_LN(USB_VIO, "USBD:submit urb%"PRIurb" on ep8%"PRIx8" DIEPxTSIZ=%x" + , view_urbid(urb->id), ep_num, REBASE(DWC_OTG_DIEPxTSIZ, ep_num) ); + /* Push first packet to memory! */ if (transfer->length) { /* Enable empty interrupt mask */ @@ -846,7 +855,8 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) size_t rem = urb->transfer.length - urb->transfer.transferred; uint32_t xfrsiz = MIN(urb->transfer.ep_size, rem); dev->private_data.ep0tsiz_pktcnt--; - USBD_LOGF_LN(USB_VIO, "USBD: new frame: ep0x%"PRIx8" len %d\n", ep_addr, xfrsiz); + USBD_LOGF_LN(USB_VIO2, "USBD: new frame: ep%"PRIx8" len %d\n", ep_addr, xfrsiz); + //USBD_LOGF_LN(USB_VIO3, "USBD:IN%x:new0:DIEP3TSIZ=0x%x", ep_num, REBASE(DWC_OTG_DIEPxTSIZ, 3)) REBASE(DWC_OTG_DIEP0TSIZ) = DWC_OTG_DIEP0TSIZ_PKTCNT_1 | DWC_OTG_DIEP0TSIZ_XFRSIZ(xfrsiz); @@ -867,7 +877,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) /* Disable Interrupt */ REBASE(DWC_OTG_DAINTMSK) &= ~DWC_OTG_DAINTMSK_IEPM(ep_num); - USBD_LOGF_LN(USB_VIO, "USBD: last frame: ep0x%"PRIx8"\n", ep_addr); + USBD_LOGF_LN(USB_VIO2, "USBD: last frame: ep%"PRIx8"\n", ep_addr); /* The URB has been processed, do the callback */ if (urb != NULL) { usbd_urb_complete(dev, urb, USBD_SUCCESS); @@ -879,7 +889,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_TXFE) { /* Send more data */ - USBD_LOGF_LN(USB_VIO2, "Sending more data for endpoint 0x%"PRIx8, ep_addr); + USBD_LOGF_LN(USB_VIO2, "Sending more data for ep%"PRIx8, ep_addr); if (urb != NULL) { /* As per doc, before writing to FIFO, we need to write to CTL register. @@ -891,7 +901,7 @@ static void process_in_endpoint_interrupt(usbd_device *dev, uint8_t ep_num) } if (REBASE(DWC_OTG_DIEPxINT, ep_num) & DWC_OTG_DIEPINT_ITTXFE) { - USBD_LOGF_LN(USB_VIO2, "Data IN Token received when ep0x%"PRIx8" FIFO was empty", + USBD_LOGF_LN(USB_VIO2, "Data IN Token received when ep%"PRIx8" FIFO was empty", ep_addr); REBASE(DWC_OTG_DIEPxINT, ep_num) = DWC_OTG_DIEPINT_ITTXFE; } diff --git a/lib/usbd/usbd_ep0.c b/lib/usbd/usbd_ep0.c index 55d292d4..d44d346b 100644 --- a/lib/usbd/usbd_ep0.c +++ b/lib/usbd/usbd_ep0.c @@ -790,7 +790,7 @@ standard_request_endpoint(usbd_device *dev, struct usbd_control_arg *arg) case USB_REQ_CLEAR_FEATURE: if (arg->setup->wValue == USB_FEAT_ENDPOINT_HALT) { uint8_t ep_addr = arg->setup->wIndex; - USBD_LOGF_LN(USB_VSETUP,"USBD:CLEAR_FEATURE - halt EP%d", ep_addr); + USBD_LOGF_LN(USB_VSETUP,"USBD:CLEAR_FEATURE - halt EP%x", ep_addr); usbd_set_ep_dtog(dev, ep_addr, false); usbd_set_ep_stall(dev, ep_addr, false); return USBD_REQ_HANDLED; @@ -799,7 +799,7 @@ standard_request_endpoint(usbd_device *dev, struct usbd_control_arg *arg) case USB_REQ_SET_FEATURE: if (arg->setup->wValue == USB_FEAT_ENDPOINT_HALT) { uint8_t ep_addr = arg->setup->wIndex; - USBD_LOGF_LN(USB_VSETUP,"USBD:SET_FEATURE - halt EP%d", ep_addr); + USBD_LOGF_LN(USB_VSETUP,"USBD:SET_FEATURE - halt EP%x", ep_addr); usbd_set_ep_stall(dev, ep_addr, true); return USBD_REQ_HANDLED; }