I2C transaction_async gets ArbitrationLost error when preempted while an equivalent write_async operation does not

[ajwock]

Bug description

I'm using the esp_rust devboard, so this bug should be reproducible on common hardware. https://github.com/esp-rs/esp-rust-board

With what appears to be two equivalent ways of expressing an async burst write transaction with the esp hal, one of them gets an ArbitrationLost error when preempted. Without the preemption which is imposed by async wifi startup tasks in the example below, both versions work.

The transaction_async version ends up issuing two separate transactions via hardware. I'm not sure why exactly arbitration gets lost here, but this same issue may be possible for other ops like write_read_async where the driver trades control with hardware multiple times for a given transaction.

Regarding hal source, it doesn't appear the i2c master driver takes full advantage of the hardware command fifo for the write_read and transaction cases. I suspect this costs reliability under cpu load.

To Reproduce

These are two different versions of the functions which I wrote for burst writes to the icm42670 imu peripheral. I wrote the original version to avoid some copy logic.

     async fn burst_write_regs(&mut self, start_address: u8, reg_vals: &[u8]) {
     self.comm.transaction_async(ACCEL_ADDRESS, &mut [Operation::Write(&[start_address]), Operation::Write(reg_vals)])
             .await
             .expect(format!("Failed to burst write vals {:?} to registers starting at {}", reg_vals, start_address).as_str());
     }

    async fn burst_write_regs(&mut self, start_address: u8, reg_vals: &[u8]) {
        let mut to_write = SmallVec::<[u8; 32]>::new();
        to_write.push(start_address);
        to_write.extend_from_slice(reg_vals);
        self.comm.write_async(ACCEL_ADDRESS, to_write.as_slice())
            .await
            .expect(format!("Failed to burst write vals {:?} to registers starting at {}", reg_vals, start_address).as_str());
    }

Here is a somewhat reduced version of the failure. Though preemption bugs aren't often hard failures, this seems to do it 100% of the time on my board.

Excuse the overall length- I was expanding upon the embassy AP example while also trying to configure the IMU. It may be possible to get it to preempt with far less excess code.

icm42670.rs

use esp_hal::i2c::master::{I2c, Operation};
use esp_hal::Async;
use alloc::format;
use esp_println::println;

// 7 bit address of the accelerometer
pub(crate) const ACCEL_ADDRESS: u8 = 0b1101000;

pub(crate) struct Icm42670<'a> {
    comm: I2c<'a, Async>,
}

impl<'a> Icm42670<'a> {
    pub(crate) fn new(i2c: I2c<'a, Async>) -> Self {
        Self {
            comm: i2c,
        }
    }

    async fn write_reg(&mut self, reg_address: u8, val: u8) {
        self.comm.write_async(ACCEL_ADDRESS, &[reg_address, val])
            .await
            .expect(format!("Failed to write val {} to register {}", val, reg_address).as_str());
    }

    async fn burst_write_regs(&mut self, start_address: u8, reg_vals: &[u8]) {
        self.comm.transaction_async(ACCEL_ADDRESS, &mut [Operation::Write(&[start_address]), Operation::Write(reg_vals)])
            .await
            .expect(format!("Failed to burst write vals {:?} to registers starting at {}", reg_vals, start_address).as_str());
    }

    // Registers have an 8-bit address
    async fn read_reg(&mut self, reg_address: u8) -> u8 {
        let mut datum = 0;
        self.comm.write_read_async(ACCEL_ADDRESS, &[reg_address], core::slice::from_mut(&mut datum))
            .await
            .expect(format!("Failed to read register {}", reg_address).as_str());
        datum
    }

    async fn burst_read_regs(&mut self, start_address: u8, regs_out: &mut [u8]) {
        self.comm.write_read_async(ACCEL_ADDRESS, &[start_address], regs_out)
            .await
            .expect(format!("Failed to burst read from {} registers starting at {}", regs_out.len(), start_address).as_str());
    }

    pub async fn configure(&mut self) {
        println!("Power on ICM42670");
        self.write_reg(0x1f, 0x0f).await;
        println!("ICM42680 powered on, verifying identity");
        let id = self.read_reg(0x75).await;
        println!("Got id: 0x{:x}", id);
        if id != 0x67 {
            panic!("Device not identified as icm42760, expected 0x67 but got 0x{:x}", id);
        }
        println!("Configuring accelerometer and gyro");
        let configuration_data = &[
            0b0100_0110, // Gyro ODR selection: 400hz
            0b0100_0111, // Accel ODR selection: 400hz,
            0b0100_0000, // Temp DLPF: 16Hz,
            0b0000_0010, // Gyro DLPF: 121Hz,
            0b0000_0010, // Accel DLPF: 121Hz,
        ];
        self.burst_write_regs(0x20, configuration_data).await;
        println!("ICM42680 configured");
    }

}

main.rs:

#![no_std]
#![no_main]

mod icm42670;

use esp_println::println;
use embassy_executor::Spawner;
use embassy_time::{Duration, Timer};
use core::net::Ipv4Addr;
use core::str::FromStr;
use embassy_net::{
    Ipv4Cidr,
    Runner,
    Stack,
    StackResources,
    StaticConfigV4,
};
use esp_backtrace as _;
use esp_hal::clock::CpuClock;
use esp_hal::timer::systimer::SystemTimer;
use esp_hal::time::Rate;
use esp_hal::timer::timg::TimerGroup;
use esp_hal::i2c;
use icm42670::Icm42670;
use esp_wifi::{
    wifi::{
        AccessPointConfiguration,
        Configuration,
        WifiController,
        WifiDevice,
        WifiEvent,
        WifiState,
    },
    EspWifiController,
};

extern crate alloc;

macro_rules! mk_static {
    ($t:ty,$val:expr) => {{
        static STATIC_CELL: static_cell::StaticCell<$t> = static_cell::StaticCell::new();
        #[deny(unused_attributes)]
        let x = STATIC_CELL.uninit().write(($val));
        x
    }};
}

#[esp_hal_embassy::main]
async fn main(spawner: Spawner) {
    // generator version: 0.3.1

    let config = esp_hal::Config::default().with_cpu_clock(CpuClock::max());
    let peripherals = esp_hal::init(config);

    esp_alloc::heap_allocator!(size: 72 * 1024);

    let timer0 = SystemTimer::new(peripherals.SYSTIMER);
    esp_hal_embassy::init(timer0.alarm0);

    let mut rng = esp_hal::rng::Rng::new(peripherals.RNG);

    let timer1 = TimerGroup::new(peripherals.TIMG0);
    let initted = &*mk_static!(EspWifiController<'static>, esp_wifi::init(
        timer1.timer0,
        rng.clone(),
        peripherals.RADIO_CLK,
    )
    .unwrap());

    let (controller, interfaces) = esp_wifi::wifi::new(
        &initted,
        peripherals.WIFI,
    ).unwrap();

    let gw_ip_addr_str = "192.168.2.1";
    let gw_ip_addr = Ipv4Addr::from_str(gw_ip_addr_str).expect("failed to parse gateway ip");

    let config = embassy_net::Config::ipv4_static(StaticConfigV4 {
        address: Ipv4Cidr::new(gw_ip_addr, 24),
        gateway: Some(gw_ip_addr),
        dns_servers: Default::default(),
    });

    let net_seed = rng.random() as u64;
    let (stack, runner) = embassy_net::new(
        interfaces.sta,
        config,
        mk_static!(StackResources<3>, StackResources::<3>::new()),
        net_seed,
    );

    spawner.spawn(connection(controller)).unwrap();
    spawner.spawn(net_task(runner)).unwrap();
    spawner.spawn(run_dhcp(stack, gw_ip_addr_str)).unwrap();

    let i2c = i2c::master::I2c::new(
        peripherals.I2C0,
        i2c::master::Config::default()
            .with_frequency(Rate::from_khz(400)),
    )
    .unwrap()
    .with_sda(peripherals.GPIO10)
    .with_scl(peripherals.GPIO8)
    .into_async();

    let mut imu = Icm42670::new(i2c); 
    imu.configure().await;

    loop {}
}

#[embassy_executor::task]
async fn run_dhcp(stack: Stack<'static>, gw_ip_addr: &'static str) {
    use core::net::{Ipv4Addr, SocketAddrV4};

    use edge_dhcp::{
        io::{self, DEFAULT_SERVER_PORT},
        server::{Server, ServerOptions},
    };
    use edge_nal::UdpBind;
    use edge_nal_embassy::{Udp, UdpBuffers};

    let ip = Ipv4Addr::from_str(gw_ip_addr).expect("dhcp task failed to parse gw ip");

    let mut buf = [0u8; 1500];

    let mut gw_buf = [Ipv4Addr::UNSPECIFIED];

    let buffers = UdpBuffers::<3, 1024, 1024, 10>::new();
    let unbound_socket = Udp::new(stack, &buffers);
    let mut bound_socket = unbound_socket
        .bind(core::net::SocketAddr::V4(SocketAddrV4::new(
            Ipv4Addr::UNSPECIFIED,
            DEFAULT_SERVER_PORT,
        )))
        .await
        .unwrap();

    loop {
        _ = io::server::run(
            &mut Server::<_, 64>::new_with_et(ip),
            &ServerOptions::new(ip, Some(&mut gw_buf)),
            &mut bound_socket,
            &mut buf,
        )
        .await
        .inspect_err(|e| println!("DHCP server error: {e:?}"));
        Timer::after(Duration::from_millis(500)).await;
    }
}


#[embassy_executor::task]
async fn connection(mut controller: WifiController<'static>) {
    println!("start connection task");
    println!("Device capabilities: {:?}", controller.capabilities());
    loop {
        match esp_wifi::wifi::wifi_state() {
            WifiState::ApStarted => {
                // wait until we're no longer connected
                controller.wait_for_event(WifiEvent::ApStop).await;
                Timer::after(Duration::from_millis(5000)).await
            }
            _ => {}
        }
        if !matches!(controller.is_started(), Ok(true)) {
            let client_config = Configuration::AccessPoint(AccessPointConfiguration {
                ssid: "esp-wifi".try_into().unwrap(),
                ..Default::default()
            });
            controller.set_configuration(&client_config).unwrap();
            println!("Starting wifi");
            controller.start_async().await.unwrap();
            println!("Wifi started!");
        }
    }
}

#[embassy_executor::task]
async fn net_task(mut runner: Runner<'static, WifiDevice<'static>>) {
    runner.run().await
}

Expected behavior

Not this:
====================== PANIC ======================
panicked at src/icm42670.rs:29:14:
Failed to burst write vals [70, 71, 64, 2, 2] to registers starting at 32: ArbitrationLost

Environment

• Target device:
  Chip type: esp32c3 (revision v0.4)
  Crystal frequency: 40 MHz
  Flash size: 4MB
  Features: WiFi, BLE
  MAC address: a0:85:e3:06:67:cc

(It's the esp-rust devboard)

• Crate name and version: esp-hal = { version = "1.0.0-beta.0", features = ["esp32c3", "unstable"] }

[bugadani]

Do you experience the same issue with the current git main?

[bjoernQ]

I just copied to code to a fresh project and it's working fine on a Rust-Board v1.0 for me

Power on ICM42670
start connection task
Device capabilities: Ok(EnumSet(Client | AccessPoint | Mixed))
Starting wifi
Wifi started!
ICM42680 powered on, verifying identity
Got id: 0x67
Configuring accelerometer and gyro
ICM42680 configured

(with the released HAL and also with main)

[ajwock]

Apologies for the delay. Unfortunately this issue does still occur at git main for me. I'll poke around more and see if I can get more consistent replication instructions.

[ajwock]

I also encountered this occasionally with write_read_async occasionally.

I did fork the repo and make a change that implements write_read_async in one hardware-driven transaction at the Driver level, which resolved the issue and fully unblocks my use case if I avoid the same transaction_async expression as above. I can work on productionizing that diff if it sounds worth accepting.

[bugadani]

I think I found the root cause of this issue but feel free to reopen if you still experience it.