Add instrumentation
diff --git a/services/i2c/backend-aspeed/src/lib.rs b/services/i2c/backend-aspeed/src/lib.rs index e79831e..63f9802 100644 --- a/services/i2c/backend-aspeed/src/lib.rs +++ b/services/i2c/backend-aspeed/src/lib.rs
@@ -548,6 +548,8 @@ // Polling loop — spins until a relevant event or budget exhausted. // At 200 MHz, ~10_000 iterations ≈ a few hundred microseconds. const POLL_BUDGET: usize = 10_000; + // Track whether any non-idle HW event was seen before budget expires. + let mut saw_hw_event = false; for _ in 0..POLL_BUDGET { match i2c.handle_slave_interrupt() { Some(SlaveEvent::DataReceived { len: _ }) => { @@ -560,10 +562,12 @@ } Some(SlaveEvent::WriteRequest) | Some(SlaveEvent::ReadRequest) => { // Transaction in progress — keep polling for data. + saw_hw_event = true; continue; } Some(SlaveEvent::DataSent { len: _ }) => { // Master read from us; not relevant for receive path. + saw_hw_event = true; continue; } None => { @@ -573,6 +577,12 @@ } } + if saw_hw_event { + pw_log::warn!( + "slave_receive bus={}: budget exhausted after HW event (partial txn?)", + bus as u32, + ); + } Err(ResponseCode::Timeout) }
diff --git a/services/i2c/server/src/main.rs b/services/i2c/server/src/main.rs index b34ebee..02743ac 100644 --- a/services/i2c/server/src/main.rs +++ b/services/i2c/server/src/main.rs
@@ -293,7 +293,19 @@ } else { // Blocking poll: spins in the backend until DataReceived or timeout. match backend.slave_receive(header.bus, buf) { - Ok(n) => encode_success(response, n), + Ok(0) => { + pw_log::info!("slave_receive bus={}: Stop (0 bytes)", header.bus as u32); + encode_success(response, 0) + } + Ok(n) => { + pw_log::info!( + "slave_receive bus={}: received {} bytes", + header.bus as u32, + n as u32, + ); + encode_success(response, n) + } + Err(ResponseCode::Timeout) => encode_success(response, 0), Err(code) => encode_error(response, code), } }
diff --git a/services/mctp/server/src/main.rs b/services/mctp/server/src/main.rs index 9cb6993..125a92e 100644 --- a/services/mctp/server/src/main.rs +++ b/services/mctp/server/src/main.rs
@@ -189,7 +189,7 @@ { pw_log::info!("MCTP server: registering SPDM listener (msg_type=0x05)"); if transport.init_sequence().is_err() { - pw_log::error!("MCTP server: SPDM transport init_sequence failed — \ + pw_log::error!("MCTP server: S PDM transport init_sequence failed — \ listener(0x05) rejected; router listener table may be full"); return Err(pw_status::Error::Internal); } @@ -315,6 +315,7 @@ #[cfg(feature = "direct-client")] let mut spdm_err: u32 = 0; let mut i2c_pkt: u32 = 0; + let mut idle_polls: u32 = 0; pw_log::info!("MCTP server ready, polling for I2C packets"); @@ -325,14 +326,41 @@ match i2c.wait_for_messages(BusIndex::BUS_2, &mut msgs, None) { Ok(n) => { for msg in msgs.get(..n).unwrap_or(&[]) { + // Log the raw I2C frame before decode so we can confirm + // the hardware actually delivered a well-formed SMBus frame. + // Format: dest_addr cmd byte_count src_addr | MCTP hdr[0..3] + let raw = msg.data(); + if raw.len() >= 8 { + pw_log::info!( + "I2C frame raw: dest=0x{:02x} cmd=0x{:02x} bc={} src=0x{:02x} \ + | mctp: ver=0x{:02x} deid=0x{:02x} seid=0x{:02x} flags=0x{:02x} \ + len={}", + raw[0] as u32, raw[1] as u32, raw[2] as u32, raw[3] as u32, + raw[4] as u32, raw[5] as u32, raw[6] as u32, raw[7] as u32, + raw.len() as u32, + ); + } else { + pw_log::warn!( + "I2C frame too short ({} bytes) to contain MCTP header", + raw.len() as u32, + ); + } + match receiver.decode(msg) { Ok((pkt, src_addr)) => { i2c_pkt = i2c_pkt.wrapping_add(1); - pw_log::debug!( - "MCTP server: I2C pkt #{} src=0x{:02x} len={}", + // Log MCTP packet fields: SOM/EOM from flags byte (pkt[3]) + let som = pkt.get(3).map_or(0u8, |b| (b >> 7) & 1); + let eom = pkt.get(3).map_or(0u8, |b| (b >> 6) & 1); + let seq = pkt.get(3).map_or(0u8, |b| (b >> 4) & 0x3); + let msg_type = pkt.get(4).map_or(0u8, |b| b & 0x7f); + pw_log::info!( + "MCTP pkt #{}: src_i2c=0x{:02x} len={} \ + SOM={} EOM={} seq={} msg_type=0x{:02x}", i2c_pkt as u32, src_addr as u32, pkt.len() as u32, + som as u32, eom as u32, seq as u32, msg_type as u32, ); if let Err(e) = server.borrow_mut().inbound(pkt) { inbound_err = inbound_err.wrapping_add(1); @@ -359,6 +387,19 @@ } } } + Err(e) if e.is_timeout() => { + // Timeout is the normal "no frame yet" result from the backend's + // poll-budget loop — not a real error. Just proceed to Phase 2 + // (SPDM responder poll) and loop again. + idle_polls = idle_polls.wrapping_add(1); + if idle_polls & 0xfff == 0 { + pw_log::info!( + "MCTP alive: idle_polls={} pkts={}", + idle_polls as u32, + i2c_pkt as u32, + ); + } + } Err(_) => { i2c_recv_err = i2c_recv_err.wrapping_add(1); if i2c_recv_err == 1 || i2c_recv_err & 0xf == 0 {