I2C NACK causes library to always return ESP_ERR_INVALID_STATE, solved by printf (IDFGH-13084)

BartolHrg commented 2 months ago

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.2.2-169-g8e82062d41

Espressif SoC revision.

wokwi ESP32

Operating System used.

Windows

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

None

Development Kit.

wokwi

Power Supply used.

USB

What is the expected behavior?

I2C functions (like i2c_master_transmit) should succeed after a few attempts. I have a custom chip in Wokwi simulator that randomly returns NACK (1 out of 5 times: rand()%5==0)

What is the actual behavior?

They always return ESP_ERR_INVALID_STATE. After the custom Wokwi slave chip fails once, it then fails every time after that. Even if I call the function 100 times after that. But, if I add printf inside i2c_master.c, it works. <- this is important (note: therefore it is probably not because of Wokwi or custom chip, because they are not dependent on i2c_master.c)

Also, function on_connect on custom chip is never called again, only on_disconnect

Steps to reproduce.

Call i2c function (e.g. i2c_master_transmit)
The custom chip fails (NACK) (random 1 out of 5 times)
call it a few more times
return code after that is always ESP_ERR_INVALID_STATE

gitbug.zip

Debug Logs.

not much to log
for `printf("%d: 0x%x", __LINE__, ret_error)`

66: 0
67: 0
69: 0
66: 0
67: 0
69: 0
57: 103
58: 103
59: 103

chip has following logs:
Hello from custom ALU chip!
on connect
1
I2C Process connected
PAR1 := 0.000000
PAR1 := 0.000000
PAR1 := 0.000000
PAR1 := 3.000000
I2C Process disconected!!!
on connect
2
I2C Process connected
Operation := 5
I2C Process disconected!!!
on connect
1
I2C Process connected
Sending rez [9.000000] [0][0]
Sending rez [9.000000] [1][0]
Sending rez [9.000000] [2][16]
Sending rez [9.000000] [3][65]
I2C Process disconected!!!
on connect
1
I2C Process connected
PAR1 := 3.000000
PAR1 := 3.000000
PAR1 := 4.000000
PAR1 := 4.000000
I2C Process disconected!!!
on connect
4
I2C Process connected
Operation := 5
I2C Process disconected!!!
on connect
1
I2C Process connected
Sending rez [16.000000] [0][0]
Sending rez [16.000000] [1][0]
Sending rez [16.000000] [2][128]
Sending rez [16.000000] [3][65]
I2C Process disconected!!!
on connect
0
Device not ready. Please repeat commad
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!
I2C Process disconected!!!

More Information.

Important note: when adding printf("staa = %x ", i2c_master->status); into i2c_master.c, it works. I suspect it may have something to do with atomic_store operation it may be that the compiler does out-of-order execution and the status is not assigned a value until after s_i2c_send_commands is called

mythbuster5 commented 2 months ago

where you call the printf? And what is the optimization level?

BartolHrg commented 2 months ago

I included modified i2c_master.c in zip file though, printfs are commented I put them inside s_i2c_transaction_start function around s_i2c_send_commands call

For printf inside my project, they are in NekiI2C.hpp after 5 calls to i2c_master_transmit/i2c_master_receive (last one is logged) (I put 5 since NACK is random, so after 5 times, it should be ACK)

Optimization level is debug -Og (in vscode menuconfig) (I didn't touch it).

dvosully commented 3 weeks ago

I think I am also experiencing this behaviour, with a real I2C device. I have not yet traced the I2C bus to verify there is actually a NACK occurring (I will do more detailed testing soon), but I sometimes get the following debug messages for the first I2C transaction:

E (1674) i2c.master: I2C hardware NACK detected
E (1694) i2c.master: I2C transaction unexpected nack detected
E (1704) i2c.master: s_i2c_synchronous_transaction(870): I2C transaction failed
E (1714) i2c.master: i2c_master_transmit(1072): I2C transaction failed

After getting this NACK, every subsequent I2C transaction fails with an ESP_ERR_INVALID_STATE error:

E (2074) i2c.master: s_i2c_synchronous_transaction(870): I2C transaction failed
E (2074) i2c.master: i2c_master_transmit_receive(1095): I2C transaction failed
W (2079) gps: GPS I2C read failed ESP_ERR_INVALID_STATE
E (2119) i2c.master: s_i2c_synchronous_transaction(870): I2C transaction failed
E (2119) i2c.master: i2c_master_transmit_receive(1095): I2C transaction failed
W (2124) gps: GPS I2C read failed ESP_ERR_INVALID_STATE
E (2164) i2c.master: s_i2c_synchronous_transaction(870): I2C transaction failed
E (2164) i2c.master: i2c_master_transmit_receive(1095): I2C transaction failed
W (2169) gps: GPS I2C read failed ESP_ERR_INVALID_STATE

The I2C device HAS been initialized correctly in the correct mode (this fault only occurs occasionally on the first I2C transaction, there is no change in the init between when it works and when it fails). Usually applying an external reset will cause the I2C to initialise and work normally, sometimes after the external reset it still fails. I have not yet tried inserting a printf as suggested above.

I am using:

IDF v5.3.0
a custom board
I am building using the command prompt.
I am using a custom 3.3V power supply with 3A capacity
ESP32-S3-WROOM, rev 0.2
Communicating with an I2C GPS chip (Quectel L76-L running an I2C capable firmware)

AxelLin commented 2 weeks ago

where you call the printf? And what is the optimization level?

@mythbuster5 Any progress for this issue?

espressif / esp-idf