Tasmota: Strange OTA behaviour with .gz files

Created on 30 May 2020 · 8Comments · Source: arendst/Tasmota

PROBLEM DESCRIPTION

1: When uploading a .gz file via OTA the device immediately restarts the upload again after reboot.
2: When a .gz file is upload and restarting an OTA update for the same file it is not detected that it is the same file (since the device sends the .bin hash, not the .gz hash, in the request)

REQUESTED INFORMATION

_Make sure your have performed every step and checked the applicable boxes before submitting your issue. Thank you!_

[ x] Read the Contributing Guide and Policy and the Code of Conduct
[x ] Searched the problem in issues
[x ] Searched the problem in the docs
[x ] Searched the problem in the forum
[x ] Searched the problem in the chat
[x ] Device used (e.g., Sonoff Basic): Sonoff Basic, L-10-A01
[x ] Tasmota binary firmware version number used: 8.3.1
- [ x] Pre-compiled
- [ ] Self-compiled
- [ ] IDE / Compiler used: _____
[x ] Flashing tools used: OTA
[ ] Provide the output of command: Backlog Template; Module; GPIO 255:

  Configuration output here:
20:29:00 CMD: Backlog Template; Module; GPIO 255
20:29:00 MQT: stat/tasmota/newL10A01/RESULT = {"NAME":"Generic","GPIO":[255,255,255,255,255,255,255,255,255,255,255,255,255],"FLAG":15,"BASE":18}
20:29:01 MQT: stat/tasmota/newL10A01/RESULT = {"Module":{"7":"Sonoff 4CH"}}
20:29:01 MQT: stat/tasmota/newL10A01/RESULT = {"GPIO0":{"17":"Button1"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"23":"Relay3"},"GPIO5":{"22":"Relay2"},"GPIO9":{"18":"Button2"},"GPIO10":{"19":"Button3"},"GPIO12":{"21":"Relay1"},"GPIO13":{"56":"Led1i"},"GPIO14":{"20":"Button4"},"GPIO15":{"24":"Relay4"},"GPIO16":{"0":"None"}}

[ ] If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:

  Rules output here:

[x ] Provide the output of this command: Status 0:

  STATUS 0 output here:
20:30:38 CMD: Status 0
20:30:38 MQT: stat/tasmota/newL10A01/STATUS = {"Status":{"Module":7,"DeviceName":"newL10A01","FriendlyName":["newL10A01-1","newL10A01-2","newL10A01-3","newL10A01-4"],"Topic":"newL10A01","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://192.168.19.200:1880/esp8266-ota/update/tasmota.bin","RestartReason":"Software/System restart","Uptime":"0T00:23:17","StartupUTC":"2020-05-30T19:07:21","Sleep":50,"CfgHolder":4617,"BootCount":41,"BCResetTime":"2020-05-07T19:20:12","SaveCount":148,"SaveAddress":"FA000"}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS2 = {"StatusFWR":{"Version":"8.3.1(tasmota)","BuildDateTime":"2020-05-18T15:39:35","Boot":31,"Core":"2_7_1","SDK":"2.2.2-dev(38a443e)","Hardware":"ESP8285","CR":"431/699"}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["PeeGee-Wifi1",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["00008009","2805C8000100060000005A00000000000000","00000000","00000000"]}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS4 = {"StatusMEM":{"ProgramSize":587,"Free":416,"Heap":23,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"144051","FlashMode":3,"Features":["00000809","8FDAE797","043683A0","000000CD","010013C0","C000F981","00000024"],"Drivers":"1,2,3,4,5,6,7,8,9,10,12,16,18,19,20,21,22,24,26,27,29,30,35,37","Sensors":"1,2,3,4,5,6"}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS5 = {"StatusNET":{"Hostname":"tmNewL10A01","IPAddress":"192.168.19.21","Gateway":"192.168.19.1","Subnetmask":"255.255.255.0","DNSServer":"84.116.46.21","Mac":"D8:F1:5B:C8:92:7A","Webserver":2,"WifiConfig":4,"WifiPower":17.0}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS6 = {"StatusMQT":{"MqttHost":"192.168.19.200","MqttPort":1883,"MqttClientMask":"DVES_%12X","MqttClient":"DVES_000000C8927A","MqttUser":"PeeGeeHome","MqttCount":1,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS7 = {"StatusTIM":{"UTC":"2020-05-30T19:30:38","Local":"2020-05-30T20:30:38","StartDST":"2020-03-29T02:00:00","EndDST":"2020-10-25T03:00:00","Timezone":"+01:00","Sunrise":"04:52","Sunset":"20:43"}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS10 = {"StatusSNS":{"Time":"2020-05-30T20:30:38"}}
20:30:38 MQT: stat/tasmota/newL10A01/STATUS11 = {"StatusSTS":{"Time":"2020-05-30T20:30:38","Uptime":"0T00:23:17","UptimeSec":1397,"Heap":23,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER1":"OFF","POWER2":"OFF","POWER3":"OFF","POWER4":"OFF","Wifi":{"AP":1,"SSId":"PeeGee-Wifi1","BSSId":"9C:2A:70:08:CA:8A","Channel":6,"RSSI":50,"Signal":-75,"LinkCount":1,"Downtime":"0T00:00:06"}}}

[x ] Provide the output of the Console log output when you experience your issue; if applicable:
_(Please use_ weblog 4 _for more debug information)_

  Console output here:
20:33:07 CMD: weblog 4
20:33:07 MQT: stat/tasmota/newL10A01/RESULT = {"WebLog":4}
20:33:07 CFG: Saved to flash at F9, Count 149, Bytes 4096
20:33:08 WIF: Checking connection...

TO REPRODUCE

_Steps to reproduce the behavior:_
1 upload tasmota-lite.bin
2 upload tasmota.bin.gz (will restart update on reboot)
3 upload tasmota.bin.gz again (will start update although already correct version)
4 upload tasmota.bin.gz again (will start update although already correct version)
5 upload tasmota.bin (no update, same version)

EXPECTED BEHAVIOUR

Not update again after successful upload or already same version.
(Especially since .gz update should be faster. Now, because of double upload it is much slower.)

SCREENSHOTS

_If applicable, add screenshots to help explain your problem._

ADDITIONAL CONTEXT

_Add any other context about the problem here._
I noticed that tasmota always sends the .bin hash in the OTA request, even when requesting .gz and .gz already loaded. This explains problem 2.

Note that problem 1 (restarting update after reboot) only happens when switching from .bin to .gz or to a different .gz.

(Please, remember to close the issue when the problem has been addressed)

question

Source

pgScorpio

All 8 comments

To better understand your situation pls try to connect your device serially and set seriallog to 3. Then log all information regarding your OTA transactions to see where you go wrong.

arendst on 31 May 2020

@ascillato2 : Sorry this is not a question but a bug report.

@arendst : Unfortunately none of my devices are easily accesable (that's why I'm using OTA).

But I think the problem is quite clear (at least to me).
On an OTA update request tasmota sends the current firmware MD5 hash in the request.
If the hash equals the hash of the requested file the response 304 "Not Modified" is returned, so in this case no update, all logical.

The main problem is that tasmota always sends the .bin hash in an update request, even when the current loaded version is a .bin.gz,
So you can never switch from a tasmota-xxx.bin.gz to the tasmota-xxx.bin (returns 304 "Not Modified" since the MD5 hashes match) and requesting an update for a tasmota-xxx-.bin.gz always performs the update, even when tasmota-xxx-.bin.gz is already loaded (since the .bin.gz hash mismatches the send .bin hash).

P.S. An additional problem is (AFAIK) you can't see which file is loaded. "Device Information" shows Version number and Build Date but not the filename. so no idea if you have bin or bin.gz nor any idea of standard or -lite -classic -sensors -knx etc.

P.S.2: Problem 1 (Restarting update after update with .gz) Probably was when trying to upgrade from an older version to 8.3.1. since I recently upgraded all my devices to 8.3.1 and saw this happening several times but it might be that those devices where still pre 8.2.0. Now all devices are at v8.3.1 I cannot reproduce it anymore.

pgScorpio on 1 Jun 2020

👍1

Although clear to you it's a mystery to me.

As far as I know Tasmota does not use the MD5 hash on both OTA upgrade functions; it just tries to load the file the user wants it to load either .bin or .bin.gz at any time!

Finding the loaded file version is easily seen during a restart:

10:53:22 MQT: tele/wemos4/INFO1 = {"Module":"Generic","Version":"8.3.1(sensors)","FallbackTopic":"cmnd/TAS_000083BB10_fb/","GroupTopic":"cmnd/tasmotas/"}

or using command status 2:

10:54:41 MQT: stat/wemos4/STATUS2 = {"StatusFWR":{"Version":"8.3.1(sensors)","BuildDateTime":"2020-05-18T15:41:26","Boot":31,"Core":"2_7_1","SDK":"2.2.2-dev(38a443e)","Hardware":"ESP8266EX","CR":"387/699"}}

in this case binary tasmota-sensors is loaded.

The difference in .bin and .bin.gz is unknown to tasmota as it is being services by the Arduino bootloader which, depending on it's signature decompresses a gzipped compressed file if needed then transfers execution to tasmota.

So again, to further assist you you will need to provide more logging information either using syslog or weblog.

arendst on 2 Jun 2020

Although clear to you it's a mystery to me.

As far as I know Tasmota does not use the MD5 hash on both OTA upgrade functions; it just tries to load the file the user wants it to load either .bin or .bin.gz at any time!

So this bug must be in the OTA library or under-laying libraries.

Finding the loaded file version is easily seen during a restart:
...
or using command status 2:
...
in this case binary tasmota-sensors is loaded.

Thanks for the hint. I didn't notice the (sensors) before since normally I always use the basic version showing just (tasmota), the same as showed at the bottom of the web-gui (Tasmota 8.3.1 by Theo Arends).
Showing the full filename might be more clear, ;=)

The difference in .bin and .bin.gz is unknown to tasmota as it is being services by the Arduino bootloader which, depending on it's signature decompresses a gzipped compressed file if needed then transfers execution to tasmota.

So again, to further assist you you will need to provide more logging information either using syslog or weblog.

The .bin / .bin.gz problem clearly has to do with the MD5 hash send in the update request, so I think we need to direct this issue to the correct source.
Since I don't know where the MD5 hash is obtained from, it might be the OTA library, but it also might be the kernel/bootloader, this needs some further inverstigation.

Will you guys pick this up (since it's causing issues with tasmota updates) or should I ?
(In the latter case I need to know the exact source and versions of OTA Library/bootloader/kernel you are using.)

pgScorpio on 2 Jun 2020

As I cannot reproduce I see no reason to escalate.

I still haven't seen any tracing/logging of your issue and also see nowhere where MD5 would be the source of your issue. I rather think you mess up the idea of loading -minimal first before the final non-gzipped binary will be loaded but again, without a log I'm in the dark.

For me, and other users this issue is unknown.

arendst on 2 Jun 2020

OK, log files attached.

I Included the Info page before, between and after updates.
perhaps they say more than the logs:
"Boot count", increments by one on every update.
"Flash write Count", increments by 3 on first update and by 2 on next updates.
"Program sizes", don't change at all.

update-logs.txt

There are no MD5 hashes in the logs. Those I obtained by logging the server site while using a (modified) version of https://flows.nodered.org/flow/888b4cd95250197eb429b2f40d188185
The original version does not accept .gz files, but you still you can see the hashes in the requests.
My current version seems to work ok with .gz files now (but still cannot determine if the current loaded file is bin or gz):
pgoESP8266-OTA.zip

pgScorpio on 3 Jun 2020

I see nothing strange in the update-logs.txt. All is as expected excluding the many commands executes just after a restart but that's not standard tasmota practice. In the log you also find the loading of the -minimal version before the final version due to memory restraints. Before every OTA upload the settings are stored in a fixed location safe from OTA overwrites so that explains the incremental flash write count. Program size is shown in 4k increments so you will likely not see a change there when minor changes have been made to the code.

As said before tasmota does not check the OTA uploaded code for version or size or equalty or anything else; it just OTA uploads what the user wants it to upload.

I see you use a node-red tool to provide OTA uploads. If that tools checks MD5 and/or version info it's up to the tool owner to do it. Tasmota has no knowledge of the OTA server. I'm just using plain old apache to provide my OTA files.

So for me I think this issue can be closed.

arendst on 4 Jun 2020

I see nothing strange in the update-logs.txt. All is as expected excluding the many commands executes just after a restart but that's not standard tasmota practice.

If you looked at the logs you should also have seen that these updates where from the official Tasmota repository, standard tasmota, so what do you mean by "not standard tasmota practice"