Add tracing

4 files changed, 38 insertions, 6 deletions

diff --git a/hexnoise.py b/hexnoise.py
index 8a8dae5..cfbe9df 100755
--- a/hexnoise.py
+++ b/hexnoise.py
@@ -277,7 +277,7 @@ class NoiseEngine:
         with suppress(NoiseInvalidMessage):
             yield setter
 
-        proto.noise_protocol.cipher_state_decrypt.n = nold
+        self.proto.noise_protocol.cipher_state_decrypt.n = nold
 
     def pairing_messages(self):
         user_input = ''
@@ -309,12 +309,11 @@ class NoiseEngine:
 
                 if msg_type is ReportType.KEYBOARD:
                     modbyte, _reserved, *keycodes = report
-                    print('    payload:', payload)
-                    print('    modifier:', list(KeyMapper.map_modifiers(modbyte)))
-                    print('    regular:', list(KeyMapper.map_regulars(keycodes)))
+                    import binascii
                     keys = { *KeyMapper.map_modifiers(modbyte), *KeyMapper.map_regulars(keycodes) }
                     if self.debug:
                         print('Emitting:', keys)
+                    print('payload:', binascii.hexlify(payload), 'emitting:', keys)
 
                     for key in keys - old_kcs:
                         ui.emit(key, 1, syn=False)
diff --git a/src/demo.c b/src/demo.c
index c176f25..8f51b54 100644
--- a/src/demo.c
+++ b/src/demo.c
@@ -30,6 +30,7 @@
 #include "noise.h"

 #include "hid_keycodes.h"

 #include "words.h"

+#include "tracing.h"

 

 #include <libopencm3/stm32/rcc.h>

 #include <libopencm3/stm32/gpio.h>

@@ -70,6 +71,7 @@ static void clock_setup(void) {
 	rcc_clock_setup_hse_3v3(&hse_8mhz_3v3[CLOCK_3V3_168MHZ]);

 

 	rcc_periph_clock_enable(RCC_GPIOA);

+	rcc_periph_clock_enable(RCC_GPIOD);

 	rcc_periph_clock_enable(RCC_GPIOE);

 

 	rcc_periph_clock_enable(RCC_USART1);

@@ -103,6 +105,9 @@ static uint32_t tim6_get_time_us(void)
 

 static void gpio_setup(void)

 {

+    /* Tracing */

+	gpio_mode_setup(GPIOD, GPIO_MODE_OUTPUT, GPIO_PUPD_NONE, 0xffff);

+

     /* D2, D3 LEDs */

 	gpio_mode_setup(GPIOA, GPIO_MODE_OUTPUT, GPIO_PUPD_NONE, GPIO6 | GPIO7);

 	gpio_set(GPIOA, GPIO6 | GPIO7);

@@ -294,8 +299,10 @@ void pairing_parse_report(struct hid_report *buf, uint8_t len) {
 }

 

 static void hid_in_message_handler(uint8_t device_id, const uint8_t *data, uint32_t length) {

+    TRACING_SET(TR_HID_MESSAGE_HANDLER);

 	if (length < 4 || length > 8) {

 		LOG_PRINTF("HID report length must be 4 < len < 8, is %d bytes\n", length);

+        TRACING_CLEAR(TR_HID_MESSAGE_HANDLER);

 		return;

 	}

 

@@ -303,6 +310,7 @@ static void hid_in_message_handler(uint8_t device_id, const uint8_t *data, uint3
 	int type = hid_get_type(device_id);

     if (type != HID_TYPE_KEYBOARD && type != HID_TYPE_MOUSE) {

         LOG_PRINTF("Unsupported HID report type %x\n", type);

+        TRACING_CLEAR(TR_HID_MESSAGE_HANDLER);

         return;

     }

 

@@ -311,6 +319,7 @@ static void hid_in_message_handler(uint8_t device_id, const uint8_t *data, uint3
             pairing_parse_report((struct hid_report *)data, length);

         else

             LOG_PRINTF("Not sending HID mouse report during pairing\n");

+        TRACING_CLEAR(TR_HID_MESSAGE_HANDLER);

         return;

     }

 

@@ -325,8 +334,10 @@ static void hid_in_message_handler(uint8_t device_id, const uint8_t *data, uint3
 

     if (send_encrypted_message(&noise_state, (uint8_t *)&pkt, sizeof(pkt))) {

         LOG_PRINTF("Error sending HID report packet\n");

+        TRACING_CLEAR(TR_HID_MESSAGE_HANDLER);

         return;

     }

+    TRACING_CLEAR(TR_HID_MESSAGE_HANDLER);

 }

 

 volatile struct {

@@ -346,9 +357,11 @@ struct dma_usart_file debug_out_s = {
 struct dma_usart_file *debug_out = &debug_out_s;

 

 void DMA_ISR(DEBUG_USART_DMA_NUM, DEBUG_USART_DMA_STREAM_NUM)(void) {

+    TRACING_SET(TR_DEBUG_OUT_DMA_IRQ);

     if (dma_get_interrupt_flag(debug_out->dma, debug_out->stream, DMA_FEIF)) {

         /* Ignore FIFO errors as they're 100% non-critical for UART applications */

         dma_clear_interrupt_flags(debug_out->dma, debug_out->stream, DMA_FEIF);

+        TRACING_CLEAR(TR_DEBUG_OUT_DMA_IRQ);

         return;

     }

 

@@ -357,6 +370,7 @@ void DMA_ISR(DEBUG_USART_DMA_NUM, DEBUG_USART_DMA_STREAM_NUM)(void) {
 

     if (debug_out->buf->wr_pos != debug_out->buf->xfr_end) /* buffer not empty */

         schedule_dma(debug_out);

+    TRACING_CLEAR(TR_DEBUG_OUT_DMA_IRQ);

 }

 

 

@@ -401,8 +415,11 @@ int main(void)
         LOG_PRINTF("Error generating identiy key\n");

 

 	while (23) {

+        TRACING_SET(TR_USBH_POLL);

 		usbh_poll(tim6_get_time_us());

+        TRACING_CLEAR(TR_USBH_POLL);

 

+        TRACING_SET(TR_HOST_PKT_HANDLER);

         if (host_packet_length > 0) {

             struct control_packet *pkt = (struct control_packet *)host_packet_buf;

             size_t payload_length = host_packet_length - 1;

@@ -427,11 +444,13 @@ int main(void)
                 }

             } else if (pkt->type == HOST_HANDSHAKE) {

                 LOG_PRINTF("Handling handshake packet of length %d\n", payload_length);

+                TRACING_SET(TR_NOISE_HANDSHAKE);

                 if (try_continue_noise_handshake(&noise_state, pkt->payload, payload_length)) {

+                    TRACING_CLEAR(TR_NOISE_HANDSHAKE);

                     LOG_PRINTF("Reporting handshake error to host\n");

                     struct control_packet out = { .type=HOST_CRYPTO_ERROR };

                     send_packet(usart2_out, (uint8_t *)&out, sizeof(out));

-                }

+                } else TRACING_CLEAR(TR_NOISE_HANDSHAKE);

                 host_packet_length = 0; /* Acknowledge to USART ISR the buffer has been handled */

 

             } else {

@@ -453,13 +472,16 @@ int main(void)
                 pairing_buf_pos = 0; /* Reset channel binding keyboard input buffer */

             }

         }

+        TRACING_CLEAR(TR_HOST_PKT_HANDLER);

 

         if (noise_state.handshake_state == HANDSHAKE_IN_PROGRESS) {

+            TRACING_SET(TR_NOISE_HANDSHAKE);

             if (try_continue_noise_handshake(&noise_state, NULL, 0)) { /* handle outgoing messages */

+                TRACING_CLEAR(TR_NOISE_HANDSHAKE);

                 LOG_PRINTF("Reporting handshake error to host\n");

                 struct control_packet pkt = { .type=HOST_CRYPTO_ERROR };

                 send_packet(usart2_out, (uint8_t *)&pkt, sizeof(pkt));

-            }

+            } else TRACING_CLEAR(TR_NOISE_HANDSHAKE);

         }

 	}

 }

diff --git a/src/packet_interface.c b/src/packet_interface.c
index 319ddd1..441fff9 100644
--- a/src/packet_interface.c
+++ b/src/packet_interface.c
@@ -2,6 +2,7 @@
 #include "packet_interface.h"
 #include "noise.h"
 #include "cobs.h"
+#include "tracing.h"
 
 #include <libopencm3/stm32/usart.h>
 #include <libopencm3/stm32/dma.h>
@@ -25,11 +26,13 @@ struct dma_usart_file usart2_out_s = {
 struct dma_usart_file *usart2_out = &usart2_out_s;
 
 void dma1_stream6_isr(void) {
+    TRACING_SET(TR_HOST_IF_DMA_IRQ);
     static unsigned int fifo_errors = 0; /* debug */
     if (dma_get_interrupt_flag(usart2_out->dma, usart2_out->stream, DMA_FEIF)) {
         /* Ignore FIFO errors as they're 100% non-critical for UART applications */
         dma_clear_interrupt_flags(usart2_out->dma, usart2_out->stream, DMA_FEIF);
         fifo_errors++;
+        TRACING_CLEAR(TR_HOST_IF_DMA_IRQ);
         return;
     }
 
@@ -38,15 +41,18 @@ void dma1_stream6_isr(void) {
 
     if (usart2_out->buf->wr_pos != usart2_out->buf->xfr_end) /* buffer not empty */
         schedule_dma(usart2_out);
+    TRACING_CLEAR(TR_HOST_IF_DMA_IRQ);
 }
 
 void usart2_isr(void) {
+    TRACING_SET(TR_HOST_IF_USART_IRQ);
     static struct cobs_decode_state host_cobs_state = {0};
     if (USART2_SR & USART_SR_ORE) { /* Overrun handling */
         LOG_PRINTF("USART2 data register overrun\n");
         /* Clear interrupt flag */
         (void)USART2_DR; /* FIXME make sure this read is not optimized out */
         host_packet_length = -1;
+        TRACING_CLEAR(TR_HOST_IF_USART_IRQ);
         return;
     }
 
@@ -55,6 +61,7 @@ void usart2_isr(void) {
     if (host_packet_length) {
         LOG_PRINTF("USART2 COBS buffer overrun\n");
         host_packet_length = -1;
+        TRACING_CLEAR(TR_HOST_IF_USART_IRQ);
         return;
     }
 
@@ -70,6 +77,7 @@ void usart2_isr(void) {
     } else if (rv > 0) {
         host_packet_length = rv;
     } /* else just return and wait for next byte */
+    TRACING_CLEAR(TR_HOST_IF_USART_IRQ);
 }
 
 void send_packet(struct dma_usart_file *f, const uint8_t *data, size_t len) {
diff --git a/src/rand_stm32.c b/src/rand_stm32.c
index 03aa98f..87bea8f 100644
--- a/src/rand_stm32.c
+++ b/src/rand_stm32.c
@@ -42,6 +42,7 @@
 
 #include "usart_helpers.h"
 #include "rand_stm32.h"
+#include "tracing.h"
 
 #include "crypto/noise-c/src/protocol/internal.h"
 #include "crypto/noise-c/src/crypto/blake2/blake2s.h"
@@ -93,6 +94,7 @@ const char *extraction_constant = "Blake2 RNG extraction constant";
 const char *chain_constant = "Blake2 RNG chaining constant";
 
 void noise_rand_bytes(void *bytes, size_t size) {
+    TRACING_SET(TR_RNG);
     BLAKE2s_context_t out_ctx, chain_ctx;
     uint8_t *out = (uint8_t *)bytes;
     uint8_t hash_buf[BLAKE2S_HASH_SIZE];
@@ -123,6 +125,7 @@ void noise_rand_bytes(void *bytes, size_t size) {
     memset(&out_ctx, 0, sizeof(out_ctx));
     memset(&chain_ctx, 0, sizeof(chain_ctx));
     memset(hash_buf, 0, sizeof(hash_buf));
+    TRACING_CLEAR(TR_RNG);
 }
 
 #ifdef ED25519_CUSTOMRANDOM /* We are building against ed25519-donna, which needs a random function */