debug(core): log optiga errors

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;
   }
 

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;
   }