scmi: Add extended logs

This commit expands the detail of the log output of the SCMI module in
order to aid in debugging. Details that were previously missing,
including the message token and the service name, are now included.

Change-Id: I00075b3e4474328f27dc7f6be5b0df21c18c0cfb
Signed-off-by: Chris Kay <chris.kay@arm.com>

7 files changed, 88 insertions, 29 deletions

diff --git a/module/scmi/include/internal/mod_scmi.h b/module/scmi/include/internal/mod_scmi.h
index 48ec9a65..b707a302 100644
--- a/module/scmi/include/internal/mod_scmi.h
+++ b/module/scmi/include/internal/mod_scmi.h
@@ -53,6 +53,9 @@ struct scmi_service_ctx {
     /* Copy of the pointer to the 'respond' function within the transport API */
     int (*respond)(fwk_id_t transport_id, const void *payload, size_t size);
 
+    /* SCMI message token, used by the agent to identify individual messages */
+    uint16_t scmi_token;
+
     /* SCMI identifier of the protocol processing the current message */
     unsigned int scmi_protocol_id;
 
diff --git a/module/scmi/src/mod_scmi.c b/module/scmi/src/mod_scmi.c
index 0639e28b..6b820db2 100644
--- a/module/scmi/src/mod_scmi.c
+++ b/module/scmi/src/mod_scmi.c
@@ -143,6 +143,12 @@ static uint8_t read_protocol_id(uint32_t message_header)
         SCMI_MESSAGE_HEADER_PROTOCOL_ID_POS;
 }
 
+static uint16_t read_token(uint32_t message_header)
+{
+    return (message_header & SCMI_MESSAGE_HEADER_TOKEN_MASK) >>
+        SCMI_MESSAGE_HEADER_TOKEN_POS;
+}
+
 /*
  * Transport entity -> SCMI module
  */
@@ -220,9 +226,12 @@ static void respond(fwk_id_t service_id, const void *payload, size_t size)
 {
     int status;
     const struct scmi_service_ctx *ctx;
+    const char *service_name;
 
     ctx = &scmi_ctx.service_ctx_table[fwk_id_get_element_idx(service_id)];
 
+    service_name = fwk_module_get_name(service_id);
+
     /*
      * Print to the error log if the message was not successfully processed.
      * We assume here that the first payload entry of the command response
@@ -231,16 +240,35 @@ static void respond(fwk_id_t service_id, const void *payload, size_t size)
      * specification it should be like that for all commands.
      */
     if ((payload != NULL) && (*((int32_t *)payload) < SCMI_SUCCESS)) {
-       scmi_ctx.log_api->log(MOD_LOG_GROUP_ERROR,
-           "[SCMI] Protocol 0x%x, message_id 0x%x returned with error %d\n",
-           ctx->scmi_protocol_id, ctx->scmi_message_id, *((int *)payload));
+        scmi_ctx.log_api->log(
+            MOD_LOG_GROUP_ERROR,
+            "[SCMI] %s: Message %u (0x%x:0x%x) returned with an error (%d)\n",
+            service_name,
+            ctx->scmi_token,
+            ctx->scmi_protocol_id,
+            ctx->scmi_message_id,
+            *((int *)payload));
+    } else {
+        scmi_ctx.log_api->log(
+            MOD_LOG_GROUP_DEBUG,
+            "[SCMI] %s: Message %u (0x%x:0x%x) returned successfully\n",
+            service_name,
+            ctx->scmi_token,
+            ctx->scmi_protocol_id,
+            ctx->scmi_message_id);
     }
 
     status = ctx->respond(ctx->transport_id, payload, size);
-    if (status != FWK_SUCCESS)
-        scmi_ctx.log_api->log(MOD_LOG_GROUP_ERROR,
-            "[SCMI] Failed to send response %s (%d)\n",
-            fwk_status_str(status), status);
+    if (status != FWK_SUCCESS) {
+        scmi_ctx.log_api->log(
+            MOD_LOG_GROUP_ERROR,
+            "[SCMI] %s: Message %u (0x%x:0x%x) failed to respond (%s)\n",
+            service_name,
+            ctx->scmi_token,
+            ctx->scmi_protocol_id,
+            ctx->scmi_message_id,
+            fwk_status_str(status));
+    }
 }
 
 static const struct mod_scmi_from_protocol_api mod_scmi_from_protocol_api = {
@@ -723,33 +751,55 @@ static int scmi_process_event(const struct fwk_event *event,
     size_t payload_size;
     unsigned int protocol_idx;
     struct scmi_protocol *protocol;
+    const char *service_name;
 
     ctx = &scmi_ctx.service_ctx_table[fwk_id_get_element_idx(event->target_id)];
     transport_api = ctx->transport_api;
     transport_id = ctx->transport_id;
 
+    service_name = fwk_module_get_name(event->target_id);
+
     status = transport_api->get_message_header(transport_id, &message_header);
     if (status != FWK_SUCCESS) {
-        scmi_ctx.log_api->log(MOD_LOG_GROUP_ERROR,
-            "[SCMI] Unable to read message header\n");
+        scmi_ctx.log_api->log(
+            MOD_LOG_GROUP_ERROR,
+            "[SCMI] %s: Unable to read message header\n",
+            service_name);
         return status;
     }
 
     status = transport_api->get_payload(transport_id, &payload, &payload_size);
     if (status != FWK_SUCCESS) {
-        scmi_ctx.log_api->log(MOD_LOG_GROUP_ERROR,
-            "[SCMI] Unable to read message payload\n");
+        scmi_ctx.log_api->log(
+            MOD_LOG_GROUP_ERROR,
+            "[SCMI] %s: Unable to read message payload\n",
+            service_name);
         return status;
     }
 
     ctx->scmi_protocol_id = read_protocol_id(message_header);
     ctx->scmi_message_id = read_message_id(message_header);
+    ctx->scmi_token = read_token(message_header);
+
+    scmi_ctx.log_api->log(
+        MOD_LOG_GROUP_DEBUG,
+        "[SCMI] %s: Message %u (0x%x:0x%x) was received\n",
+        service_name,
+        ctx->scmi_token,
+        ctx->scmi_protocol_id,
+        ctx->scmi_message_id);
 
     protocol_idx = scmi_ctx.scmi_protocol_id_to_idx[ctx->scmi_protocol_id];
 
     if (protocol_idx == 0) {
-        scmi_ctx.log_api->log(MOD_LOG_GROUP_ERROR,
-            "[SCMI] Protocol 0x%x not supported\n", ctx->scmi_protocol_id);
+        scmi_ctx.log_api->log(
+            MOD_LOG_GROUP_ERROR,
+            "[SCMI] %s: Message %u (0x%x:0x%x) requested an unsupported "
+            "protocol\n",
+            service_name,
+            ctx->scmi_token,
+            ctx->scmi_protocol_id,
+            ctx->scmi_message_id);
         ctx->respond(transport_id, &(int32_t) { SCMI_NOT_SUPPORTED },
                      sizeof(int32_t));
         return FWK_SUCCESS;
@@ -760,10 +810,16 @@ static int scmi_process_event(const struct fwk_event *event,
         payload, payload_size, ctx->scmi_message_id);
 
     if (status != FWK_SUCCESS) {
-        scmi_ctx.log_api->log(MOD_LOG_GROUP_ERROR,
-            "[SCMI] Protocol 0x%x handler error %s (%d), message_id = 0x%x\n",
-            ctx->scmi_protocol_id, fwk_status_str(status), status,
-            ctx->scmi_message_id);
+        scmi_ctx.log_api->log(
+            MOD_LOG_GROUP_ERROR,
+            "[SCMI] %s: Message %u (0x%x:0x%x) encountered an error (%s)\n",
+            service_name,
+            ctx->scmi_token,
+            ctx->scmi_protocol_id,
+            ctx->scmi_message_id,
+            fwk_status_str(status));
+
+        return FWK_SUCCESS;
     }
 
     return FWK_SUCCESS;
diff --git a/product/juno/scp_ramfw/config_scmi.c b/product/juno/scp_ramfw/config_scmi.c
index 4d69e274..67d841f9 100644
--- a/product/juno/scp_ramfw/config_scmi.c
+++ b/product/juno/scp_ramfw/config_scmi.c
@@ -33,7 +33,7 @@ static const struct fwk_element element_table[] = {
     },
 
     [JUNO_SCMI_SERVICE_IDX_OSPM_0] = {
-        .name = "OSPM 0",
+        .name = "OSPM-0",
         .data = &(struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(
                 FWK_MODULE_IDX_SMT,
@@ -49,7 +49,7 @@ static const struct fwk_element element_table[] = {
     },
 
     [JUNO_SCMI_SERVICE_IDX_OSPM_1] = {
-        .name = "OSPM 1",
+        .name = "OSPM-1",
         .data = &(struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(
                 FWK_MODULE_IDX_SMT,
diff --git a/product/rdn1e1/scp_ramfw/config_scmi.c b/product/rdn1e1/scp_ramfw/config_scmi.c
index 07f0b506..45347025 100644
--- a/product/rdn1e1/scp_ramfw/config_scmi.c
+++ b/product/rdn1e1/scp_ramfw/config_scmi.c
@@ -17,7 +17,7 @@
 
 static const struct fwk_element service_table[] = {
     [SCP_RDN1E1_SCMI_SERVICE_IDX_PSCI] = {
-        .name = "SERVICE0",
+        .name = "PSCI",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(
                 FWK_MODULE_IDX_SMT,
@@ -32,7 +32,7 @@ static const struct fwk_element service_table[] = {
         }),
     },
     [SCP_RDN1E1_SCMI_SERVICE_IDX_OSPM] = {
-        .name = "SERVICE1",
+        .name = "OSPM",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(
                 FWK_MODULE_IDX_SMT,
diff --git a/product/sgi575/scp_ramfw/config_scmi.c b/product/sgi575/scp_ramfw/config_scmi.c
index ca669216..223296ae 100644
--- a/product/sgi575/scp_ramfw/config_scmi.c
+++ b/product/sgi575/scp_ramfw/config_scmi.c
@@ -17,7 +17,7 @@
 
 static const struct fwk_element service_table[] = {
     [SCP_SGI575_SCMI_SERVICE_IDX_PSCI] = {
-        .name = "SERVICE0",
+        .name = "PSCI",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(
                 FWK_MODULE_IDX_SMT,
@@ -32,7 +32,7 @@ static const struct fwk_element service_table[] = {
         }),
     },
     [SCP_SGI575_SCMI_SERVICE_IDX_OSPM] = {
-        .name = "SERVICE1",
+        .name = "OSPM",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(
                 FWK_MODULE_IDX_SMT,
diff --git a/product/sgm775/scp_ramfw/config_scmi.c b/product/sgm775/scp_ramfw/config_scmi.c
index b81fc04b..45379688 100644
--- a/product/sgm775/scp_ramfw/config_scmi.c
+++ b/product/sgm775/scp_ramfw/config_scmi.c
@@ -17,7 +17,7 @@
 
 static const struct fwk_element service_table[] = {
     [SGM775_SCMI_SERVICE_IDX_PSCI] = {
-        .name = "SERVICE0",
+        .name = "PSCI",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(FWK_MODULE_IDX_SMT,
                                                 SGM775_SCMI_SERVICE_IDX_PSCI),
@@ -30,7 +30,7 @@ static const struct fwk_element service_table[] = {
         }),
     },
     [SGM775_SCMI_SERVICE_IDX_OSPM_0] = {
-        .name = "SERVICE1",
+        .name = "OSPM-0",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(FWK_MODULE_IDX_SMT,
                                                 SGM775_SCMI_SERVICE_IDX_OSPM_0),
@@ -43,7 +43,7 @@ static const struct fwk_element service_table[] = {
         }),
     },
     [SGM775_SCMI_SERVICE_IDX_OSPM_1] = {
-        .name = "SERVICE2",
+        .name = "OSPM-1",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(FWK_MODULE_IDX_SMT,
                                                 SGM775_SCMI_SERVICE_IDX_OSPM_1),
diff --git a/product/sgm776/scp_ramfw/config_scmi.c b/product/sgm776/scp_ramfw/config_scmi.c
index fc128fca..e4841117 100644
--- a/product/sgm776/scp_ramfw/config_scmi.c
+++ b/product/sgm776/scp_ramfw/config_scmi.c
@@ -17,7 +17,7 @@
 
 static const struct fwk_element service_table[] = {
     [SGM776_SCMI_SERVICE_IDX_PSCI] = {
-        .name = "SERVICE0",
+        .name = "PSCI",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(FWK_MODULE_IDX_SMT,
                                                 SGM776_SCMI_SERVICE_IDX_PSCI),
@@ -30,7 +30,7 @@ static const struct fwk_element service_table[] = {
         }),
     },
     [SGM776_SCMI_SERVICE_IDX_OSPM_0] = {
-        .name = "SERVICE1",
+        .name = "OSPM-0",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(FWK_MODULE_IDX_SMT,
                                                 SGM776_SCMI_SERVICE_IDX_OSPM_0),
@@ -43,7 +43,7 @@ static const struct fwk_element service_table[] = {
         }),
     },
     [SGM776_SCMI_SERVICE_IDX_OSPM_1] = {
-        .name = "SERVICE2",
+        .name = "OSPM-1",
         .data = &((struct mod_scmi_service_config) {
             .transport_id = FWK_ID_ELEMENT_INIT(FWK_MODULE_IDX_SMT,
                                                 SGM776_SCMI_SERVICE_IDX_OSPM_1),