[i2c_aspeed]: i2c_aspeed reports error when calling "i2c_smbus_read_block_data()"

[adamliyi]

obmc linux version:

root@barreleye:~# uname -a
Linux barreleye 4.3.6-openbmc-20160222-1 #1 Mon Feb 29 11:07:55 CST 2016 armv5tejl GNU/Linux

When run a short test like bellow:

 u8 block_buffer[I2C_SMBUS_BLOCK_MAX + 1];
 ret = i2c_smbus_read_block_data(client, 0x99, block_buffer);

i2c_aspeed driver will give error:

i2c_aspeed i2c-4: Invalid state (msg cfb1bcac, pending 8)?

[shenki]

Can you please reproduce this with dynamic debugging enabled for the i2c-aspeed driver, and paste the log here?

Something like:

cd /sys/kernel/debug/dynamic_debug
echo "file i2c-aspeed.c +p" > control

[adamliyi]

For "log" do you mean "dmesg"?
Looks the i2c_aspeed driver will generate too many log, and the error message will be overwrite.
How can I only produce debug log just for this test?

# echo adm1278 0x10 > /sys/class/i2c-adapter/i2c-4/new_device
# dmesg
[131123.600000] i2c_aspeed i2c-6: irq! status 0x00000001, cmd 0x0c430000
[131123.600000] i2c_aspeed i2c-6: ast_i2c_master_xfer_done xfer 0S
[131123.600000] i2c_aspeed i2c-6: ast_i2c_do_byte_xfer W-: addr 2e xfer 0, len 1
[131123.600000] i2c_aspeed i2c-6: issuing cmd: 2
[131123.600000] i2c_aspeed i2c-6: irq! status 0x00000001, cmd 0x0c430000
[131123.600000] i2c_aspeed i2c-6: ast_i2c_master_xfer_done xfer 0
[131123.600000] i2c_aspeed i2c-6: ast_i2c_do_byte_xfer R: addr 2e start, len 1
[131123.600000] i2c_aspeed i2c-6: issuing cmd: 3
[131123.600000] i2c_aspeed i2c-6: irq! status 0x00000001, cmd 0x0c410000
[131123.600000] i2c_aspeed i2c-6: ast_i2c_master_xfer_done xfer 0S
[131123.600000] i2c_aspeed i2c-6: ast_i2c_do_byte_xfer RT: addr 2e xfer 0, len 1
[131123.600000] i2c_aspeed i2c-6: issuing cmd: 38
[131123.600000] i2c_aspeed i2c-6: irq! status 0x00000014, cmd 0x0bdd0000
[131123.600000] i2c_aspeed i2c-6: ast_i2c_master_xfer_done xfer 0
[131123.610000] systemd-journald[515]: /dev/kmsg buffer overrun, some messages lost.

[shenki]

Okay, it looks like systemd might be stuffing us up. I'll try debugging this with a sane userspace. Can you please describe to me how to replicate the issue? Do I need a barreleye?

[adamliyi]

Thanks Milton. I increased kmesg buffer to 16MB and catch the log:

[    5.860000] i2c_aspeed i2c-4: i2c bus 4 registered, irq 224
[  627.500000] i2c_aspeed i2c-4: state[0], SCL[1], SDA[1], BUS[0]
[  627.500000] i2c_aspeed i2c-4: ast_i2c_do_byte_xfer W: addr 10 start, len 1
[  627.500000] i2c_aspeed i2c-4: issuing cmd: 3
[  627.500000] i2c_aspeed i2c-4: irq! status 0x00000001, cmd 0x0c430000
[  627.500000] i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0S
[  627.500000] i2c_aspeed i2c-4: ast_i2c_do_byte_xfer W-: addr 10 xfer 0, len 1
[  627.500000] i2c_aspeed i2c-4: issuing cmd: 2
[  627.500000] i2c_aspeed i2c-4: irq! status 0x00000001, cmd 0x0c430000
[  627.500000] i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0
[  627.510000] i2c_aspeed i2c-4: ast_i2c_do_byte_xfer R: addr 10 start, len 1
[  627.510000] i2c_aspeed i2c-4: issuing cmd: 3
[  627.510000] i2c_aspeed i2c-4: irq! status 0x00000001, cmd 0x0c410000
[  627.510000] i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0S
[  627.510000] i2c_aspeed i2c-4: ast_i2c_do_byte_xfer RT: addr 10 xfer 0, len 1
[  627.510000] i2c_aspeed i2c-4: issuing cmd: 38
[  627.510000] i2c_aspeed i2c-4: irq! status 0x00000004, cmd 0x135d0000
[  627.510000] i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0
[  627.510000] i2c_aspeed i2c-4: got rx len: 3
[  627.510000] i2c_aspeed i2c-4: ast_i2c_do_byte_xfer R-: addr 10 xfer 1, len 4
[  627.510000] i2c_aspeed i2c-4: issuing cmd: 8
[  627.510000] i2c_aspeed i2c-4: irq! status 0x00000010, cmd 0x0a060008
[  627.510000] i2c_aspeed i2c-4: Invalid state (msg ce833c94, pending 8)?
[  632.510000] i2c_aspeed i2c-4: controller timed out
[  632.530000] i2c i2c-4: new_device: Instantiated device adm1278 at 0x10

[adamliyi]

To reproduce the issue:
(Latest obmc at this moment has built adm1275 driver into kernel, so we have to use an earlier version):

1. Kernel version:

root@barreleye:/sys/kernel/debug/dynamic_debug# uname -a
Linux barreleye 4.3.6-openbmc-20160222-1 #2 Thu Mar 3 16:31:12 CST 2016 armv5tejl GNU/Linux

1. Need to test on Barreleye.
2. Please use the modules in the adm1278.zip
   adm1278.zip
3. insmod pmbus_core.ko
4. insmod adm1275.ko
5. echo adm1278 0x10 > /sys/class/i2c-adapter/i2c-4/new_device
   And you can see above error message in dmesg.
   (As Milton suggested, I add log_buf_len=16M in the kernel boot option. Otherwise, dmesg log will be overwrite.)

The error is triggered by code:

        ret = i2c_smbus_read_block_data(client, PMBUS_MFR_ID, block_buffer);
        if (ret < 0) {
                dev_err(&client->dev, "Failed to read Manufacturer ID\n");
                return ret;
        }

[shenki]

I've had a read of our driver, and it appears we should be okay with this. I'll take a closer look tomorrow.

[shenki]

Upstream has gained support for this device!

Here's the pull request for 4.6 that adds support for the adm1278:

https://lkml.org/lkml/2016/3/14/404

The commit is here:

https://git.kernel.org/cgit/linux/kernel/git/groeck/linux-staging.git/commit/?h=hwmon-for-linus-v4.6&id=709066acdd12c3312c94ebccc37630932e381949

[shenki]

I reproduced using our dev-4.4 kernel and the upstream driver:

i2c_aspeed i2c-4: state[0], SCL[1], SDA[1], BUS[0]
i2c_aspeed i2c-4: ast_i2c_do_byte_xfer W: addr 10 start, len 1
i2c_aspeed i2c-4: issuing cmd: 3
i2c_aspeed i2c-4: irq! status 0x00000001, cmd 0x0c430000
i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0S
i2c_aspeed i2c-4: ast_i2c_do_byte_xfer W-: addr 10 xfer 0, len 1
i2c_aspeed i2c-4: issuing cmd: 2
i2c_aspeed i2c-4: irq! status 0x00000001, cmd 0x0c430000
i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0 
i2c_aspeed i2c-4: ast_i2c_do_byte_xfer R: addr 10 start, len 1
i2c_aspeed i2c-4: issuing cmd: 3
i2c_aspeed i2c-4: irq! status 0x00000001, cmd 0x0c410000
i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0S
i2c_aspeed i2c-4: ast_i2c_do_byte_xfer RT: addr 10 xfer 0, len 1
i2c_aspeed i2c-4: issuing cmd: 38
i2c_aspeed i2c-4: irq! status 0x00000004, cmd 0x135d0000
i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0 
i2c_aspeed i2c-4: got rx len: 3
i2c_aspeed i2c-4: ast_i2c_do_byte_xfer R-: addr 10 xfer 1, len 4
i2c_aspeed i2c-4: issuing cmd: 8
i2c_aspeed i2c-4: irq! status 0x00000010, cmd 0x0a060008
i2c_aspeed i2c-4: Invalid state (msg cfaf3c94, pending 8)?
i2c_aspeed i2c-4: controller timed out
adm1275 4-0010: Failed to read Manufacturer ID
adm1275: probe of 4-0010 failed with error -5

[shenki]

We issue command AST_I2CD_M_RX_CMD (8).

irq status 0x00000010 (at offset 0x10, I2CD10: Interrupt Status Register):

Bit 4 is (WC) Normal Stop Condition Detection interrupt status.

irq cmd 0x0a060008 is I2CD14: Command/Status Register, bits set: 27, 25, 18, 17, 3.

                     SDA_OE: 0x0
                      SDA_O: 0x1
                      SCL_O: 0x0
                     SCL_OE: 0x1
 Transfer mode timing stage: 0x0
Transfer mode state machine: 0x0 [IDLE]
                Sampled SCL: 0x1
                Sampled SDA: 0x1
                   Bus busy: 0x0
      SDA_OE direct control: 0x0
       SDA_O direct control: 0x0
      SCL_OE direct control: 0x0
       SCL_O direct control: 0x0
         Enable bus recover: 0x0
         Enable slave alert: 0x0
 Enable receive data buffer: 0x0
Enable transmit data buffer: 0x0
                Master stop: 0x0
       Reveive command last: 0x0
             Master receive: 0x1
             Slave transmit: 0x0
            Master transmit: 0x0
               Master start: 0x0

[jk-ozlabs]

OK, here's what I think is happening:

i2c_aspeed i2c-4: ast_i2c_do_byte_xfer R: addr 10 start, len 1
i2c_aspeed i2c-4: issuing cmd: 3
i2c_aspeed i2c-4: irq! status 0x00000001, cmd 0x0c410000
i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0S

The client has done a read from address 0x10, so we're sending a start along with the one-byte write to provide the address value. The actual command is transmit | start. That command completes sucessfully.

Next:

i2c_aspeed i2c-4: ast_i2c_do_byte_xfer RT: addr 10 xfer 0, len 1
i2c_aspeed i2c-4: issuing cmd: 38
i2c_aspeed i2c-4: irq! status 0x00000004, cmd 0x135d0000
i2c_aspeed i2c-4: ast_i2c_master_xfer_done xfer 0 
i2c_aspeed i2c-4: got rx len: 3

Here we're doing a read with the I2C_M_RECV_LEN flag (so a one-byte read to get the length, then a length-byte read to get the rest of the data). RT in the first line indicates that the client wants the driver to also send a stop after that read is done.

However, the command we've issued there is receive | last | stop. We shouldn't have set the stop or last bits there, as we expect the M_RECV_LEN flag to indicate that there are actually more bytes to read, once we've updated len in ast_i2c_master_xfer_done.

So, we should be suppressing the stop command if query_len is set. I think the most sensible way to do this would be in the is_last check in ast_i2c_do_byte_xfer.

[shenki]

Thanks Jeremy! I took your suggestion and this patch resulted in working transfers:

--- a/drivers/i2c/busses/i2c-aspeed.c
+++ b/drivers/i2c/busses/i2c-aspeed.c
@@ -471,7 +471,7 @@ static bool ast_i2c_do_byte_xfer(struct ast_i2c_bus *bus)

                if (bus->msg->flags & I2C_M_RD) {
                        cmd = AST_I2CD_M_RX_CMD;
-                       if (bus->send_stop && is_last)
+                       if (bus->send_stop && is_last && !bus->query_len)
                                cmd |= AST_I2CD_M_S_RX_CMD_LAST |
                                        AST_I2CD_M_STOP_CMD;

You also metioned we might need to ensure we do the right thing if the received length is zero. I'll think about that and send out a final patch tomorrow.

[shenki]

This is fixed as of c2c9856 in the dev-4.4 tree.