fix multi tech timings in the trace list. 'hf iclass sam' or 'hf seos sam'

armsrc/BigBuf.c

@@ -76,6 +76,13 @@ static dmabuf8_t s_dma_8 = {
 static uint32_t s_trace_len = 0;
 static bool s_tracing = true;
 
+static uint32_t s_trace_origin = 0;
+static bool s_trace_origin_valid = false;
+
+void trace_restart_timeline(void) {
+    s_trace_origin_valid = false;
+}
+
 // compute the available size for BigBuf
 void BigBuf_initialize(void) {
     s_bigbuf_size = (uint32_t)_stack_start - (uint32_t)__bss_end__;
@@ -215,6 +222,7 @@ uint16_t BigBuf_max_traceLen(void) {
 
 void clear_trace(void) {
     s_trace_len = 0;
+    trace_restart_timeline();
 }
 
 void set_tracelen(uint32_t value) {
@@ -264,8 +272,16 @@ bool RAMFUNC LogTrace(const uint8_t *btBytes, uint16_t iLen, uint32_t timestamp_
         return false;
     }
 
+    // the first frame of a phase is the zero the rest of it is measured from
+    if ((s_trace_origin_valid == false) || (timestamp_start < s_trace_origin)) {
+        s_trace_origin = timestamp_start;
+        s_trace_origin_valid = true;
+    }
+    timestamp_start -= s_trace_origin;
+    timestamp_end -= s_trace_origin;
+
     uint32_t duration;
-    if (timestamp_end > timestamp_start) {
+    if (timestamp_end >= timestamp_start) {
         duration = timestamp_end - timestamp_start;
     } else {
         duration = (UINT32_MAX - timestamp_start) + timestamp_end;

armsrc/BigBuf.h

@@ -58,6 +58,8 @@ void set_tracing(bool enable);
 void set_tracelen(uint32_t value);
 bool get_tracing(void);
 
+void trace_restart_timeline(void);
+
 bool RAMFUNC LogTrace(const uint8_t *btBytes, uint16_t iLen, uint32_t timestamp_start, uint32_t timestamp_end, const uint8_t *parity, bool reader2tag);
 bool RAMFUNC LogTraceBits(const uint8_t *btBytes, uint16_t bitLen, uint32_t timestamp_start, uint32_t timestamp_end, bool reader2tag);
 bool LogTrace_ISO15693(const uint8_t *bytes, uint16_t len, uint32_t ts_start, uint32_t ts_end, const uint8_t *parity, bool reader2tag);

armsrc/i2c.c

@@ -168,6 +168,7 @@ void I2C_Reset_EnterMainProgram(void) {
     s_proto_announced = false;
     s_pps_proto_cmd = 0;
     StartTicks();
+    sc_log_trace_reset();
     I2C_init(true);
     I2C_SetResetStatus(0, 0, 0);
     WaitMS(30);
@@ -864,17 +865,27 @@ int I2C_get_version(uint8_t *major, uint8_t *minor) {
     return PM3_EDEVNOTSUPP;
 }
 
-// Will read response from smart card module,  retries 3 times to get the data.
 static uint32_t s_trace_tick = 0;
+static bool s_trace_tick_valid = false;
 
 void sc_log_trace_reset(void) {
-    s_trace_tick = GetTicks();
+    s_trace_tick_valid = false;
 }
 
+void sc_log_trace_span(const uint8_t *d, uint16_t len, bool reader2tag, uint32_t start) {
+    uint32_t now = GetTicks();
+    LogTrace(d, len, start, now, NULL, reader2tag);
+    s_trace_tick = now;
+    s_trace_tick_valid = true;
+}
+
+// A frame that can only be timed from the end of the one before - the card's
+// answer, which is not known to have arrived until it has been read.
 void sc_log_trace(const uint8_t *d, uint16_t len, bool reader2tag) {
     uint32_t now = GetTicks();
-    if (s_trace_tick == 0) {
+    if (s_trace_tick_valid == false) {
         s_trace_tick = now;
+        s_trace_tick_valid = true;
     }
     LogTrace(d, len, s_trace_tick, now, NULL, reader2tag);
     s_trace_tick = now;

armsrc/i2c.h

@@ -142,6 +142,7 @@ void sc_request_sam_t1_profile(void);
 // the previous frame ended, so a Tag frame's span is how long the card took to
 // answer and a Rdr frame's is how long the host took to ask.
 void sc_log_trace(const uint8_t *d, uint16_t len, bool reader2tag);
+void sc_log_trace_span(const uint8_t *d, uint16_t len, bool reader2tag, uint32_t start);
 void sc_log_trace_reset(void);
 
 bool sc_rx_bytes(uint8_t *dest, uint16_t *destlen, uint32_t wait);

armsrc/sam_common.c

@@ -218,7 +218,10 @@ int sam_rxtx(const uint8_t *data, uint16_t n, uint8_t *resp, uint16_t *resplen)
     const uint8_t dev_cmd = active_cmd;
 #endif
 
+    uint32_t tx_start = GetTicks();
     bool res = I2C_BufferWrite(data, n, dev_cmd, I2C_DEVICE_ADDRESS_MAIN);
+    sc_log_trace_span(data, n, true, tx_start);
+
     if (res == false) {
         DbpString("failed to send to SIM CARD");
         goto out;
@@ -282,12 +285,11 @@ int sam_rxtx(const uint8_t *data, uint16_t n, uint8_t *resp, uint16_t *resplen)
                                 0x00, (uint8_t)(want >> 8), (uint8_t)want};
     const uint8_t *cmd_getresp = t1 ? cmd_getresp_t1 : cmd_getresp_t0;
     const uint16_t cmd_getresp_len = t1 ? sizeof(cmd_getresp_t1) : sizeof(cmd_getresp_t0);
-    sc_log_trace(cmd_getresp, cmd_getresp_len, true);
 
-    // Keep response assembly at the PM3, and use the ordinary active protocol
-    // opcode for the continuation rather than recursively selecting the
-    // compatibility alias.
+    tx_start = GetTicks();
     res = I2C_BufferWrite(cmd_getresp, cmd_getresp_len, active_cmd, I2C_DEVICE_ADDRESS_MAIN);
+    sc_log_trace_span(cmd_getresp, cmd_getresp_len, true, tx_start);
+
     if (res == false) {
         DbpString("failed to send to SIM CARD 2");
         goto out;
@@ -307,14 +309,21 @@ out:
     return res;
 }
 
+// The tick counter and the ssp_clk counter share the same timer block, so a SAM
+// session can only ever run one of them, and every handover starts the incoming
+// counter from zero.  The trace holds both halves, so each technology's frames
+// are timed from the moment that technology took the timer over
 void switch_clock_to_ticks(void) {
     StopTicks();
     StartTicks();
+    sc_log_trace_reset();
+    trace_restart_timeline();
 }
 
 void switch_clock_to_countsspclk(void) {
     StopTicks();
     StartCountSspClk();
+    trace_restart_timeline();
 }
 
 /**
@@ -411,7 +420,6 @@ int sam_send_payload_ex(
         buf[length++] = 0x00;
     }
 
-    sc_log_trace(buf, length, true);
     if (g_dbglevel >= DBG_INFO) {
         DbpString("SAM REQUEST APDU: ");
         Dbhexdump(length, buf, false);