espota.py does not receive `OK` when Signed Update is used

[thangktran]

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.2]
• Development Env: [Arduino IDE]
• Operating System: [Ubuntu]

Problem Description

When Signed Update is used, the *bin.signed is uploaded normally. However when the upload is done, espota.py did not receive any OK ACK and timeouted.

/home/ubuntu/.arduino15/packages/esp8266/tools/python/3.7.2-post1/python /home/ubuntu/.arduino15/packages/esp8266/hardware/esp8266/2.5.2/tools/espota.py -i 192.168.0.101 -p 49867 --auth=************ -f /tmp/arduino_build_503180/sketch_jul09a.ino.bin 
Signed Update is used. /tmp/arduino_build_503180/sketch_jul09a.ino.bin.signed will be uploaded instead.
Authenticating...OK
Uploading..................................................................................................................................................................................................................................................
11:38:33 [ERROR]: No Result!

The ESP-12 did however receive this update and execute the new update normally.

I believe the bug is somewhere in the Updater module that makes Update.end() return false
hence

Arduino/libraries/ArduinoOTA/ArduinoOTA.cpp

Lines 330 to 333 in 824a833

	if (Update.end()) {
	client.print("OK");
	client.stop();
	delay(10);

I'm currently investigating this bug.

[earlephilhower]

Looking at the Updater base class, it seems like the uboot is only ever told to do something at the very end:

Arduino/cores/esp8266/Updater.cpp

Lines 266 to 284 in 824a833

	if (_command == U_FLASH) {
	eboot_command ebcmd;
	ebcmd.action = ACTION_COPY_RAW;
	ebcmd.args[0] = _startAddress;
	ebcmd.args[1] = 0x00000;
	ebcmd.args[2] = _size;
	eboot_command_write(&ebcmd);
	#ifdef DEBUG_UPDATER
	DEBUG_UPDATER.printf_P(PSTR("Staged: address:0x%08X, size:0x%08zX\n"), _startAddress, _size);
	}
	else if (_command == U_FS) {
	DEBUG_UPDATER.printf_P(PSTR("Filesystem: address:0x%08X, size:0x%08zX\n"), _startAddress, _size);
	#endif
	}
	_reset();
	return true;
	}

That path can only ever return true to the ArduinoOTA library.

What I think is more likely is a race condition. Could it be possible that the OK message was not sent over the air before the system completely rebooted? A quick and easy (wrong, too, but easy) way yo check would be to make that delay(10) a delay(5000). If that consistently passes then maybe client.stop() needs a flush() before it, or some other sort of handshake (or, at least, a longer default delay)...

[thangktran]

@earlephilhower Thank you for your hint.
The problem is indeed because the message was not sent over the air before the system completely rebooted. i changed the delay(5000) and it fixes the problem.
We already have a flush() inside client.stop, i tested calling client.flush explicitly with delay of [300, 500, 800, 1000, 2000, 5000] but it doesn't work.
I then tested the delay with different value [300, 500, 800, 1000, 2000, 5000], and it seems that the system needs minimum 1000ms delay to work properly.