I've finally managed to get my RFM69 radios working almost 100% and am testing FOTA on my battery powered nodes.
These nodes sleep for 3h, wake up, do some processing, and then go back to sleep.
The summarized sketch is as follows:
void loop()
{
if (!isFirmwareUpdateOngoing()) {
< read sensors and do the processing>
sleep(SLEEP_TIME_3h, true);
}
When I upload a new fw to MYSController, the new fw is detected and the download appears to start for a few lines, but then the node goes to sleep and the update doesn't continue until the next wake-up cycle. This is the node log:
0 MCO:BGN:INIT NODE,CP=RPONA---,VER=2.2.0-rc.1
4 TSM:INIT
4 TSF:WUR:MS=0
8 TSM:INIT:TSP OK
10 TSF:SID:OK,ID=8
12 TSM:FPAR
12 TSM:FPAR:STATP=0
14 TSM:ID
16 TSM:ID:OK
18 TSM:UPL
24 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
45 TSF:MSG:READ,0-0-8,s=255,c=3,t=25,pt=1,l=1,sg=0:1
49 TSF:MSG:PONG RECV,HP=1
53 TSM:UPL:OK
55 TSM:READY:ID=8,PAR=0,DIS=1
65 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=0,pt=6,l=10,sg=0,ft=0,st=OK:03000000400547620300
133 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
145 TSF:MSG:READ,0-0-8,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
159 TSF:MSG:SEND,8-8-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.2.0-rc.1
225 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
258 TSF:MSG:READ,0-0-8,s=255,c=3,t=6,pt=0,l=1,sg=0:M
272 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=11,pt=0,l=17,sg=0,ft=0,st=OK:Sensor de humedad
337 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:3.0
446 TSF:MSG:SEND,8-8-0-0,s=1,c=0,t=35,pt=0,l=13,sg=0,ft=0,st=OK:Humedad suelo
454 MCO:REG:REQ
509 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
524 TSF:MSG:READ,0-0-8,s=255,c=3,t=27,pt=1,l=1,sg=0:1
530 MCO:PIM:NODE REG=1
534 MCO:BGN:STP
534 MCO:BGN:INIT OK,TSP=1
540 TSF:MSG:READ,0-0-8,s=255,c=3,t=6,pt=0,l=1,sg=0:M
737 TSF:MSG:SEND,8-8-0-0,s=1,c=1,t=37,pt=3,l=2,sg=0,ft=0,st=OK:0
804 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=0,pt=1,l=1,sg=0,ft=0,st=OK:25
Value1=775 96.87
Value2=185 97.10
Result = 96.99% (0.43cb)
VCC = 3.30 Volts
VCC% = 25 %
819 MCO:SLP:MS=30000,SMS=1,I1=255,M1=255,I2=255,M2=255
868 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=32,pt=5,l=4,sg=0,ft=0,st=OK:500
899 TSF:MSG:READ,0-0-8,s=0,c=4,t=1,pt=6,l=8,sg=0:0300000040054396
907 OTA:FWP:UPDATE
909 OTA:FRQ:FW REQ,T=0003,V=0000,B=053F
921 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003F05
958 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003F05FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
968 OTA:FWP:RECV B=053F
976 OTA:FRQ:FW REQ,T=0003,V=0000,B=053E
989 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003E05
1026 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003E05003F002100322E322E302D72632E3100
1036 OTA:FWP:RECV B=053E
1042 OTA:FRQ:FW REQ,T=0003,V=0000,B=053D
1054 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003D05
1093 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003D05003C4E4F4E43453E004F4B004E41434B
1103 OTA:FWP:RECV B=053D
1110 OTA:FRQ:FW REQ,T=0003,V=0000,B=053C
1122 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003C05
1155 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003C0525000D0A006E616E00696E66006F7666
1165 OTA:FWP:RECV B=053C
1171 OTA:FRQ:FW REQ,T=0003,V=0000,B=053B
1183 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003B05
1216 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003B0520566F6C74730056434325203D200020
1226 OTA:FWP:RECV B=053B
1234 OTA:FRQ:FW REQ,T=0003,V=0000,B=053A
1247 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003A05
1286 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003A05002520280063622900564343203D2000
1296 OTA:FWP:RECV B=053A
1302 OTA:FRQ:FW REQ,T=0003,V=0000,B=0539
1314 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003905
1349 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003905616C7565323D00526573756C74203D20
1359 OTA:FWP:RECV B=0539
1366 OTA:FRQ:FW REQ,T=0003,V=0000,B=0538
1376 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003805
1384 TSF:TDI:TSL
1388 MCO:SLP:WUP=-1
1390 TSF:TRI:TSB
1398 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=33,pt=5,l=4,sg=0,ft=0,st=OK:30000
1867 OTA:FRQ:FW REQ,T=0003,V=0000,B=0538
1878 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003805
1914 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003805207375656C6F0056616C7565313D0056
1925 OTA:FWP:RECV B=0538
1931 OTA:FRQ:FW REQ,T=0003,V=0000,B=0537
1943 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003705
1978 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:0300000037056564616400332E300048756D65646164
1988 OTA:FWP:RECV B=0537
1996 OTA:FRQ:FW REQ,T=0003,V=0000,B=0536
2009 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003605
2045 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:03000000360507010353656E736F722064652068756D
2056 OTA:FWP:RECV B=0536
2062 OTA:FRQ:FW REQ,T=0003,V=0000,B=0535
2074 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003505
2111 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:03000000350507070707070707070707070707070707
2121 OTA:FWP:RECV B=0535
2127 OTA:FRQ:FW REQ,T=0003,V=0000,B=0534
2140 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003405
2174 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:03000000340507000204060707070707070707070707
2185 OTA:FWP:RECV B=0534
2191 OTA:FRQ:FW REQ,T=0003,V=0000,B=0533
2203 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003305
2238 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:03000000330500AE0A7E0ADE0A520A760A620A530A05
2248 OTA:FWP:RECV B=0533
2256 OTA:FRQ:FW REQ,T=0003,V=0000,B=0532
2269 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003205
2304 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:0300000032051151117C112B12AD118B119F11000000
2314 OTA:FWP:RECV B=0532
2320 OTA:FRQ:FW REQ,T=0003,V=0000,B=0531
2332 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003105
2371 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003105FF3AFF3C053D106F30FF0000000000E4
2381 OTA:FWP:RECV B=0531
2387 OTA:FRQ:FW REQ,T=0003,V=0000,B=0530
2400 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003005
2433 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003005DC2C002D032E882F2D306437D4384239
2443 OTA:FWP:RECV B=0530
2449 OTA:FRQ:FW REQ,T=0003,V=0000,B=052F
2461 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000002F05
2496 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000002F0502044005030633188819422607281029
2506 OTA:FWP:RECV B=052F
2514 OTA:FRQ:FW REQ,T=0003,V=0000,B=052E
2527 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000002E05
2562 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000002E05FF1F0A1F0A01FFF709CF080104020003
2574 OTA:FWP:RECV B=052E
2580 OTA:FRQ:FW REQ,T=0003,V=0000,B=052D
2590 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000002D05
2625 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000002D056C084208A40856042708D407A8079507
2635 OTA:FWP:RECV B=052D
2641 OTA:FRQ:FW REQ,T=0003,V=0000,B=052C
2654 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000002C05
2689 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000002C055040E0F70895F894FFCFFFFF5A073207
2701 OTA:FWP:RECV B=052C
2705 OTA:FRQ:FW REQ,T=0003,V=0000,B=052B
2717 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000002B05
2797 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000002B0548F001900D920020C9F701C01D924150
2807 OTA:FWP:RECV B=052B
2818 OTA:FRQ:FW REQ,T=0003,V=0000,B=052A
2828 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000002A05
2928 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000002A0541505040D8F70895FB01DC0141505040
2938 OTA:FWP:RECV B=052A
<continues>
As can be seen, the node starts, presents itself, etc, does the first processing cycle, and arrives to the sleep instruction (line 819, sleep time reduced to 30s to speed testing). Then some CRC seems to be exchanged with the gw, and it is determined that an fota is needed (line 907). Then some blocks of code are received until the node goes to sleep after receving block 0538 (line 1384). When it returns (line 1388), the update continues with the same block and from there on to the end of the update.
As a side to this, I've capture occasions where the node determined that no fw update was necessary, went to sleep, and then did an update after waking up, like in this case:
942 MCO:SLP:MS=30000,SMS=1,I1=255,M1=255,I2=255,M2=255
993 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=32,pt=5,l=4,sg=0,ft=0,st=OK:500
1021 TSF:MSG:READ,0-0-8,s=0,c=4,t=1,pt=6,l=8,sg=0:0300000040054396
1028 OTA:FWP:UPDATE
1030 OTA:FRQ:FW REQ,T=0003,V=0000,B=053F
1042 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003F05
1071 TSF:MSG:READ,0-0-8,s=0,c=4,t=1,pt=6,l=8,sg=0:0300000040054396
1077 OTA:FWP:UPDATE SKIPPED
1089 TSF:MSG:READ,0-0-8,s=0,c=4,t=1,pt=6,l=8,sg=0:0300000040054396
1097 OTA:FWP:UPDATE SKIPPED
1501 TSF:TDI:TSL
1503 MCO:SLP:WUP=-1
1505 TSF:TRI:TSB
1513 TSF:MSG:SEND,8-8-0-0,s=255,c=3,t=33,pt=5,l=4,sg=0,ft=0,st=OK:30000
1531 OTA:FRQ:FW REQ,T=0003,V=0000,B=053F
1581 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003F05
1615 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003F05FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
1626 OTA:FWP:RECV B=053F
1636 OTA:FRQ:FW REQ,T=0003,V=0000,B=053E
1646 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003E05
1681 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003E05003F002100322E322E302D72632E3100
1693 OTA:FWP:RECV B=053E
1697 OTA:FRQ:FW REQ,T=0003,V=0000,B=053D
1710 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003D05
1980 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003D05003C4E4F4E43453E004F4B004E41434B
1992 OTA:FWP:RECV B=053D
1996 OTA:FRQ:FW REQ,T=0003,V=0000,B=053C
2009 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003C05
2048 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003C0525000D0A006E616E00696E66006F7666
2058 OTA:FWP:RECV B=053C
2064 OTA:FRQ:FW REQ,T=0003,V=0000,B=053B
2076 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003B05
2111 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003B0520566F6C74730056434325203D200020
2121 OTA:FWP:RECV B=053B
2129 OTA:FRQ:FW REQ,T=0003,V=0000,B=053A
2142 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003A05
2416 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003A05002520280063622900564343203D2000
2426 OTA:FWP:RECV B=053A
2433 OTA:FRQ:FW REQ,T=0003,V=0000,B=0539
2445 TSF:MSG:SEND,8-8-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:030000003905
2484 TSF:MSG:READ,0-0-8,s=255,c=4,t=3,pt=6,l=22,sg=0:030000003905616C7565323D00526573756C74203D20
2494 OTA:FWP:RECV B=0539
Lines 1077 (and 1097 again for some reason) indicate UPDATE SKIPPED; the node goes to sleep, but then an update is launched after wake-up.
Of course, no changes in the ino.hex file were done while the node was sleeping.
Would this be expected behaviour or is there some inconsistency? The fact that the firmware update needs to wait until the next wake-up cycle is very inconvenient in this scenario where the node sleeps for hours.
Alternatively is there some detailed description of the FOTA update process flow where I can try to understand?
Thanks.