Debug

padelsbach · padelsbach · commit 9d9d6b60d2ff · 2026-03-01T23:32:07.000-08:00
diff --git a/.github/scripts/run-with-watchdog.sh b/.github/scripts/run-with-watchdog.sh
@@ -0,0 +1,88 @@
+#!/usr/bin/env bash
+set -euo pipefail
+
+if [ "$#" -lt 4 ]; then
+    echo "Usage: $0 <timeout_sec> <log_file> -- <command> [args...]" >&2
+    exit 2
+fi
+
+TIMEOUT_SEC="$1"
+LOG_FILE="$2"
+shift 2
+
+if [ "$1" != "--" ]; then
+    echo "Missing '--' separator before command" >&2
+    exit 2
+fi
+shift
+
+if [ "$#" -eq 0 ]; then
+    echo "Missing command to execute" >&2
+    exit 2
+fi
+
+HEARTBEAT_SEC="${WATCHDOG_HEARTBEAT_SEC:-60}"
+POLL_SEC=5
+
+echo "[watchdog] timeout=${TIMEOUT_SEC}s heartbeat=${HEARTBEAT_SEC}s log=${LOG_FILE}"
+echo "[watchdog] command: $*"
+
+# Run command in isolated process group so timeout handling can terminate
+# the entire subtree.
+setsid "$@" >"$LOG_FILE" 2>&1 &
+CMD_PID=$!
+CMD_PGID="$CMD_PID"
+START_TS="$(date +%s)"
+
+dump_diagnostics() {
+    echo "[watchdog] diagnostics begin"
+    echo "[watchdog] tail ${LOG_FILE}"
+    tail -n 200 "$LOG_FILE" || true
+
+    echo "[watchdog] process snapshot"
+    ps -eo pid,ppid,pgid,etime,comm,args | awk -v pgid="$CMD_PGID" '$3 == pgid { print }' || true
+
+    if command -v gdb >/dev/null 2>&1; then
+        while read -r pid _; do
+            [ -n "${pid:-}" ] || continue
+            echo "[watchdog] gdb backtrace pid=${pid}"
+            gdb -q -batch -ex "set pagination off" -ex "thread apply all bt" -p "$pid" || true
+        done < <(ps -eo pid,pgid | awk -v pgid="$CMD_PGID" '$2 == pgid { print $1, $2 }')
+    else
+        echo "[watchdog] gdb not found; skipping stack dumps"
+    fi
+    echo "[watchdog] diagnostics end"
+}
+
+while kill -0 "$CMD_PID" 2>/dev/null; do
+    NOW_TS="$(date +%s)"
+    ELAPSED="$((NOW_TS - START_TS))"
+
+    if [ "${NEXT_HEARTBEAT_TS:-0}" -le "$NOW_TS" ]; then
+        LAST_LINE="$(tail -n 1 "$LOG_FILE" 2>/dev/null || true)"
+        echo "[watchdog] elapsed=${ELAPSED}s last='${LAST_LINE}'"
+        NEXT_HEARTBEAT_TS="$((NOW_TS + HEARTBEAT_SEC))"
+    fi
+
+    if [ "$ELAPSED" -ge "$TIMEOUT_SEC" ]; then
+        echo "[watchdog] timeout reached after ${ELAPSED}s"
+        dump_diagnostics
+
+        kill -TERM -- "-${CMD_PGID}" 2>/dev/null || true
+        sleep 5
+        kill -KILL -- "-${CMD_PGID}" 2>/dev/null || true
+
+        wait "$CMD_PID" || true
+        exit 124
+    fi
+
+    sleep "$POLL_SEC"
+done
+
+set +e
+wait "$CMD_PID"
+RC=$?
+set -e
+
+cat "$LOG_FILE"
+exit "$RC"
diff --git a/.github/workflows/build-and-test.yml b/.github/workflows/build-and-test.yml
@@ -39,11 +39,11 @@ jobs:
 
     # Build and test ASAN build, with wolfCrypt tests enabled.
     - name: Build and test ASAN TESTWOLFCRYPT
-      run: cd test && make clean && make -j ASAN=1 TESTWOLFCRYPT=1 WOLFSSL_DIR=../wolfssl && make run
+      run: cd test && make clean && make -j ASAN=1 TESTWOLFCRYPT=1 WOLFSSL_DIR=../wolfssl && ../.github/scripts/run-with-watchdog.sh 2700 /tmp/wh_test_asan_testwolfcrypt.log -- make run
 
     # Build and test ASAN build, with wolfCrypt tests enabled and using the DMA devId.
     - name: Build and test ASAN TESTWOLFCRYPT TESTWOLFCRYPT_DMA
-      run: cd test && make clean && make -j ASAN=1 TESTWOLFCRYPT=1 TESTWOLFCRYPT_DMA=1 DMA=1 WOLFSSL_DIR=../wolfssl && make run
+      run: cd test && make clean && make -j ASAN=1 TESTWOLFCRYPT=1 TESTWOLFCRYPT_DMA=1 DMA=1 WOLFSSL_DIR=../wolfssl && ../.github/scripts/run-with-watchdog.sh 2700 /tmp/wh_test_asan_testwolfcrypt_dma.log -- make run
 
     # Build and test debug build with ASAN and NOCRYPTO
     - name: Build and test ASAN DEBUG NOCRYPTO
@@ -71,8 +71,8 @@ jobs:
 
     # Build and test in multithreaded mode with everything enabled and wolfCrypt tests
     - name: Build and test with THREADSAFE and TESTWOLFCRYPT and everything
-      run: cd test && make clean && make -j THREADSAFE=1 TESTWOLFCRYPT=1 DMA=1 SHE=1 ASAN=1 WOLFSSL_DIR=../wolfssl && make run
+      run: cd test && make clean && make -j THREADSAFE=1 TESTWOLFCRYPT=1 DMA=1 SHE=1 ASAN=1 WOLFSSL_DIR=../wolfssl && ../.github/scripts/run-with-watchdog.sh 2700 /tmp/wh_test_threadsafe_testwolfcrypt.log -- make run
 
     # Build and test in multithreaded mode with everything enabled and wolfCrypt tests with dma
     - name: Build and test with THREADSAFE and TESTWOLFCRYPT with DMA
-      run: cd test && make clean && make -j THREADSAFE=1 TESTWOLFCRYPT=1 TESTWOLFCRYPT_DMA=1 DMA=1 SHE=1 ASAN=1 WOLFSSL_DIR=../wolfssl && make run
+      run: cd test && make clean && make -j THREADSAFE=1 TESTWOLFCRYPT=1 TESTWOLFCRYPT_DMA=1 DMA=1 SHE=1 ASAN=1 WOLFSSL_DIR=../wolfssl && ../.github/scripts/run-with-watchdog.sh 2700 /tmp/wh_test_threadsafe_testwolfcrypt_dma.log -- make run
diff --git a/src/wh_transport_mem.c b/src/wh_transport_mem.c
@@ -169,6 +169,11 @@ int wh_TransportMem_RecvResponse(void* c, uint16_t* out_len, void* data)
         return WH_ERROR_NOTREADY;
     }
 
+    /* Guard against transient/torn CSR reads and corrupted len values. */
+    if (resp.s.len > (context->resp_size - sizeof(whTransportMemCsr))) {
+        return WH_ERROR_NOTREADY;
+    }
+
     if ((data != NULL) && (resp.s.len != 0)) {
         wh_Utils_memcpy_invalidate(data, context->resp_data, resp.s.len);
     }
@@ -253,6 +258,11 @@ int wh_TransportMem_RecvRequest(void* c, uint16_t* out_len, void* data)
         return WH_ERROR_NOTREADY;
     }
 
+    /* Guard against transient/torn CSR reads and corrupted len values. */
+    if (req.s.len > (context->req_size - sizeof(whTransportMemCsr))) {
+        return WH_ERROR_NOTREADY;
+    }
+
     if ((data != NULL) && (req.s.len != 0)) {
         wh_Utils_memcpy_invalidate(data, context->req_data, req.s.len);
     }
@@ -262,4 +272,4 @@ int wh_TransportMem_RecvRequest(void* c, uint16_t* out_len, void* data)
 
     return 0;
 }
-#endif /* WOLFHSM_CFG_ENABLE_SERVER */
+#endif /* WOLFHSM_CFG_ENABLE_SERVER */
diff --git a/test/wh_test_crypto.c b/test/wh_test_crypto.c
@@ -457,8 +457,10 @@ static int whTest_CryptoEcc(whClientContext* ctx, int devId, WC_RNG* rng)
                 }
                 /* Test ECDSA sign/verify with exported keys */
                 if (ret == 0) {
+                    WH_TEST_PRINT("ECC export key SIGN/VERIFY: begin\n");
                     memcpy(hash, shared_ba, sizeof(hash));
                     word32 sigLen = sizeof(sig);
+                    WH_TEST_PRINT("ECC export key SIGN/VERIFY: signing...\n");
                     ret           = wc_ecc_sign_hash((void*)hash, sizeof(hash),
                                                      (void*)sig, &sigLen, rng, bobKey);
                     if (ret != 0) {
@@ -467,6 +469,7 @@ static int whTest_CryptoEcc(whClientContext* ctx, int devId, WC_RNG* rng)
                     }
                     else {
                         int res = 0;
+                        WH_TEST_PRINT("ECC export key SIGN/VERIFY: verifying...\n");
                         ret =
                             wc_ecc_verify_hash((void*)sig, sigLen, (void*)hash,
                                                sizeof(hash), &res, bobKey);
@@ -484,8 +487,10 @@ static int whTest_CryptoEcc(whClientContext* ctx, int devId, WC_RNG* rng)
                         }
                     }
                 }
+                WH_TEST_PRINT("ECC export key test: freeing aliceKey\n");
                 wc_ecc_free(aliceKey);
             }
+            WH_TEST_PRINT("ECC export key test: freeing bobKey\n");
             wc_ecc_free(bobKey);
         }
     }
@@ -675,7 +680,15 @@ static int whTest_CryptoEccCacheDuplicate(whClientContext* client)
     }
 
     if (!WH_KEYID_ISERASED(keyId)) {
-        wh_Client_KeyEvict(client, keyId);
+        WH_TEST_PRINT("    Cleaning up duplicate ECC cache key (keyId=0x%X)...\n",
+                      keyId);
+        ret = wh_Client_KeyEvict(client, keyId);
+        if (ret != WH_ERROR_OK) {
+            WH_ERROR_PRINT("    FAIL: wh_Client_KeyEvict returned %d\n", ret);
+        }
+        else {
+            WH_TEST_PRINT("    PASS: Duplicate ECC cache key evicted\n");
+        }
     }
 
     return ret;
@@ -1029,6 +1042,8 @@ static int whTest_CryptoEd25519Inline(whClientContext* ctx, int devId,
     byte         pubKeyRaw[ED25519_PUB_KEY_SIZE];
     word32       pubKeySize = sizeof(pubKeyRaw);
 
+    WH_TEST_PRINT("Testing Ed25519 inline DEVID=0x%X...\n", devId);
+
     ret = wc_ed25519_init_ex(key, NULL, devId);
     if (ret != 0) {
         WH_ERROR_PRINT("Failed to initialize Ed25519 key: %d\n", ret);
@@ -1117,6 +1132,8 @@ static int whTest_CryptoEd25519ServerKey(whClientContext* ctx, int devId,
     int         verified = 0;
     uint8_t     label[]  = "Ed25519 Server Key";
 
+    WH_TEST_PRINT("Testing Ed25519 server key DEVID=0x%X...\n", devId);
+
     ret = wc_ed25519_init_ex(key, NULL, devId);
     if (ret != 0) {
         WH_ERROR_PRINT("Failed to initialize Ed25519 key: %d\n", ret);
@@ -1220,6 +1237,8 @@ static int whTest_CryptoEd25519Dma(whClientContext* ctx, int devId, WC_RNG* rng)
     int         verified = 0;
     uint8_t     label[]  = "Ed25519 DMA Key";
 
+    WH_TEST_PRINT("Testing Ed25519 DMA DEVID=0x%X...\n", devId);
+
     ret = wc_ed25519_init_ex(key, NULL, devId);
     if (ret != 0) {
         WH_ERROR_PRINT("Failed to initialize Ed25519 key (DMA): %d\n", ret);
@@ -1312,6 +1331,8 @@ static int whTest_CryptoCurve25519(whClientContext* ctx, int devId, WC_RNG* rng)
     uint8_t label_b[WH_NVM_LABEL_LEN] = "Curve25519 Label B";
     word32 len = 0;
 
+    WH_TEST_PRINT("Testing Curve25519 DEVID=0x%X...\n", devId);
+
     /* Use wolfcrypt ephemeral local keys */
     ret = wc_curve25519_init_ex(key_a, NULL, devId);
     if (ret != 0) {
@@ -2766,9 +2787,11 @@ static int whTest_KeyCache(whClientContext* ctx, int devId, WC_RNG* rng)
     }
 
 #ifdef WOLFHSM_CFG_DMA
+    WH_TEST_PRINT("KEY CACHE: entering DMA-specific tests\n");
     /* test cache/export using DMA */
     if (ret == 0) {
         keyId = WH_KEYID_ERASED;
+        WH_TEST_PRINT("KEY CACHE DMA: cache/export test begin\n");
         ret =
             whTest_CacheExportKeyDma(ctx, &keyId, labelIn, labelOut,
                                      sizeof(labelIn), key, keyOut, sizeof(key));
@@ -3128,6 +3151,9 @@ static int whTestCrypto_Aes(whClientContext* ctx, int devId, WC_RNG* rng)
     uint8_t plainOut[WH_TEST_AES_TEXTSIZE] = { 0 };
     whKeyId keyId = WH_KEYID_ERASED;
     uint8_t labelIn[WH_NVM_LABEL_LEN] = "AES Key Label";
+    int evictRet = WH_ERROR_OK;
+
+    WH_TEST_PRINT("AES test begin DEVID=0x%X\n", devId);
 
     memset(plainIn, 0xAA, sizeof(plainIn));
 
@@ -3370,6 +3396,7 @@ static int whTestCrypto_Aes(whClientContext* ctx, int devId, WC_RNG* rng)
 
 #ifdef HAVE_AES_ECB
     if (ret == 0) {
+        WH_TEST_PRINT("AES ECB DEVID=0x%X: client-side begin\n", devId);
         /* test aes ECB with client side key */
         ret = wc_AesInit(aes, NULL, devId);
         if (ret != 0) {
@@ -3415,45 +3442,55 @@ static int whTestCrypto_Aes(whClientContext* ctx, int devId, WC_RNG* rng)
         }
     }
     if (ret == 0) {
+        WH_TEST_PRINT("AES ECB DEVID=0x%X: HSM-side begin\n", devId);
         /* test aes ECB with HSM side key */
         ret = wc_AesInit(aes, NULL, devId);
         if (ret != 0) {
             WH_ERROR_PRINT("Failed to wc_AesInit %d\n", ret);
         }
         else {
             keyId = WH_KEYID_ERASED;
+            WH_TEST_PRINT("AES ECB DEVID=0x%X: key cache request\n", devId);
             ret   = wh_Client_KeyCache(
                   ctx, WH_NVM_FLAGS_USAGE_ENCRYPT | WH_NVM_FLAGS_USAGE_DECRYPT,
                   labelIn, sizeof(labelIn), key, sizeof(key), &keyId);
             if (ret != 0) {
                 WH_ERROR_PRINT("Failed to wh_Client_KeyCache %d\n", ret);
             }
             else {
+                WH_TEST_PRINT("AES ECB DEVID=0x%X: key cache id=0x%X\n",
+                              devId, keyId);
                 ret = wh_Client_AesSetKeyId(aes, keyId);
                 if (ret != 0) {
                     WH_ERROR_PRINT("Failed to wh_Client_SetKeyIdAes %d\n", ret);
                 }
                 else {
+                    WH_TEST_PRINT("AES ECB DEVID=0x%X: set iv (null)\n", devId);
                     /* AES-ECB does not use IV */
                     ret = wc_AesSetIV(aes, NULL);
                     if (ret != 0) {
                         WH_ERROR_PRINT("Failed to wc_AesSetIV %d\n", ret);
                     }
                     else {
+                        WH_TEST_PRINT("AES ECB DEVID=0x%X: encrypt\n", devId);
                         ret = wc_AesEcbEncrypt(aes, cipher, plainIn,
                                                sizeof(plainIn));
                         if (ret != 0) {
                             WH_ERROR_PRINT("Failed to wc_AesEcbEncrypt %d\n",
                                            ret);
                         }
                         else {
+                            WH_TEST_PRINT("AES ECB DEVID=0x%X: reset iv (null)\n",
+                                          devId);
                             /* AES-ECB does not use IV */
                             ret = wc_AesSetIV(aes, NULL);
                             if (ret != 0) {
                                 WH_ERROR_PRINT("Failed to wc_AesSetIV %d\n",
                                                ret);
                             }
                             else {
+                                WH_TEST_PRINT("AES ECB DEVID=0x%X: decrypt\n",
+                                              devId);
                                 ret = wc_AesEcbDecrypt(aes, plainOut, cipher,
                                                        sizeof(plainIn));
                                 if (ret != 0) {
@@ -3471,7 +3508,17 @@ static int whTestCrypto_Aes(whClientContext* ctx, int devId, WC_RNG* rng)
                         }
                     }
                 }
-                (void)wh_Client_KeyEvict(ctx, keyId);
+                evictRet = wh_Client_KeyEvict(ctx, keyId);
+                if (evictRet != WH_ERROR_OK) {
+                    WH_ERROR_PRINT("AES ECB DEVID=0x%X: key evict failed %d\n",
+                                   devId, evictRet);
+                    if (ret == WH_ERROR_OK) {
+                        ret = evictRet;
+                    }
+                }
+                else {
+                    WH_TEST_PRINT("AES ECB DEVID=0x%X: key evicted\n", devId);
+                }
             }
             (void)wc_AesFree(aes);
             memset(cipher, 0, sizeof(cipher));
@@ -5491,12 +5538,17 @@ int whTest_CryptoClientConfig(whClientConfig* config)
 
     if (ret == 0) {
         /* Test Key Cache functions */
+        WH_TEST_PRINT("Crypto stage: whTest_KeyCache begin\n");
         ret = whTest_KeyCache(client, WH_DEV_ID, rng);
+        WH_TEST_PRINT("Crypto stage: whTest_KeyCache end ret=%d\n", ret);
     }
 
     if (ret == 0) {
         /* Test Non-Exportable Flag enforcement on keystore */
+        WH_TEST_PRINT("Crypto stage: whTest_NonExportableKeystore begin\n");
         ret = whTest_NonExportableKeystore(client, WH_DEV_ID, rng);
+        WH_TEST_PRINT("Crypto stage: whTest_NonExportableKeystore end ret=%d\n",
+                      ret);
     }
 
     if (ret == 0) {
diff --git a/test/wh_test_multiclient.c b/test/wh_test_multiclient.c
diff --git a/test/wh_test_she.c b/test/wh_test_she.c

Original file line number	Diff line number	Diff line change
`@@ -169,6 +169,11 @@ int wh_TransportMem_RecvResponse(void* c, uint16_t* out_len, void* data)`
`169`	`169`	`return WH_ERROR_NOTREADY;`
`170`	`170`	`}`
`171`	`171`
	`172`	`+ /* Guard against transient/torn CSR reads and corrupted len values. */`
	`173`	`+ if (resp.s.len > (context->resp_size - sizeof(whTransportMemCsr))) {`
	`174`	`+ return WH_ERROR_NOTREADY;`
	`175`	`+ }`
	`176`	`+`
`172`	`177`	`if ((data != NULL) && (resp.s.len != 0)) {`
`173`	`178`	`wh_Utils_memcpy_invalidate(data, context->resp_data, resp.s.len);`
`174`	`179`	`}`
`@@ -253,6 +258,11 @@ int wh_TransportMem_RecvRequest(void* c, uint16_t* out_len, void* data)`
`253`	`258`	`return WH_ERROR_NOTREADY;`
`254`	`259`	`}`
`255`	`260`
	`261`	`+ /* Guard against transient/torn CSR reads and corrupted len values. */`
	`262`	`+ if (req.s.len > (context->req_size - sizeof(whTransportMemCsr))) {`
	`263`	`+ return WH_ERROR_NOTREADY;`
	`264`	`+ }`
	`265`	`+`
`256`	`266`	`if ((data != NULL) && (req.s.len != 0)) {`
`257`	`267`	`wh_Utils_memcpy_invalidate(data, context->req_data, req.s.len);`
`258`	`268`	`}`
`@@ -262,4 +272,4 @@ int wh_TransportMem_RecvRequest(void* c, uint16_t* out_len, void* data)`
`262`	`272`
`263`	`273`	`return 0;`
`264`	`274`	`}`
`265`		`-#endif /* WOLFHSM_CFG_ENABLE_SERVER */`
	`275`	`+#endif /* WOLFHSM_CFG_ENABLE_SERVER */`