search

mongoose-os-apps / shelly-homekit

Apple HomeKit firmware for Shelly's
Other
1.78k stars 128 forks source link

+1/+1PM upgrades seems to finish, but didnt upgrade #1433

Open Littlericket opened 1 month ago

Littlericket commented 1 month ago

Hi all,

i have 2 out of 10 shelly 1 plus at my home which are not correctly upgrading. I dont know if they both were in the same double-package and have some common differences with the other ones in this home.

When applying the upgrade, the process runs successfully, but after rebooting the shelly is still running the previous version, even if the logs tell me that everything went fine.

Tried downgrading, upgrading (from 2.11.2 to 2.12.1) , reverting to stock. The shelly always comes back with the previous version 2.11.2.

Below the log entries when starting the upgrade.

1587473164 mgos_ota_core.c:656     FW: Plus1 esp32 2.12.1 20240623-075054/2.12.1-g417cbdf sig 0x00
1592449201 shelly_ota.cpp:90       Starting firmware update
1592463683 esp32xx_ota_backend:209 App: Plus1.bin -> app_0 enc 0, FS: fs.img -> fs_0 enc 0
1592470759 mgos_mongoose.c:66      New heap free LWM: 191904
1592477697 mgos_mongoose.c:66      New heap free LWM: 190360
1592485015 mgos_ota_core.c:685     0.15% total, bootloader.bin 512 of 23728
1592492514 mgos_ota_core.c:1202    Update state: 0
1592749625 mgos_ota_core.c:685     1.59% total, partition-table.bin 512 of 3072
1592757215 mgos_ota_core.c:1202    Update state: 0
1592787058 mgos_ota_core.c:685     1.78% total, otadata.bin 512 of 8192
1592794606 mgos_ota_core.c:1202    Update state: 0
1592994993 esp32xx_ota_backend:303 Writing FS @ 0x190000
1593271487 mgos_ota_core.c:685     2.27% total, fs.img 512 of 458752
1593279087 mgos_ota_core.c:1202    Update state: 0
1596631647 mgos_ota_core.c:685     18.13% total, fs.img 262656 of 458752
1596639355 mgos_ota_core.c:1202    Update state: 0
1599408737 esp32xx_ota_backend:399 fs_0 verified (429e0768a2f79d22bfe9fcbb5aaf057f1977d88b)
1599793739 esp32xx_ota_backend:299 Skip writing app (digest matches)
1599808646 mgos_ota_core.c:685     30.03% total, Plus1.bin 512 of 1156448
1599816325 mgos_ota_core.c:1202    Update state: 0
1600441530 shelly_main.cpp:449     Up 1600.43, HAP 0/0/16 ns 0, RAM: 200624/190360; st 44; disabled
1601097220 mgos_ota_core.c:685     45.89% total, Plus1.bin 262656 of 1156448
1601104796 mgos_ota_core.c:1202    Update state: 0
1602365390 mgos_ota_core.c:685     61.75% total, Plus1.bin 524800 of 1156448
1602373363 mgos_ota_core.c:1202    Update state: 0
1603624269 mgos_ota_core.c:685     77.61% total, Plus1.bin 786944 of 1156448
1603631862 mgos_ota_core.c:1202    Update state: 0
1604920368 mgos_ota_core.c:685     93.46% total, Plus1.bin 1049088 of 1156448
1604928924 mgos_ota_core.c:1202    Update state: 0
1605447556 mgos_ota_core.c:820     Reached the end of archive
1605459862 esp32xx_ota_backend:463 Setting boot partition to app_0
1605469123 I (1606158) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=30944h (198980) map
1605586052 I (1606278) esp_image: segment 1: paddr=0004096c vaddr=3ffb0000 size=03630h ( 13872) 
1605603000 I (1606288) esp_image: segment 2: paddr=00043fa4 vaddr=40080000 size=0c074h ( 49268) 
1605638405 I (1606328) esp_image: segment 3: paddr=00050020 vaddr=400d0020 size=d1f40h (859968) map
1606097992 I (1606788) esp_image: segment 4: paddr=00121f68 vaddr=4008c074 size=085b0h ( 34224) 
1606125380 I (1606818) esp_image: segment 5: paddr=0012a520 vaddr=50000000 size=00010h (    16) 
1606134834 I (1606828) esp_ota_ops: New OTA data 0: seq 0x0000005b, st 0x10, CRC 0x12ad02a7
1606194324 mgos_ota_core.c:1051    Update finished, result 1 (Update applied, rebooting)
1606200533 mgos_ota_core.c:1202    Update state: 0
markirb commented 1 month ago

Mhhh everything looks okay.

This does not look like a software issue to me unfortunately... :(

I think somehow the device bots the new version and then reverts, because it did not boot successfully...

mike-jl commented 3 weeks ago

same problem here..

Littlericket commented 2 weeks ago

Mhhh everything looks okay.

This does not look like a software issue to me unfortunately... :(

I think somehow the device bots the new version and then reverts, because it did not boot successfully...

I had similiar issues when trying to flash mongoose for the first time tho. It took me several attempts that the shelly finally booted into the mongoose os. It mostly came back with the original shelly firmware. I dont know if these shellys maybe need a special formatting of the firmware image, which differs than the current known layering for plus 1? But that would mean that I could never have flashed these shellys in the first place. I don‘t know whats happening. Still, I have one shelly plus which can not be flashed to mongoose. Maybe there‘s something going on with different hardware units?

Interestingly, the flash-shelly python tool also doens‘t correctly detect these units. I can see them when running in verbose, but it seems there is no action being taken after being discovered with mdns. This happens with units on mongoose and on original firmware, which always come back as before.

markirb commented 2 weeks ago

Mhhh everything looks okay. This does not look like a software issue to me unfortunately... :( I think somehow the device bots the new version and then reverts, because it did not boot successfully...

I had similiar issues when trying to flash mongoose for the first time tho. It took me several attempts that the shelly finally booted into the mongoose os. It mostly came back with the original shelly firmware. I dont know if these shellys maybe need a special formatting of the firmware image, which differs than the current known layering for plus 1? But that would mean that I could never have flashed these shellys in the first place.

Exactly, this is the strange thing, the reason has to be somehow non-deterministic.

I don‘t know whats happening. Still, I have one shelly plus which can not be flashed to mongoose. Maybe there‘s something going on with different hardware units?

There definitely seems to be something. But without a serial bootlog this won't be a problem we can debug. Unfortunately I have no device where this seems to happen.

Interestingly, the flash-shelly python tool also doens‘t correctly detect these units. I can see them when running in verbose, but it seems there is no action being taken after being discovered with mdns. This happens with units on mongoose and on original firmware, which always come back as before.

This makes it even more strange... ?!

Littlericket commented 2 weeks ago

@markirb I can send you one of the failing ones if you would like. I have some st links but not really into shelly debugging. I could imagine that these shellys maybe have two boot partitions and one is maybe read-only, whereas the other inactive one can be written on. Maybe the partition has to be switched to before a firmware upgrade. But thats only a thing I know from higher priced STM boards.

Peeeep commented 2 weeks ago

I had the same issue and no indication of an error in the logs. Got it to work by first reverting to stock (1.3.3), factory resetting from the shelly ui, then flashing again using http://A.B.C.D/ota?url=http://shelly.rojer.cloud/update.

markirb commented 2 weeks ago

I think it has to do with the filesystem somehow. On startup of the new fw it tries to copy over the old config. If it cannot do that a revert is triggered.

That's why it can work on a freshly reset one.

xsaranaut commented 2 days ago

I ran into this problem right now. Tried to reset to stock firmware - successfully. Then tried to update to 2.12.2 via ota, which wasn't successful either. So I captured the log, maybe it helps:

Connected. 11:35:02 shelly_debug.cpp:236 Streaming logs to 192.168.172.189:62794 11:35:02 shos_rpc_inst.c:222 No handler for Shelly.GetInfo 11:35:10 shos_rpc_inst.c:222 No handler for Shelly.GetInfo 11:35:11 shelly_ota_source_ht:33 Update URL: http://shelly.rojer.cloud/update (0x3ffe431c) 11:35:53 shelly_http_client.:304 0x3ffe5154: HTTP GET http://shelly.rojer.cloud/update 11:35:53 shelly_ota.cpp:248 Starting update (0x3ffe3d44), to=600 cd=0/ct=0 ignore_same=0 11:35:53 shelly_http_client.:607 0x3ffe5154: Finished; bytes 416, code 302, redir 1/3, auth 0, status ABORTED: Abandoned 11:35:53 shelly_http_client.:304 0x3ffe5154: HTTP GET http://shelly.rojer.cloud/shelly-homekit-ShellyPlus1.zip 11:35:53 shelly_ota.cpp:375 Plus1-2.12.2/manifest.json: 1805 bytes (hdr 56 desc 0 CRC 7f043517) 11:35:53 shelly_ota.cpp:554 fw: Plus1 ver 2.12.2 20240912-182009/2.12.2-gfff6707 11:35:53 shelly_ota.cpp:182 OTA status in_progress, 0 % 11:35:53 shelly_update.cpp:332 incoming fw signatures: 00 11:35:53 shelly_ota_esp32_ba:512 Will write to slot 0 11:35:53 shelly_ota.cpp:375 Plus1-2.12.2/bootloader.bin: 23728 bytes (hdr 57 desc 0 CRC dc7241b3) 11:35:53 shos_init.c:94 New min heap free: 106808 11:35:53 shelly_notification:208 Event from sys: {"component":"sys", "event":"ota_begin", "msg":"in_progress", "ts":1727429753.37} 11:35:53 shos_init.c:94 New min heap free: 106652 11:35:53 shelly_ota_esp32_ba:709 Boot: cur 010000ff, new 00040127, min 00000000, update? 0 11:35:53 shelly_ota.cpp:375 Plus1-2.12.2/partition-table.bin: 3072 bytes (hdr 62 desc 0 CRC e2333c22) 11:35:53 shelly_ota_esp32_ba:620 New app_0: 1572864@0x10000 11:35:54 shelly_ota_esp32_ba:620 New fs_0: 458752@0x190000 11:35:54 shelly_ota.cpp:261 Aborting update: backend error while processing data: -1 (-11: PT update is req'd but unsupported by the new fw) 11:35:54 shelly_ota.cpp:182 OTA status error, 1 % 11:35:54 shelly_notification:208 Event from sys: {"component":"sys", "event":"ota_error", "msg":"error", "ts":1727429754.01} 11:35:54 shelly_http_client.:607 0x3ffe5154: Finished; bytes 33120, code 200, redir 0/2, auth 0, status CANCELLED: Cancelled

markirb commented 2 days ago

I ran into this problem right now. Tried to reset to stock firmware - successfully. Then tried to update to 2.12.2 via ota, which wasn't successful either. So I captured the log, maybe it helps:

`Connected.

11:35:02

shelly_debug.cpp:236 Streaming logs to 192.168.172.189:62794

11:35:02

shos_rpc_inst.c:222 No handler for Shelly.GetInfo

11:35:10

shos_rpc_inst.c:222 No handler for Shelly.GetInfo

11:35:11

shelly_ota_source_ht:33 Update URL: http://shelly.rojer.cloud/update (0x3ffe431c)

11:35:53

shelly_http_client.:304 0x3ffe5154: HTTP GET http://shelly.rojer.cloud/update

11:35:53

shelly_ota.cpp:248 Starting update (0x3ffe3d44), to=600 cd=0/ct=0 ignore_same=0

11:35:53

shelly_http_client.:607 0x3ffe5154: Finished; bytes 416, code 302, redir 1/3, auth 0, status ABORTED: Abandoned

11:35:53

shelly_http_client.:304 0x3ffe5154: HTTP GET http://shelly.rojer.cloud/shelly-homekit-ShellyPlus1.zip

11:35:53

shelly_ota.cpp:375 Plus1-2.12.2/manifest.json: 1805 bytes (hdr 56 desc 0 CRC 7f043517)

11:35:53

shelly_ota.cpp:554 fw: Plus1 ver 2.12.2 20240912-182009/2.12.2-gfff6707

11:35:53

shelly_ota.cpp:182 OTA status in_progress, 0 %

11:35:53

shelly_update.cpp:332 incoming fw signatures: 00

11:35:53

shelly_ota_esp32_ba:512 Will write to slot 0

11:35:53

shelly_ota.cpp:375 Plus1-2.12.2/bootloader.bin: 23728 bytes (hdr 57 desc 0 CRC dc7241b3)

11:35:53

shos_init.c:94 New min heap free: 106808

11:35:53

shelly_notification:208 Event from sys: {"component":"sys", "event":"ota_begin", "msg":"in_progress", "ts":1727429753.37}

11:35:53

shos_init.c:94 New min heap free: 106652

11:35:53

shelly_ota_esp32_ba:709 Boot: cur 010000ff, new 00040127, min 00000000, update? 0

11:35:53

shelly_ota.cpp:375 Plus1-2.12.2/partition-table.bin: 3072 bytes (hdr 62 desc 0 CRC e2333c22)

11:35:53

shelly_ota_esp32_ba:620 New app_0: 1572864@0x10000

11:35:54

shelly_ota_esp32_ba:620 New fs_0: 458752@0x190000

11:35:54

shelly_ota.cpp:261 Aborting update: backend error while processing data: -1 (-11: PT update is req'd but unsupported by the new fw)

11:35:54

shelly_ota.cpp:182 OTA status error, 1 %

11:35:54

shelly_notification:208 Event from sys: {"component":"sys", "event":"ota_error", "msg":"error", "ts":1727429754.01}

11:35:54

shelly_http_client.:607 0x3ffe5154: Finished; bytes 33120, code 200, redir 0/2, auth 0, status CANCELLED: Cancelled`

This is not this issue. You are trying to upgrade from 1.4.x which is not supported ATM. See readme

xsaranaut commented 2 days ago

Sorry, overlooked the 1.3.3 remark. Trying to downgrade it and then install 2.12.2 again.

Thank you @markirb

lindingerm commented 9 hours ago

Same problem here. Two ShellyPlus1 updated successfully to 2.12.2. One is not updating. It stay on 2.12.1 (20240623-075054/2.12.1-g417cbdf)

Here is my Log:

348571358 shelly_ota.cpp:90       Starting firmware update
348584642 esp32xx_ota_backend:209 App: Plus1.bin -> app_0 enc 0, FS: fs.img -> fs_0 enc 0
348596050 mgos_ota_core.c:685     0.15% total, bootloader.bin 512 of 23728
348603842 mgos_ota_core.c:1202    Update state: 0
348725539 mgos_ota_core.c:685     1.59% total, partition-table.bin 512 of 3072
348733377 mgos_ota_core.c:1202    Update state: 0
348759798 mgos_ota_core.c:685     1.78% total, otadata.bin 512 of 8192
348767598 mgos_ota_core.c:1202    Update state: 0
348964620 esp32xx_ota_backend:303 Writing FS @ 0x190000
349221496 mgos_ota_core.c:685     2.27% total, fs.img 512 of 458752
349229388 mgos_ota_core.c:1202    Update state: 0
349236405 mgos_mongoose.c:66      New heap free LWM: 193308
349408982 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
349474491 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
350410630 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
350476622 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
351714840 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
351797030 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
352541662 mgos_ota_core.c:685     18.13% total, fs.img 262656 of 458752
352549547 mgos_ota_core.c:1202    Update state: 0
352566306 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
352802096 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
353411653 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
353475792 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
353891901 shelly_main.cpp:483     Up 353.88, HAP 0/0/16 ns 0, RAM: 202160/193308; st 47; disabled
354413228 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
354502078 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
355243288 esp32xx_ota_backend:399 fs_0 verified (27a5f139e357555037b1d626e6304909684d6576)
355630948 esp32xx_ota_backend:299 Skip writing app (digest matches)
355649924 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
355670619 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
355681480 mgos_mongoose.c:66      New heap free LWM: 193008
355688790 mgos_ota_core.c:685     30.03% total, Plus1.bin 512 of 1156448
355696555 mgos_ota_core.c:1202    Update state: 0
355709858 mgos_mongoose.c:66      New heap free LWM: 192344
356414630 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
356474506 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
356964765 mgos_ota_core.c:685     45.89% total, Plus1.bin 262656 of 1156448
356972639 mgos_ota_core.c:1202    Update state: 0
357416681 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
357474422 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
358232438 mgos_ota_core.c:685     61.75% total, Plus1.bin 524800 of 1156448
358240348 mgos_ota_core.c:1202    Update state: 0
358415224 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
358475636 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
359417391 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
359473618 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
359544691 mgos_ota_core.c:685     77.61% total, Plus1.bin 786944 of 1156448
359552543 mgos_ota_core.c:1202    Update state: 0
360418348 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
360473104 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin
360811171 mgos_ota_core.c:685     93.47% total, Plus1.bin 1049088 of 1156448
360819046 mgos_ota_core.c:1202    Update state: 0
361316518 mgos_ota_core.c:820     Reached the end of archive
361329952 esp32xx_ota_backend:463 Setting boot partition to app_0
361339198 I (361959) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=30944h (198980) map
361454721 I (362079) esp_image: segment 1: paddr=0004096c vaddr=3ffb0000 size=03630h ( 13872) 
361472355 I (362089) esp_image: segment 2: paddr=00043fa4 vaddr=40080000 size=0c074h ( 49268) 
361507640 I (362129) esp_image: segment 3: paddr=00050020 vaddr=400d0020 size=d1f40h (859968) map
361974378 I (362599) esp_image: segment 4: paddr=00121f68 vaddr=4008c074 size=085b0h ( 34224) 
362001665 I (362619) esp_image: segment 5: paddr=0012a520 vaddr=50000000 size=00010h (    16) 
362011065 I (362629) esp_ota_ops: New OTA data 1: seq 0x00000013, st 0x10, CRC 0x9141b478
362064461 mgos_ota_core.c:1051    Update finished, result 1 (Update applied, rebooting)
362070898 mgos_ota_core.c:1202    Update state: 0
362075688 mgos_ota_core.c:1096    Update requires reboot
362128400 mgos_mongoose.c:66      New heap free LWM: 190448
362147604 shelly_main.cpp:483     Up 362.14, HAP 0/0/16 ns 0, RAM: 206420/190448; st 47; disabled
362418018 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:50612 user admin
362474344 mg_rpc.c:315            Shelly.GetInfoExt via WS_in 192.168.178.31:63829 user admin