search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.6k stars 7.27k forks source link

esp_http_client_read seems to return wrong data in OTA Update Process (IDFGH-9359) #10726

Closed franz-ms-muc closed 1 year ago

franz-ms-muc commented 1 year ago

Answers checklist.

IDF version.

ESP-IDF Pre-release v5.0-rc1

Operating System used.

Windows

How did you build your project?

Eclipse IDE

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

PowerShell

Development Kit.

Custom Board

Power Supply used.

USB

What is the expected behavior?

I expected a clean OTA Process.

What is the actual behavior?

but sometimes there are 16bit Portions in the Flash corrupted, and therefore the OTA Checksum failes.

sometimes also sectors gets filled with FF,

image

Steps to reproduce.

In the Moment we cannot let you reproduce this, it is happening in our closed-Source software, and we could not see it in the Samples, nor reproduce it. so we need Support in detecting and fixing the Error.

Debug Logs.

ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x28 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3810,len:0x1838
load:0x403c9700,len:0xbd0
load:0x403cc700,len:0x2f7c
entry 0x403c9900
I (25) boot: ESP-IDF v5.0-rc1-dirty 2nd stage bootloader
I (25) boot: compile time 17:34:39
I (25) boot: chip revision: V001
I (27) boot_comm: chip revision: 1, min. bootloader chip revision: 0
I (34) boot.esp32s3: Boot SPI Speed : 80MHz
I (39) boot.esp32s3: SPI Mode       : DIO
I (44) boot.esp32s3: SPI Flash Size : 16MB
I (49) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 otadata          OTA data         01 00 0000d000 00002000
I (72) boot:  1 №reserved      WiFi data        01 02 0000f000 00001000
I (80) boot:  2 ota_0            OTA app          00 10 00010000 00280000
I (87) boot:  3 ota_1            OTA app          00 11 00290000 00280000
I (95) boot:  4 prod             Unknown data     01 ff 00610000 00003000
I (102) boot:  5 safeNVrb0        Unknown data     01 ff 00613000 00003000
I (110) boot:  6 safeNVrb1        Unknown data     01 ff 00616000 00003000
I (117) boot:  7 safeNVrb2        Unknown data     01 ff 00619000 00003000
I (125) boot:  8 config           WiFi data        01 02 0061c000 00046000
I (133) boot:  9 appl             WiFi data        01 02 00662000 00004000
I (140) boot: 10 shared           WiFi data        01 02 00666000 00003000
I (148) boot: 11 efuse_em         efuse            01 05 00669000 00002000
I (155) boot: 12 nvs_key          NVS keys         01 04 0066b000 00001000
I (163) boot: 13 nvs              WiFi data        01 02 0066c000 00004000
I (170) boot: 14 coredump         Unknown data     01 03 00670000 00008000
I (178) boot: 15 log              Unknown data     01 82 00678000 00050000
I (185) boot: 16 spiffs           Unknown data     01 82 006c8000 00137000
I (193) boot: End of partition table
I (197) boot: No factory image, trying OTA 0
I (202) boot_comm: chip revision: 1, min. application chip revision: 0
W (209) esp_image: segment data length 0x62724 data starts 0x10020
W (216) esp_image: segment 0 map_segment 1 segment_data_offs 0x10020 load_addr 0x3c140020
W (225) esp_image: segment 0: paddr=00010020 vaddr=3c140020 size=62724h (403236) map
W (233) esp_image: free data page_count 0x000001ff
W (311) esp_image: Segment 0 checksum 0x94aa207c
W (312) esp_image: segment data length 0x79b4 data starts 0x7274c
W (312) esp_image: segment 1 map_segment 0 segment_data_offs 0x7274c load_addr 0x3fc9d200
W (321) esp_image: segment 1: paddr=0007274c vaddr=3fc9d200 size=079b4h ( 31156) load
W (330) esp_image: free data page_count 0x000001ff
W (341) esp_image: Segment 1 checksum 0xc341f775
W (342) esp_image: segment data length 0x5f10 data starts 0x7a108
W (347) esp_image: segment 2 map_segment 0 segment_data_offs 0x7a108 load_addr 0x40374000
0x40374000: _WindowOverflow4 at C:/Espressif/frameworks/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

W (356) esp_image: segment 2: paddr=0007a108 vaddr=40374000 size=05f10h ( 24336) load
W (364) esp_image: free data page_count 0x000001ff
W (375) esp_image: Segment 2 checksum 0xd4a0900d
W (376) esp_image: segment data length 0x130d5c data starts 0x80020
W (382) esp_image: segment 3 map_segment 1 segment_data_offs 0x80020 load_addr 0x42000020
0x42000020: _stext at ??:?

W (391) esp_image: segment 3: paddr=00080020 vaddr=42000020 size=130d5ch (1248604) map
W (400) esp_image: free data page_count 0x000001ff
W (629) esp_image: Segment 3 checksum 0x921b59e0
W (629) esp_image: segment data length 0x131f0 data starts 0x1b0d84
W (630) esp_image: segment 4 map_segment 0 segment_data_offs 0x1b0d84 load_addr 0x40379f10
0x40379f10: r_lld_con_sched_hack at ??:?

W (639) esp_image: segment 4: paddr=001b0d84 vaddr=40379f10 size=131f0h ( 78320) load
W (648) esp_image: free data page_count 0x000001ff
W (670) esp_image: Segment 4 checksum 0xb4d66dd
W (670) esp_image: segment data length 0x10 data starts 0x1c3f7c
W (671) esp_image: segment 5 map_segment 0 segment_data_offs 0x1c3f7c load_addr 0x50000000
W (680) esp_image: segment 5: paddr=001c3f7c vaddr=50000000 size=00010h (    16) load
W (688) esp_image: free data page_count 0x000001ff
W (694) esp_image: Segment 5 checksum 0xb4d66dd
W (699) esp_image: segment data length 0x3c data starts 0x1c3f94
W (706) esp_image: segment 6 map_segment 0 segment_data_offs 0x1c3f94 load_addr 0x600fe000
W (715) esp_image: segment 6: paddr=001c3f94 vaddr=600fe000 size=0003ch (    60) load
W (723) esp_image: free data page_count 0x000001ff
W (729) esp_image: Segment 6 checksum 0x92c73d5d
W (734) esp_image: segment data length 0xbff8 data starts 0x1c3fd8
W (741) esp_image: segment 7 map_segment 0 segment_data_offs 0x1c3fd8 load_addr 0x0
W (749) esp_image: segment 7: paddr=001c3fd8 vaddr=00000000 size=0bff8h ( 49144)
W (757) esp_image: free data page_count 0x000001ff
W (772) esp_image: Segment 7 checksum 0x92c73d5d
W (772) esp_image: image start 0x00010000 end of last section 0x001cffd0
I (786) boot: Loaded app from partition at offset 0x10000
I (815) boot: Set actual ota_seq=1 in otadata[0]
I (815) boot: Disabling RNG early entropy source...
I (826) esp_psram: Found 2MB PSRAM device
I (826) esp_psram: Speed: 80MHz
I (826) cpu_start: Pro cpu up.
I (827) cpu_start: Starting app cpu, entry point is 0x40375908
0x40375908: call_start_cpu1 at C:/Espressif/frameworks/esp-idf/components/esp_system/port/cpu_start.c:142

I (0) cpu_start: App cpu up.
I (1063) esp_psram: SPI SRAM memory test OK
I (1079) cpu_start: Pro cpu start user code
I (1079) cpu_start: cpu freq: 160000000 Hz
I (1079) cpu_start: Application information:
I (1082) cpu_start: Project name:     ksc2n_Appl
I (1088) cpu_start: App version:      Tag_Plan_SW_2304_v1.2-6-g9912d4
I (1095) cpu_start: Compile time:     Feb  8 2023 13:58:40
I (1101) cpu_start: ELF file SHA256:  3877a99fe5dcaa4c...
I (1107) cpu_start: ESP-IDF:          v5.0-rc1-dirty
I (1113) heap_init: Initializing. RAM available for dynamic allocation:
I (1120) heap_init: At 3FCC4230 len 000254E0 (149 KiB): D/IRAM
I (1126) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (1133) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (1140) heap_init: At 600FE03C len 00001FC4 (7 KiB): RTCRAM
I (1146) esp_psram: Adding pool of 1972K of PSRAM memory to heap allocator
I (1154) spi_flash: detected chip: gd
I (1158) spi_flash: flash io: dio
W (1162) cpu_start: eFuse virtual mode is enabled. If Secure boot or Flash encryption is enabled then it does not provide any security. FOR TESTING ONLY!
W (1177) efuse: Loading virtual efuse blocks from flash
EFUSE_BLKx:
0) 0x00800101 0x000f0000 0x09c0d1f5 0x00500000 0x00000022 0x00000000
1) 0xb32a0b3c 0x000068b6 0x00000000 0x02040000 0xb829f6d0 0x6c05c024
2) 0xc23619fd 0xca35ce22 0x3ae7be7c 0x4546815e 0x93ab7671 0xf1d240bc 0xc2d2d6d9 0x3b6ce8de
3) 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
4) 0x7e68a2e3 0x08fe1124 0x53ed80b5 0xa7d5faa7 0x1b37941e 0x0b3d3af1 0x7e3e1a92 0x7dee2768
5) 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
6) 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
7) 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
8) 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
9) 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000
10) 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000 0x00000000

W (1269) ADC: legacy driver is deprecated, please migrate to `esp_adc/adc_oneshot.h`
I (1279) sleep: Configure to isolate all GPIO pins in sleep state
I (1284) sleep: Enable automatic switching of GPIO sleep configuration
I (1291) esp_core_dump_flash: Init core dump to flash
I (1296) esp_core_dump_flash: Found partition 'coredump' @ 670000 32768 bytes
I (1336) esp_core_dump_flash: Core dump data checksum is correct
I (1336) esp_core_dump_flash: Found core dump 24548 bytes in flash @ 0x670000
I (1340) coexist: coexist rom version e7ae62f
I (1345) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1355) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (00:00:00.316) SystemLogger: Partition size: total: 293921, used: 40160
I (00:00:00.317) SystemLogger: Initialized
I (00:00:00.318) SystemLogger: log output destination changed to 2
W (00:00:00.324) SystemLogger: Output mode OUTPUT_UART_FILE is for developing use only!
I (00:00:00.632) SystemLogger: ESP logs get written to file now.
0 I (00:00:00.810) NVManager: Initializing NVManager
1 I (00:00:00.811) NVManager: NV Manager Start Internal Status check !
2 I (00:00:00.813) NVManager: Checking Safe NV Blocks...
3 I (00:00:00.819) NVManager: Start 3 blocks verifying for Safe NV Data
4 I (00:00:00.828) NVManager: Extracted payload length: 5309
5 I (00:00:00.833) NVManager: Safe NV Extracted from NV memory for redundant block '0' CRC32: OK! [crc32: 0x706E9B4B]
6 I (00:00:00.843) NVManager: Safe NV Extracted from NV memory occurrence counter: 0x0 !
7 I (00:00:00.854) NVManager: Extracted payload length: 5309
8 I (00:00:00.859) NVManager: Safe NV Extracted from NV memory for redundant block '1' CRC32: OK! [crc32: 0x706E9B4B]
9 I (00:00:00.869) NVManager: Safe NV Extracted from NV memory occurrence counter: 0x0 !
10 I (00:00:00.923) NVManager: Extracted payload length: 5309
11 I (00:00:00.925) NVManager: Safe NV Extracted from NV memory for redundant block '2' CRC32: OK! [crc32: 0x706E9B4B]
12 I (00:00:00.936) NVManager: Safe NV Extracted from NV memory occurrence counter: 0x0 !
13 I (00:00:00.950) NVManager: All CRC32 for all Safe NV blocks are correct!
14 I (00:00:00.955) NVManager: All CRC32 for all Safe NV blocks are equal!
15 I (00:00:00.963) NVManager: Start occurrence counter check...
16 I (00:00:00.969) NVManager: Verified Safe NV Block with ID 3 has highest occurrence counter 0.
17 I (00:00:00.979) NVManager: 'NVManager_Verify_SafeNVDataBlocks' used only for verification and recovery!
18 I (00:00:00.989) NVManager: No blocks for recovery !
19 I (00:00:00.995) NVManager: Safe NV Block validity check: OK !
20 I (00:00:01.008) NVManager: Checking Production Block...
21 I (00:00:01.011) NVManager: Validation of 'Production Data Block' extracted from NV memory with CRC32: OK! [crc32: 0x108D6E86]
22 I (00:00:01.022) NVManager: Production Block validity check: OK !
23 W (00:00:01.030) NVManager: There are not parameters in Operation Data!
24 E (00:00:01.081) NVManager: Read all Operation Data: FAILED !
25 I (00:00:01.108) NVManager: Read all Error Data: OK !
26 I (00:00:01.119) NVManager: Request for Read, ID: 128, data type: 2
27 I (00:00:01.121) NVManager: Request for read Configuration Data !
28 I (00:00:01.129) NVManager: RAM mirror store interval set to: 120 minutes (7200000 ms)
29 I (00:00:01.150) DEM: The DEM is initialized.
30 I (00:00:01.150) BE_CommManager: Initializing SNTP
31 I (00:00:01.162) system_api: Base MAC address is not set
32 I (00:00:01.163) system_api: read default base MAC address from EFUSE
33 I (00:00:01.169) BE_CommManager: Client initialized successfully
34 I (00:00:01.175) BE_CommManager: OTAMessageRequest kscnfz/C0131000000000005/local/_otaupdaterbackend/_private/local/_otaupdater/_rpc/request
35 I (00:00:01.191) BE_CommManager: OperatingRecordMessage kscnfz/C0131000000000005/local/_orc/_public/datamessage
36 I (00:00:01.202) BE_CommManager: OTAMessageStatus kscnfz/C0131000000000005/local/_otaupdater/_public/status
37 I (00:00:01.213) BE_CommManager: OTAMessageReply kscnfz/C0131000000000005/local/_otaupdater/_private/local/_otaupdaterbackend/_rpc/reply
38 I (00:00:01.231) BE_CommManager: LogFileTopic kscnfz/C0131000000000005/local/_dlc/_public/loggingmessage
39 I (00:00:01.242) gpio: GPIO[1]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
40 I (00:00:01.252) gpio: GPIO[2]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
41 I (00:00:01.262) gpio: GPIO[6]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
42 I (00:00:01.272) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
43 I (00:00:01.321) gpio: GPIO[10]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
44 I (00:00:01.330) gpio: GPIO[11]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
45 I (00:00:01.341) gpio: GPIO[45]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
46 I (00:00:01.351) gpio: GPIO[46]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
47 I (00:00:01.361) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0
48 I (00:00:01.371) gpio: GPIO[5]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 1| Intr:0
49 I (00:00:01.383) HAL_CAN_DRV: Driver installed
50 I (00:00:01.390) MC3479: Initializing I2C...

51 I (00:00:01.518) MC3479: MC3479 chip found. ID:
52 I (00:00:01.519) MC3479: A4
53 I (00:00:01.571) MC3479: ACC_Manager_Init passed!
54 I (00:00:01.582) ACC: Configuration data for motion detection:
55 I (00:00:01.583) ACC: Thresh: 2500
56 I (00:00:01.587) ACC: Debounce: 100
57 I (00:00:01.590) ACC: Timeout: 3
58 I (00:00:01.649) RPC_UART:  =======================
59 I (00:PL�61 I (00:00:01.657) RPC_UART: Configure uart params OK!
62 I (00:00:01.658) RPC_UART: Set uart pins OK!
63 I (00:00:01.670) RPC_UART: RPC UART [0] Initialized OK!
64 I (00:00:01.671) RPC_UART:  =======================
65 I (00:00:01.676) temperature_sensor: Range [-10°C ~ 80°C], error < 1°C
66 I (00:00:01.685) EcuManager: Characterized using Default Vref
67 I (00:00:01.700) EcuManager: Internal and externl temperature sensors are installed, expected temp ranger range: -20~80 ℃
68 I (00:00:01.707) EcuManager: +++++++  initialisation completed
69 I (00:00:01.720) ResourceManager: WiFi AP name: C0131000000000005
70 I (00:00:01.732) ResourceManager: WiFi AP pass: 12345678
71 I (00:00:01.739) ResourceManager: ++  Initialization completed
72 I (00:00:01.744) DataLogger: Initialized
73 I (00:00:01.749) SystemLogger: log output destination changed to 0
W (00:00:01.812) HAL_CAN_DRV: CAN SelfTest passed
I (00:00:01.814) HAL_CAN_DRV: Driver started
I (00:00:01.814) HAL_CAN_DRV: Starting transmissions
E (00:00:01.818) NVManager: Read all Operation Data: FAILED !
I (00:00:01.850) pp: pp rom version: e7ae62f
I (00:00:01.851) net80211: net80211 rom version: e7ae62f
I (00:00:01.860) wifi_init: rx ba win: 6
I (00:00:01.861) wifi_init: tcpip mbox: 32
I (00:00:01.861) wifi_init: udp mbox: 6
I (00:00:01.864) wifi_init: tcp mbox: 6
I (00:00:01.869) wifi_init: tcp tx win: 5744
I (00:00:01.873) wifi_init: tcp rx win: 5744
I (00:00:01.878) wifi_init: tcp mss: 1440
I (00:00:01.883) wifi_init: WiFi/LWIP prefer SPIRAM
I (00:00:01.888) wifi_init: WiFi IRAM OP enabled
I (00:00:01.894) wifi_init: WiFi RX IRAM OP enabled
I (00:00:01.900) ResourceManager: ++  STA initialized
I (00:00:01.905) ResourceManager: ++  WiFI STA shall be stopped
I (00:00:01.911) statusLED: statusLED initialization!
I (00:00:01.917) statusLED: statusLED initialized!
I (00:00:01.923) ResourceManager: ++  RESOURCE_INTERNET changed state: from RESOURCE_STATE_INIT to RESOURCE_STATE_STOPPED with target state: RESOURCE_TARGET_STATE_STOPPED
I (00:00:01.938) EcuManager: +++++++  ECU state changed from ECU_STATE_NOT_INIT to ECU_STATE_INITIALIZING
I (00:00:01.948) EcuSleepWakeup: Wakeup cause undefined, probably normal startup.
I (00:00:01.956) EcuManager: NV data check status OK !
I (00:00:01.963) ResourceManager: ++  CAN0 proceed to starting
I (00:00:01.968) ResourceManager: ++  IsoLib CAN0 shutting down
I (00:00:01.975) ResourceManager: ++  WiFI AP starting
I (00:00:01.981) EcuManager: +++++++  ECU state changed from ECU_STATE_INITIALIZING to ECU_STATE_NORMAL
I (00:00:01.992) ResourceManager: ++  RESOURCE_CAN_0 changed state: from RESOURCE_STATE_INIT to RESOURCE_STATE_STARTING with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:02.006) ResourceManager: ++  CAN0 starting
I (00:00:02.012) ResourceManager: ++  CAN0 started successfully
I (00:00:02.018) ResourceManager: ++  RESOURCE_ISOLIB_CAN_0 changed state: from RESOURCE_STATE_INIT to RESOURCE_STATE_STOPPED with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:02.034) ResourceManager: ++  ISOLIB CAN0 starting
I (00:00:02.040) ResourceManager: ++  RESOURCE_WIFI_CON changed state: from RESOURCE_STATE_INIT to RESOURCE_STATE_STARTING with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:02.056) ResourceManager: ++  send start AP command
I (00:00:02.063) WiFi_AP: WiFi starts as AP
I (00:00:02.068) phy_init: phy_version 503,13653eb,Jun  1 2022,17:47:08
W (00:00:02.075) phy_init: failed to load RF calibration data (0x110f), falling back to full calibration
W (00:00:02.114) WiFi_AP: WiFi AP event, event_id: 12
I (00:00:02.116) WiFi_AP: received WIFI_EVENT_AP_START
I (00:00:02.119) UDS: Session changed from 0x0 to 0x1
W (00:00:02.121) UDS: Evaluating reset reason flag!
I (00:00:02.127) UDS: calculated CRC: 0x3ecf786e
I (00:00:02.132) UDS: reproramming_flag addr: 0x50000010
I (00:00:02.138) UDS: reproramming_flag crc: 0xc79e8212
I (00:00:02.144) UDS: reproramming_flag: 0xcb1eb2c3
I (00:00:02.149) UDS: resetReasonFlag: 0x86e28011
I (00:00:02.155) ResourceManager: ++  RESOURCE_CAN_0 changed state: from RESOURCE_STATE_STARTING to RESOURCE_STATE_STARTED with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:02.171) ResourceManager: ++  RESOURCE_ISOLIB_CAN_0 changed state: from RESOURCE_STATE_STOPPED to RESOURCE_STATE_STARTING with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:02.187) ResourceManager: ++  IsoLib CAN0 starting
I (00:00:02.193) ResourceManager: ++   Target state changed for STA - start it
I (00:00:02.207) ResourceManager: ++  RESOURCE_WIFI_CON changed state: from RESOURCE_STATE_STARTING to RESOURCE_STATE_CONNECTING with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:02.221) ResourceManager: ++  connect the STA to the remote AP
W (00:00:02.225) WiFi_AP: WiFi_AP::connect called but not supported
I (00:00:02.231) ResourceManager: ++  RESOURCE_INTERNET changed state: from RESOURCE_STATE_STOPPED to RESOURCE_STATE_STARTING with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:02.248) ResourceManager: ++  send start STA command
I (00:00:02.254) WiFi_STA: WiFi starts as STA
I (00:00:02.259) WiFi_STA: SSID: PC_HS
I (00:00:02.263) WiFi_STA: Pass: nokia3310
I (00:00:02.268) CF1_BDC: READ_iso_manuf_code: 111 - 0 6f
W (00:00:02.268) WiFi_AP: WiFi AP event, event_id: 13
I (00:00:02.275) CF1_BDC: READ_iso_serial_no: 5 - 5 - 0 0 5
I (00:00:02.279) WiFi_AP: received WIFI_EVENT_AP_STOP
W (00:00:02.293) WiFi_AP: WiFi AP event, event_id: 2
I (00:00:02.298) WiFi_STA: received WIFI_EVENT_STA_START
W (00:00:02.304) WiFi_AP: WiFi AP event, event_id: 12
I (00:00:02.308) WiFi_AP: received WIFI_EVENT_AP_START
I (00:00:02.310) CF1_BDC: iso_self_cnf_addr: 1 iso_ind_group: 2 iso_dev_class_inst: 0 iso_dev_class: 11 iso_padding: 0 iso_func: 132 iso_func_inst: 2 iso_ecu_inst: 1 iso_man_code: 111 iso_serial_no: 5
I (00:00:02.318) ResourceManager: ++  RESOURCE_INTERNET changed state: from RESOURCE_STATE_STARTING to RESOURCE_STATE_CONNECTING with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:02.349) ResourceManager: ++  connect the STA to the remote AP
I (00:00:02.421) CF2_IsoBus: READ_iso_manuf_code: 111 - 0 6f
I (00:00:02.423) CF2_IsoBus: READ_iso_serial_no: 5 - 5 - 0 0 5
I (00:00:02.450) CF2_IsoBus: iso_self_cnf_addr: 1 iso_ind_group: 2 iso_dev_class_inst: 0 iso_dev_class: 11 iso_padding: 0 iso_func: 132 iso_func_inst: 0 iso_ecu_inst: 1 iso_man_code: 111 iso_serial_no: 5
I (00:00:02.527) statusLED: Displayed code (status) changed to STATE_BLINK_CODE_22 - J1939 Error
I (00:00:02.554) CF3_Telematic: READ_iso_manuf_code: 111 - 0 6f
I (00:00:02.556) CF3_Telematic: READ_iso_serial_no: 5 - 5 - 0 0 5
I (00:00:02.584) CF3_Telematic: iso_self_cnf_addr: 0 iso_ind_group: 2 iso_dev_class_inst: 0 iso_dev_class: 11 iso_padding: 0 iso_func: 132 iso_func_inst: 1 iso_ecu_inst: 1 iso_man_code: 111 iso_serial_no: 5
I (00:00:03.711) ResourceManager: ++  IsoLib CAN0 started successfully
I (00:00:03.714) ResourceManager: ++  RESOURCE_ISOLIB_CAN_0 changed state: from RESOURCE_STATE_STARTING to RESOURCE_STATE_STARTED with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:03.725) ResourceManager: ++  connect the STA to the remote AP
W (00:00:03.732) WiFi_AP: WiFi_AP::connect called but not supported
W (00:00:03.748) WiFi_AP: WiFi AP event, event_id: 4
I (00:00:03.752) WiFi_STA: received WIFI_EVENT_STA_CONNECTED
I (00:00:04.253) statusLED: Displayed code (status) changed to STATE_05_HZ_BLINK_RATE - Normal
I (00:00:04.277) CF2_IsoBus: NETWORK EVENT CF2 32
I (00:00:04.277) CF3_Telematic: NETWORK EVENT CF3 32
I (00:00:04.278) CF2_IsoBus: NETWORK EVENT CF2 200
I (00:00:04.283) CF3_Telematic: NETWORK EVENT CF3 200
W (00:00:04.347) WiFi_AP: WiFi AP event, event_id: 0
I (00:00:04.348) esp_netif_handlers: sta ip: 192.168.137.160, mask: 255.255.255.0, gw: 192.168.137.1
I (00:00:04.353) WiFi_STA: received IP_EVENT_STA_GOT_IP
I (00:00:04.359) ResourceManager: ++   connection to the AP established
I (00:00:04.367) ResourceManager: ++  RESOURCE_INTERNET changed state: from RESOURCE_STATE_CONNECTING to RESOURCE_STATE_STARTED with target state: RESOURCE_TARGET_STATE_STARTED
I (00:00:18.487) OTA: Starting OTA initialization
E (00:00:18.488) OTA: OTA IMAGE URL: https://192.168.16.22:443/hello_world.bin
W (19805) wifi:<ba-add>idx:0 (ifx:0, 56:6c:eb:00:9f:60), tid:0, ssn:8, winSize:64
I (00:00:19.796) esp_https_ota: Starting OTA...
I (00:00:19.797) esp_https_ota: Writing to partition subtype 17 at offset 0x290000
I (00:00:19.799) OTA: Finished OTA initialization
I (00:00:19.805) BE_CommManager: Tracking message with MQTT ID 1 (tracking NUM: 1)
I (00:00:19.813) BE_CommManager: Enqueue msg id 1 to topic kscnfz/C0131000000000005/local/_otaupdater/_public/status qos 2 retain 0
I (00:00:19.838) OTA: Running firmware version: Tag_Plan_SW_2304_v1.2-6-g9912d4
I (00:00:19.840) BE_CommManager: Tracking message with MQTT ID 2 (tracking NUM: 2)
I (00:00:19.844) BE_CommManager: Enqueue msg id 2 to topic kscnfz/C0131000000000005/local/_otaupdater/_public/status qos 2 retain 0
I (00:00:19.894) OTA: OTA Downloading: 1
I (00:00:19.950) OTA: OTA Downloading: 2
I (00:00:20.004) OTA: OTA Downloading: 3
I (00:00:20.050) OTA: OTA Downloading: 4
I (00:00:20.104) OTA: OTA Downloading: 5
I (00:00:20.150) OTA: OTA Downloading: 6
I (00:00:20.210) OTA: OTA Downloading: 7
I (00:00:20.218) OTA: OTA Downloading: 8
I (00:00:20.310) OTA: OTA Downloading: 9
I (00:00:20.318) OTA: OTA Downloading: 10
I (00:00:20.417) OTA: OTA Downloading: 11
I (00:00:20.427) OTA: OTA Downloading: 12
I (00:00:20.470) OTA: OTA Downloading: 13
I (00:00:20.534) OTA: OTA Downloading: 14
I (00:00:20.580) OTA: OTA Downloading: 15
I (00:00:20.634) OTA: OTA Downloading: 16
I (00:00:20.680) OTA: OTA Downloading: 17
I (00:00:20.734) OTA: OTA Downloading: 18
I (00:00:20.740) OTA: OTA Downloading: 19
I (00:00:20.837) OTA: OTA Downloading: 20
I (00:00:20.846) OTA: OTA Downloading: 21
I (00:00:20.940) OTA: OTA Downloading: 22
I (00:00:20.950) OTA: OTA Downloading: 23
I (00:00:21.057) OTA: OTA Downloading: 24
I (00:00:21.062) OTA: OTA Downloading: 25
I (00:00:21.110) OTA: OTA Downloading: 26
I (00:00:21.163) OTA: OTA Downloading: 27
I (00:00:21.220) OTA: OTA Downloading: 28
I (00:00:21.274) OTA: OTA Downloading: 29
I (00:00:21.320) OTA: OTA Downloading: 30
I (00:00:21.370) OTA: OTA Downloading: 31
I (00:00:21.379) OTA: OTA Downloading: 32
I (00:00:21.480) OTA: OTA Downloading: 33
I (00:00:21.488) OTA: OTA Downloading: 34
I (00:00:21.580) OTA: OTA Downloading: 35
I (00:00:21.588) OTA: OTA Downloading: 36
I (00:00:21.690) OTA: OTA Downloading: 37
I (00:00:21.695) OTA: OTA Downloading: 38
I (00:00:21.750) OTA: OTA Downloading: 39
I (00:00:21.809) OTA: OTA Downloading: 40
I (00:00:21.860) OTA: OTA Downloading: 41
I (00:00:21.913) OTA: OTA Downloading: 42
I (00:00:21.950) OTA: OTA Downloading: 43
I (00:00:22.000) OTA: OTA Downloading: 44
I (00:00:22.009) OTA: OTA Downloading: 45
I (00:00:22.110) OTA: OTA Downloading: 46
I (00:00:22.119) OTA: OTA Downloading: 47
I (00:00:22.218) OTA: OTA Downloading: 48
I (00:00:22.228) OTA: OTA Downloading: 49
I (00:00:22.270) OTA: OTA Downloading: 50
I (00:00:22.333) OTA: OTA Downloading: 51
I (00:00:22.380) OTA: OTA Downloading: 52
I (00:00:22.433) OTA: OTA Downloading: 53
I (00:00:22.470) OTA: OTA Downloading: 54
I (00:00:22.523) OTA: OTA Downloading: 55
I (00:00:22.528) OTA: OTA Downloading: 56
I (00:00:22.620) OTA: OTA Downloading: 57
I (00:00:22.628) OTA: OTA Downloading: 58
I (00:00:22.720) OTA: OTA Downloading: 59
I (00:00:22.728) OTA: OTA Downloading: 60
I (00:00:22.830) OTA: OTA Downloading: 61
I (00:00:22.834) OTA: OTA Downloading: 62
I (00:00:22.887) OTA: OTA Downloading: 63
I (00:00:22.943) OTA: OTA Downloading: 64
I (00:00:22.980) OTA: OTA Downloading: 65
I (00:00:23.034) OTA: OTA Downloading: 66
I (00:00:23.080) OTA: OTA Downloading: 67
I (00:00:23.140) OTA: OTA Downloading: 68
I (00:00:23.146) OTA: OTA Downloading: 69
I (00:00:23.240) OTA: OTA Downloading: 70
I (00:00:23.249) OTA: OTA Downloading: 71
I (00:00:23.346) OTA: OTA Downloading: 72
I (00:00:23.355) OTA: OTA Downloading: 73
I (00:00:23.460) OTA: OTA Downloading: 74
I (00:00:23.477) OTA: OTA Downloading: 75
I (00:00:23.520) OTA: OTA Downloading: 76
I (00:00:23.584) OTA: OTA Downloading: 77
I (00:00:23.620) OTA: OTA Downloading: 78
I (00:00:23.673) OTA: OTA Downloading: 79
I (00:00:23.720) OTA: OTA Downloading: 80
I (00:00:23.770) OTA: OTA Downloading: 81
I (00:00:23.778) OTA: OTA Downloading: 82
I (00:00:23.870) OTA: OTA Downloading: 83
I (00:00:23.878) OTA: OTA Downloading: 84
I (00:00:23.970) OTA: OTA Downloading: 85
I (00:00:23.978) OTA: OTA Downloading: 86
I (00:00:24.020) OTA: OTA Downloading: 87
I (00:00:24.073) OTA: OTA Downloading: 88
I (00:00:24.110) OTA: OTA Downloading: 89
I (00:00:24.173) OTA: OTA Downloading: 90
I (00:00:24.210) OTA: OTA Downloading: 91
I (00:00:24.264) OTA: OTA Downloading: 92
I (00:00:24.270) OTA: OTA Downloading: 93
I (00:00:24.367) OTA: OTA Downloading: 94
I (00:00:24.376) OTA: OTA Downloading: 95
I (00:00:24.490) OTA: OTA Downloading: 96
I (00:00:24.498) OTA: OTA Downloading: 97
I (00:00:24.590) OTA: OTA Downloading: 98
I (00:00:24.599) OTA: OTA Downloading: 99
I (00:00:24.605) OTA: OTA Downloading: 100
I (00:00:24.607) OTA: OTA Update was successful
I (00:00:24.608) BE_CommManager: Tracking message with MQTT ID 3 (tracking NUM: 3)
I (00:00:24.613) BE_CommManager: Enqueue msg id 3 to topic kscnfz/C0131000000000005/local/_otaupdater/_public/status qos 2 retain 0
W (00:00:24.626) esp_image: segment data length 0x7ce0 data starts 0x290020
W (00:00:24.633) esp_image: segment 0 map_segment 1 segment_data_offs 0x290020 load_addr 0x3c020020
W (00:00:24.643) esp_image: segment 0: paddr=00290020 vaddr=3c020020 size=07ce0h ( 31968) map
W (00:00:24.652) esp_image: free data page_count 0x000000c5
W (00:00:24.663) esp_image: Segment 0 checksum 0x2cea25ef
W (00:00:24.664) esp_image: segment data length 0x2a40 data starts 0x297d08
W (00:00:24.672) esp_image: segment 1 map_segment 0 segment_data_offs 0x297d08 load_addr 0x3fc90410
W (00:00:24.681) esp_image: segment 1: paddr=00297d08 vaddr=3fc90410 size=02a40h ( 10816)
W (00:00:24.690) esp_image: free data page_count 0x000000c5
W (00:00:24.698) esp_image: Segment 1 checksum 0x9df4f64c
W (00:00:24.703) esp_image: segment data length 0x58c8 data starts 0x29a750
W (00:00:24.710) esp_image: segment 2 map_segment 0 segment_data_offs 0x29a750 load_addr 0x40374000
0x40374000: _WindowOverflow4 at C:/Espressif/frameworks/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1742

W (00:00:24.720) esp_image: segment 2: paddr=0029a750 vaddr=40374000 size=058c8h ( 22728)
W (00:00:24.729) esp_image: free data page_count 0x000000c5
W (00:00:24.738) esp_image: Segment 2 checksum 0x1441e506
W (00:00:24.741) esp_image: segment data length 0x173b8 data starts 0x2a0020
W (00:00:24.748) esp_image: segment 3 map_segment 1 segment_data_offs 0x2a0020 load_addr 0x42000020
0x42000020: _stext at ??:?

W (00:00:24.758) esp_image: segment 3: paddr=002a0020 vaddr=42000020 size=173b8h ( 95160) map
W (00:00:24.767) esp_image: free data page_count 0x000000c5
W (00:00:24.787) esp_image: Segment 3 checksum 0xdc8a24c1
W (00:00:24.787) esp_image: segment data length 0x6b44 data starts 0x2b73e0
W (00:00:24.790) esp_image: segment 4 map_segment 0 segment_data_offs 0x2b73e0 load_addr 0x403798c8
0x403798c8: llc_con_conflict_check at ??:?

W (00:00:24.799) esp_image: segment 4: paddr=002b73e0 vaddr=403798c8 size=06b44h ( 27460)
W (00:00:24.808) esp_image: free data page_count 0x000000c5
W (00:00:24.819) esp_image: Segment 4 checksum 0xd9b26908
W (00:00:24.820) esp_image: segment data length 0x10 data starts 0x2bdf2c
W (00:00:24.828) esp_image: segment 5 map_segment 0 segment_data_offs 0x2bdf2c load_addr 0x50000000
W (00:00:24.838) esp_image: segment 5: paddr=002bdf2c vaddr=50000000 size=00010h (    16)
W (00:00:24.846) esp_image: free data page_count 0x000000c5
W (00:00:24.853) esp_image: Segment 5 checksum 0xd9b26908
W (00:00:24.858) esp_image: image start 0x00290000 end of last section 0x002bdf3c
I (00:00:24.867) esp_image: Verifying image signature...
I (00:00:24.873) secure_boot_v2: Take trusted digest key(s) from eFuse block(s)
E (00:00:24.880) esp_image: Secure boot signature verification failed
I (00:00:24.887) esp_image: Calculating simple hash to check for corruption...
W (00:00:24.913) esp_image: image valid, signature bad
E (00:00:24.918) OTA: Image validation failed, image is corrupted
E (00:00:24.919) OTA: OTA verifying procedure - failed
E (00:00:24.921) MARTO: OTA state before abort 3

assert failed: tlsf_free tlsf.c:1049 (!block_is_free(block) && "block already marked as free")

Backtrace: 0x4037654a:0x3fcb5710 0x40382b79:0x3fcb5730 0x40389f85:0x3fcb5750 0x40388a17:0x3fcb5870 0x40388354:0x3fcb5890 0x40376976:0x3fcb58b0 0x40389fb5:0x3fcb58d0 0x4209c8e7:0x3fcb58f0 0x42026788:0x3fcb5910 0x42026ae1:0x3fcb5930 0x42126657:0x3fcb5950 0x42010cdd:0x3fcb5970 0x40386516:0x3fcb5990
0x4037654a: panic_abort at C:/Espressif/frameworks/esp-idf/components/esp_system/panic.c:412

0x40382b79: esp_system_abort at C:/Espressif/frameworks/esp-idf/components/esp_system/esp_system.c:135

0x40389f85: __assert_func at C:/Espressif/frameworks/esp-idf/components/newlib/assert.c:78

0x40388a17: tlsf_free at C:/Espressif/frameworks/esp-idf/components/heap/tlsf/tlsf.c:1049 (discriminator 1)

0x40388354: multi_heap_free_impl at C:/Espressif/frameworks/esp-idf/components/heap/multi_heap.c:241

0x40376976: heap_caps_free at C:/Espressif/frameworks/esp-idf/components/heap/heap_caps.c:353

0x40389fb5: free at C:/Espressif/frameworks/esp-idf/components/newlib/heap.c:39

0x4209c8e7: esp_https_ota_abort at C:/Espressif/frameworks/esp-idf/components/esp_https_ota/src/esp_https_ota.c:639

0x42026788: OTA_AbortUpdate at C:/Projects/ksc-2n/src/APPL/OTA/OTA.c:772

0x42026ae1: OTA_MainFunction at C:/Projects/ksc-2n/src/APPL/OTA/OTA.c:415

0x42126657: osw::Event::run() const at C:/Projects/ksc-2n/src/OS/os_wrapper/src/Event.cpp:27

0x42010cdd: osw::Task<1u>::run(void*) at C:/Projects/ksc-2n/src/OS/os_wrapper/include/Task.hpp:213

0x40386516: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:151

More Information.

No response

Alvin1Zhang commented 1 year ago

Thanks for reporting.

franz-ms-muc commented 1 year ago

Hello Franz,

Changing the TLS memory setting from SPIRAM to Internal RAM seems to solve the problem.

Made longterm flash in the loop test with one application updating the other => no checksum verification failures.

However, with the same setting in the example project advanced_https_ota I can’t still force it to break so that I can show the issue to ESP.

Best regards,

Martin

hmalpani commented 1 year ago

Hello @franz-ms-muc Could you also share the sdkconfig file? It will be helpful in reproducing the issue. Thanks!

mahavirj commented 1 year ago

@franz-ms-muc

I suspect this could be related to memory corruption. Please use guidelines from https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-reference/system/heap_debug.html.

Alternatively, if you would recreate the issue under any IDF example then please share us the instructions.

hmalpani commented 1 year ago

Hello @franz-ms-muc Any update on this issue?

Alvin1Zhang commented 1 year ago

@franz-ms-muc Thanks for reporting, would you please help share if any updates for the issue? Thanks.

mahavirj commented 1 year ago

Closing. Please drop a comment if you are still facing a issue here..