mgmt: ec_host_cmd: add logging system

Add a native way to log Host Command communication. Use Zephyr logging system to do it. Use debug and normal levels. Signed-off-by: Dawid Niedzwiecki <dawidn@google.com>
Willmish · Jun 26, 2023 · c8c149d · c8c149d
1 parent 159f56d
commit c8c149d
Show file tree

Hide file tree

Showing 4 changed files with 75 additions and 4 deletions.
diff --git a/doc/services/device_mgmt/ec_host_cmd.rst b/doc/services/device_mgmt/ec_host_cmd.rst
@@ -69,6 +69,18 @@ buffers are useful for applications that use multiple backends. Defining separat
 backend would increase the memory usage. However, some buffers can be defined by a peripheral driver
 e.g. eSPI. These ones should be reused as much as possible.
 
+Logging
+*******
+
+The host command has an embedded logging system of the ongoing communication. The are a few logging
+levels:
+
+* `LOG_INF` is used to log a command id of a new command and not success responses. Repeats of the
+  same command are not logged
+* `LOG_DBG` logs every command, even repeats
+* `LOG_DBG` + :kconfig:option:`CONFIG_EC_HOST_CMD_LOG_DBG_BUFFERS` logs every command and responses
+  with the data buffers
+
 API Reference
 *************
 

diff --git a/subsys/mgmt/ec_host_cmd/Kconfig b/subsys/mgmt/ec_host_cmd/Kconfig
@@ -87,8 +87,9 @@ config EC_HOST_CMD_DEDICATED_THREAD
 	  The ec_host_cmd_init function creates a new thread dedicated for Host Command.
 	  Otherwise the ec_host_cmd_task function has to be called within another thread.
 
-endif # EC_HOST_CMD
-
+source "subsys/mgmt/ec_host_cmd/Kconfig.logging"
 source "subsys/mgmt/ec_host_cmd/backends/Kconfig"
 
+endif # EC_HOST_CMD
+
 endmenu
diff --git a/subsys/mgmt/ec_host_cmd/Kconfig.logging b/subsys/mgmt/ec_host_cmd/Kconfig.logging
@@ -0,0 +1,12 @@
+# Host command logging configs
+
+# Copyright (c) 2023 Google LLC
+# SPDX-License-Identifier: Apache-2.0
+
+config EC_HOST_CMD_LOG_DBG_BUFFERS
+	bool "Log full params and response buffers in debug log level"
+	depends on EC_HC_LOG_LEVEL_DBG
+	help
+	  Every command is logged with the debug logging level. Use this config
+	  to decide, if full reqest and response buffers are logged alongside
+	  other command parameters.
diff --git a/subsys/mgmt/ec_host_cmd/ec_host_cmd_handler.c b/subsys/mgmt/ec_host_cmd/ec_host_cmd_handler.c
@@ -10,6 +10,7 @@
 #include <zephyr/mgmt/ec_host_cmd/ec_host_cmd.h>
 #include <zephyr/mgmt/ec_host_cmd/backend.h>
 #include <zephyr/sys/iterable_sections.h>
+#include <stdio.h>
 #include <string.h>
 
 LOG_MODULE_REGISTER(host_cmd_handler, CONFIG_EC_HC_LOG_LEVEL);
@@ -161,10 +162,20 @@ int ec_host_cmd_send_response(enum ec_host_cmd_status status,
 	struct ec_host_cmd_tx_buf *tx = &hc->tx;
 
 	if (status != EC_HOST_CMD_SUCCESS) {
+		const struct ec_host_cmd_request_header *const rx_header =
+			(const struct ec_host_cmd_request_header *const)hc->rx_ctx.buf;
+
+		LOG_INF("HC 0x%04x err %d", rx_header->cmd_id, status);
 		send_status_response(hc->backend, tx, status);
 		return status;
 	}
 
+#ifdef CONFIG_EC_HOST_CMD_LOG_DBG_BUFFERS
+	if (args->output_buf_size) {
+		LOG_HEXDUMP_DBG(args->output_buf, args->output_buf_size, "HC resp:");
+	}
+#endif
+
 	status = prepare_response(tx, args->output_buf_size);
 	if (status != EC_HOST_CMD_SUCCESS) {
 		send_status_response(hc->backend, tx, status);
@@ -174,6 +185,41 @@ int ec_host_cmd_send_response(enum ec_host_cmd_status status,
 	return hc->backend->api->send(hc->backend);
 }
 
+static void ec_host_cmd_log_request(const uint8_t *rx_buf)
+{
+	static uint16_t prev_cmd;
+	const struct ec_host_cmd_request_header *const rx_header =
+		(const struct ec_host_cmd_request_header *const)rx_buf;
+
+	if (IS_ENABLED(CONFIG_EC_HOST_CMD_LOG_DBG_BUFFERS)) {
+		if (rx_header->data_len) {
+			const uint8_t *rx_data = rx_buf + RX_HEADER_SIZE;
+			static const char dbg_fmt[] = "HC 0x%04x.%d:";
+			/* Use sizeof because "%04x" needs 4 bytes for command id, and
+			 * %d needs 2 bytes for version, so no additional buffer is required.
+			 */
+			char dbg_raw[sizeof(dbg_fmt)];
+
+			snprintf(dbg_raw, sizeof(dbg_raw), dbg_fmt, rx_header->cmd_id,
+				 rx_header->cmd_ver);
+			LOG_HEXDUMP_DBG(rx_data, rx_header->data_len, dbg_raw);
+
+			return;
+		}
+	}
+
+	/* In normal output mode, skip printing repeats of the same command
+	 * that occur in rapid succession - such as flash commands during
+	 * software sync.
+	 */
+	if (rx_header->cmd_id != prev_cmd) {
+		prev_cmd = rx_header->cmd_id;
+		LOG_INF("HC 0x%04x", rx_header->cmd_id);
+	} else {
+		LOG_DBG("HC 0x%04x", rx_header->cmd_id);
+	}
+}
+
 FUNC_NORETURN static void ec_host_cmd_thread(void *hc_handle, void *arg2, void *arg3)
 {
 	ARG_UNUSED(arg2);
@@ -196,15 +242,15 @@ FUNC_NORETURN static void ec_host_cmd_thread(void *hc_handle, void *arg2, void *
 		/* Wait until RX messages is received on host interface */
 		k_sem_take(&rx->handler_owns, K_FOREVER);
 
+		ec_host_cmd_log_request(rx->buf);
 		status = verify_rx(rx);
 		if (status != EC_HOST_CMD_SUCCESS) {
 			ec_host_cmd_send_response(status, &args);
 			continue;
 		}
 
 		found_handler = NULL;
-		STRUCT_SECTION_FOREACH(ec_host_cmd_handler, handler)
-		{
+		STRUCT_SECTION_FOREACH(ec_host_cmd_handler, handler) {
 			if (handler->id == rx_header->cmd_id) {
 				found_handler = handler;
 				break;