diff --git a/boards/atguigu/mini_keyboard/mini_keyboard.dts b/boards/atguigu/mini_keyboard/mini_keyboard.dts index c117f26..df23b1a 100644 --- a/boards/atguigu/mini_keyboard/mini_keyboard.dts +++ b/boards/atguigu/mini_keyboard/mini_keyboard.dts @@ -16,6 +16,8 @@ zephyr,code-partition = &slot0_partition; zephyr,display = &screen_lcd; zephyr,led-strip = &led_strip; + zephyr,console = &cdc_acm_uart1; + zephyr,log-uart = &log_uarts; }; aliases { @@ -25,6 +27,11 @@ backlight = &backlight; }; + log_uarts: log_uarts { + compatible = "zephyr,log-uart"; + uarts = <&cdc_acm_uart1>; + }; + hid_kbd: hid_kbd { compatible = "zephyr,hid-device"; label = "HID_KBD"; @@ -260,4 +267,9 @@ compatible = "zephyr,cdc-acm-uart"; label = "CDC_ACM_0"; }; + + cdc_acm_uart1: cdc_acm_uart1 { + compatible = "zephyr,cdc-acm-uart"; + label = "CDC_ACM_1"; + }; }; diff --git a/prj.conf b/prj.conf index e0ba398..0442222 100644 --- a/prj.conf +++ b/prj.conf @@ -27,12 +27,18 @@ CONFIG_NVS=y CONFIG_HEAP_MEM_POOL_SIZE=4096 CONFIG_LOG=y CONFIG_LOG_BUFFER_SIZE=16384 +CONFIG_LOG_BACKEND_UART=y +CONFIG_LOG_BACKEND_SHOW_COLOR=n CONFIG_LOG_BACKEND_RTT_OUTPUT_BUFFER_SIZE=16384 CONFIG_ASSERT=y CONFIG_SEGGER_RTT_BUFFER_SIZE_UP=16384 CONFIG_APP_EVENT_MANAGER_MAX_EVENT_CNT=64 CONFIG_LED_STRIP=y CONFIG_WS2812_STRIP_SPI=y +CONFIG_CONSOLE=y +CONFIG_UART_CONSOLE=y +CONFIG_STDOUT_CONSOLE=y +CONFIG_PRINTK=y # USB HID next stack CONFIG_USB_DEVICE_STACK_NEXT=y @@ -132,4 +138,4 @@ CONFIG_LV_FONT_MONTSERRAT_32=y CONFIG_MAIN_STACK_SIZE=4096 CONFIG_USE_SEGGER_RTT=y -CONFIG_SPEED_OPTIMIZATIONS=y \ No newline at end of file +CONFIG_SPEED_OPTIMIZATIONS=y diff --git a/src/protocol_module.c b/src/protocol_module.c index 571b74b..9b1c33e 100644 --- a/src/protocol_module.c +++ b/src/protocol_module.c @@ -100,6 +100,30 @@ static const char *proto_transport_name(enum proto_transport transport) } } +static void proto_session_set(enum proto_transport transport, + enum proto_session_state new_state, + const char *reason) +{ + enum proto_session_state old_state; + + if (transport >= PROTO_TRANSPORT_COUNT) { + return; + } + + old_state = session_state[transport]; + if (old_state == new_state) { + LOG_INF("Protocol session keep transport:%s state:%s reason:%s", + proto_transport_name(transport), + proto_session_name(new_state), reason); + return; + } + + session_state[transport] = new_state; + LOG_INF("Protocol session transport:%s %s -> %s reason:%s", + proto_transport_name(transport), proto_session_name(old_state), + proto_session_name(new_state), reason); +} + static int decode_body(const uint8_t *payload, size_t payload_len, CdcPacketBody *body) { @@ -214,6 +238,8 @@ static int do_init(void) session_state[i] = PROTO_SESSION_DOWN; } + LOG_INF("Protocol init done"); + return 0; } @@ -233,7 +259,8 @@ static int do_stop(void) } for (size_t i = 0; i < ARRAY_SIZE(session_state); i++) { - session_state[i] = PROTO_SESSION_DOWN; + proto_session_set((enum proto_transport)i, PROTO_SESSION_DOWN, + "module_stop"); } return 0; @@ -284,7 +311,7 @@ int protocol_module_process_message(enum proto_transport transport, body.body.hello_req.protocol_version); } - session_state[transport] = PROTO_SESSION_ACTIVE; + proto_session_set(transport, PROTO_SESSION_ACTIVE, "hello_req"); return encode_hello_rsp(rsp_payload, rsp_payload_buf_size, rsp_payload_len); case CdcPacketBody_bitmap_tag: @@ -396,6 +423,9 @@ static bool handle_proto_rx_event(const struct proto_rx_event *event) return false; } + LOG_INF("Protocol response ready transport:%s rsp_len:%u session:%s", + proto_transport_name(event->transport), (unsigned int)rsp_payload_len, + proto_session_name(session_state[event->transport])); err = submit_proto_tx_event(event->transport, rsp_payload, rsp_payload_len); if (err) { LOG_WRN("Proto TX submit failed (%d)", err); @@ -413,11 +443,13 @@ static bool handle_proto_transport_state_event( switch (event->state) { case PROTO_TRANSPORT_LINK_DOWN: - session_state[event->transport] = PROTO_SESSION_DOWN; + proto_session_set(event->transport, PROTO_SESSION_DOWN, + "transport_link_down"); break; case PROTO_TRANSPORT_LINK_READY: - session_state[event->transport] = PROTO_SESSION_WAIT_HELLO; + proto_session_set(event->transport, PROTO_SESSION_WAIT_HELLO, + "transport_link_ready"); break; default: @@ -441,6 +473,9 @@ static bool handle_function_bitmap_state_event( for (enum proto_transport transport = 0; transport < PROTO_TRANSPORT_COUNT; transport++) { if (session_state[transport] != PROTO_SESSION_ACTIVE) { + LOG_INF("FunctionKeyEvent skip transport:%s session:%s", + proto_transport_name(transport), + proto_session_name(session_state[transport])); continue; } @@ -454,6 +489,10 @@ static bool handle_function_bitmap_state_event( err = submit_proto_tx_event(transport, payload, payload_len); if (err) { LOG_WRN("FunctionKeyEvent submit failed (%d)", err); + } else { + LOG_INF("FunctionKeyEvent submit transport:%s len:%u", + proto_transport_name(transport), + (unsigned int)payload_len); } } @@ -476,6 +515,9 @@ static bool handle_hid_led_event(const struct hid_led_event *event) PROTO_TRANSPORT_BLE_NUS; if (session_state[transport] != PROTO_SESSION_ACTIVE) { + LOG_INF("LedState skip transport:%s session:%s led_mask:0x%02x", + proto_transport_name(transport), + proto_session_name(session_state[transport]), event->led_bm); return false; } @@ -488,6 +530,10 @@ static bool handle_hid_led_event(const struct hid_led_event *event) err = submit_proto_tx_event(transport, payload, payload_len); if (err) { LOG_WRN("LedState submit failed (%d)", err); + } else { + LOG_INF("LedState submit transport:%s len:%u led_mask:0x%02x", + proto_transport_name(transport), (unsigned int)payload_len, + event->led_bm); } return false; diff --git a/src/usb_cdc_module.c b/src/usb_cdc_module.c index aa54c3b..018bc5c 100644 --- a/src/usb_cdc_module.c +++ b/src/usb_cdc_module.c @@ -74,7 +74,7 @@ static struct usb_cdc_ctx ctx = { .ops = &lifecycle_ops, }, .business = USB_CDC_BUS_OFFLINE, - .cdc_dev = DEVICE_DT_GET_ONE(zephyr_cdc_acm_uart), + .cdc_dev = DEVICE_DT_GET(DT_NODELABEL(cdc_acm_uart0)), .usb_active = false, .proto_rx_len = 0U, }; @@ -83,6 +83,32 @@ static struct usb_cdc_ctx ctx = { static void validate_line_coding(void); +static const char *usb_cdc_business_state_name(enum usb_cdc_business_state state) +{ + switch (state) { + case USB_CDC_BUS_OFFLINE: + return "BUS_OFFLINE"; + case USB_CDC_WAIT_DTR: + return "WAIT_DTR"; + case USB_CDC_SESSION_READY: + return "SESSION_READY"; + default: + return "?"; + } +} + +static const char *proto_link_state_name(enum proto_transport_link_state state) +{ + switch (state) { + case PROTO_TRANSPORT_LINK_DOWN: + return "DOWN"; + case PROTO_TRANSPORT_LINK_READY: + return "READY"; + default: + return "?"; + } +} + static bool lifecycle_is_ready(void) { return module_lifecycle_is_running(&ctx.lc); @@ -128,6 +154,7 @@ static void state_reconcile(enum module_lifecycle old_lifecycle, if ((old_lifecycle == LC_RUNNING) && (old_business == USB_CDC_SESSION_READY) && (new_link == PROTO_TRANSPORT_LINK_DOWN)) { + LOG_INF("CDC reconcile: link READY -> DOWN, disable UART IO"); disable_uart_io(); } @@ -135,6 +162,9 @@ static void state_reconcile(enum module_lifecycle old_lifecycle, (new_link == PROTO_TRANSPORT_LINK_READY)) { int err; + LOG_INF("CDC reconcile: link DOWN -> READY (business:%s usb_active:%u lc:%s)", + usb_cdc_business_state_name(ctx.business), ctx.usb_active, + module_lifecycle_name(ctx.lc.state)); validate_line_coding(); err = uart_line_ctrl_set(ctx.cdc_dev, UART_LINE_CTRL_DCD, 1); @@ -151,6 +181,11 @@ static void state_reconcile(enum module_lifecycle old_lifecycle, } if (old_link != new_link) { + LOG_INF("CDC link %s -> %s (business:%s usb_active:%u lc:%s)", + proto_link_state_name(old_link), + proto_link_state_name(new_link), + usb_cdc_business_state_name(ctx.business), ctx.usb_active, + module_lifecycle_name(ctx.lc.state)); submit_proto_transport_state_event(PROTO_TRANSPORT_USB_CDC, new_link); } @@ -166,11 +201,19 @@ static void business_state_set(enum usb_cdc_business_state new_state) } ctx.business = new_state; + LOG_INF("CDC business %s -> %s (usb_active:%u lc:%s)", + usb_cdc_business_state_name(old_business), + usb_cdc_business_state_name(ctx.business), ctx.usb_active, + module_lifecycle_name(ctx.lc.state)); state_reconcile(old_lifecycle, old_business); } static void business_state_sync_from_usb(void) { + LOG_INF("CDC sync from USB (usb_active:%u business:%s lc:%s)", + ctx.usb_active, usb_cdc_business_state_name(ctx.business), + module_lifecycle_name(ctx.lc.state)); + if (!ctx.usb_active) { business_state_set(USB_CDC_BUS_OFFLINE); return; @@ -188,9 +231,14 @@ static void business_state_sync_from_usb(void) static void kick_tx(void) { if (transport_link_state_get() != PROTO_TRANSPORT_LINK_READY) { + LOG_INF("CDC kick_tx skipped: link=%s business:%s usb_active:%u tx_rb:%u", + proto_link_state_name(transport_link_state_get()), + usb_cdc_business_state_name(ctx.business), ctx.usb_active, + ring_buf_size_get(&ctx.tx_ringbuf)); return; } + LOG_INF("CDC kick_tx: enable TX IRQ (tx_rb:%u)", ring_buf_size_get(&ctx.tx_ringbuf)); uart_irq_tx_enable(ctx.cdc_dev); } @@ -249,6 +297,9 @@ static void rx_work_handler(struct k_work *work) return; } + LOG_INF("CDC rx_work pulled %u bytes from RX ring (proto_rx_len:%u)", + (unsigned int)len, (unsigned int)ctx.proto_rx_len); + if ((ctx.proto_rx_len + len) > sizeof(proto_rx_buf)) { LOG_WRN("Drop oversized CDC protobuf message len:%u", (uint32_t)(ctx.proto_rx_len + len)); @@ -269,9 +320,14 @@ static void rx_flush_work_handler(struct k_work *work) if ((transport_link_state_get() != PROTO_TRANSPORT_LINK_READY) || (ctx.proto_rx_len == 0U)) { + LOG_INF("CDC rx_flush skipped: link=%s proto_rx_len:%u business:%s", + proto_link_state_name(transport_link_state_get()), + (unsigned int)ctx.proto_rx_len, + usb_cdc_business_state_name(ctx.business)); return; } + LOG_INF("CDC rx_flush submit proto_rx len:%u", (unsigned int)ctx.proto_rx_len); (void)submit_proto_rx_event(PROTO_TRANSPORT_USB_CDC, proto_rx_buf, ctx.proto_rx_len); ctx.proto_rx_len = 0U; @@ -304,6 +360,10 @@ static void cdc_interrupt_handler(const struct device *dev, void *user_data) recv_len - (int)written); } + LOG_INF("CDC IRQ RX recv:%d written:%u rx_rb:%u", + recv_len, (unsigned int)written, + ring_buf_size_get(&ctx.rx_ringbuf)); + k_work_submit(&ctx.rx_work); } } @@ -318,6 +378,7 @@ static void cdc_interrupt_handler(const struct device *dev, void *user_data) irq_unlock(key); if (len == 0U) { + LOG_INF("CDC IRQ TX ready but no pending data, disable TX IRQ"); uart_irq_tx_disable(dev); continue; } @@ -330,6 +391,10 @@ static void cdc_interrupt_handler(const struct device *dev, void *user_data) LOG_WRN("Drop %u CDC TX bytes", (unsigned int)(len - (uint32_t)sent_len)); } + + LOG_INF("CDC IRQ TX requested:%u sent:%d tx_rb_remain:%u", + (unsigned int)len, sent_len, + ring_buf_size_get(&ctx.tx_ringbuf)); } } } @@ -348,6 +413,9 @@ static int do_init(void) ctx.business = USB_CDC_BUS_OFFLINE; ctx.usb_active = false; ctx.proto_rx_len = 0U; + LOG_INF("CDC init done (business:%s usb_active:%u lc:%s dev:%p)", + usb_cdc_business_state_name(ctx.business), ctx.usb_active, + module_lifecycle_name(ctx.lc.state), ctx.cdc_dev); return 0; } @@ -359,6 +427,9 @@ static int do_start(void) static int do_stop(void) { + LOG_INF("CDC stop requested (business:%s usb_active:%u lc:%s)", + usb_cdc_business_state_name(ctx.business), ctx.usb_active, + module_lifecycle_name(ctx.lc.state)); ctx.business = USB_CDC_BUS_OFFLINE; return 0; } @@ -379,6 +450,11 @@ static int apply_lifecycle(enum module_lifecycle target) business_state_sync_from_usb(); } + LOG_INF("CDC lifecycle %s -> %s done (business:%s usb_active:%u link:%s)", + module_lifecycle_name(old_lifecycle), module_lifecycle_name(target), + usb_cdc_business_state_name(ctx.business), ctx.usb_active, + proto_link_state_name(transport_link_state_get())); + return 0; } @@ -391,6 +467,10 @@ static bool handle_usb_state_event(const struct usb_state_event *event) } ctx.usb_active = new_usb_active; + LOG_INF("CDC usb_active -> %u from usb_state:%d (business:%s lc:%s)", + ctx.usb_active, event->state, + usb_cdc_business_state_name(ctx.business), + module_lifecycle_name(ctx.lc.state)); business_state_sync_from_usb(); return false; @@ -404,7 +484,13 @@ static bool handle_usb_control_event(const struct usb_control_event *event) switch (event->type) { case USB_CONTROL_EVENT_CDC_LINE_STATE: + LOG_INF("CDC control event line_state dtr:%u usb_active:%u lc:%s business:%s", + event->data.cdc_line_state.dtr, ctx.usb_active, + module_lifecycle_name(ctx.lc.state), + usb_cdc_business_state_name(ctx.business)); if (!ctx.usb_active || !lifecycle_is_ready()) { + LOG_INF("CDC line_state ignored: usb_active:%u lc:%s", + ctx.usb_active, module_lifecycle_name(ctx.lc.state)); return false; } @@ -419,6 +505,13 @@ static bool handle_usb_control_event(const struct usb_control_event *event) return false; case USB_CONTROL_EVENT_CDC_LINE_CODING: + LOG_INF("CDC control event line_coding baud:%u data:%u stop:%u parity:%u flow:%u business:%s", + event->data.cdc_line_coding.baudrate, + event->data.cdc_line_coding.data_bits, + event->data.cdc_line_coding.stop_bits, + event->data.cdc_line_coding.parity, + event->data.cdc_line_coding.flow_ctrl, + usb_cdc_business_state_name(ctx.business)); if (event->data.cdc_line_coding.baudrate != 0U) { LOG_INF("CDC baudrate %u", event->data.cdc_line_coding.baudrate); @@ -459,6 +552,10 @@ static bool handle_proto_tx_event(const struct proto_tx_event *event) } if (transport_link_state_get() != PROTO_TRANSPORT_LINK_READY) { + LOG_INF("CDC proto_tx ignored len:%u link:%s business:%s usb_active:%u", + (unsigned int)event->dyndata.size, + proto_link_state_name(transport_link_state_get()), + usb_cdc_business_state_name(ctx.business), ctx.usb_active); return false; } @@ -467,6 +564,10 @@ static bool handle_proto_tx_event(const struct proto_tx_event *event) (uint32_t)event->dyndata.size); irq_unlock(key); + LOG_INF("CDC proto_tx queued len:%u written:%u tx_rb:%u", + (unsigned int)event->dyndata.size, (unsigned int)written, + ring_buf_size_get(&ctx.tx_ringbuf)); + if (written < event->dyndata.size) { LOG_WRN("Drop %zu CDC TX bytes", event->dyndata.size - written); } diff --git a/src/usb_device_module.c b/src/usb_device_module.c index 2066b57..8b75bf8 100644 --- a/src/usb_device_module.c +++ b/src/usb_device_module.c @@ -88,6 +88,54 @@ static struct usb_owner_ctx usb_ctx = { .bus = USB_BUS_DISCONNECTED, }; +static const char *usb_stack_state_name(enum usb_stack_state state) +{ + switch (state) { + case USB_STACK_UNINITIALIZED: + return "UNINITIALIZED"; + case USB_STACK_READY: + return "READY"; + case USB_STACK_ENABLED: + return "ENABLED"; + default: + return "?"; + } +} + +static const char *usb_bus_state_name(enum usb_bus_state state) +{ + switch (state) { + case USB_BUS_DISCONNECTED: + return "DISCONNECTED"; + case USB_BUS_POWERED: + return "POWERED"; + case USB_BUS_ACTIVE: + return "ACTIVE"; + case USB_BUS_SUSPENDED: + return "SUSPENDED"; + default: + return "?"; + } +} + +static const char *usb_public_state_name(enum usb_state state) +{ + switch (state) { + case USB_STATE_DISABLED: + return "DISABLED"; + case USB_STATE_DISCONNECTED: + return "DISCONNECTED"; + case USB_STATE_POWERED: + return "POWERED"; + case USB_STATE_ACTIVE: + return "ACTIVE"; + case USB_STATE_SUSPENDED: + return "SUSPENDED"; + default: + return "?"; + } +} + static inline enum usb_state usb_public_state_get(void) { if (!module_lifecycle_is_running(&usb_ctx.lc) || @@ -111,12 +159,21 @@ static inline enum usb_state usb_public_state_get(void) static inline void usb_bus_set(enum usb_bus_state state) { + enum usb_bus_state old_state = usb_ctx.bus; + if (usb_ctx.bus == state) { return; } usb_ctx.bus = state; + LOG_INF("USB bus %s -> %s (stack:%s lc:%s public:%s)", + usb_bus_state_name(old_state), + usb_bus_state_name(usb_ctx.bus), + usb_stack_state_name(usb_ctx.stack), + module_lifecycle_name(usb_ctx.lc.state), + usb_public_state_name(usb_public_state_get())); + if (module_lifecycle_is_initialized(&usb_ctx.lc)) { submit_usb_state(usb_public_state_get()); } @@ -168,6 +225,12 @@ static void usbd_msg_cb(struct usbd_context *const usbd_ctx, { ARG_UNUSED(usbd_ctx); + LOG_INF("USBD msg:%s status:%u dev:%p stack:%s bus:%s lc:%s", + usbd_msg_type_string(msg->type), msg->status, msg->dev, + usb_stack_state_name(usb_ctx.stack), + usb_bus_state_name(usb_ctx.bus), + module_lifecycle_name(usb_ctx.lc.state)); + if (msg->type == USBD_MSG_CDC_ACM_CONTROL_LINE_STATE) { uint32_t dtr = 0U; int err = uart_line_ctrl_get(msg->dev, UART_LINE_CTRL_DTR, &dtr); @@ -175,6 +238,7 @@ static void usbd_msg_cb(struct usbd_context *const usbd_ctx, if (err) { LOG_WRN("Failed to get CDC DTR (%d)", err); } else { + LOG_INF("CDC control line state DTR:%u dev:%p", dtr, msg->dev); submit_usb_control_cdc_line_state_event(msg->dev, dtr != 0U); } @@ -210,6 +274,8 @@ static void usbd_msg_cb(struct usbd_context *const usbd_ctx, } #endif + LOG_INF("CDC line coding baud:%u data:%u stop:%u parity:%u flow:%u dev:%p", + baudrate, data_bits, stop_bits, parity, flow_ctrl, msg->dev); submit_usb_control_cdc_line_coding_event(msg->dev, baudrate, data_bits, stop_bits, parity, flow_ctrl); @@ -280,6 +346,10 @@ static int do_init(void) usb_ctx.stack = USB_STACK_UNINITIALIZED; usb_ctx.bus = USB_BUS_DISCONNECTED; + LOG_INF("USB init start (stack:%s bus:%s lc:%s)", + usb_stack_state_name(usb_ctx.stack), + usb_bus_state_name(usb_ctx.bus), + module_lifecycle_name(usb_ctx.lc.state)); update_power_manager_restriction(false); STRUCT_SECTION_FOREACH(usb_function_hook, hook) { @@ -313,6 +383,11 @@ static int do_init(void) } usb_ctx.stack = USB_STACK_READY; + LOG_INF("USB init done (stack:%s bus:%s lc:%s public:%s)", + usb_stack_state_name(usb_ctx.stack), + usb_bus_state_name(usb_ctx.bus), + module_lifecycle_name(usb_ctx.lc.state), + usb_public_state_name(usb_public_state_get())); return 0; } @@ -321,7 +396,13 @@ static int do_start(void) { int err; + LOG_INF("USB start requested (stack:%s bus:%s lc:%s)", + usb_stack_state_name(usb_ctx.stack), + usb_bus_state_name(usb_ctx.bus), + module_lifecycle_name(usb_ctx.lc.state)); + if (usb_ctx.stack == USB_STACK_ENABLED) { + LOG_INF("USB start ignored: already enabled"); return 0; } @@ -334,11 +415,15 @@ static int do_start(void) usb_ctx.stack = USB_STACK_ENABLED; usb_ctx.bus = USB_BUS_POWERED; + LOG_INF("USB enabled without VBUS detect (stack:%s bus:%s)", + usb_stack_state_name(usb_ctx.stack), + usb_bus_state_name(usb_ctx.bus)); update_power_manager_restriction(true); return 0; } if (usb_ctx.bus == USB_BUS_DISCONNECTED) { + LOG_INF("USB start deferred: waiting for VBUS"); return 0; } @@ -349,6 +434,8 @@ static int do_start(void) } usb_ctx.stack = USB_STACK_ENABLED; + LOG_INF("USB enabled (stack:%s bus:%s)", usb_stack_state_name(usb_ctx.stack), + usb_bus_state_name(usb_ctx.bus)); update_power_manager_restriction(true); return 0; } @@ -357,6 +444,11 @@ static int do_stop(void) { int err; + LOG_INF("USB stop requested (stack:%s bus:%s lc:%s)", + usb_stack_state_name(usb_ctx.stack), + usb_bus_state_name(usb_ctx.bus), + module_lifecycle_name(usb_ctx.lc.state)); + if (usb_ctx.stack == USB_STACK_ENABLED) { err = usbd_disable(&blinky_usbd); if (err) { @@ -366,6 +458,8 @@ static int do_stop(void) } usb_ctx.stack = USB_STACK_READY; + LOG_INF("USB stopped (stack:%s bus:%s)", usb_stack_state_name(usb_ctx.stack), + usb_bus_state_name(usb_ctx.bus)); update_power_manager_restriction(false); return 0; }