Can't see AES-CBC-NO-PADDING 2nd test log messages

[snowuyl]

I call nrfAes128Test() two times in function body of main(). But RTT Viewer only shows log messages of 1st times.

void main(void) {
    nrfAes128Init();
    nrfAes128Test(1);
    nrfAes128Test(2);

#ifdef CONFIG_PM
    while (1) {
        k_usleep(1);
    }
#endif
}

The following are log messages of RTT Viewer.

00> *** Booting Zephyr OS build v3.3.99-ncs1 ***
00> btInit() e
00> btInit() x
00> [00:00:00.974,151] <inf> aes_cbc: Starting AES-CBC-NO-PADDING test 1
00> [00:00:00.974,456] <inf> aes_cbc: Importing random AES key...
00> psa_import_key() nrf e
00> [00:00:00.974,853] <inf> aes_cbc: AES key imported successfully!
00> [00:00:00.975,189] <inf> aes_cbc: Encrypting using AES CBC MODE...
00> psa_cipher_encrypt_setup() nrf e
00> psa_cipher_setup() nrf e
00> psa_key_algorithm_permits() e key_type=9216, policy_alg=71319552, requested_alg=71319552
00> psa_cipher_setup() return 0
00> [00:00:00.976,531] <inf> aes_cbc: Encryption successful!
00> [00:00:00.976,867] <inf> aes_cbc: Decrypting using AES CBC MODE...
00> psa_cipher_setup() nrf e
00> psa_key_algorithm_permits() e key_type=9216, policy_alg=71319552, requested_alg=71319552
00> psa_cipher_setup() return 0
00> [00:00:00.977,996] <inf> aes_cbc: Decryption successful!
00> [00:00:00.978,302] <inf> aes_cbc: Example finished successfully!
00> [00:00:00.978,607] <

Procedures to reproduce this issue are as follows.

1. Unzipping minimal_log_aes.zip to D:\ncs\v2.4.0\nrf\samples folder.
2. cd D:\ncs\v2.4.0\nrf\samples\minimal_log_aes
3. west build -b nrf5340dk_nrf5340_cpuapp
4. west flash
5. Rebooting nRF5340 device and connecting to RTT Viewer.

[ovrebekk]

Hi 

Did you try to run the debugger to see if the code gets stuck somewhere? 

Looking at your code I notice that you run crypto_init() every time you call nrfAes128Test(..). Is this on purpose? 
I am not sure initializing the psa_crypto libraries twice will work. 

Could you try to move this into the nrfAes128Init() function instead and see if it works better?

Best regards
Torbjørn

[snowuyl]

Thanks for your suggestion! I have moved crypto_init() to function body of nrfAes128Init(). But I still don't see AES-CBC-NO-PADDING 2nd test log messages.

int nrfAes128Init(void) {
    const int status = crypto_init();
    if (status != APP_SUCCESS) {
        LOG_INF(APP_ERROR_MESSAGE);
        return APP_ERROR;
    }

    LOG_INF("crypto_init() ok");
    return 0;
}

int nrfAes128Test(const int count) {
    int status;

    LOG_INF("Starting AES-CBC-NO-PADDING test %d", count);
    status = import_key();
    if (status != APP_SUCCESS) {
        LOG_INF(APP_ERROR_MESSAGE);
        return APP_ERROR;
    }

    status = encrypt_cbc_aes();
    if (status != APP_SUCCESS) {
        LOG_INF(APP_ERROR_MESSAGE);
        return APP_ERROR;
    }

    status = decrypt_cbc_aes();
    if (status != APP_SUCCESS) {
        LOG_INF(APP_ERROR_MESSAGE);
        return APP_ERROR;
    }

    status = crypto_finish();
    if (status != APP_SUCCESS) {
        LOG_INF(APP_ERROR_MESSAGE);
        return APP_ERROR;
    }

    LOG_INF(APP_SUCCESS_MESSAGE);

    return APP_SUCCESS;
}

The following are log messages of RTT Viewer.

00> *** Booting Zephyr OS build v3.3.99-ncs1 ***
00> btInit() e
00> btInit() x
00> [00:00:00.986,968] <inf> aes_cbc: crypto_init() ok
00> [00:00:00.987,243] <inf> aes_cbc: Starting AES-CBC-NO-PADDING test 1
00> [00:00:00.987,579] <inf> aes_cbc: Importing random AES key...
00> psa_import_key() nrf e
00> [00:00:00.987,945] <inf> aes_cbc: AES key imported successfully!
00> [00:00:00.988,281] <inf> aes_cbc: Encrypting using AES CBC MODE...
00> psa_cipher_encrypt_setup() nrf e
00> psa_cipher_setup() nrf e
00> psa_key_algorithm_permits() e key_type=9216, policy_alg=71319552, requested_alg=71319552
00> psa_cipher_setup() return 0
00> [00:00:00.989,654] <inf> aes_cbc: Encryption successful!
00> [00:00:00.989,959] <inf> aes_cbc: Decrypting using AES CBC MODE...
00> psa_cipher_setup() nrf e
00> psa_key_algorithm_permits() e key_type=9216, policy_alg=71319552, requested_alg=71319552
00> psa_cipher_setup() return 0
00> [00:00:00.991,088] <inf> aes_cbc: Decryption successful!
00> [00:00:00.991,394] <inf> aes_cbc:

[ovrebekk]

Hi

What if you add a while loop at the end of your main function so it doesn't exit? 

Something like this:

while (1) {
  k_msleep(100);
}

Normally it shouldn't be a problem to exit the main function in Zephyr, but it is worth a shot...

Best regards
Torbjørn

[snowuyl]

Thanks for your reply! I have removed the following code from main.c. But I still don't see AES-CBC-NO-PADDING 2nd test log messages.

//#ifdef CONFIG_PM
//    while (1) {
//        k_usleep(1);
//    }
//#endif

The following are log messages of RTT Viewer.

00> *** Booting Zephyr OS build v3.3.99-ncs1 ***
00> btInit() e
00> btInit() x
00> [00:00:00.947,082] <inf> aes_cbc: crypto_init() ok
00> [00:00:00.947,357] <inf> aes_cbc: Starting AES-CBC-NO-PADDING test 1
00> [00:00:00.947,692] <inf> aes_cbc: Importing random AES key...
00> psa_import_key() nrf e
00> [00:00:00.948,059] <inf> aes_cbc: AES key imported successfully!
00> [00:00:00.948,394] <inf> aes_cbc: Encrypting using AES CBC MODE...
00> psa_cipher_encrypt_setup() nrf e
00> psa_cipher_setup() nrf e
00> psa_key_algorithm_permits() e key_type=9216, policy_alg=71319552, requested_alg=71319552
00> psa_cipher_setup() return 0
00> [00:00:00.949,737] <inf> aes_cbc: Encryption successful!
00> [00:00:00.950,042] <inf> aes_cbc: Decrypting using AES CBC MODE...
00> psa_cipher_setup() nrf e
00> psa_key_algorithm_permits() e key_type=9216, policy_alg=71319552, requested_alg=71319552
00> psa_cipher_setup() return 0
00> [00:00:00.951,202] <inf> aes_cbc: Decryption successful!
00> [00:00:00.951,507] <inf> aes_cbc:

[ovrebekk]

Hi 

I tested your code, and it seems to work fine for me. The only change I made was to use the UART LOG backend instead of RTT:

*** Booting Zephyr OS build v3.3.99-ncs1 ***
btInit() e
btInit() x
[00:00:00.270,477] <inf> aes_cbc: Starting AES-CBC-NO-PADDING test 1
[00:00:00.277,252] <inf> aes_cbc: Importing random AES key...
[00:00:00.283,477] <inf> aes_cbc: AES key imported successfully!
[00:00:00.289,916] <inf> aes_cbc: Encrypting using AES CBC MODE...
[00:00:00.296,936] <inf> aes_cbc: Encryption successful!
[00:00:00.302,642] <inf> aes_cbc: Decrypting using AES CBC MODE...
[00:00:00.309,570] <inf> aes_cbc: Decryption successful!
[00:00:00.315,277] <inf> aes_cbc: Example finished successfully!
[00:00:00.321,685] <inf> aes_cbc: Starting AES-CBC-NO-PADDING test 2
[00:00:00.328,491] <inf> aes_cbc: Importing random AES key...
[00:00:00.334,686] <inf> aes_cbc: AES key imported successfully!
[00:00:00.341,125] <inf> aes_cbc: Encrypting using AES CBC MODE...
[00:00:00.348,144] <inf> aes_cbc: Encryption successful!
[00:00:00.353,851] <inf> aes_cbc: Decrypting using AES CBC MODE...
[00:00:00.360,778] <inf> aes_cbc: Decryption successful!
[00:00:00.366,485] <inf> aes_cbc: Example finished successfully!
_btReady(0) e
Bluetooth initialized
_btReady(0) x

Could you try this as well and see if it makes a difference?

Are you testing on an nRF5340DK, or on custom hardware?

Best regards
Torbjørn

[snowuyl]

Thanks for your reply! I am using Raytac MDBT53-DB-40 board. (https://www.raytac.com/product/ins.php?index_id=139). Could you try to use RTT LOG backend since I don't use UART?