I2C should make sure the controller's off before taking over its pins

[cbiffle]

tl;dr: our I2C bus reset logic is deeply flawed and is causing problems in practice, including situations where the driver's sense of the mux states doesn't match the muxes, and devices are OR'd together.

The smoking gun trace

I've spent the past few days going down a rabbit hole of weird I2C behavior on Gimlet. This bug is not the root cause, but it's one of the things blocking my view of the root cause by compounding the problem.

Here's a picture:

Shown here is an I2C transaction where we're communicating with one of the NVMe-MI interfaces. Notice how at the +0.45ms mark we stop speaking I2C and instead start...pulse width modulating?

What you are seeing is actually the bus reset cargo-cult pin wiggle dance, where we attempt to unstick a device that's holding SCL low. And the disk is, indeed, holding SCL low -- I've seen it stretch the clock for up to 974.192µs during a write-repeatedstart-read sequence like this. For reasons I can't yet explain, we have decided to do a bus reset right smack in the middle of this transaction, and our drivers are fighting with the disk's for control of SCL.

Our wiggle sequence is a bit weird so it doesn't actually mind that its first five wiggles never make it to the outside. (I'm not sure it can actually see this, since from its perspective on the far side of a resistor and a mux, SCL is changing.)

Notice then that SDA falls low. I suspect that this is the disk, and this is another lower-level bug that I need to investigate. But what's more important is what's slightly to the right of that.

During a bus reset, we wiggle SCL until we're pretty sure it's free, and then we reset all the muxes. The lowest numbered mux address on this segment is 0x70, and you can see at the far right of that image that we write 0 to 0x70, turning off all its channels. Great. Working as intended, if you intended to reset the bus, which I didn't but that's another bug.

But just before that, there are some transitions and clocks. There are, in fact, four negative clock pulses during that time, one of which is only 712ns across. What gives? Who is doing that?

Well.

Those four pulses, combined with the four wiggle pulses between the +1.3ms and +1.65ms marks, and the extended negative pulse generated by the drive stretching the clock, all add up to nine pulses. Nine pulses is what you need to complete an I2C frame. Suspicious, no?

The cause

This is because we don't actually stop the I2C controller before we take over its GPIO pins and wiggle them madly, so basically we are clock stretching our own controller. The call is coming from inside the house.

At the time of this writing, the reset_and_wiggle_if_needed routine that the driver decided (still inexplicably) to call during the transaction was shaped like this:

fn reset_and_wiggle_if_needed(
    code: ResponseCode,
    controller: &I2cController<'_>,
    port: PortIndex,
    muxes: &[I2cMux<'_>],
    muxmap: &mut MuxMap,
    pins: &[I2cPins],
) {
    if reset_needed(code) {
       ...
        for pin in pins
            .iter()
            .filter(|p| p.controller == controller.controller)
            .filter(|p| p.port == port)
        {
            wiggle_scl(&sys, pin.scl, pin.sda);
            ....
        }

        reset(controller, port, muxes, muxmap);
    }
}

The reset routine is the one that tries to stop any outstanding transaction by turning off the controller.

The "proximally correct" thing to do here would be to shut off the controller, wait until it is fully idle, and only then take over its pins and wiggle them, turning it back on only after its pins have been released. (The "ultimately correct" thing is still "don't decide a bus reset would be fun in the middle of a perfectly good transaction," but I'm still working on that part and it'll be easier to see what's going on if we stop corrupting mux state.)

The effects

The most immediate effect is that, for reasons I can't yet explain, we tend to do this when talking to a specific type of NVMe disk, and this prevents us from doing so successfully.

A more interesting compound effect: I've seen the I2C controller, after it has been abused like this, fail to correctly generate the Start condition for the mux-resetting writes (at the far right of that trace image). Here's a closeup of another trace:

(The Saleae decode along the top is wrong, I'll warn you in advance.)

We've just done the "stomp all over the bus" thing to the left of the window shown here. There's a NACK to terminate the read transaction (good) and then ... a byte that says 0xC1? What's that?

That, my friends, is 0x70 plus a NACK bit, shifted left by one position, because the Saleae decoder is out of sync (I warned you). Normally this would be preceded by a start condition! But the controller is in a totally undefined state at this point because we've taken over its I/Os, and for whatever reason, it fails to generate the start condition.

Reliably.

At least once per minute.

Due to another bug I'm about to file, we treat this as A-OK and pretend the mux at 0x70 has been reset. The net effect? We wind up activating multiple I2C mux channels and effectively wiring several drives together, which creates different problems that get in the way of the real problem I'm trying to find.

So, it has been an exciting day!