Merge pull request #262 from bigbrett/logging-invocations

Logging: part 2

Author: dgarske

port/posix/posix_log_file.c

@@ -39,21 +39,6 @@
 
 #ifdef WOLFHSM_CFG_LOGGING
 
-/* Helper function to convert log level to string */
-static const char* posixLogFile_LevelToString(whLogLevel level)
-{
-    switch (level) {
-        case WH_LOG_LEVEL_INFO:
-            return "INFO";
-        case WH_LOG_LEVEL_ERROR:
-            return "ERROR";
-        case WH_LOG_LEVEL_SECEVENT:
-            return "SECEVENT";
-        default:
-            return "UNKNOWN";
-    }
-}
-
 /* Helper function to convert string to log level */
 static whLogLevel posixLogFile_StringToLevel(const char* str)
 {
@@ -146,7 +131,7 @@ int posixLogFile_AddEntry(void* c, const whLogEntry* entry)
     /* Format log entry: TIMESTAMP|LEVEL|FILE:LINE|FUNCTION|MESSAGE\n */
     len = snprintf(buffer, sizeof(buffer), "%llu|%s|%s:%u|%s|%.*s\n",
                    (unsigned long long)entry->timestamp,
-                   posixLogFile_LevelToString(entry->level),
+                   wh_Log_LevelToString(entry->level),
                    entry->file ? entry->file : "", entry->line,
                    entry->function ? entry->function : "", (int)entry->msg_len,
                    entry->msg);

src/wh_log.c

@@ -36,6 +36,20 @@
 
 #ifdef WOLFHSM_CFG_LOGGING
 
+const char* wh_Log_LevelToString(whLogLevel level)
+{
+    switch (level) {
+        case WH_LOG_LEVEL_INFO:
+            return "INFO";
+        case WH_LOG_LEVEL_ERROR:
+            return "ERROR";
+        case WH_LOG_LEVEL_SECEVENT:
+            return "SECEVENT";
+        default:
+            return "UNKNOWN";
+    }
+}
+
 void wh_Log_AddMsg(whLogContext* ctx, whLogLevel level, const char* file,
                    const char* function, uint32_t line, const char* src,
                    size_t src_len)

src/wh_log_printf.c

@@ -0,0 +1,98 @@
+/*
+ * Copyright (C) 2024 wolfSSL Inc.
+ *
+ * This file is part of wolfHSM.
+ *
+ * wolfHSM is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * wolfHSM 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 General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with wolfHSM.  If not, see <http://www.gnu.org/licenses/>.
+ */
+/*
+ * src/wh_log_printf.c
+ *
+ * Printf-style logging backend implementation
+ */
+
+#include <stddef.h> /* For NULL */
+#include <string.h> /* For memset, memcpy */
+
+#include "wolfhsm/wh_settings.h"
+
+#include "wolfhsm/wh_log_printf.h"
+#include "wolfhsm/wh_error.h"
+#include "wolfhsm/wh_log.h"
+
+#ifdef WOLFHSM_CFG_LOGGING
+
+int whLogPrintf_Init(void* c, const void* cf)
+{
+    whLogPrintfContext*      context = (whLogPrintfContext*)c;
+    const whLogPrintfConfig* config  = (const whLogPrintfConfig*)cf;
+
+    if (context == NULL) {
+        return WH_ERROR_BADARGS;
+    }
+
+    /* Initialize context */
+    memset(context, 0, sizeof(*context));
+
+    /* Copy config if provided, otherwise use defaults */
+    if (config != NULL) {
+        context->logIfNotDebug = config->logIfNotDebug;
+    }
+    else {
+        context->logIfNotDebug = 0;
+    }
+
+    context->initialized = 1;
+
+    return WH_ERROR_OK;
+}
+
+
+int whLogPrintf_AddEntry(void* c, const whLogEntry* entry)
+{
+    whLogPrintfContext* context = (whLogPrintfContext*)c;
+
+    if ((context == NULL) || (entry == NULL)) {
+        return WH_ERROR_BADARGS;
+    }
+
+    if (!context->initialized) {
+        return WH_ERROR_ABORTED;
+    }
+
+    /* Conditional logging:
+     * - If logIfNotDebug is true: always log
+     * - If logIfNotDebug is false: only log if WOLFHSM_CFG_DEBUG is defined
+     */
+#ifndef WOLFHSM_CFG_DEBUG
+    if (!context->logIfNotDebug) {
+        return WH_ERROR_OK;
+    }
+#endif
+
+    /* Format: [TIMESTAMP] [LEVEL] [FILE:LINE FUNC] MESSAGE */
+    (void)WOLFHSM_CFG_PRINTF(
+        "[%llu] [%s] [%s:%u %s] %.*s\n", (unsigned long long)entry->timestamp,
+        wh_Log_LevelToString(entry->level),
+        (entry->file != NULL) ? entry->file : "", entry->line,
+        (entry->function != NULL) ? entry->function : "",
+        (entry->msg_len <= WOLFHSM_CFG_LOG_MSG_MAX)
+            ? (int)(entry->msg_len)
+            : (int)WOLFHSM_CFG_LOG_MSG_MAX,
+        entry->msg);
+
+    return WH_ERROR_OK;
+}
+
+#endif /* WOLFHSM_CFG_LOGGING */

src/wh_server.c

@@ -325,6 +325,7 @@ int wh_Server_HandleRequestMessage(whServerContext* server)
     uint16_t seq = 0;
     uint16_t size = 0;
     uint8_t* data = NULL;
+    int      handlerRc = 0;
 
     if (server == NULL) {
         return WH_ERROR_BADARGS;
@@ -342,7 +343,7 @@ int wh_Server_HandleRequestMessage(whServerContext* server)
     int rc = wh_CommServer_RecvRequest(server->comm, &magic, &kind, &seq,
             &size, data);
     /* Got a packet? */
-    if (rc == 0) {
+    if (rc == WH_ERROR_OK) {
         group = WH_MESSAGE_GROUP(kind);
         action = WH_MESSAGE_ACTION(kind);
         switch (group) {
@@ -407,33 +408,56 @@ int wh_Server_HandleRequestMessage(whServerContext* server)
 #endif /* WOLFHSM_CFG_CERTIFICATE_MANAGER && !WOLFHSM_CFG_NO_CRYPTO */
 
         default:
-            /* Unknown group. Return empty packet*/
-            /* TODO: Respond with aux error flag */
+            /* Unknown group. Return empty packet */
+            rc   = WH_ERROR_NOTIMPL;
+            data = NULL;
             size = 0;
         }
 
-        /* Send a response */
-        /* TODO: Respond with ErrorResponse if handler returns an error */
+        /* Capture handler result for logging. The response packet already
+         * contains the error code for the client in the resp.rc field. */
+        handlerRc = rc;
+
+        /* Handle cancellation by modifying response kind */
 #ifdef WOLFHSM_CFG_CANCEL_API
-        if (rc == WH_ERROR_CANCEL) {
+        if (handlerRc == WH_ERROR_CANCEL) {
             /* notify the client that their request was canceled */
             kind = WH_MESSAGE_KIND(WH_MESSAGE_GROUP_CANCEL, 0);
             size = 0;
             data = NULL;
-            /* reset RC so the cancellation response is sent */
-            rc = 0;
         }
 #endif
-        if (rc == 0) {
-            do {
-                rc = wh_CommServer_SendResponse(server->comm, magic, kind, seq,
-                    size, data);
-            } while (rc == WH_ERROR_NOTREADY);
-        }
+
+        /* Always send the response to the client, regardless of handler error.
+         * The response packet contains the operational error code for the
+         * client in the resp.rc field. */
+        do {
+            rc = wh_CommServer_SendResponse(server->comm, magic, kind, seq,
+                                            size, data);
+        } while (rc == WH_ERROR_NOTREADY);
+
+        /* Log error code from request handler, if present */
+        WH_LOG_ON_ERROR_F(&server->log, WH_LOG_LEVEL_ERROR, handlerRc,
+                          "Handler (group=%d, action=%d, seq=%d) returned %d",
+                          group, action, seq, handlerRc);
+        (void)handlerRc; /* suppress unused var warning */
+
+        /* Log error code from sending response, if present */
+        WH_LOG_ON_ERROR_F(
+            &server->log, WH_LOG_LEVEL_ERROR, rc,
+            "SendResponse failed for (group=%d, action=%d, seq=%d): %d", group,
+            action, seq, rc);
+
+        /* Handler errors are logged above via handlerRc but don't affect
+         * return code. Errors from SendResponse are propagated back to the
+         * caller in rc */
+    }
+    else if (rc != WH_ERROR_NOTREADY) {
+        /* Log error code from processing request, if present */
         WH_LOG_ON_ERROR_F(
             &server->log, WH_LOG_LEVEL_ERROR, rc,
-            "Request Handler for (group=%d, action=%d) Returned Error: %d",
-            group, action, rc);
+            "RecvRequest failed for (group=%d, action=%d, seq=%d): %d", group,
+            action, seq, rc);
     }
 
     return rc;

src/wh_server_counter.c

@@ -80,8 +80,6 @@ int wh_Server_HandleCounter(whServerContext* server, uint16_t magic,
                 resp.counter = *counter;
             }
             resp.rc = ret;
-            /* TODO: are there any fatal server errors? */
-            ret = WH_ERROR_OK;
 
             (void)wh_MessageCounter_TranslateInitResponse(
                 magic, &resp, (whMessageCounter_InitResponse*)resp_packet);
@@ -139,9 +137,6 @@ int wh_Server_HandleCounter(whServerContext* server, uint16_t magic,
                 magic, &resp, (whMessageCounter_IncrementResponse*)resp_packet);
 
             *out_resp_size = sizeof(resp);
-
-            /* TODO: are there any fatal server errors? */
-            ret = WH_ERROR_OK;
         } break;
 
         case WH_COUNTER_READ: {
@@ -178,9 +173,6 @@ int wh_Server_HandleCounter(whServerContext* server, uint16_t magic,
                 magic, &resp, (whMessageCounter_ReadResponse*)resp_packet);
 
             *out_resp_size = sizeof(resp);
-
-            /* TODO: are there any fatal server errors? */
-            ret = WH_ERROR_OK;
         } break;
 
         case WH_COUNTER_DESTROY: {
@@ -211,9 +203,6 @@ int wh_Server_HandleCounter(whServerContext* server, uint16_t magic,
                 magic, &resp, (whMessageCounter_DestroyResponse*)resp_packet);
 
             *out_resp_size = sizeof(resp);
-
-            /* TODO: are there any fatal server errors? */
-            ret = WH_ERROR_OK;
         } break;
 
         default:

src/wh_server_crypto.c

@@ -4239,16 +4239,6 @@ int wh_Server_HandleCryptoRequest(whServerContext* ctx, uint16_t magic,
 
     WH_DEBUG_SERVER_VERBOSE("End ret:%d\n", ret);
 
-    /* Since crypto error codes are propagated to the client in the response
-     * packet, return success to the caller unless a cancellation has occurred
-     */
-#ifdef WOLFHSM_CFG_CANCEL_API
-    if (ret != WH_ERROR_CANCEL) {
-        ret = WH_ERROR_OK;
-    }
-#else
-    ret = WH_ERROR_OK;
-#endif
     return ret;
 }
 
@@ -5732,16 +5722,7 @@ int wh_Server_HandleCryptoDmaRequest(whServerContext* ctx, uint16_t magic,
 
 
     WH_DEBUG_SERVER_VERBOSE("Crypto DMA request. Action:%u\n", action);
-    /* Since crypto error codes are propagated to the client in the response
-     * packet, return success to the caller unless a cancellation has occurred
-     */
-#ifdef WOLFHSM_CFG_CANCEL_API
-    if (ret != WH_ERROR_CANCEL) {
-        ret = WH_ERROR_OK;
-    }
-#else
-    ret = WH_ERROR_OK;
-#endif
+
     return ret;
 }
 #endif /* WOLFHSM_CFG_DMA */