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 

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?

[ovrebekk]

Hi

Switching to RTT logging I see the same issue, for some reason it hangs in the middle. 

Adding a 3 second delay at the top of main solves it, but I am not exactly sure why. 

I will have to investigate this a bit further and see if I can find the root cause. 

Best regards
Torbjørn

[snowuyl]

Thanks for your support!

[ovrebekk]

Hi 

I believe the issue is related to the size of the outgoing RTT buffer, which you can change by modifying the CONFIG_SEGGER_RTT_BUFFER_SIZE_UP parameter. 

By default this is set to 1024, which is not enough to buffer all the output during your boot sequence. 

Every time you flash the nRF device and reset the board the JLink RTT viewer will be disconnected, and by the time you are able to reconnect the viewer and start polling out the RTT data the buffers have overflowed, leading to loss of logging data. 

The reason adding a delay worked for me is that I was able to connect the RTT viewer before the nRF started printing log messages, avoiding the overflow.

Try setting CONFIG_SEGGER_RTT_BUFFER_SIZE_UP  to 2048 or more and it should work fine. 

Best regards
Torbjørn

[snowuyl]

Thanks for your great support. I can see AES-CBC-NO-PADDING 2nd test log messages after adding CONFIG_SEGGER_RTT_BUFFER_SIZE_UP=2048 to prj.conf file.

00> *** Booting Zephyr OS build v3.3.99-ncs1 ***
00> btInit() e
00> btInit() x
00> [00:00:00.948,272] <inf> aes_cbc: crypto_init() ok
00> [00:00:00.948,516] <inf> aes_cbc: Starting AES-CBC-NO-PADDING test 1
00> [00:00:00.948,852] <inf> aes_cbc: Importing random AES key...
00> psa_import_key() nrf e
00> [00:00:00.949,218] <inf> aes_cbc: AES key imported successfully!
00> [00:00:00.949,554] <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.950,927] <inf> aes_cbc: Encryption successful!
00> [00:00:00.951,232] <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.952,392] <inf> aes_cbc: Decryption successful!
00> [00:00:00.952,667] <inf> aes_cbc: Example finished successfully!
00> [00:00:00.952,972] <inf> aes_cbc: Starting AES-CBC-NO-PADDING test 2
00> [00:00:00.953,277] <inf> aes_cbc: Importing random AES key...
00> psa_import_key() nrf e
00> [00:00:00.953,643] <inf> aes_cbc: AES key imported successfully!
00> [00:00:00.953,979] <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.955,352] <inf> aes_cbc: Encryption successful!
00> [00:00:00.955,657] <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.956,787] <inf> aes_cbc: Decryption successful!
00> [00:00:00.957,092] <inf> aes_cbc: Example finished successfully!
00> _btReady(0) e
00> Bluetooth initialized
00> _btReady(0) x

[snowuyl]

07162.prj.conf

[ovrebekk]

I am glad to hear you got it working! I will consider the case resolved then