From d9c5833a53e3a6e425d420b4d06dfa4929f158b1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Vejpustek?= Date: Tue, 16 Apr 2024 17:52:38 +0200 Subject: [PATCH] debug(core): log optiga errors --- core/embed/trezorhal/optiga/optiga_commands.c | 54 +++++++++++++++++++ .../embed/trezorhal/optiga/optiga_transport.c | 54 +++++++++++++++++++ 2 files changed, 108 insertions(+) diff --git a/core/embed/trezorhal/optiga/optiga_commands.c b/core/embed/trezorhal/optiga/optiga_commands.c index 07ee0d695..c52798412 100644 --- a/core/embed/trezorhal/optiga/optiga_commands.c +++ b/core/embed/trezorhal/optiga/optiga_commands.c @@ -33,6 +33,8 @@ #include "optiga_transport.h" #include "sha2.h" +void vcp_println(const char *fmt, ...); + // Static buffer for commands and responses. static uint8_t tx_buffer[OPTIGA_MAX_APDU_SIZE] = {0}; static size_t tx_size = 0; @@ -53,11 +55,15 @@ const optiga_metadata_item OPTIGA_META_VERSION_DEFAULT = { static optiga_result process_output(uint8_t **out_data, size_t *out_size) { // Check that there is no trailing output data in the response. if (tx_size < 4 || (tx_buffer[2] << 8) + tx_buffer[3] != tx_size - 4) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } // Check response status code. if (tx_buffer[0] != 0) { + vcp_println("Error: OPTIGA_ERR_CMD, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_CMD; } @@ -76,6 +82,8 @@ static optiga_result process_output_fixedlen(uint8_t *data, size_t data_size) { // Expecting data_size bytes of output data in the response. if (out_size != data_size) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } @@ -97,6 +105,8 @@ static optiga_result process_output_varlen(uint8_t *data, size_t max_data_size, } if (out_size > max_data_size) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -157,12 +167,16 @@ optiga_result optiga_parse_metadata(const uint8_t *serialized, if (serialized_size < 2 || serialized[0] != 0x20 || serialized[1] + 2 != serialized_size) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } size_t pos = 2; while (pos < serialized_size) { if (pos + 2 >= serialized_size) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -177,6 +191,8 @@ optiga_result optiga_parse_metadata(const uint8_t *serialized, if (item == NULL || item->ptr != NULL) { // Invalid tag or multiply defined tag. + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -186,6 +202,8 @@ optiga_result optiga_parse_metadata(const uint8_t *serialized, } if (pos != serialized_size) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -198,6 +216,8 @@ optiga_result optiga_serialize_metadata(const optiga_metadata *metadata, size_t *serialized_size) { *serialized_size = 0; if (max_serialized < 2) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -212,6 +232,8 @@ optiga_result optiga_serialize_metadata(const optiga_metadata *metadata, } if (max_serialized < pos + 2 + item->len) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -223,6 +245,8 @@ optiga_result optiga_serialize_metadata(const optiga_metadata *metadata, // Set length byte. if (pos - 2 > 256) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } serialized[1] = pos - 2; @@ -327,6 +351,8 @@ optiga_result optiga_set_data_object(uint16_t oid, bool set_metadata, const uint8_t *data, size_t data_size) { tx_size = data_size + 8; if (tx_size > sizeof(tx_buffer)) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -364,6 +390,8 @@ optiga_result optiga_count_data_object(uint16_t oid, uint8_t count) { tx_size = 9; if (tx_size > sizeof(tx_buffer)) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -393,6 +421,8 @@ optiga_result optiga_count_data_object(uint16_t oid, uint8_t count) { optiga_result optiga_get_random(uint8_t *random, size_t random_size) { if (random_size < OPTIGA_RANDOM_MIN_SIZE || random_size > OPTIGA_RANDOM_MAX_SIZE) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -422,6 +452,8 @@ optiga_result optiga_encrypt_sym(optiga_sym_mode mode, uint16_t oid, uint8_t *output, size_t max_output_size, size_t *output_size) { if (input_size < 1 || input_size > 640) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -524,6 +556,8 @@ optiga_result optiga_clear_auto_state(uint16_t key_oid) { // Expecting no output data. Response status code should indicate failure. if (tx_size != 4 || tx_buffer[0] != 0xff || tx_buffer[2] != 0 || tx_buffer[3] != 0) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } @@ -539,6 +573,8 @@ optiga_result optiga_calc_sign(uint16_t oid, const uint8_t *digest, size_t max_sig_size, size_t *sig_size) { tx_size = digest_size + 12; if (tx_size > sizeof(tx_buffer)) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -576,12 +612,16 @@ optiga_result optiga_calc_sign(uint16_t oid, const uint8_t *digest, for (int i = 0; i < 2; ++i) { if (!der_reencode_int(&sig_reader, &sig_writer)) { + vcp_println("Error: OPTIGA_ERR_PROCESS, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PROCESS; } } if (buffer_remaining(&sig_reader) != 0) { // Unexpected trailing data. + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } @@ -600,6 +640,8 @@ optiga_result optiga_verify_sign(optiga_curve curve, const uint8_t *public_key, size_t sig_size) { tx_size = 17 + digest_size + sig_size + public_key_size; if (tx_size > sizeof(tx_buffer)) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -703,6 +745,8 @@ optiga_result optiga_calc_ssec(optiga_curve curve, uint16_t oid, static const size_t MAX_PUBKEY_SIZE = 5 + 2 * 66; if (public_key_size > MAX_PUBKEY_SIZE) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -747,10 +791,14 @@ optiga_result optiga_derive_key(optiga_key_derivation deriv, uint16_t oid, deriv == OPTIGA_DERIV_HKDF_SHA512); if (salt_size > 1024 || (!is_hkdf && salt_size < 8)) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } if (info_size > 256 || (!is_hkdf && info_size != 0)) { + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -848,6 +896,8 @@ optiga_result optiga_set_priv_key(uint16_t oid, const uint8_t priv_key[32]) { uint16_t payload_version = 0; if (metadata.version.ptr != NULL) { if (metadata.version.len != 2) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } payload_version = @@ -857,6 +907,8 @@ optiga_result optiga_set_priv_key(uint16_t oid, const uint8_t priv_key[32]) { if (payload_version > 23) { // CBOR integer encoding not implemented. + vcp_println("Error: OPTIGA_ERR_PARAM, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PARAM; } @@ -904,6 +956,8 @@ optiga_result optiga_set_priv_key(uint16_t oid, const uint8_t priv_key[32]) { if (0 != ecdsa_sign_digest(&nist256p1, TA_PRIV_KEY, digest, &sop_cmd1[81], NULL, NULL)) { memzero(sop_cmd2, sizeof(sop_cmd2)); + vcp_println("Error: OPTIGA_ERR_PROCESS, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PROCESS; } diff --git a/core/embed/trezorhal/optiga/optiga_transport.c b/core/embed/trezorhal/optiga/optiga_transport.c index e26076371..335877115 100644 --- a/core/embed/trezorhal/optiga/optiga_transport.c +++ b/core/embed/trezorhal/optiga/optiga_transport.c @@ -33,6 +33,8 @@ #include TREZOR_BOARD +void vcp_println(const char *fmt, ...); + // Maximum possible packet size that can be transmitted. #define OPTIGA_MAX_PACKET_SIZE (OPTIGA_DATA_REG_LEN - 5) @@ -197,6 +199,8 @@ static optiga_result optiga_i2c_write(const uint8_t *data, uint16_t data_size) { } hal_delay_us(1000); } + vcp_println("Error: OPTIGA_ERR_I2C_WRITE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_I2C_WRITE; } @@ -209,6 +213,8 @@ static optiga_result optiga_i2c_read(uint8_t *buffer, uint16_t buffer_size) { return OPTIGA_SUCCESS; } } + vcp_println("Error: OPTIGA_ERR_I2C_READ, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_I2C_READ; } @@ -260,6 +266,8 @@ static optiga_result optiga_check_ack(void) { optiga_result ret = OPTIGA_SUCCESS; if (frame_size != 3 || frame_buffer[0] != fctr || frame_buffer[1] != 0 || frame_buffer[2] != 0) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); ret = OPTIGA_ERR_UNEXPECTED; } @@ -290,6 +298,8 @@ static optiga_result optiga_ensure_ready(void) { // Not busy and no response that would need to be flushed out. return OPTIGA_SUCCESS; } + vcp_println("Eror: OPTIGA_ERR_BUSY, File: %s, Line: %d", __FILE__, + __LINE__); ret = OPTIGA_ERR_BUSY; } @@ -302,6 +312,8 @@ static optiga_result optiga_ensure_ready(void) { uint16_t size = (frame_buffer[2] << 8) + frame_buffer[3]; if (size > sizeof(frame_buffer)) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -316,6 +328,8 @@ static optiga_result optiga_ensure_ready(void) { } if (size < 3) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } @@ -338,11 +352,15 @@ static optiga_result optiga_ensure_ready(void) { } } + vcp_println("Error: OPTIGA_ERR_TIMEOUT, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_TIMEOUT; } optiga_result optiga_set_data_reg_len(size_t size) { if (size > 0xffff) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -365,6 +383,8 @@ optiga_result optiga_set_data_reg_len(size_t size) { } if ((frame_buffer[0] << 8) + frame_buffer[1] != size) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } return OPTIGA_SUCCESS; @@ -385,6 +405,8 @@ static optiga_result optiga_read(void) { if (frame_buffer[0] & I2C_STATE_BYTE1_RESP_RDY) { uint16_t size = (frame_buffer[2] << 8) + frame_buffer[3]; if (size > sizeof(frame_buffer)) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -400,6 +422,8 @@ static optiga_result optiga_read(void) { if (calc_crc(frame_buffer, size - 2) != (frame_buffer[size - 2] << 8) + frame_buffer[size - 1]) { + vcp_println("Error: OPTIGA_ERR_CRC, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_CRC; } @@ -412,10 +436,14 @@ static optiga_result optiga_read(void) { // Optiga has no response ready and is not busy. This shouldn't happen if // we are expecting to read a response, but Optiga occasionally fails to // give any response to a command. + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } } + vcp_println("Error: OPTIGA_ERR_TIMEOUT, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_TIMEOUT; } @@ -425,6 +453,8 @@ static optiga_result optiga_send_packet(uint8_t packet_control_byte, _Static_assert(sizeof(frame_buffer) - 7 >= OPTIGA_MAX_PACKET_SIZE - 1); if (packet_data_size > sizeof(frame_buffer) - 7) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -459,11 +489,15 @@ static optiga_result optiga_receive_packet(uint8_t *packet_control_byte, if (frame_size < 3 || frame_buffer[0] != fctr || *packet_data_size + 4 != frame_size) { frame_size = 0; + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } frame_size = 0; if (*packet_data_size > max_packet_data_size) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -597,6 +631,8 @@ optiga_result optiga_execute_command(const uint8_t *command_data, } sec_chan_size = command_size + SEC_CHAN_OVERHEAD_SIZE; if (sec_chan_size > sizeof(sec_chan_buffer)) { + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -617,6 +653,8 @@ optiga_result optiga_execute_command(const uint8_t *command_data, associated_data, sizeof(associated_data), command_data, command_size, SEC_CHAN_TAG_SIZE, ciphertext)) { + vcp_println("Error: OPTIGA_ERR_PROCESS, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PROCESS; } @@ -634,12 +672,16 @@ optiga_result optiga_execute_command(const uint8_t *command_data, sec_chan_buffer[0] != SCTR_PROTECTED || memcmp(&sec_chan_buffer[SEC_CHAN_SEQ_OFFSET], sec_chan_sseq, SEC_CHAN_SEQ_SIZE) != 0) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } *response_size = sec_chan_size - SEC_CHAN_OVERHEAD_SIZE; if (*response_size > max_response_size) { *response_size = 0; + vcp_println("Error: OPTIGA_ERR_SIZE, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_SIZE; } @@ -654,6 +696,8 @@ optiga_result optiga_execute_command(const uint8_t *command_data, ciphertext, *response_size + SEC_CHAN_TAG_SIZE, SEC_CHAN_TAG_SIZE, response_data)) { + vcp_println("Error: OPTIGA_ERR_PROCESS, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PROCESS; } @@ -676,6 +720,8 @@ optiga_result optiga_sec_chan_handshake(const uint8_t *secret, if (sec_chan_size != 2 + SEC_CHAN_RND_SIZE + SEC_CHAN_SEQ_SIZE || sec_chan_buffer[0] != SCTR_HELLO || sec_chan_buffer[1] != SEC_CHAN_PROTOCOL) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } @@ -709,6 +755,8 @@ optiga_result optiga_sec_chan_handshake(const uint8_t *secret, associated_data, sizeof(associated_data), payload, SEC_CHAN_HANDSHAKE_SIZE, SEC_CHAN_TAG_SIZE, ciphertext)) { + vcp_println("Error: OPTIGA_ERR_PROCESS, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_PROCESS; } @@ -723,6 +771,8 @@ optiga_result optiga_sec_chan_handshake(const uint8_t *secret, // Process response (sctr[1], mseq[4], ciphertext[44]). if (sec_chan_size != SEC_CHAN_HANDSHAKE_SIZE + SEC_CHAN_OVERHEAD_SIZE || sec_chan_buffer[0] != SCTR_FINISHED) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } uint8_t *mseq = &sec_chan_buffer[SEC_CHAN_SEQ_OFFSET]; @@ -738,12 +788,16 @@ optiga_result optiga_sec_chan_handshake(const uint8_t *secret, sizeof(associated_data), ciphertext, SEC_CHAN_HANDSHAKE_SIZE + SEC_CHAN_TAG_SIZE, SEC_CHAN_TAG_SIZE, response_payload)) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; } if (memcmp(response_payload, rnd, SEC_CHAN_RND_SIZE) != 0 || memcmp(response_payload + SEC_CHAN_RND_SIZE, mseq, SEC_CHAN_SEQ_SIZE) != 0) { + vcp_println("Error: OPTIGA_ERR_UNEXPECTED, File: %s, Line: %d", __FILE__, + __LINE__); return OPTIGA_ERR_UNEXPECTED; }