[BUG] esp32-devkitc:mcuboot_update_agent

[maxikrie]

Description / Steps to reproduce the issue

Following the description, the update process starts but randomly hangs after a few percent of downloading. I confirmed that everything works as expected for nuttx-12.4.0, but not for the latest version nuttx-12.12.0.

rst:0x1 (POWERON_RESET),boot:0x13 (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:0x3fff7c98,len:6980
load:0x40078000,len:13428
load:0x40090000,len:8712
entry 0x4007b41c
[esp32] [INF] *** Booting MCUboot build v2.2.0-118-gaa4fa2b6 ***
[esp32] [INF] [boot] chip revision: v3.1
[esp32] [INF] [boot.esp32] SPI Speed      : 40MHz
[esp32] [INF] [boot.esp32] SPI Mode       : DIO
[esp32] [INF] [boot.esp32] SPI Flash Size : 4MB
[esp32] [INF] [boot] Enabling RNG early entropy source...
[esp32] [INF] Primary image: magic=good, swap_type=0x1, copy_done=0x3, image_ok=0x1
[esp32] [INF] Scratch: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
[esp32] [INF] Boot source: primary slot
[esp32] [INF] Image index: 0, Swap type: none
[esp32] [INF] Disabling RNG early entropy source...
[esp32] [INF] br_image_off = 0x20000
[esp32] [INF] ih_hdr_size = 0x20
[esp32] [INF] Loading image 0 - slot 0 from flash, area id: 1
[esp32] [INF] DRAM segment: start=0x384fc, size=0x3434, vaddr=0x3ffc22a0
[esp32] [INF] IRAM segment: start=0x20080, size=0x1847c, vaddr=0x40080000
[esp32] [INF] start=0x40085288
IROM segment aligned lma 0x00060000 vma 0x400d0000 len 0x079cb8 (498872)
DROM segment aligned lma 0x00040000 vma 0x3f410000 len 0x013628 (79400)
telnetd [8:100]

NuttShell (NSH) NuttX-12.12.0
This is MCUBoot Update Agent image
nsh> 
nsh> mcuboot_agent http://192.168.1.102:8000/nuttx.bin
MCUboot Update Agent example
Downloading from http://192.168.1.102:8000/nuttx.bin
Firmware Update size: 1048576 bytes
Received: 512      of 1048576 bytes [0%]
Received: 1024     of 1048576 bytes [0%]
Received: 1536     of 1048576 bytes [0%]
Received: 2048     of 1048576 bytes [0%]
Received: 2560     of 1048576 bytes [0%]
Received: 3072     of 1048576 bytes [0%]
Received: 3584     of 1048576 bytes [0%]
Received: 4096     of 1048576 bytes [0%]
Received: 4608     of 1048576 bytes [0%]
Received: 5120     of 1048576 bytes [0%]
Received: 5632     of 1048576 bytes [0%]
Received: 6144     of 1048576 bytes [0%]
Received: 6656     of 1048576 bytes [0%]
Received: 7168     of 1048576 bytes [0%]
Received: 7680     of 1048576 bytes [0%]
Received: 8192     of 1048576 bytes [0%]
Received: 8704     of 1048576 bytes [0%]
Received: 9216     of 1048576 bytes [0%]
Received: 9728     of 1048576 bytes [0%]
Received: 10240    of 1048576 bytes [0%]
Received: 10752    of 1048576 bytes [1%]
Received: 11264    of 1048576 bytes [1%]
Received: 11776    of 1048576 bytes [1%]
Received: 12288    of 1048576 bytes [1%]

On which OS does this issue occur?

[OS: Linux]

What is the version of your OS?

Debian12

NuttX Version

12.12.0

Issue Architecture

[Arch: xtensa]

Issue Area

[Area: Applications]

Host information

esptool v4.10.0

Verification

• I have verified before submitting the report.

[maxikrie]

@tmedicci I added you since you responded to another issue I had with mcuboot.

[tmedicci]

This is probably related to #17736

@eren-terzioglu is taking a look. Thanks!

[maxikrie]

@tmedicci @eren-terzioglu I could resolve #17736 by changing the AP. Unfortunately, it doesn't resolve this issue. I changed the AP and the update still stops, this time around 50%.

Can anybody confirm that this working for nuttx-12.12.0? I can confirm it is working for nuttx-12.4.0, but I haven't bisected yet to determine where it starts failing.

[eren-terzioglu]

@tmedicci @eren-terzioglu I could resolve #17736 by changing the AP. Unfortunately, it doesn't resolve this issue. I changed the AP and the update still stops, this time around 50%.

Can anybody confirm that this working for nuttx-12.12.0? I can confirm it is working for nuttx-12.4.0, but I haven't bisected yet to determine where it starts failing.

I tried with 12.12.0 and seems it has an issue but I need to check it a bit more.

Update: Problem seems only happening on esp32

[maxikrie]

@eren-terzioglu So far I have only managed to get nuttx-12.4.0 working. nuttx-12.5.0 stops during the update process at non-repeatable instances with

Received: 297164   of 1048576 bytes [28%]
webclient_perform failed with -11
Application Image download failure.
Update aborted.

nuttx-12.12.0 stops with no error output and just hangs never returning to the shell

[eren-terzioglu]

@eren-terzioglu So far I have only managed to get nuttx-12.4.0 working. nuttx-12.5.0 stops during the update process at non-repeatable instances with

Received: 297164   of 1048576 bytes [28%]
webclient_perform failed with -11
Application Image download failure.
Update aborted.

nuttx-12.12.0 stops with no error output and just hangs never returning to the shell

It might cause of WiFi network on 12.5 but my trials showed that nuttx-12.11.0 was working fine

[fdcavalcanti]

I was able to see the same output on 12.12.0 and confirmed with Wireshark.
Also @eren-terzioglu noticed this issue is only happening on ESP32, other Espressif devices are fine.

It is possible to also replicate using wget (which means it is not an issue on mcuboot):

nsh> wget -o /data/nuttx.bin http://192.168.0.125:8000/nuttx.bin

You can see window size is 0. At this point the OS is stuck.

3404	51.776035843	0.055020719	192.168.0.125	192.168.0.85	TCP	678	[TCP Window Full] 8000 → 24253 [PSH, ACK] Seq=809014 Ack=101 Win=64140 Len=624 [TCP segment of a reassembled PDU]
3408	52.017006407	0.018010319	192.168.0.125	192.168.0.85	TCP	678	[TCP Window Full] [TCP Retransmission] 8000 → 24253 [PSH, ACK] Seq=809014 Ack=101 Win=64140 Len=624 [TCP segment of a reassembled PDU]
3409	52.023658539	0.006652132	192.168.0.85	192.168.0.125	TCP	60	[TCP ZeroWindow] 24253 → 8000 [ACK] Seq=101 Ack=809638 Win=0 Len=0
3412	52.496110072	0.291869522	192.168.0.125	192.168.0.85	TCP	54	[TCP Keep-Alive] 8000 → 24253 [ACK] Seq=809637 Ack=101 Win=64140 Len=0
3415	52.530408329	0.009927336	192.168.0.85	192.168.0.125	TCP	60	[TCP ZeroWindow] 24253 → 8000 [ACK] Seq=101 Ack=809638 Win=0 Len=0
3482	54.440016412	0.034209512	192.168.0.125	192.168.0.85	TCP	54	[TCP Keep-Alive] 8000 → 24253 [ACK] Seq=809637 Ack=101 Win=64140 Len=0
3485	54.509585238	0.003180028	192.168.0.85	192.168.0.125	TCP	60	[TCP ZeroWindow] 24253 → 8000 [ACK] Seq=101 Ack=809638 Win=0 Len=0
3586	58.280014729	0.028881903	192.168.0.125	192.168.0.85	TCP	54	[TCP Keep-Alive] 8000 → 24253 [ACK] Seq=809637 Ack=101 Win=64140 Len=0
3587	58.283975718	0.003960989	192.168.0.85	192.168.0.125	TCP	60	[TCP ZeroWindow] 24253 → 8000 [ACK] Seq=101 Ack=809638 Win=0 Len=0
3738	65.960035587	0.165605472	192.168.0.125	192.168.0.85	TCP	54	[TCP Keep-Alive] 8000 → 24253 [ACK] Seq=809637 Ack=101 Win=64140 Len=0
3739	65.966643525	0.006607938	192.168.0.85	192.168.0.125	TCP	60	[TCP ZeroWindow] 24253 → 8000 [ACK] Seq=101 Ack=809638 Win=0 Len=0
4147	81.320031168	0.451837352	192.168.0.125	192.168.0.85	TCP	54	[TCP Keep-Alive] 8000 → 24253 [ACK] Seq=809637 Ack=101 Win=64140 Len=0
4148	81.344674786	0.024643618	192.168.0.85	192.168.0.125	TCP	60	[TCP ZeroWindow] 24253 → 8000 [ACK] Seq=101 Ack=809638 Win=0 Len=0

It stops right after a few packets due to TCP Window Full. This means the network driver is somehow not offloading the packets properly.
Looking into it.

[fdcavalcanti]

@maxikrie issue seems related to SMP. Something is different and causing it to get stuck.
For a quick fix with a small performance hit: disable CONFIG_SMP. Can you try it?

Here are my results with SMP disabled:

nsh> mcuboot_agent http://192.168.0.125:8000/nuttx.bin
MCUboot Update Agent example
Downloading from http://192.168.0.125:8000/nuttx.bin
Firmware Update size: 1048576 bytes
Received: 512      of 1048576 bytes [0%]
Received: 1024     of 1048576 bytes [0%]
...

Received: 1048302  of 1048576 bytes [99%]
Received: 1048576  of 1048576 bytes [100%]
Application Image successfully downloaded!
Requested update for next boot. Restarting...
�ets Jul 29 2019 12:21:46
...
[esp32] [INF] *** Booting MCUboot build v2.2.0-118-gaa4fa2b6 ***
[esp32] [INF] [boot] chip revision: v3.0
[esp32] [INF] [boot.esp32] SPI Speed      : 40MHz
[esp32] [INF] [boot.esp32] SPI Mode       : DIO
[esp32] [INF] [boot.esp32] SPI Flash Size : 4MB
[esp32] [INF] [boot] Enabling RNG early entropy source...
[esp32] [INF] Primary image: magic=good, swap_type=0x1, copy_done=0x3, image_ok=0x1
[esp32] [INF] Scratch: magic=bad, swap_type=0x2, copy_done=0x2, image_ok=0x2
[esp32] [INF] Boot source: primary slot
[esp32] [INF] Image index: 0, Swap type: test
[esp32] [INF] Starting swap using scratch algorithm.
[esp32] [INF] Disabling RNG early entropy source...
[esp32] [INF] br_image_off = 0x20000
[esp32] [INF] ih_hdr_size = 0x20
[esp32] [INF] Loading image 0 - slot 0 from flash, area id: 1
[esp32] [INF] DRAM segment: start=0x37ca0, size=0x41cc, vaddr=0x3ffc1050
[esp32] [INF] IRAM segment: start=0x20080, size=0x17c20, vaddr=0x40080000
[esp32] [INF] start=0x40084f90
IROM segment aligned lma 0x00060000 vma 0x400d0000 len 0x07b5d0 (505296)
DROM segment aligned lma 0x00040000 vma 0x3f410000 len 0x018adc (101084)
...
NuttShell (NSH) NuttX-12.12.0
This is MCUBoot Update Agent 2
nsh> 

I'll be looking into changes that could have affected and with some luck we will have a quick hotfix for a 12.12.1 and master.

[maxikrie]

@fdcavalcanti Thank you for looking into this!

@acassis

I can confirm that in principle it works when disabling CONFIG_SMP=y. However, it hardly ever gets through to 100% download and fails before with
webclient_perform failed with -11

When compared to nuttx-12.4.0, this really is a degradation.