Fix/time driver race condition, fix BLE queries.

rust/src/embassy/time_driver.rs

@@ -57,10 +57,25 @@ static LAST_CLOCK_TIME: AtomicU32 = AtomicU32::new(0);
 /// to safely handle concurrent access without locks in the common case.
 ///
 /// # Algorithm
-/// 1. Read current hardware time and previously seen time
-/// 2. If current time < last time, we may have an overflow
-/// 3. Use a critical section to safely update the upper 32 bits if overflow confirmed
+/// 1. Inside a critical section (interrupts disabled), read the current hardware time
+///    and the previously seen time atomically together
+/// 2. If current time < last time, the 32-bit hardware counter has overflowed - increment
+///    the upper 32 bits to extend the counter
+/// 3. Update the last seen time
 /// 4. Return a combined 64-bit timestamp (upper 32 bits | lower 32 bits)
+///
+/// # Why clock_time() must be called inside the critical section
+///
+/// Previously, clock_time() was called BEFORE entering the critical section. This created
+/// a race condition: if a hardware interrupt fired between reading clock_time() and reading
+/// LAST_CLOCK_TIME, and that interrupt handler itself called clock_time64() (e.g. to step
+/// a light transition), it would update LAST_CLOCK_TIME to a newer value. When the
+/// interrupted code resumed, LAST_CLOCK_TIME was now genuinely larger than the stale
+/// current_time, so the code falsely detected a 32-bit overflow and incremented the upper
+/// bits. At 16-24 MHz this adds ~180-268 seconds to Instant::now() instantaneously, which
+/// blew past any in-progress transition timestamp and caused the light to snap to its final
+/// state. By reading clock_time() inside the critical section, interrupts are physically
+/// incapable of wedging themselves between the hardware read and the comparison.
 #[cfg_attr(test, mry::mry)]
 pub fn clock_time64() -> u64 {
     // When not testing, these static variables are defined here
@@ -70,38 +85,28 @@ pub fn clock_time64() -> u64 {
     #[cfg(not(test))]
     static LAST_CLOCK_TIME: AtomicU32 = AtomicU32::new(0);
 
-    // Get current hardware time
-    let current_time = clock_time();
-    let last_time = LAST_CLOCK_TIME.load(Ordering::Relaxed);
-
-    // Only enter critical section if we suspect an overflow
-    // (current time is less than last seen time)
-    if current_time < last_time {
-        critical_section::with(|_| {
-            // Re-check within critical section to avoid race conditions
-            // This prevents multiple threads from incrementing the upper bits
-            let last_time_cs = LAST_CLOCK_TIME.load(Ordering::Relaxed);
-            if current_time < last_time_cs {
-                // Overflow confirmed - increment upper bits
-                // Use load-modify-store instead of fetch_add since fetch_add might not be supported
-                // on all platforms or with all atomics implementations
-                let upper = CLOCK_TIME_UPPER.load(Ordering::Relaxed);
-                CLOCK_TIME_UPPER.store(upper + 1, Ordering::Relaxed);
-            }
-
-            // Update last time seen within the critical section
-            LAST_CLOCK_TIME.store(current_time, Ordering::Relaxed);
-        });
-    } else {
-        // Normal case (no overflow) - just update the last seen time
-        // This fast path avoids the critical section in most calls
+    critical_section::with(|_| {
+        // Read the hardware time inside the critical section so that no interrupt can update
+        // LAST_CLOCK_TIME between this read and the comparison below.
+        let current_time = clock_time();
+        let last_time = LAST_CLOCK_TIME.load(Ordering::Relaxed);
+
+        if current_time < last_time {
+            // Overflow confirmed - increment upper bits.
+            // Use load-modify-store instead of fetch_add since fetch_add might not be supported
+            // on all platforms or with all atomics implementations.
+            let upper = CLOCK_TIME_UPPER.load(Ordering::Relaxed);
+            CLOCK_TIME_UPPER.store(upper + 1, Ordering::Relaxed);
+        }
+
+        // Always update the last seen time so subsequent calls can detect the next overflow.
         LAST_CLOCK_TIME.store(current_time, Ordering::Relaxed);
-    }
 
-    // Combine upper and lower bits to form the 64-bit timestamp
-    // Upper 32 bits track number of overflows
-    // Lower 32 bits are the current hardware timer value
-    (CLOCK_TIME_UPPER.load(Ordering::Relaxed) as u64) << 32 | current_time as u64
+        // Combine upper and lower bits to form the 64-bit timestamp.
+        // Upper 32 bits track the number of overflows.
+        // Lower 32 bits are the current hardware timer value.
+        (CLOCK_TIME_UPPER.load(Ordering::Relaxed) as u64) << 32 | current_time as u64
+    })
 }
 
 #[cfg(test)]

rust/src/main_light.rs

@@ -272,7 +272,7 @@ pub fn rf_link_response_callback(ppp: &mut PacketAttValue, p_req: &PacketAttValu
     let group_address = GROUP_ADDRESS.lock();
 
     let mut idx = 0;
-    match p_req.val[15] {
+    match ppp.val[15] {
         GET_STATUS => {
             ppp.val[0] = LGT_CMD_LIGHT_STATUS | 0xc0;
 
@@ -1103,9 +1103,9 @@ mod tests {
 
         let mut request = create_test_packet_att_value();
         request.src = [0x56, 0x78];
-        request.val[15] = GET_GROUP1;
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = GET_GROUP1;
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);
@@ -1134,9 +1134,9 @@ mod tests {
 
         let mut request = create_test_packet_att_value();
         request.src = [0x56, 0x78];
-        request.val[15] = GET_GROUP2;
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = GET_GROUP2;
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);
@@ -1169,9 +1169,9 @@ mod tests {
 
         let mut request = create_test_packet_att_value();
         request.src = [0x56, 0x78];
-        request.val[15] = GET_GROUP3;
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = GET_GROUP3;
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);
@@ -1194,9 +1194,9 @@ mod tests {
 
         let mut request = create_test_packet_att_value();
         request.src = [0x56, 0x78];
-        request.val[15] = GET_DEV_ADDR;
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = GET_DEV_ADDR;
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);
@@ -1216,9 +1216,9 @@ mod tests {
 
         let mut request = create_test_packet_att_value();
         request.src = [0x56, 0x78];
-        request.val[15] = GET_USER_NOTIFY;
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = GET_USER_NOTIFY;
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);
@@ -1248,9 +1248,9 @@ mod tests {
 
         let mut request = create_test_packet_att_value();
         request.src = [0x56, 0x78];
-        request.val[15] = CMD_START_OTA;
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = CMD_START_OTA;
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);
@@ -1284,9 +1284,9 @@ mod tests {
 
         let mut request = create_test_packet_att_value();
         request.src = [0xAA, 0xBB];
-        request.val[15] = CMD_OTA_DATA;
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = CMD_OTA_DATA;
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);
@@ -1317,9 +1317,9 @@ mod tests {
 
         let mut request = create_test_packet_att_value();
         request.src = [0xCC, 0xDD];
-        request.val[15] = CMD_END_OTA;
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = CMD_END_OTA;
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);
@@ -1342,9 +1342,9 @@ mod tests {
         DEVICE_ADDRESS.set(0x1234);
 
         let mut request = create_test_packet_att_value();
-        request.val[15] = 0xFF; // Invalid command
 
         let mut response = create_test_packet_att_value();
+        response.val[15] = 0xFF; // Invalid command
 
         // Execute
         let result = rf_link_response_callback(&mut response, &request);

rust/src/sdk/ble_app/light_ll/packet_processing.rs

@@ -580,11 +580,11 @@ pub fn rf_link_slave_add_status(packet: &Packet) {
     // Copy the source address (2 bytes)
     let src_bytes = packet.mesh().src_adr.to_le_bytes();
     st_ptr.att_data_mut().dat[5..7].copy_from_slice(&src_bytes);
+    // Copy the operation code (1 byte) — op precedes vendor_id in the mesh packet layout
+    st_ptr.att_data_mut().dat[7] = packet.mesh().op;
     // Copy the vendor ID (2 bytes)
     let vendor_bytes = packet.mesh().vendor_id.to_le_bytes();
-    st_ptr.att_data_mut().dat[7..9].copy_from_slice(&vendor_bytes);
-    // Copy the operation code (1 byte)
-    st_ptr.att_data_mut().dat[9] = packet.mesh().op;
+    st_ptr.att_data_mut().dat[8..10].copy_from_slice(&vendor_bytes);
     // Copy the parameters (10 bytes)
     st_ptr.att_data_mut().dat[10..20].copy_from_slice(&packet.mesh().par);
 
@@ -2111,8 +2111,70 @@ mod tests {
         );
     }
 
-    // ================================================================================
-    // Tests for is_add_packet_buf_ready function
+    /// Tests that the assembled BLE notification packet has op at dat[7] and
+    /// vendor_id at dat[8..10], matching the mesh packet memory layout and the
+    /// format expected by the Python client's decrypt_notification parser.
+    #[test]
+    #[mry::lock()]
+    fn test_rf_link_slave_add_status_packet_layout() {
+        reset_test_state();
+        SLAVE_READ_STATUS_BUSY.set(LGT_CMD_LIGHT_STATUS); // allow notify req mask
+
+        let mut packet = create_test_packet(
+            LGT_CMD_LIGHT_STATUS | 0xc0,
+            [0xAA, 0xBB, 0xCC],
+            0x001F, // src_adr = 31
+            0x0000, // dst_adr
+        );
+        // Set known par values so we can verify them in the output
+        packet.att_cmd_mut().value.val[3] = 0x11; // par[0] = CW lo
+        packet.att_cmd_mut().value.val[4] = 0x22; // par[1] = CW hi
+
+        rf_link_slave_add_status(&packet);
+
+        assert_eq!(
+            DEVICE_STATUS_BUFFER_WRITE_POINTER.get(),
+            1,
+            "Write pointer should advance"
+        );
+
+        let buf = BUFF_RESPONSE.lock();
+        let st = &buf[0];
+
+        // dat[0..3] = sno
+        assert_eq!(
+            &st.att_data().dat[0..3],
+            &[0xAA, 0xBB, 0xCC],
+            "sno mismatch"
+        );
+        // dat[3..5] = src_adr (overwritten from dst then from src at the end)
+        assert_eq!(st.att_data().dat[3], 0x1F, "src_adr low byte");
+        assert_eq!(st.att_data().dat[4], 0x00, "src_adr high byte");
+        // dat[5..7] = src_adr (original src copy)
+        assert_eq!(st.att_data().dat[5], 0x1F, "dat[5] src low");
+        assert_eq!(st.att_data().dat[6], 0x00, "dat[6] src high");
+        // dat[7] = op — MUST come before vendor_id so Python parser reads it at index 0
+        // of the decrypted payload (after sno+src+mic are stripped)
+        assert_eq!(
+            st.att_data().dat[7],
+            LGT_CMD_LIGHT_STATUS | 0xc0,
+            "dat[7] must be opcode (not vendor_id)"
+        );
+        // dat[8..10] = vendor_id (little-endian)
+        assert_eq!(
+            st.att_data().dat[8],
+            (VENDOR_ID & 0xFF) as u8,
+            "vendor_id lo"
+        );
+        assert_eq!(
+            st.att_data().dat[9],
+            ((VENDOR_ID >> 8) & 0xFF) as u8,
+            "vendor_id hi"
+        );
+        // dat[10..12] = first two par bytes
+        assert_eq!(st.att_data().dat[10], 0x11, "par[0] = CW lo");
+        assert_eq!(st.att_data().dat[11], 0x22, "par[1] = CW hi");
+    }
     // ================================================================================
 
     /// Tests transmission buffer ready status with empty buffer.

rust/src/version.rs

@@ -1 +1 @@
-pub static BUILD_VERSION: u32 = 3515;
+pub static BUILD_VERSION: u32 = 3518;

sdk/version.in

@@ -1,2 +1,2 @@
-.equ BUILD_VERSION,3515
+.equ BUILD_VERSION,3517
 .equ XTAL_16MHZ,0