Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

i2c emulation bug (QEMU-228) #110

Open
3 tasks done
wodz opened this issue Dec 18, 2024 · 6 comments
Open
3 tasks done

i2c emulation bug (QEMU-228) #110

wodz opened this issue Dec 18, 2024 · 6 comments

Comments

@wodz
Copy link

wodz commented Dec 18, 2024

Checklist

  • Checked the issue tracker for similar issues to ensure this is not a duplicate
  • Read the documentation to confirm the issue is not addressed there and your configuration is set correctly
  • Tested with the latest version to ensure the issue hasn't been fixed

How often does this bug occurs?

always

Expected behavior

Successful communication with virtual i2c device (tmp105).

Actual behavior (suspected bug)

WDT reset

Error logs or terminal output

ets Jul 29 2019 12:21:46

rst:0x1 (POWERON_RESET),boot:0x12 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:7172
load:0x40078000,len:15540
load:0x40080400,len:4
0x40080400: _init at ??:?

ho 8 tail 4 room 4
load:0x40080404,len:3904
entry 0x40080640
I (703) boot: ESP-IDF v5.2.1-507-gf8319f08cc 2nd stage bootloader
I (704) boot: compile time Dec 16 2024 09:18:00
I (704) boot: Multicore bootloader
I (722) boot: chip revision: v0.0
I (725) boot.esp32: SPI Speed      : 40MHz
I (725) boot.esp32: SPI Mode       : DIO
I (725) boot.esp32: SPI Flash Size : 4MB
I (734) boot: Enabling RNG early entropy source...
I (744) boot: Partition Table:
I (745) boot: ## Label            Usage          Type ST Offset   Length
I (745) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (745) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (746) boot:  2 factory          factory app      00 00 00010000 00100000
I (753) boot: End of partition table
I (759) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0b18ch ( 45452) map
I (783) esp_image: segment 1: paddr=0001b1b4 vaddr=3ffb0000 size=02254h (  8788) load
I (803) esp_image: segment 2: paddr=0001d410 vaddr=40080000 size=02c08h ( 11272) load
I (835) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=1703ch ( 94268) map
I (867) esp_image: segment 4: paddr=00037064 vaddr=40082c08 size=0a140h ( 41280) load
I (890) boot: Loaded app from partition at offset 0x10000
I (890) boot: Disabling RNG early entropy source...
I (901) cpu_start: Multicore app
I (1506) cpu_start: Pro cpu start user code
I (1507) cpu_start: cpu freq: 160000000 Hz
I (1507) cpu_start: Application information:
I (1507) cpu_start: Project name:     qemu-firmware
I (1507) cpu_start: App version:      1
I (1508) cpu_start: Compile time:     Dec 16 2024 09:17:53
I (1508) cpu_start: ELF file SHA256:  4bfd61c5f...
I (1508) cpu_start: ESP-IDF:          v5.2.1-507-gf8319f08cc
I (1508) cpu_start: Min chip rev:     v0.0
I (1509) cpu_start: Max chip rev:     v3.99 
I (1509) cpu_start: Chip rev:         v0.0
I (1510) heap_init: Initializing. RAM available for dynamic allocation:
I (1511) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1512) heap_init: At 3FFB2B28 len 0002D4D8 (181 KiB): DRAM
I (1512) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1512) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1512) heap_init: At 4008CD48 len 000132B8 (76 KiB): IRAM
I (1543) spi_flash: detected chip: gd
I (1547) spi_flash: flash io: dio
I (1567) main_task: Started on CPU0
I (1577) main_task: Calling app_main()
I (1577) gpio: GPIO[19]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 
I (1587) gpio: GPIO[18]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 
I (1587) qemu-i2c: i2c device 0x48 present

Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0). 

Core  0 register dump:
PC      : 0x400833fb  PS      : 0x00060034  A0      : 0x80083555  A1      : 0x3ffb0de0  
0x400833fb: i2c_isr_receive_handler at /opt/esp/idf/components/driver/i2c/i2c_master.c:566 (discriminator 1)

A2      : 0x3ffb5bac  A3      : 0x00000000  A4      : 0xb33fffff  A5      : 0x3ffb4cd0  
A6      : 0x3ffb604c  A7      : 0x3ffb5ed4  A8      : 0x00000110  A9      : 0x3ffb0dd0  
A10     : 0x3ffb5fac  A11     : 0xffffffff  A12     : 0x3ffb4cd0  A13     : 0x00060023  
A14     : 0x3ffb604c  A15     : 0x0000cdcd  SAR     : 0x00000020  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0x00000000  
0x4000c46c: memset in ROM
0x4000c477: memset in ROM

Core  0 was running in ISR context:
EPC1    : 0x400d22c3  EPC2    : 0x00000000  EPC3    : 0x00000000  EPC4    : 0x400833fb
0x400d22c3: uart_hal_write_txfifo at /opt/esp/idf/components/hal/uart_hal_iram.c:27
0x400833fb: i2c_isr_receive_handler at /opt/esp/idf/components/driver/i2c/i2c_master.c:566 (discriminator 1)



Backtrace: 0x400833f8:0x3ffb0de0 0x40083552:0x3ffb0e10 0x40082179:0x3ffb0e50 0x40082f7d:0x3ffb0e70 0x4000bfed:0x3ffb4c20 0x40086983:0x3ffb4c30 0x400d741e:0x3ffb4c50 0x400d7bcd:0x3ffb4c70 0x400d7d68:0x3ffb4ca0 0x400d7e3d:0x3ffb4cd0 0x400d88a5:0x3ffb4d00 0x400d5695:0x3ffb4d90 0x400d5743:0x3ffb4dc0 0x400e670c:0x3ffb4e20 0x400865e1:0x3ffb4e50
0x400833f8: i2c_ll_is_bus_busy at /opt/esp/idf/components/hal/esp32/include/hal/i2c_ll.h:460
 (inlined by) i2c_isr_receive_handler at /opt/esp/idf/components/driver/i2c/i2c_master.c:566
0x40083552: i2c_master_isr_handler_default at /opt/esp/idf/components/driver/i2c/i2c_master.c:627
0x40082179: shared_intr_isr at /opt/esp/idf/components/esp_hw_support/intr_alloc.c:445
0x40082f7d: _xt_lowint1 at /opt/esp/idf/components/xtensa/xtensa_vectors.S:1240
0x4000bfed: _xtos_set_intlevel in ROM
0x40086983: vPortClearInterruptMaskFromISR at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:564
 (inlined by) vPortExitCritical at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:504
0x400d741e: vPortExitCriticalSafe at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:600
 (inlined by) s_i2c_read_command at /opt/esp/idf/components/driver/i2c/i2c_master.c:278
0x400d7bcd: s_i2c_send_commands at /opt/esp/idf/components/driver/i2c/i2c_master.c:435
0x400d7d68: s_i2c_transaction_start at /opt/esp/idf/components/driver/i2c/i2c_master.c:544
0x400d7e3d: s_i2c_synchronous_transaction at /opt/esp/idf/components/driver/i2c/i2c_master.c:830
0x400d88a5: i2c_master_transmit_receive at /opt/esp/idf/components/driver/i2c/i2c_master.c:1056
0x400d5695: tmp105_temp_raw at /workspaces/firmware/main/qemu-firmware.c:409
0x400d5743: app_main at /workspaces/firmware/main/qemu-firmware.c:441
0x400e670c: main_task at /opt/esp/idf/components/freertos/app_startup.c:208
0x400865e1: vPortTaskWrapper at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134



Core  1 register dump:
PC      : 0x400848c2  PS      : 0x00060734  A0      : 0x800d215a  A1      : 0x3ffb5a00  
0x400848c2: esp_cpu_wait_for_intr at /opt/esp/idf/components/esp_hw_support/cpu.c:145

A2      : 0x00000000  A3      : 0x00000000  A4      : 0x3ffaf840  A5      : 0x3ffaf820  
A6      : 0x4008465c  A7      : 0x00000001  A8      : 0x800da0e6  A9      : 0x3ffb59c0  
0x4008465c: ipc_task at /opt/esp/idf/components/esp_system/esp_ipc.c:48

A10     : 0x00000000  A11     : 0x00000000  A12     : 0x3ffaf820  A13     : 0x3ffaf7f0  
A14     : 0x00000001  A15     : 0x3ffafe50  SAR     : 0x00000000  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  


Backtrace: 0x400848bf:0x3ffb5a00 0x400d2157:0x3ffb5a20 0x400873d2:0x3ffb5a40 0x400865e1:0x3ffb5a60
0x400848bf: xt_utils_wait_for_intr at /opt/esp/idf/components/xtensa/include/xt_utils.h:81
 (inlined by) esp_cpu_wait_for_intr at /opt/esp/idf/components/esp_hw_support/cpu.c:132
0x400d2157: esp_vApplicationIdleHook at /opt/esp/idf/components/esp_system/freertos_hooks.c:59
0x400873d2: prvIdleTask at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/tasks.c:4273 (discriminator 1)
0x400865e1: vPortTaskWrapper at /opt/esp/idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134

Steps to reproduce the behavior

  1. create empty efuse file: dd if=/dev/zero of=build/efuse.bin bs=1 count=124
  2. build firmware: idf.py build
  3. merge flash image using: esptool.py --chip esp32 merge_bin --flash_size 4MB --fill-flash-size 4MB -o flash_image.bin $(tail +2 flash_args)
  4. run firmware in qemu: qemu-system-xtensa -machine esp32 -nographic -drive file=build/flash_image.bin,if=mtd,format=raw -drive file=build/efuse.bin,if=none,format=raw,id=efuse -global driver=nvram.esp32.efuse,property=drive,value=efuse

Firmware source:
`
#include <stdio.h>
#include <string.h>
#include "freertos/FreeRTOS.h"
#include "driver/i2c_master.h"
#include "esp_log.h"
#include "esp_system.h"

#define I2C_PORT I2C_NUM_0
#define I2C_SCL_IO GPIO_NUM_18
#define I2C_SDA_IO GPIO_NUM_19

const char *TAG = "qemu-i2c";

uint16_t tmp105_temp_raw(i2c_master_dev_handle_t dev_handle)
{
uint8_t txbuf[1] = {0};
uint8_t rxbuf[2] = {0, 0};
i2c_master_transmit_receive(dev_handle, txbuf, sizeof(txbuf), rxbuf, sizeof(rxbuf), -1);
return (rxbuf[0] << 8) | rxbuf[1];
}

void app_main()
{
i2c_master_bus_config_t i2c_mst_config = {
.clk_source = I2C_CLK_SRC_DEFAULT,
.i2c_port = I2C_PORT,
.scl_io_num = I2C_SCL_IO,
.sda_io_num = I2C_SDA_IO,
.glitch_ignore_cnt = 7,
.flags.enable_internal_pullup = true,
};

i2c_master_bus_handle_t bus_handle;
ESP_ERROR_CHECK(i2c_new_master_bus(&i2c_mst_config, &bus_handle));

i2c_device_config_t dev_cfg = {
    .dev_addr_length = I2C_ADDR_BIT_LEN_7,
    .device_address = 0x48,
    .scl_speed_hz = 400000,
};

i2c_master_dev_handle_t dev_handle;
ESP_ERROR_CHECK(i2c_master_bus_add_device(bus_handle, &dev_cfg, &dev_handle));

if (i2c_master_probe(bus_handle, 0x48, -1) == ESP_OK)
{
    ESP_LOGI(TAG, "i2c device 0x48 present\n");
}

uint16_t temp_raw = tmp105_temp_raw(dev_handle);
ESP_LOGI(TAG, "tmp105: 0x%x\n", temp_raw);

}
`

Project release version

8.2.0-20240122

System architecture

Intel/AMD 64-bit (modern PC, older Mac)

Operating system

Linux

Operating system version

Ubuntu 20.04

Shell

Bash

Additional context

As can be seen from console logs i2c_master_probe() succeeds but reading from i2c device does not.

@github-actions github-actions bot changed the title i2c emulation bug i2c emulation bug (QEMU-228) Dec 18, 2024
@wodz
Copy link
Author

wodz commented Dec 23, 2024

Debugging from the firmware side - wdt reset comes from the line in i2c_isr_receive_handler() in i2c_master.c in IDF:
while(i2c_ll_is_bus_busy(hal->dev)){}
i2c_ll_is_bus_busy() is inline function

static inline bool i2c_ll_is_bus_busy(i2c_dev_t *hw) { return hw->status_reg.bus_busy; }

The counter part in qemu is esp32_i2c.c function static uint32_t esp32_i2c_get_status_reg(). Making this function always return 0 kinda solves the problem. I don't think this is proper solution and rather nasty hack. I tried to trace the i2c emulation from qemu side but failed. The code is awkward and without any comments.

@igrr
Copy link
Member

igrr commented Dec 23, 2024

Hi @wodz, thanks for the issue report. I am not very familiar with the I2C peripheral, QEMU emulation was contributed in #11. Will try to investigate this in the first weeks of January.

One idea, does disabling the watchdogs work in QEMU around the issue?

@wodz
Copy link
Author

wodz commented Dec 24, 2024

One idea, does disabling the watchdogs work in QEMU around the issue?

No. while(i2c_ll_is_bus_busy(hal->dev)){} is busy loop inside ISR handler in IDF. There is no timeout so firmware waits there indefinitely.

@wodz
Copy link
Author

wodz commented Dec 24, 2024

Hi @wodz, thanks for the issue report. I am not very familiar with the I2C peripheral, QEMU emulation was contributed in #11. Will try to investigate this in the first weeks of January.

PR says it was tested writing to emulated display controller. Write works correctly. The reading part is failing to clear status flags.

@Throows
Copy link

Throows commented Dec 25, 2024

Hello 👋 ,

imo its a ESP-IDF issue. I tried to run the program with the latest version of qemu and ESP-IDF v5.2.1 and i was able to reproduce the bug.
Then I comiled the latest commit of espressif/qemu on ubuntu 20.10 and tried to reproduce the bug with ESP-IDF v5.3.2 and it seemed to work. 🥇

I (647) boot: ESP-IDF v5.3.2 2nd stage bootloader
I (648) boot: compile time Dec 25 2024 12:32:24
I (648) boot: Multicore bootloader
I (655) boot: chip revision: v0.0
I (657) boot.esp32: SPI Speed      : 40MHz
I (657) boot.esp32: SPI Mode       : DIO
I (657) boot.esp32: SPI Flash Size : 2MB
I (660) boot: Enabling RNG early entropy source...
I (665) boot: Partition Table:
I (665) boot: ## Label            Usage          Type ST Offset   Length
I (666) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (666) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (666) boot:  2 factory          factory app      00 00 00010000 00100000
I (669) boot: End of partition table
I (671) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0b0e4h ( 45284) map
I (679) esp_image: segment 1: paddr=0001b10c vaddr=3ffb0000 size=02364h (  9060) load
I (685) esp_image: segment 2: paddr=0001d478 vaddr=40080000 size=02ba0h ( 11168) load
I (694) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=171e4h ( 94692) map
I (705) esp_image: segment 4: paddr=0003720c vaddr=40082ba0 size=0a48ch ( 42124) load
I (712) boot: Loaded app from partition at offset 0x10000
I (712) boot: Disabling RNG early entropy source...
I (723) cpu_start: Multicore app
I (1150) cpu_start: Pro cpu start user code
I (1150) cpu_start: cpu freq: 160000000 Hz
I (1151) app_init: Application information:
I (1151) app_init: Project name:     i2c_temp
I (1151) app_init: App version:      1
I (1151) app_init: Compile time:     Dec 25 2024 12:32:22
I (1151) app_init: ELF file SHA256:  4330afa83...
I (1151) app_init: ESP-IDF:          v5.3.2
I (1151) efuse_init: Min chip rev:     v0.0
I (1151) efuse_init: Max chip rev:     v3.99 
I (1152) efuse_init: Chip rev:         v0.0
I (1152) heap_init: Initializing. RAM available for dynamic allocation:
I (1153) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1153) heap_init: At 3FFB2C48 len 0002D3B8 (180 KiB): DRAM
I (1153) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1153) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1153) heap_init: At 4008D02C len 00012FD4 (75 KiB): IRAM
I (1169) spi_flash: detected chip: gd
I (1172) spi_flash: flash io: dio
W (1174) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (1179) main_task: Started on CPU0
I (1189) main_task: Calling app_main()
I (1189) gpio: GPIO[5]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 
I (1189) gpio: GPIO[4]| InputEn: 1| OutputEn: 1| OpenDrain: 1| Pullup: 1| Pulldown: 0| Intr:0 
I (1189) I2C: I2C device found at address 0x48
I (1189) I2C: Temperature raw data: 6400
I (2189) I2C: Temperature raw data: 6400
I (3189) I2C: Temperature raw data: 6400
I (4189) I2C: Temperature raw data: 6400
I (5189) I2C: Temperature raw data: 6400
I (6189) I2C: Temperature raw data: 6400
I (7189) I2C: Temperature raw data: 6400
I (8189) I2C: Temperature raw data: 6400
I (9189) I2C: Temperature raw data: 6400

However I am wondering, are we able to control the data sent by the simulated sensor ?

Best regards, Romain

@wodz
Copy link
Author

wodz commented Dec 27, 2024

Yes you can control data sent by the sensor. First you need to add option -qmp unix:/tmp/qmp.sock,server,nowait to the qemu args. Then you have to search for emulated i2c device in qemu object hierarchy using scripts/qmp/qom-list -s /tmp/qmp.sock (I personally grep for 'temperature' property as object hierarchy is pretty long). Then you can use qom-set -s /tmp/qmp.sock object.property value to set value returned by the sensor. However there is known bug which allows setting only string properties this way so you need to hack qom-set to send int instead of string. Can't find the patch right now but it is pretty trivial. Python backtrace will guide you.

Regarding IDF vs qemu issue. This is qemu issue revealed by IDF. Reading path of i2c emulation incorrectly returns busy status of the bus BUT indefinitely waiting for some flag in ISR is definitely bad practice.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

4 participants