OTA update fails every other attempt after reset (> r2.4.2)

[aboulfad]

Basic Infos

• This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it.
• I have filled out all fields below.

Platform

• Hardware: [ESP-12]
• Core Version: [2.5.0-b3, 2.5.0, 2.4.2]
• Development Env: [Arduino IDE, cmd line]
• Operating System: [MacOS]

Settings in IDE

• Module: [Nodemcu]
• Flash Mode: [qio]
• Flash Size: [4MB]
• lwip Variant: [v2 Lower Memory]
• Reset Method: [ck]
• Flash Frequency: [40Mhz]
• CPU Frequency: [80Mhz]
• Upload Using: [OTA]
• Upload Speed: OTA

Problem Description

Hello, Arduino OTA fails every other attempt after rest, after much searching and debugging I believe this is a side effect of issue #3481. Arduino OTA uses UDP to initiate the transfer and espota.py expects a reply to the UDP Flash command packet within a timeout. If the esp8266 does not reply with an UDP "OK" payload the script will timeout with the famous "No Answer".

Upon doing various tests, wireshark proves the above behaviour. The first UDP packet issue does not seem to exist in r2.4.2, where OTA update works all the time. The OTA UDP "OK" reply is always sent after an esp8266 reset.

I am not familiar with esp8266 src code, but i've looked at the diffs for 'ArduinoOTA.cpp' of 2.4.2 and 2.5.0, and although i know NULL about C++, it does not seem the issue is introduced from all those updates.

I also quickly diffed lwip v2 of 2.4.2 vs 2.5.0, there is a bunch of patches that also likely did not affect the UDP first packet issue.

I am willing to continue to dig further, if someone could be kind to point me in some direction! A temporary workaround could be to implement a retry on the sendto socket call

Arduino/tools/espota.py

Line 95 in 77451d6

sent = sock2.sendto(message.encode(), remote_address)

in espota.py script.

Steps to reproduce

• Use either 2.5.0 or later installed from IDE board manager.
• Load BasicOTA sketch via serial, then reset
• Attempt OTA update , it will fail on first try, observe that there is NO UDP OK packet sent from esp8266
• Attempt another OTA update, it will work as the UDP OK packet is sent.

[d-a-v]

Me, I would replace this by

  for (int i = 0; i < 10; i++)
  {
    _udp_ota->append("OK", 2);
    _udp_ota->send(ota_ip, _ota_udp_port);
    delay(10);
  }

and replace python's if (data != "OK"): by if ("OK" not in data):.

Better, I would replace this UDP message by a TCP one.
Because UDP has nothing to do here. A TCP message, would be always sent, received and acknowledged reliably.

[aboulfad]

@d-a-v , merci 😄 your workaround should work as we wait for a conclusion on issue #3481 . I wrongly thought a temporary workaround to retry on revc fail in espota.py would work, but noticed that the ArduinoOTA code initiates the TCP transfer irregardless if the UDP OK is sent (and it can’t know as it’s UDP), whereafter espota times out on UDP recv.

I agree whole heartedly that the OTA update init sequence (Flash command/OK) is best served using TCP, but I can’t comment why UDP was chosen.

PS: I just tried your code and it works as intended.

[aboulfad]

Salut @d-a-v , is the enhancement tag for implementing a TCP solution for OTA session initiation instead of UDP? If yes, and if this is accepted, I would like to « attempt » implementing it. I know it would take you guys literally hours to do. I have much spare time and would be nice to make this tiny contribution. I think the scope is mostly limited to ArduinoOTA.cpp and espota.py?

What do you think?

[d-a-v]

Yes go ahead!

(Keep backward compatibility in mind though)

[aboulfad]

That was quick 😀

By backward compatibility, do you mean a solution that initiates the OTA handshake based on a common transport between client and esp?

A scenario I can think of, client has an old version of esports.py which does not support TCP - so switch to UDP, How valid is this?

Afraid I don’t much insight or history about all this so I may be way off... my first attempt will be a simple TCP transport implemented in both .py and .cpp.

PS: heavy focus on attempt as very new to esp code base and C++/python

[aboulfad]

@igrr , do you have any insight why UDP was chosen as the transport for the OTA Flash command? As you are one of the authors for OTA, do you have any additional thoughts regarding our proposal to use TCP for that initial OTA setup?

As this is my first public contrib, I just want to consult and include all relevant folks. Thank you.

[igrr]

UDP was chosen due to resources used, mostly. Keeping a TCP PCB (~socket) listening needed more memory than an open UDP PCB. Also the total number of TCP sockets was limited to 4 or so, in earlier versions of the LwIP (which came pre-compiled with the SDK).

Although on one hand I agree with the "eh, UDP is not reliable, let's slap on TCP here" approach, it might be worth actually looking into the UDP loss issue, especially if it happens predictably ("on every other reset").

[aboulfad]

Thank you for the very valuable insight and quick reply.
One point to add, and I know very little, after the U_FLASH command exchange which uses UDP, a TCP session is used for the firmware transfer.
Couldn’t this same TCP socket be also used for the initial commands too? This way there is no additional resource usage.

The UDP first packet loss is reproduced in every other OTA attempt, predictably, which I believe is related to issue #3481. I can also attempt to look into this but some guidance would be helpful.

[d-a-v]

it might be worth actually looking into the UDP loss issue, especially if it happens predictably ("on every other reset").

I agree with that. I got back to #3481 and found that without some delays, UDP packets are not even sent out.

Couldn’t this same TCP socket be also used for the initial commands too? This way there is no additional resource usage.

I agree with that too.

[aboulfad]

@d-a-v @igrr , Small update, lwip v1.4 (high BW) does NOT exhibit the issue compared to lwip v2 (high BW) in same release 2.5.0. OTA transfer (and hence UDP exchange) works everytime.

The lwip v1.4 -> v2 evolution is convoluted to my noob eyes, I don't think I can narrow it further as the lwip codebase is large and don't have much history.

[aboulfad]

@d-a-v , need some help svp, trying to use lwip debugging by setting ULWIPDEBUG, using your instructions from #3884 (comment), running the sketch outputs nothing related to those defines. I verified that sdk/lib contains the newly compiled -llwip* (am using git checkout 2.5.0)

Other defines that I set, e.g. DEBUG_ESP_MDNS_RESPONDER works fine and show up on serial port.

And I believe if I set both defines UDEBUG & ULWIPDEBUG, compilations breaks ...

lwip2 make install

C  build-536-feat-v6/glue/doprint.o
C  build-536-feat-v6/glue/uprint.o
C  build-536-feat-v6/glue-lwip/lwip-git.o
glue-lwip/lwip-git.c: In function 'new_display_netif':
glue-lwip/lwip-git.c:144:37: error: 'ip_addr_t' has no member named 'addr'
 display_ip32(" ip=", netif->ip_addr.addr);
                                    ^
glue-lwip/lwip-git.c:145:39: error: 'ip_addr_t' has no member named 'addr'
 display_ip32(" mask=", netif->netmask.addr);
                                      ^
glue-lwip/lwip-git.c:146:32: error: 'ip_addr_t' has no member named 'addr'
 display_ip32(" gw=", netif->gw.addr);
                               ^
glue-lwip/lwip-git.c: At top level:
glue-lwip/lwip-git.c:467:9: note: #pragma message: 

-------- TCP_MSS = 536 --------
-------- LWIP_FEATURES = 1 --------
-------- LWIP_IPV6 = 1 --------

#pragma message "\n\n" VAR_NAME_VALUE(TCP_MSS) VAR_NAME_VALUE(LWIP_FEATURES) VAR_NAME_VALUE(LWIP_IPV6)
        ^
make[3]: *** [build-536-feat-v6/glue-lwip/lwip-git.o] Error 1
make[2]: *** [liblwip6-536-feat.a] Error 2
make -f makefiles/Makefile.glue-esp BUILD=build-1460-feat-v6 V=0
C  build-1460-feat-v6/glue-esp/lwip-esp.o
AR liblwip6-1460-feat.a
make -f makefiles/Makefile.glue target=arduino BUILD=build-1460-feat-v6 TCP_MSS=1460 LWIP_FEATURES=1 LWIP_IPV6=1 V=0
C  build-1460-feat-v6/glue/doprint.o
C  build-1460-feat-v6/glue/uprint.o
C  build-1460-feat-v6/glue-lwip/lwip-git.o
glue-lwip/lwip-git.c: In function 'new_display_netif':
glue-lwip/lwip-git.c:144:37: error: 'ip_addr_t' has no member named 'addr'
 display_ip32(" ip=", netif->ip_addr.addr);
                                    ^
glue-lwip/lwip-git.c:145:39: error: 'ip_addr_t' has no member named 'addr'
 display_ip32(" mask=", netif->netmask.addr);
                                      ^
glue-lwip/lwip-git.c:146:32: error: 'ip_addr_t' has no member named 'addr'
 display_ip32(" gw=", netif->gw.addr);
                               ^
glue-lwip/lwip-git.c: At top level:
glue-lwip/lwip-git.c:467:9: note: #pragma message: 

-------- TCP_MSS = 1460 --------
-------- LWIP_FEATURES = 1 --------
-------- LWIP_IPV6 = 1 --------

#pragma message "\n\n" VAR_NAME_VALUE(TCP_MSS) VAR_NAME_VALUE(LWIP_FEATURES) VAR_NAME_VALUE(LWIP_IPV6)
        ^
make[3]: *** [build-1460-feat-v6/glue-lwip/lwip-git.o] Error 1
make[2]: *** [liblwip6-1460-feat.a] Error 2
make[1]: *** [install] Error 2
make: *** [install] Error 2```
</details>

[d-a-v]

This bug is already fixed in master (and I just fixed the previous fix), in tools/sdk/lwip2/:

cd builder
git fetch
git checkout master

edit: Sorry for being unclear. Only the compilation error is fixed.

[aboulfad]

Sorry, unsure to which bug you say is fixed, no lwip debugging output or setting both defines that breaks compilation? Ok the latter.

In any case I’ll checkout builder master and go from there. Thank you.
PS: found it d-a-v/esp82xx-nonos-linklayer@10c1fe1 Oh its fresh off the oven!