Runtime Error in esp_flash_write in esp_flash_api

GermanSheepDog commented 5 years ago

Hello,

I download the new version of esp32-homekit-cam and compiled it successfully after I changed this: I got this error:

AR build/lwip/liblwip.a
CC build/x264/x264-snapshot-20181221-2245-stable/common/base.o
cc1: error: -Werror=format-truncation=: no option -Wformat-truncation=
cc1: warning: unrecognized command line option '-Wno-frame-address'
make[1]: *** [x264-snapshot-20181221-2245-stable/common/base.o] Error 1
make: *** [component-x264-build] Error 2

I changed */x264/component.mk:

# ESP_IDF
x264_THIRDPARTY_ROOT = x264-snapshot-20181221-2245-stable

COMPONENT_SRCDIRS = $(x264_THIRDPARTY_ROOT)/common $(x264_THIRDPARTY_ROOT)/encoder
COMPONENT_ADD_INCLUDEDIRS = . $(x264_THIRDPARTY_ROOT)

#CFLAGS += -Wno-error=format-truncation=      <- This did not work for me

$(eval $(call compile_exclude, $(addprefix $(x264_THIRDPARTY_ROOT)/, \
    common/opencl.o \
    common/threadpool.o \
    common/win32thread.o \
    encoder/rdo.o \
    encoder/slicetype.o \
)))

The program started at esp32 and the connection to homekit started. At Pair Setup Step 3/3 I got this error:

...
I (6142) camera: Allocating 2 frame buffers (75 KB total)
I (6152) camera: Allocating 37 KB frame buffer in OnBoard RAM
I (6162) camera: Allocating 37 KB frame buffer in OnBoard RAM
>>> HomeKit: Starting server
>>> HomeKit: Using existing accessory ID: C0:B1:A8:09:BF:ED
>>> HomeKit: Configuring mDNS
>>> HomeKit: Got new client connection: 55
>>> HomeKit: [Client 55] Pair Setup Step 1/3
>>> HomeKit: [Client 55] Pair Setup Step 2/3
>>> HomeKit: [Client 55] Pair Setup Step 3/3
abort() was called at PC 0x400833d9 on core 0
0x400833d9: esp_flash_write at /Users/username/esp/esp-idf/components/spi_flash/esp_flash_api.c:609

ELF file SHA256: 259834b78efd7d0bfd0a74940c1c5bf4f4c8c4149ca0a202f5863d1e3bc23397

Backtrace: 0x4008bb55:0x3ffe6f50 0x4008bec5:0x3ffe6f70 0x400833d9:0x3ffe6f90 0x400e6bed:0x3ffe6fe0 0x4017f386:0x3ffe7000 0x4017e41f:0x3ffe7080 0x4017ef19:0x3ffe71d0 0x40183091:0x3ffe71f0 0x4017c757:0x3ffe7250 0x4017dc03:0x3ffe7280 0x4017ed32:0x3ffe72c0 0x4008e06d:0x3ffe72e0
0x4008bb55: invoke_abort at /Users/username/esp/esp-idf/components/esp32/panic.c:719

0x4008bec5: abort at /Users/username/esp/esp-idf/components/esp32/panic.c:719

0x400833d9: esp_flash_write at /Users/username/esp/esp-idf/components/spi_flash/esp_flash_api.c:609

0x400e6bed: spi_flash_write at /Users/username/esp/esp-idf/components/spi_flash/esp_flash_api.c:657

0x4017f386: homekit_storage_add_pairing at /Users/username/esp/esp32-homekit-camera/components/homekit/src/storage.c:247

0x4017e41f: homekit_server_on_pair_setup at /Users/username/esp/esp32-homekit-camera/components/homekit/src/server.c:1353

0x4017ef19: homekit_server_on_message_complete at /Users/username/esp/esp32-homekit-camera/components/homekit/src/server.c:2925

0x40183091: http_parser_execute at /Users/username/esp/esp32-homekit-camera/components/http-parser/http-parser/http_parser.c:2335

0x4017c757: homekit_client_process at /Users/username/esp/esp32-homekit-camera/components/homekit/src/server.c:3149

0x4017dc03: homekit_run_server at /Users/username/esp/esp32-homekit-camera/components/homekit/src/server.c:3257

0x4017ed32: homekit_server_task at /Users/username/esp/esp32-homekit-camera/components/homekit/src/server.c:3425

0x4008e06d: vPortTaskWrapper at /Users/username/esp/esp-idf/components/freertos/port.c:403

Rebooting...
...

Can anyone help me? Which version of esp-idf did you use? Did you use Mac Catalina?

Kristian8606 commented 5 years ago

I use Catalina with this version https://docs.espressif.com/projects/esp-idf/en/latest/get-started/macos-setup.html

maximkulkin commented 5 years ago

It looks like it has paired, but failed to write pairing info to flash. Check your flash size and address where homekit supposed to write it’s data.

GermanSheepDog commented 5 years ago

Hello @maximkulkin, hello @Kristian8606, I think, there are amongst other things some problems with the versions of esp-idf. Last time I used:

I (38) boot: ESP-IDF v4.1-dev-369-g4dac7c7df 2nd stage bootloader

and got this runtime errors:

I (5941) gpio: GPIO[14]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
E (5951) ledc: requested frequency and duty resolution can not be achieved, try reducing freq_hz or duty_resolution. div_param=3
E (5961) camera_xclk: ledc_timer_config failed, rc=ffffffff
I (5961) sccb: pin_sda 13 pin_scl 12

I (5971) gpio: GPIO[26]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
E (6001) sccb: SCCB_Write [ff]=01 failed

E (6001) sccb: SCCB_Write [12]=80 failed

I (6021) sccb: SCCB_Probe start
E (7281) camera: Camera probe failed with error 0x20001
E (7281) esp32_camera: Camera init failed with error 0x20001

My previous version is:

I (884) cpu_start: ESP-IDF:          v4.0-dev-1191-g138c941fa

With this version I got this problem:

I (7089) gpio: GPIO[25]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (7099) gpio: GPIO[19]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (7109) camera: Allocating 2 frame buffers (75 KB total)
Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.
Core 0 register dump:
PC      : 0x40094eda  PS      : 0x00060533  A0      : 0x8008f52d  A1      : 0x3ffc9a90  
0x40094eda: uxPortCompareSet at /Users/username/esp/esp-idf/components/freertos/tasks.c:3507
 (inlined by) vPortCPUAcquireMutexIntsDisabledInternal at /Users/username/esp/esp-idf/components/freertos/portmux_impl.inc.h:86
 (inlined by) vPortCPUAcquireMutexIntsDisabled at /Users/username/esp/esp-idf/components/freertos/portmux_impl.h:99
 (inlined by) vTaskEnterCritical at /Users/username/esp/esp-idf/components/freertos/tasks.c:4201

I suspect a problem with my hardware. I used a "TTGO T-Kamera ESP32 WROVER & PSRAM Kamera Modul ESP32-WROVER-B OV2640 Kamera Modul 0,96 OLED" and configured it as "TTGO CAM v1.7" with "Support for external, SPI connected RAM". It is correct?

Without "Support for external, SPI connected RAM" I got an runtime error, if I started video.

Which version of esp-idf do you use? Which hardware do you use?

GermanSheepDog commented 5 years ago

@maximkulkin: I like to isolate the problem and I will start one time more from scratch: make clean; rm sdkconfig; It will help me if I know the esp-idf version and the camera type which worked sure correctly. There are more unknown effects like MacOS Version and so on.

maximkulkin commented 5 years ago

What is the problem with MacOS version?? You're using a separate toolchain, not bound neither to OS, nor to Xcode.

I tested code on ESP-IDF versions 3.3 (branch "v3.3" in Git), 4.0 (branch "release/v4.0") and on "master" (commit "4dac7c7df"). Tested it on ESP-EYE, M5Stack Camera and AI-Thinker ESP32-CAM modules. With v4.x you need to apply esp32-camera.patch to components/esp32-camera, with v3.x you do not need that. I did not test all permutations (mostly I was testing esp-idf master branch on different modules and then tested different esp-idf versions on ESP-EYE module). It worked in all configurations.

GermanSheepDog commented 5 years ago

@maximkulkin: I suspect that with my configuration something is a little different. Today I downloaded the newest esp32-homekit-cam and I started from scratch. At my first test with esp-idf v3.3 and M5Camera (4M Flash, 4M PSRAM) I got this problem with stream:

..
>>> HomeKit: [Client 55] Update Characteristics
I (42203) esp32_camera: Processing session command 1
I (42203) esp32_camera: Adding streaming session
I (42203) esp32_camera: Starting streaming
I (42213) esp32_camera: Total free memory: 11256
x264 [error]: malloc of size 37984 failed
E (42223) esp32_camera: Failed to open H.264 encoder
E (42223) FreeRTOS: FreeRTOS Task "Camera Stream" should not return, Aborting now!
abort() was called at PC 0x40092e53 on core 1
0x40092e53: vPortTaskWrapper at /Users/username/esp/esp-idf/components/freertos/port.c:435

ELF file SHA256: 55fb26956f9dd62af7695bc4ec3fe4ba1fd4ebfed8b082396cbc31ec9c41b16a

Backtrace: 0x4008c3d8:0x3fffeeb0 0x4008c621:0x3fffeed0 0x40092e53:0x3fffeef0
0x4008c3d8: invoke_abort at /Users/username/esp/esp-idf/components/esp32/panic.c:715

0x4008c621: abort at /Users/username/esp/esp-idf/components/esp32/panic.c:715
0x40092e53: vPortTaskWrapper at /Users/username/esp/esp-idf/components/freertos/port.c:435

Rebooting...

Second test with same camera and esp-idf v4.0:

...
>>> HomeKit: [Client 56] Update Characteristics
I (146815) esp32_camera: Processing session command 1
I (146815) esp32_camera: Adding streaming session
I (146815) esp32_camera: Starting streaming
I (146825) esp32_camera: Total free memory: 6208
x264 [error]: malloc of size 37984 failed
E (146835) esp32_camera: Failed to open H.264 encoder
E (146835) FreeRTOS: FreeRTOS Task "Camera Stream" should not return, Aborting now!
abort() was called at PC 0x40095037 on core 1
0x40095037: vPortTaskWrapper at /Users/username/esp/esp-idf/components/freertos/port.c:435

ELF file SHA256: 8b2fdd00d1c98def1c4832ac7f15f4024aeff3677a8e9eb63f03d7d9fb1862f4

Backtrace: 0x40092561:0x3fffeeb0 0x400928e5:0x3fffeed0 0x40095037:0x3fffeef0
0x40092561: invoke_abort at /Users/username/esp/esp-idf/components/esp32/panic.c:719

0x400928e5: abort at /Users/username/esp/esp-idf/components/esp32/panic.c:719

0x40095037: vPortTaskWrapper at /Users/username/esp/esp-idf/components/freertos/port.c:435

Rebooting...

What can I do to isolate this errors?

maximkulkin commented 5 years ago

What can I do to isolate this errors?

Add more memory?

I (146825) esp32_camera: Total free memory: 6208

This 6208 is a problem. You're supposed to have ~4MB (well, at least 1MB, but they come in multiples of 4MB) of RAM for the whole thing to work. Make sure your module has SPI RAM installed and you have enabled SPI RAM support in config (see README).

GermanSheepDog commented 5 years ago

I did not pay enough attention to the memory-message. Thank you!

I double-checked the two SPI RAM parameters in menuconfig:

ESP32-specific
 - Support for external, SPI-connected RAM = check 
 - SPI RAM config
    - Initialize SPI RAM when booting the ESP32 = check -> ok
    - SPI RAM access method = Make RAM allocatable using malloc() as well -> ok

At start of ESP32 it seemed that everything was ok:

I (35) boot: SPI Speed      : 40MHz
I (39) boot: SPI Mode       : DIO
I (43) boot: SPI Flash Size : 4MB
I (47) boot: Partition Table:
I (51) boot: ## Label            Usage          Type ST Offset   Length
I (58) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (66) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (73) boot:  2 factory          factory app      00 00 00010000 00200000
I (81) boot: End of partition table
...
I (843) spiram: Found 64MBit SPI RAM device
I (846) spiram: SPI RAM mode: flash 40m sram 40m
I (852) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
...
I (889) cpu_start: App cpu up.
I (1788) spiram: SPI SRAM memory test OK
I (1788) heap_init: Initializing. RAM available for dynamic allocation:
I (1789) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (1795) heap_init: At 3FFBBC80 len 00024380 (144 KiB): DRAM
I (1801) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1807) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1814) heap_init: At 400987F8 len 00007808 (30 KiB): IRAM
I (1820) cpu_start: Pro cpu start user code
I (1825) spiram: Adding pool of 4096K of external SPI memory to heap allocator
...
I (29356) esp32_camera: WiFI ready
I (29356) esp32_camera: Free heap: 4364696

I optimized using of memory:

Homekit: Maximum number of sim. clients: 2
Component config/ESP32-specific/SPI RAM config/Reserve this amount of bytes for data that specifically needs to bin DM =0 (old value:32768)

Reduce both 'xTaskCreate'-statements in code to 80% Now I got this:

>>> HomeKit: [Client 56] Update Characteristics
I (71251) esp32_camera: Processing session command 1
I (71251) esp32_camera: Adding streaming session
I (71261) esp32_camera: Starting streaming
I (71261) esp32_camera: Total free memory: 50240
x264 [error]: malloc of size 37984 failed
E (71271) esp32_camera: Failed to open H.264 encoder
E (71271) FreeRTOS: FreeRTOS Task "Camera Stream" should not return, Aborting now!
abort() was called at PC 0x40091ce3 on core 1
0x40091ce3: vPortTaskWrapper at /Users/username/esp/esp-idf/components/freertos/port.c:435

I didn't understand these both messages:

There are 50.240 bytes of memory free before error occurred.
At start of program there are 4.364.696 bytes of free heap.

Is there any other Parameter in "SPI RAM config" to change?

maximkulkin commented 5 years ago

It looks like you do have 4MB of RAM. So where did all memory go?

GermanSheepDog commented 5 years ago

Yes, it looks like I do have 4MB of RAM for HEAP.

I build in some logging information like this:

ESP_LOGI(TAG, "Free heap %s 1: %d", __FUNCTION__, xPortGetFreeHeapSize());

Output of 1. test:

I (7525) camera: Free heap camera_probe 2: 4397092
I (7525) camera_xclk: Free heap camera_enable_out_clock 1: 4397092
I (7535) camera_xclk: Free heap camera_enable_out_clock 2: 4397092
I (7545) camera_xclk: Free heap camera_enable_out_clock 3: 4397092
I (7545) camera_xclk: Free heap camera_enable_out_clock 4: 202828
I (7555) camera_xclk: Free heap camera_enable_out_clock 5: 202828
I (7565) camera: Free heap camera_probe 3: 202828
I (7565) sccb: pin_sda 22 pin_scl 23

Output of 2. + 3. test:

I (7555) camera_xclk: Free heap camera_enable_out_clock 5: 4397092
I (7565) camera: Free heap camera_probe 3: 4397092
I (7565) sccb: pin_sda 22 pin_scl 23

I (7575) camera: Free heap camera_probe 4: 202416

Output of 4. test:

I (7527) camera: Free heap camera_probe 2: 4397092
I (7527) camera_xclk: Free heap camera_enable_out_clock 1: 4397092
I (7537) camera_xclk: Free heap camera_enable_out_clock 2: 4397092
I (7547) camera_xclk: Free heap camera_enable_out_clock 3: 202828
I (7547) camera_xclk: Free heap camera_enable_out_clock 4: 202828

Why are the process different? Who stole me 4MB of RAM? I used M5Camera with 4MB of flash and 4MB of PSRAM und ESP-IDF v4.0-beta1.

GermanSheepDog commented 5 years ago

I found the problem - it is the LED! I use default parameters for LED ant it was mapped with GPIO16 (look at sdkconfig: CONFIG_CAMERA_PIN_LED=16) I switched at my M5CameraF LED to Pin 2 (Data of Mic!) an it worked fine. I can see a stream, a little bit blurred. Today I did not need the mic.

maximkulkin commented 5 years ago

My M5Camera LED is GPIO 14, consult your documentation.

And congratulations!

GermanSheepDog commented 5 years ago

Yes, in second step I found the LED on GPIO14.

Thank you for help and congratulations.

maximkulkin / esp32-homekit-camera

Runtime Error in esp_flash_write in esp_flash_api #38