bootutil: Improve logging coverage

Add additional log lines to allow easier tracking potential
failures in image validation.

Signed-off-by: Dominik Ermel <[email protected]>

Author: de-nordic

boot/bootutil/src/bootutil_misc.c

@@ -141,6 +141,9 @@ int boot_trailer_scramble_offset(const struct flash_area *fa, size_t alignment,
 {
     int ret = 0;
 
+    BOOT_LOG_DBG("boot_trailer_scramble_offset: flash_area %p, alignment %u",
+                 fa, (unsigned int)alignment);
+
     /* Not allowed to enforce alignment smaller than device allows */
     if (alignment < flash_area_align(fa)) {
         alignment = flash_area_align(fa);
@@ -162,6 +165,9 @@ int boot_trailer_scramble_offset(const struct flash_area *fa, size_t alignment,
         *off = flash_area_get_size(fa) - ALIGN_DOWN(boot_trailer_sz(alignment), alignment);
     }
 
+    BOOT_LOG_DBG("boot_trailer_scramble_offset: final alignment %u, offset %u",
+                 (unsigned int)alignment, (unsigned int)*off);
+
     return ret;
 }
 
@@ -173,6 +179,8 @@ int boot_header_scramble_off_sz(const struct flash_area *fa, int slot, size_t *o
     size_t loff = 0;
     struct flash_sector sector;
 
+    BOOT_LOG_DBG("boot_header_scramble_off_sz: slot %d", slot);
+
     (void)slot;
 #if defined(MCUBOOT_SWAP_USING_OFFSET)
     /* In case of swap offset, header of secondary slot image is positioned
@@ -201,6 +209,8 @@ int boot_header_scramble_off_sz(const struct flash_area *fa, int slot, size_t *o
     }
     *off = loff;
 
+    BOOT_LOG_DBG("boot_header_scramble_off_sz: size %u", (unsigned int)*size);
+
     return ret;
 }
 
@@ -578,13 +588,18 @@ boot_erase_region(const struct flash_area *fa, uint32_t off, uint32_t size, bool
 {
     int rc = 0;
 
+    BOOT_LOG_DBG("boot_erase_region: flash_area %p, offset %d, size %d, backwards == %d",
+                 fa, off, size, (int)backwards);
+
     if (off >= flash_area_get_size(fa) || (flash_area_get_size(fa) - off) < size) {
         rc = -1;
         goto end;
     } else if (device_requires_erase(fa)) {
         uint32_t end_offset = 0;
         struct flash_sector sector;
 
+        BOOT_LOG_DBG("boot_erase_region: device with erase");
+
         if (backwards) {
             /* Get the lowest page offset first */
             rc = flash_area_get_sector(fa, off, &sector);
@@ -658,6 +673,8 @@ boot_erase_region(const struct flash_area *fa, uint32_t off, uint32_t size, bool
                 off += 1;
             }
         }
+    } else {
+        BOOT_LOG_DBG("boot_erase_region: device without erase");
     }
 
 end:

boot/bootutil/src/bootutil_public.c

@@ -248,6 +248,8 @@ boot_read_swap_state(const struct flash_area *fap,
     uint8_t swap_info;
     int rc;
 
+    BOOT_LOG_DBG("boot_read_swap_state: flash area %p", fap);
+
     off = boot_magic_off(fap);
     rc = flash_area_read(fap, off, magic, BOOT_MAGIC_SZ);
     if (rc < 0) {
@@ -262,6 +264,7 @@ boot_read_swap_state(const struct flash_area *fap,
     off = boot_swap_info_off(fap);
     rc = flash_area_read(fap, off, &swap_info, sizeof swap_info);
     if (rc < 0) {
+        BOOT_LOG_DBG("boot_read_swap_state: error %d reading state", rc);
         return BOOT_EFLASH;
     }
 
@@ -324,12 +327,13 @@ boot_write_magic(const struct flash_area *fap)
     memset(&magic[0], erased_val, sizeof(magic));
     memcpy(&magic[BOOT_MAGIC_ALIGN_SIZE - BOOT_MAGIC_SZ], BOOT_IMG_MAGIC, BOOT_MAGIC_SZ);
 
-    BOOT_LOG_DBG("writing magic; fa_id=%d off=0x%lx (0x%lx)",
+    BOOT_LOG_DBG("boot_write_magic: fa_id=%d off=0x%lx (0x%lx)",
                  flash_area_get_id(fap), (unsigned long)off,
                  (unsigned long)(flash_area_get_off(fap) + off));
     rc = flash_area_write(fap, pad_off, &magic[0], BOOT_MAGIC_ALIGN_SIZE);
 
     if (rc != 0) {
+        BOOT_LOG_DBG("boot_write_magic: error %d on write", rc);
         return BOOT_EFLASH;
     }
 
@@ -350,9 +354,14 @@ boot_write_trailer(const struct flash_area *fap, uint32_t off,
     uint32_t align;
     int rc;
 
+    BOOT_LOG_DBG("boot_write_trailer: for %p at %d, size = %d",
+                 fap, off, inlen);
+
     align = flash_area_align(fap);
     align = ALIGN_UP(inlen, align);
     if (align > BOOT_MAX_ALIGN) {
+        /* This should never happen */
+        assert(0);
         return -1;
     }
     erased_val = flash_area_erased_val(fap);
@@ -596,6 +605,9 @@ boot_set_next(const struct flash_area *fa, bool active, bool confirm)
     struct boot_swap_state slot_state;
     int rc;
 
+    BOOT_LOG_DBG("boot_set_next: fa %p active == %d, confirm == %d",
+                 fa, (int)active, (int)confirm);
+
     if (active) {
         /* The only way to set active slot for next boot is to confirm it,
          * as DirectXIP will conclude that, since slot has not been confirmed
@@ -606,6 +618,7 @@ boot_set_next(const struct flash_area *fa, bool active, bool confirm)
 
     rc = boot_read_swap_state(fa, &slot_state);
     if (rc != 0) {
+        BOOT_LOG_DBG("boot_set_next: error %d reading state", rc);
         return rc;
     }
 
@@ -733,6 +746,8 @@ boot_set_confirmed_multi(int image_index)
 
     rc = flash_area_open(FLASH_AREA_IMAGE_PRIMARY(image_index), &fap);
     if (rc != 0) {
+        BOOT_LOG_DBG("boot_set_confirmed_multi: error %d opening image %d",
+                     rc, image_index);
         return BOOT_EFLASH;
     }
 
@@ -763,10 +778,11 @@ boot_image_load_header(const struct flash_area *fa_p,
     uint32_t size;
     int rc = flash_area_read(fa_p, 0, hdr, sizeof *hdr);
 
+    BOOT_LOG_DBG("boot_image_load_header: from %p, result %d", fa_p, rc);
+
     if (rc != 0) {
-        rc = BOOT_EFLASH;
         BOOT_LOG_ERR("Failed reading image header");
-	return BOOT_EFLASH;
+        return BOOT_EFLASH;
     }
 
     if (hdr->ih_magic != IMAGE_MAGIC) {
@@ -783,6 +799,7 @@ boot_image_load_header(const struct flash_area *fa_p,
 
     if (!boot_u32_safe_add(&size, hdr->ih_img_size, hdr->ih_hdr_size) ||
         size >= flash_area_get_size(fa_p)) {
+        BOOT_LOG_ERR("Incorrect image size");
         return BOOT_EBADIMAGE;
     }
 

boot/bootutil/src/ed25519_psa.c

@@ -29,6 +29,8 @@ int ED25519_verify(const uint8_t *message, size_t message_len,
     psa_key_id_t kid;
     int ret = 0;        /* Fail by default */
 
+    BOOT_LOG_DBG("ED25519_verify: PSA implementation");
+
     /* Initialize PSA Crypto */
     status = psa_crypto_init();
     if (status != PSA_SUCCESS) {

boot/bootutil/src/encrypted.c

@@ -43,9 +43,12 @@
 #include "bootutil/enc_key.h"
 #include "bootutil/sign_key.h"
 #include "bootutil/crypto/common.h"
+#include "bootutil/bootutil_log.h"
 
 #include "bootutil_priv.h"
 
+BOOT_LOG_MODULE_DECLARE(mcuboot);
+
 #define EXPECTED_ENC_LEN        BOOT_ENC_TLV_SIZE
 
 #if defined(MCUBOOT_ENCRYPT_RSA)
@@ -411,6 +414,8 @@ boot_decrypt_key(const uint8_t *buf, uint8_t *enckey)
     uint8_t *cpend;
     size_t olen;
 #endif
+
+    BOOT_LOG_DBG("boot_decrypt_key:");
 #if defined(MCUBOOT_ENCRYPT_EC256)
     bootutil_ecdh_p256_context ecdh_p256;
 #endif
@@ -625,8 +630,11 @@ boot_enc_load(struct boot_loader_state *state, int slot,
 #endif
     int rc;
 
+    BOOT_LOG_DBG("boot_enc_load: slot %d", slot);
+
     /* Already loaded... */
     if (enc_state[slot].valid) {
+        BOOT_LOG_DBG("boot_enc_load: already loaded");
         return 1;
     }
 

boot/bootutil/src/encrypted_psa.c

@@ -146,9 +146,11 @@ boot_decrypt_key(const uint8_t *buf, uint8_t *enckey)
     uint8_t iv_and_key[PSA_CIPHER_IV_LENGTH(PSA_KEY_TYPE_AES, PSA_ALG_CTR) +
                        BOOT_ENC_KEY_SIZE];
 
+    BOOT_LOG_DBG("boot_decrypt_key: PSA ED25519");
+
     psa_ret = psa_crypto_init();
     if (psa_ret != PSA_SUCCESS) {
-        BOOT_LOG_ERR("AES crypto init failed %d", psa_ret);
+        BOOT_LOG_ERR("PSA crypto init failed %d", psa_ret);
         return -1;
     }
 

boot/bootutil/src/image_ecdsa.c

@@ -28,6 +28,7 @@
 #include <string.h>
 
 #include "mcuboot_config/mcuboot_config.h"
+#include "bootutil/bootutil_log.h"
 
 #if defined(MCUBOOT_SIGN_EC256) || defined(MCUBOOT_SIGN_EC384)
 
@@ -46,6 +47,8 @@ bootutil_verify_sig(uint8_t *hash, uint32_t hlen, uint8_t *sig, size_t slen,
     uint8_t *pubkey;
     uint8_t *end;
 
+    BOOT_LOG_DBG("bootutil_verify_sig: ECDSA builtin key %d", key_id);
+
     pubkey = (uint8_t *)bootutil_keys[key_id].key;
     end = pubkey + *bootutil_keys[key_id].len;
     bootutil_ecdsa_init(&ctx);
@@ -75,6 +78,8 @@ bootutil_verify_sig(uint8_t *hash, uint32_t hlen, uint8_t *sig, size_t slen,
     bootutil_ecdsa_context ctx;
     FIH_DECLARE(fih_rc, FIH_FAILURE);
 
+    BOOT_LOG_DBG("bootutil_verify_sig: ECDSA embedded key %hhd", key_id);
+
     /* Use builtin key for image verification, no key parsing is required. */
     ctx.key_id = key_id;
     bootutil_ecdsa_init(&ctx);

boot/bootutil/src/image_ed25519.c

@@ -21,8 +21,11 @@
 #include "bootutil/crypto/common.h"
 #endif
 
-#include "bootutil_priv.h"
+#include "bootutil/bootutil_log.h"
 #include "bootutil/crypto/sha.h"
+#include "bootutil_priv.h"
+
+BOOT_LOG_MODULE_DECLARE(mcuboot);
 
 #define EDDSA_SIGNATURE_LENGTH 64
 #define NUM_ED25519_BYTES 32
@@ -90,7 +93,11 @@ bootutil_verify(uint8_t *buf, uint32_t blen,
     uint8_t *pubkey;
     uint8_t *end;
 
+    BOOT_LOG_DBG("bootutil_verify: ED25519 key_id %d", (int)key_id);
+
     if (slen != EDDSA_SIGNATURE_LENGTH) {
+        BOOT_LOG_DBG("bootutil_verify: expected slen %d, got %u",
+                     EDDSA_SIGNATURE_LENGTH, (unsigned int)slen);
         FIH_SET(fih_rc, FIH_FAILURE);
         goto out;
     }
@@ -101,6 +108,7 @@ bootutil_verify(uint8_t *buf, uint32_t blen,
 #if !defined(MCUBOOT_KEY_IMPORT_BYPASS_ASN)
     rc = bootutil_import_key(&pubkey, end);
     if (rc) {
+        BOOT_LOG_DBG("bootutil_verify: import key failed %d", rc);
         FIH_SET(fih_rc, FIH_FAILURE);
         goto out;
     }
@@ -110,6 +118,7 @@ bootutil_verify(uint8_t *buf, uint32_t blen,
      * There is no check whether this is the correct key,
      * here, by the algorithm selected.
      */
+    BOOT_LOG_DBG("bootutil_verify: bypass ASN1");
     if (*bootutil_keys[key_id].len < NUM_ED25519_BYTES) {
         FIH_SET(fih_rc, FIH_FAILURE);
         goto out;
@@ -144,7 +153,11 @@ bootutil_verify_sig(uint8_t *hash, uint32_t hlen,
 {
     FIH_DECLARE(fih_rc, FIH_FAILURE);
 
+    BOOT_LOG_DBG("bootutil_verify_sig: ED25519 key_id %d", (int)key_id);
+
     if (hlen != IMAGE_HASH_SIZE) {
+        BOOT_LOG_DBG("bootutil_verify_sig: expected hlen %d, got %d",
+                     IMAGE_HASH_SIZE, hlen);
         FIH_SET(fih_rc, FIH_FAILURE);
         goto out;
     }
@@ -167,6 +180,8 @@ bootutil_verify_img(uint8_t *img, uint32_t size,
 {
     FIH_DECLARE(fih_rc, FIH_FAILURE);
 
+    BOOT_LOG_DBG("bootutil_verify_img: ED25519 key_id %d", (int)key_id);
+
     FIH_CALL(bootutil_verify, fih_rc, img, size, sig,
              slen, key_id);
 

boot/bootutil/src/image_rsa.c

@@ -28,6 +28,9 @@
 #include <string.h>
 
 #include "mcuboot_config/mcuboot_config.h"
+#include "bootutil/bootutil_log.h"
+
+BOOT_LOG_MODULE_DECLARE(mcuboot);
 
 #ifdef MCUBOOT_SIGN_RSA
 #include "bootutil_priv.h"
@@ -268,6 +271,8 @@ bootutil_verify_sig(uint8_t *hash, uint32_t hlen, uint8_t *sig, size_t slen,
     uint8_t *cp;
     uint8_t *end;
 
+    BOOT_LOG_DBG("bootutil_verify_sig: RSA key_id %d", key_id);
+
     bootutil_rsa_init(&ctx);
 
     cp = (uint8_t *)bootutil_keys[key_id].key;