feat(usb_cdc): 添加USB CDC ACM控制台和日志后端支持

添加zephyr,console和zephyr,log-uart设备树配置，启用UART控制台和日志功能，同时增加第二个CDC ACM UART实例用于控制台输出。在prj.conf中启用相关配置项。 refactor(protocol): 优化协议会话状态管理并增强日志记录引入proto_session_set函数统一管理协议会话状态转换，添加详细的日志输出来跟踪状态变化、消息处理和传输事件，提高系统的可调试性。 feat(usb_device): 增强USB设备模块状态跟踪和日志输出为USB栈、总线和公共状态添加命名函数，实现详细的状态转换日志记录，包括USB 连接、断开、使能等关键事件的日志输出，便于系统调试和问题排查。
2026-04-21 16:40:37 +08:00
parent 0a1357c62d
commit a11f4c0110
5 changed files with 265 additions and 6 deletions
--- 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";
+	};
 };
--- 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
--- 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;
--- 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);
 	}
--- 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;
 }