FOTA flow in sleeping nodes - need two cycles?

tekka

@manutremo Can you post the entire sketch + full log when you receive a "OTA:FWP:UPDATE SKIPPED" message. In addition, it would be helpful to get infos on your setup, i.e. HW, IDE & board definition versions.

manutremo

@tekka Sure, here it goes:

#define MY_RADIO_RFM69
#define MY_RFM69_NEW_DRIVER  
#define MY_IS_RFM69HW
#define MY_RFM69_MAX_POWER_LEVEL_DBM 13
#define MY_RFM69_FREQUENCY RFM69_868MHZ
//#define MY_DEBUG_VERBOSE_RFM69
#define MY_PARENT_NODE_ID 0
#define MY_PARENT_NODE_IS_STATIC
#define MY_TRANSPORT_MAX_TX_FAILURES (3u)

#define MY_OTA_FIRMWARE_FEATURE
#define MY_OTA_USE_I2C_EEPROM

#define MY_DEBUG 

#include <MySensors.h>
#include <SPI.h>
#include <Vcc.h>
#include <Streaming.h>
#include <math.h>

#define SLEEP_TIME_15min  900000    // 15min x 60s = 900000 ms -13% = 783000                (my arduinos show a delay of 8s/min = 13%)
#define SLEEP_TIME_1h     3600000   // 1 h = 1*60*60000 = 3600000 ms -13% = 3132000 ms
#define SLEEP_TIME_2h     7200000   // 2 h = 2*60*60000 = 7200000 ms -13% = 6264000 ms
#define SLEEP_TIME_3h     10800000  // 3 h = 3*60*60000 = 10800000 ms -13% = 9396000 ms

#define VERSION "3.0"
#define PIN_ALIM1 4                                   // Connect to input of resistor
#define PIN_ALIM2 7                                   // Connect to input of measuring probe
#define PIN_LECTURA A0

#define AGUA_DIR            800.0
#define AGUA_INV            160.0
#define AIRE_DIR            0.0
#define AIRE_INV            1023.0
#define TIEMPO_LECTURA      10
#define MAX_REP_LECTURA     20
#define MAX_REPORTING_LOOPS 4

// Battery calibration (Li-ion)
const float VccMin   = 3.0;                         // Minimum expected Vcc level, in Volts.
const float VccMax   = 4.2;                         // Maximum expected Vcc level, in Volts.
const float VccCorrection = 3.82/3.74;              // Measured Vcc by multimeter divided by reported Vcc

#define CHILD_MOIST_ID 1
MyMessage msgmoist(CHILD_MOIST_ID, V_LEVEL);
Vcc vcc(VccCorrection);

int count=0;
signed int oldv1=0, oldv2=0;
float oldresultcb=0;

void setup() {
#ifdef MY_DEBUG
  Serial.begin(115200);
#endif
  analogReference(DEFAULT);
  pinMode(PIN_LECTURA, INPUT);
  pinMode(PIN_ALIM1, OUTPUT);
  pinMode(PIN_ALIM2, OUTPUT);
}

void presentation(){
    sendSketchInfo("Sensor de humedad", VERSION);
    present(CHILD_MOIST_ID, S_MOISTURE, "Humedad suelo");
}

void loop()
{
  if (!isFirmwareUpdateOngoing()) {
    signed int value1=0, value2=0, i=0;
    float result1, result2, resultp, resultcb;

    //Loop until readings are stable or max number of readings is reached
    do {
      oldv1=value1; oldv2=value2;
      wait(TIEMPO_LECTURA);
      digitalWrite(PIN_ALIM1, HIGH);
      digitalWrite(PIN_ALIM2, LOW);
      wait(TIEMPO_LECTURA);
      value1 = analogRead(PIN_LECTURA);

      digitalWrite(PIN_ALIM1, LOW);
      digitalWrite(PIN_ALIM2, HIGH);
      wait(TIEMPO_LECTURA);
      value2 = analogRead(PIN_LECTURA);;
      digitalWrite(PIN_ALIM1, LOW);
      digitalWrite(PIN_ALIM2, LOW);
    } while (((oldv1 != value1) && (oldv2 != value2)) || (i == MAX_REP_LECTURA));

/*
      0-10 Saturated Soil. Occurs for a day or two after irrigation 
      10-20 Soil is adequately wet (except coarse sands which are drying out at this range) 
      20-60 Usual range to irrigate or water (most soils except heavy clay soils). 
      60-100 Usual range to irrigate heavy clay soils 
      100-200 Soil is becoming dangerously dry
    */
    result1=constrain(value1/(AGUA_DIR-AIRE_DIR)*100.0, 1, 100);
    result2=constrain(100-(value2-AGUA_INV)/(AIRE_INV-AGUA_INV)*100.0,1,100);
    resultp = (result1+result2)/2.0;
    resultcb = resultcb + constrain(square((-2.96699 + 351.395/resultp)),0,200);                           //Equation fit using stat software
    count++;
  
    //Send the data - only if moisture changed to save battery (send anyways once every 4 readings). If moisture sent, send battery level.
    if ((oldresultcb!=resultcb) || (count==MAX_REPORTING_LOOPS)) {
      send(msgmoist.set((unsigned int)resultcb));
      oldresultcb=resultcb;
      //Measure battery voltage and send level
      float v = vcc.Read_Volts();  
      int p = vcc.Read_Perc(VccMin, VccMax);
      p=constrain(p,0,100);
      sendBatteryLevel(p);
      #ifdef MY_DEBUG
        Serial << "Value1=" << value1 << " " << result1 << endl << "Value2=" << value2 << " " << result2 << endl << "Result = " << resultp << "% (" << resultcb << "cb)" << endl;
        Serial << "VCC = " << v << " Volts" << endl << "VCC% = " << p << " %" << endl;
      #endif
    }
  
    if (count==MAX_REPORTING_LOOPS) count=0;
    sleep(SLEEP_TIME_3h, true);
  }
}

The node uses a Mini Pro 3.3v @ 8 MHz. I'm powering it with a Li battery through a MCP1703 LDO with the 2 caps as shown in the datasheet. The radio is a RFM69HW with a 47uF cap in the power rail and a 0.1uF soldered to the power pins of the board shield. I'm using Arduino IDE v1.8.4, with boards definition v1.6.20.

Thanks in advance.

tekka

@manutremo you're using a i2c eeprom? Please re-run a FOTA update with

#define MY_DEBUG_VERBOSE_OTA_UPDATE

enabled and post the full log. Could be an issue with the i2c eeprom...let's see

manutremo

Yes, an AT24C256. Will enable fota verbose debug but the update skipped issue doesn't happen always. Will try to reproduce it, though.

in case it matters, I'm using kisse66's bootloader here

manutremo

@tekka See below the log of a new occurence of the same issue with UPDATE SKIPPED. This time I enabled verbose debug for OTA . This time I was testing with another different node with a similar hw setup - I'm also adding the sketch below although I think that from an OTA standpoint it's the same. First the node says UPDATE (line 2600), then UPDATE SKIPPED (line 2654), then goes to sleep, and after wake-up the update starts. This time the firmware was a new one, so the update is correct - which makes me think that maybe it's just that the UPDATE SKIPPED appears incorrectly.

18 MCO:BGN:INIT NODE,CP=RPONA---,VER=2.2.0-rc.1
28 TSM:INIT
28 TSF:WUR:MS=0
32 TSM:INIT:TSP OK
34 TSM:INIT:STATID=22
36 TSF:SID:OK,ID=22
38 TSM:FPAR
38 TSM:FPAR:STATP=0
40 TSM:ID
43 TSM:ID:OK
45 TSM:UPL
53 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
71 TSF:MSG:READ,0-0-22,s=255,c=3,t=25,pt=1,l=1,sg=0:1
77 TSF:MSG:PONG RECV,HP=1
79 TSM:UPL:OK
81 TSM:READY:ID=22,PAR=0,DIS=1
307 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=0,pt=6,l=10,sg=0,ft=0,st=OK:010001000005990D0300
370 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
382 TSF:MSG:READ,0-0-22,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
397 TSF:MSG:SEND,22-22-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.2.0-rc.1
464 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
491 TSF:MSG:READ,0-0-22,s=255,c=3,t=6,pt=0,l=1,sg=0:M
507 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=11,pt=0,l=23,sg=0,ft=0,st=OK:Sensor de fugas de agua
575 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.1
638 TSF:MSG:SEND,22-22-0-0,s=1,c=0,t=32,pt=0,l=13,sg=0,ft=0,st=OK:Fugas de agua
647 MCO:REG:REQ
700 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
952 TSF:MSG:READ,0-0-22,s=255,c=3,t=27,pt=1,l=1,sg=0:1
958 MCO:PIM:NODE REG=1
960 MCO:BGN:STP
962 MCO:BGN:INIT OK,TSP=1
2459 !TSF:MSG:SEND,22-22-0-0,s=1,c=1,t=16,pt=1,l=1,sg=0,ft=0,st=NACK:0
2498 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=0,pt=1,l=1,sg=0,ft=1,st=OK:36
No detection
2506 MCO:SLP:MS=30000,SMS=1,I1=1,M1=1,I2=255,M2=255
2560 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=32,pt=5,l=4,sg=0,ft=0,st=OK:500
2592 TSF:MSG:READ,0-0-22,s=0,c=4,t=1,pt=6,l=8,sg=0:0100010000057CC3
2600 OTA:FWP:UPDATE
2603 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FF
2615 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FF04
2648 TSF:MSG:READ,0-0-22,s=0,c=4,t=1,pt=6,l=8,sg=0:0100010000057CC3
2654 OTA:FWP:UPDATE SKIPPED
3069 TSF:TDI:TSL
3072 MCO:SLP:WUP=-1
3074 TSF:TRI:TSB
3082 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=33,pt=5,l=4,sg=0,ft=0,st=OK:30000
3104 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FF
3143 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FF04
3178 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FF04FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
3188 OTA:FWP:RECV B=04FF
3198 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FE
3211 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FE04
3254 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FE04FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
3264 OTA:FWP:RECV B=04FE
3270 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FD
3282 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FD04
3315 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FD042E310000FFFFFFFFFFFFFFFFFFFFFFFF
3328 OTA:FWP:RECV B=04FD
3334 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FC
3346 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FC04
3379 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FC0441434B003F002100322E322E302D7263
3389 OTA:FWP:RECV B=04FC
3397 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FB
3407 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FB04
3446 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FB04696F6E003C4E4F4E43453E004F4B004E
3457 OTA:FWP:RECV B=04FB
3467 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FA
3477 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FA04
3514 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FA04746564000D0A004E6F20646574656374
3524 OTA:FWP:RECV B=04FA
3530 OTA:FRQ:FW REQ,T=0001,V=0001,B=04F9
3543 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100F904
3579 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100F9046167756100466C6F6F64206465746563
3592 OTA:FWP:RECV B=04F9
3598 OTA:FRQ:FW REQ,T=0001,V=0001,B=04F8
3608 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100F804
3651 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100F804756100312E3100467567617320646520
3661 OTA:FWP:RECV B=04F8
3667 OTA:FRQ:FW REQ,T=0001,V=0001,B=04F7
3680 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100F704
3715 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100F70472206465206675676173206465206167
3727 OTA:FWP:RECV B=04F7

#define MY_RADIO_RFM69
#define MY_RFM69_NEW_DRIVER   // ATC on RFM69 works only with the new driver (not compatible with old=default driver)
#define MY_IS_RFM69HW
#define MY_RFM69_MAX_POWER_LEVEL_DBM 13
#define MY_RFM69_FREQUENCY RFM69_868MHZ
#define MY_DEBUG_VERBOSE_OTA_UPDATE
#define MY_PARENT_NODE_ID 0
#define MY_PARENT_NODE_IS_STATIC
#define MY_TRANSPORT_MAX_TX_FAILURES (3u)

#define MY_NODE_ID 22

#define MY_OTA_FIRMWARE_FEATURE
#define MY_OTA_USE_I2C_EEPROM

#define MY_DEBUG 

#include <MySensors.h>
#include <SPI.h>
#include <Vcc.h>
#include <Streaming.h>

#define SLEEP_TIME_5min   300000
#define SLEEP_TIME_10min  600000  
#define SLEEP_TIME_15min  900000
#define SLEEP_TIME_1h     3600000
#define SLEEP_TIME_2h     7200000
#define SLEEP_TIME_3h     10800000

#define VERSION "1.1"
#define PIN_INTERRUPT 3

// Battery calibration (Li-ion)
const float VccMin   = 3.0;                         // Minimum expected Vcc level, in Volts.
const float VccMax   = 4.2;                         // Maximum expected Vcc level, in Volts.
const float VccCorrection = 3.82/3.74;              // Measured Vcc by multimeter divided by reported Vcc

#define CHILD_FLOOD_ID 1
MyMessage msgflood(CHILD_FLOOD_ID, V_TRIPPED);
Vcc vcc(VccCorrection);

bool res;
int interrupt=digitalPinToInterrupt(PIN_INTERRUPT), oldbat=101;     // Set so that it will be sent always on the first run

void setup(){
  Serial.begin(115200);
  pinMode(PIN_INTERRUPT, INPUT);
}

void presentation(){
    sendSketchInfo("Sensor de fugas de agua", VERSION);
    present(CHILD_FLOOD_ID, S_WATER_LEAK, "Fugas de agua");
}

void loop()
{
  if (!isFirmwareUpdateOngoing()) {
    // Contact status is always sent as a safety measure to allow checking if the sensor is working
    // We start with a short delay for debouncing the contact (otherwise the reading from the pin might be incorrect after exiting from the sleep()
    delay(150);
    res = (digitalRead(PIN_INTERRUPT) == LOW);
    send(msgflood.set(res));
    //Measure battery voltage and send level if it has changed
    int p = vcc.Read_Perc(VccMin, VccMax);
    p=constrain(p,0,100);
    if (p != oldbat) { oldbat = p; sendBatteryLevel(p); }
    #ifdef MY_DEBUG
    if (res) Serial.println("Flood detected"); else Serial.println("No detection");
    #endif
    sleep(interrupt, CHANGE, 20000, true);//SLEEP_TIME_3h, true);
  }
}

manutremo

By the way - following the above, I made a small modification to the sketch, compiled, etc. Myscontroller detected the new fw corectly and the update run fine at the next wake-up, with no SKIPPED messages.

20987 MCO:SLP:MS=20000,SMS=1,I1=1,M1=1,I2=255,M2=255
21041 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=32,pt=5,l=4,sg=0,ft=0,st=OK:500
21073 TSF:MSG:READ,0-0-22,s=0,c=4,t=1,pt=6,l=8,sg=0:010001000005990D
21082 OTA:FWP:UPDATE
21084 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FF
21096 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FF04
21135 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FF04FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
21145 OTA:FWP:RECV B=04FF
21155 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FE

However I then modified the sketch again, uploaded it to Myscontroller, etc, but this time I reset the node. The log showed the UPDATE SKIPPED message again before starting the update.

18 MCO:BGN:INIT NODE,CP=RPONA---,VER=2.2.0-rc.1
28 TSM:INIT
28 TSF:WUR:MS=0
32 TSM:INIT:TSP OK
34 TSM:INIT:STATID=22
36 TSF:SID:OK,ID=22
38 TSM:FPAR
38 TSM:FPAR:STATP=0
40 TSM:ID
43 TSM:ID:OK
45 TSM:UPL
53 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
71 TSF:MSG:READ,0-0-22,s=255,c=3,t=25,pt=1,l=1,sg=0:1
77 TSF:MSG:PONG RECV,HP=1
79 TSM:UPL:OK
81 TSM:READY:ID=22,PAR=0,DIS=1
94 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=0,pt=6,l=10,sg=0,ft=0,st=OK:010001000005990D0300
161 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
172 TSF:MSG:READ,0-0-22,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
188 TSF:MSG:SEND,22-22-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.2.0-rc.1
253 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
282 TSF:MSG:READ,0-0-22,s=255,c=3,t=6,pt=0,l=1,sg=0:M
299 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=11,pt=0,l=23,sg=0,ft=0,st=OK:Sensor de fugas de agua
364 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.1
428 TSF:MSG:SEND,22-22-0-0,s=1,c=0,t=32,pt=0,l=13,sg=0,ft=0,st=OK:Fugas de agua
436 MCO:REG:REQ
489 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
505 TSF:MSG:READ,0-0-22,s=255,c=3,t=27,pt=1,l=1,sg=0:1
512 MCO:PIM:NODE REG=1
514 MCO:BGN:STP
516 MCO:BGN:INIT OK,TSP=1
675 TSF:MSG:SEND,22-22-0-0,s=1,c=1,t=16,pt=1,l=1,sg=0,ft=0,st=OK:0
739 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=0,pt=1,l=1,sg=0,ft=0,st=OK:32
No detection
745 MCO:SLP:MS=30000,SMS=1,I1=1,M1=1,I2=255,M2=255
802 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=32,pt=5,l=4,sg=0,ft=0,st=OK:500
831 TSF:MSG:READ,0-0-22,s=0,c=4,t=1,pt=6,l=8,sg=0:0100010000057CC3
839 OTA:FWP:UPDATE
841 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FF
854 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FF04
882 TSF:MSG:READ,0-0-22,s=0,c=4,t=1,pt=6,l=8,sg=0:0100010000057CC3
888 OTA:FWP:UPDATE SKIPPED
1220 TSF:MSG:READ,0-0-22,s=255,c=3,t=6,pt=0,l=1,sg=0:M
1288 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FF04FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
1298 OTA:FWP:RECV B=04FF
1308 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FE
1320 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FE04
1329 TSF:TDI:TSL
1331 MCO:SLP:WUP=-1
1333 TSF:TRI:TSB
1343 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=33,pt=5,l=4,sg=0,ft=0,st=OK:30000
1810 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FE
1820 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FE04
1859 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FE04FFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
1869 OTA:FWP:RECV B=04FE
1878 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FD
1888 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FD04
1925 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FD042E310000FFFFFFFFFFFFFFFFFFFFFFFF
1935 OTA:FWP:RECV B=04FD
1943 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FC
1953 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FC04
1992 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FC0441434B003F002100322E322E302D7263
2002 OTA:FWP:RECV B=04FC
2009 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FB
2021 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FB04
2056 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FB04696F6E003C4E4F4E43453E004F4B004E
2066 OTA:FWP:RECV B=04FB
2076 OTA:FRQ:FW REQ,T=0001,V=0001,B=04FA
2086 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100FA04
2123 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100FA04746564000D0A004E6F20646574656374
2134 OTA:FWP:RECV B=04FA
2140 OTA:FRQ:FW REQ,T=0001,V=0001,B=04F9
2152 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:01000100F904
2187 TSF:MSG:READ,0-0-22,s=255,c=4,t=3,pt=6,l=22,sg=0:01000100F9046167756100466C6F6F64206465746563
2197 OTA:FWP:RECV B=04F9
2203 OTA:FRQ:FW REQ,T=0001,V=0001,B=04F8

So it looks this happens only if right after a node reset. I hope this gives a hint.

As a side note - I also find interesting that the number of update blocks sent before the node goes to sleep changes between test runs.

tekka

@manutremo ok, I'm on something - it has to do with the smart sleep feature. I will prepare a fix for you to test.

tekka

@manutremo here you go: https://github.com/tekka007/MySensors/tree/FOTAUpdates

manutremo

Many thanks @tekka, that was really fast! I'll give it a try as soon as I can spare some minutes.

manutremo

@tekka Tested the new library and both issues seem to be gone now, great job ! :clap:

I have one more question though :)

During testing I treid to put things difficult for my radios and move them until reception started to be bad. At some point the FOTA process gave up with a FW UPD FAIL message (line 41146 in attached log). So the node gave up and went to sleep. I was expecting it to try again after wake-up, but it didn't (see lines after 43589).

36734 !RFM69:SWR:NACK
36737 RFM69:PTX:NO ADJ
36771 RFM69:SWR:SEND,TO=0,RETRY=5
36966 RFM69:SWR:ACK,FROM=0,SEQ=119,RSSI=-55
36972 RFM69:ATC:ADJ TXL,cR=-55,tR=-80,TXL=12
36976 RFM69:PTX:LEVEL=12 dBm
36978 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:010001002005
36988 OTA:FRQ:FW REQ,T=0001,V=0001,B=0520
36993 RFM69:SWR:SEND,TO=0,RETRY=0
37203 !RFM69:SWR:NACK
37206 RFM69:PTX:LEVEL=13 dBm
37216 RFM69:SWR:SEND,TO=0,RETRY=1
37423 !RFM69:SWR:NACK
37425 RFM69:PTX:NO ADJ
37459 RFM69:SWR:SEND,TO=0,RETRY=2
37666 !RFM69:SWR:NACK
37668 RFM69:PTX:NO ADJ
37679 RFM69:SWR:SEND,TO=0,RETRY=3
37885 !RFM69:SWR:NACK
37888 RFM69:PTX:NO ADJ
37922 RFM69:SWR:SEND,TO=0,RETRY=4
38129 !RFM69:SWR:NACK
38131 RFM69:PTX:NO ADJ
38174 RFM69:SWR:SEND,TO=0,RETRY=5
38313 RFM69:SWR:ACK,FROM=0,SEQ=120,RSSI=-56
38318 RFM69:ATC:ADJ TXL,cR=-56,tR=-80,TXL=12
38322 RFM69:PTX:LEVEL=12 dBm
38326 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:010001002005
38334 OTA:FRQ:FW REQ,T=0001,V=0001,B=0520
38338 RFM69:SWR:SEND,TO=0,RETRY=0
38547 !RFM69:SWR:NACK
38549 RFM69:PTX:LEVEL=13 dBm
38559 RFM69:SWR:SEND,TO=0,RETRY=1
38768 !RFM69:SWR:NACK
38770 RFM69:PTX:NO ADJ
38805 RFM69:SWR:SEND,TO=0,RETRY=2
39012 !RFM69:SWR:NACK
39014 RFM69:PTX:NO ADJ
39024 RFM69:SWR:SEND,TO=0,RETRY=3
39231 !RFM69:SWR:NACK
39233 RFM69:PTX:NO ADJ
39268 RFM69:SWR:SEND,TO=0,RETRY=4
39475 !RFM69:SWR:NACK
39477 RFM69:PTX:NO ADJ
39520 RFM69:SWR:SEND,TO=0,RETRY=5
39702 RFM69:SWR:ACK,FROM=0,SEQ=121,RSSI=-54
39706 RFM69:ATC:ADJ TXL,cR=-54,tR=-80,TXL=12
39712 RFM69:PTX:LEVEL=12 dBm
39714 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:010001002005
39723 OTA:FRQ:FW REQ,T=0001,V=0001,B=0520
39729 RFM69:SWR:SEND,TO=0,RETRY=0
39938 !RFM69:SWR:NACK
39940 RFM69:PTX:LEVEL=13 dBm
39983 RFM69:SWR:SEND,TO=0,RETRY=1
40192 !RFM69:SWR:NACK
40194 RFM69:PTX:NO ADJ
40228 RFM69:SWR:SEND,TO=0,RETRY=2
40435 !RFM69:SWR:NACK
40437 RFM69:PTX:NO ADJ
40480 RFM69:SWR:SEND,TO=0,RETRY=3
40687 !RFM69:SWR:NACK
40689 RFM69:PTX:NO ADJ
40724 RFM69:SWR:SEND,TO=0,RETRY=4
40931 !RFM69:SWR:NACK
40933 RFM69:PTX:NO ADJ
40943 RFM69:SWR:SEND,TO=0,RETRY=5
41125 RFM69:SWR:ACK,FROM=0,SEQ=122,RSSI=-54
41129 RFM69:ATC:ADJ TXL,cR=-54,tR=-80,TXL=12
41134 RFM69:PTX:LEVEL=12 dBm
41138 TSF:MSG:SEND,22-22-0-0,s=255,c=4,t=2,pt=6,l=6,sg=0,ft=0,st=OK:010001002005
41146 !OTA:FRQ:FW UPD FAIL
41299 RFM69:SWR:SEND,TO=0,RETRY=0
41506 !RFM69:SWR:NACK
41508 RFM69:PTX:LEVEL=13 dBm
41519 RFM69:SWR:SEND,TO=0,RETRY=1
41725 !RFM69:SWR:NACK
41728 RFM69:PTX:NO ADJ
41762 RFM69:SWR:SEND,TO=0,RETRY=2
41969 !RFM69:SWR:NACK
41971 RFM69:PTX:NO ADJ
42014 RFM69:SWR:SEND,TO=0,RETRY=3
42221 !RFM69:SWR:NACK
42223 RFM69:PTX:NO ADJ
42258 RFM69:SWR:SEND,TO=0,RETRY=4
42465 !RFM69:SWR:NACK
42467 RFM69:PTX:NO ADJ
42477 RFM69:SWR:SEND,TO=0,RETRY=5
42684 !RFM69:SWR:NACK
42686 RFM69:PTX:NO ADJ
42721 !TSF:MSG:SEND,22-22-0-0,s=1,c=1,t=16,pt=1,l=1,sg=0,ft=0,st=NACK:0
42729 RFM69:SWR:SEND,TO=0,RETRY=0
42950 !RFM69:SWR:NACK
42952 RFM69:PTX:NO ADJ
42995 RFM69:SWR:SEND,TO=0,RETRY=1
43005 RFM69:SWR:ACK,FROM=0,SEQ=124,RSSI=-55
43010 RFM69:ATC:ADJ TXL,cR=-55,tR=-80,TXL=12
43014 RFM69:PTX:LEVEL=12 dBm
43018 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=0,pt=1,l=1,sg=0,ft=1,st=OK:20
No detection
43026 MCO:SLP:MS=30000,SMS=1,I1=1,M1=1,I2=255,M2=255
43030 RFM69:SWR:SEND,TO=0,RETRY=0
43065 RFM69:SWR:ACK,FROM=0,SEQ=125,RSSI=-56
43069 RFM69:ATC:ADJ TXL,cR=-56,tR=-80,TXL=11
43075 RFM69:PTX:LEVEL=11 dBm
43077 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=32,pt=5,l=4,sg=0,ft=0,st=OK:500
43585 TSF:TDI:TSL
43587 RFM69:RSL
43589 MCO:SLP:WUP=-1
43591 TSF:TRI:TSB
43593 RFM69:RSB
43595 RFM69:SWR:SEND,TO=0,RETRY=0
43606 RFM69:SWR:ACK,FROM=0,SEQ=126,RSSI=-56
43610 RFM69:ATC:ADJ TXL,cR=-56,tR=-80,TXL=10
43616 RFM69:PTX:LEVEL=10 dBm
43618 TSF:MSG:SEND,22-22-0-0,s=255,c=3,t=33,pt=5,l=4,sg=0,ft=0,st=OK:30000
43778 RFM69:SWR:SEND,TO=0,RETRY=0
43788 RFM69:SWR:ACK,FROM=0,SEQ=127,RSSI=-59
43792 RFM69:ATC:ADJ TXL,cR=-59,tR=-80,TXL=9
43796 RFM69:PTX:LEVEL=9 dBm

So when this occurs the only way I can think of to force another update would be update the sketch, refresh the repo in MysController and assign it to the node again. Therefore I wonder if this is intended behaviour and if so, if there is some other way to force an update after a failed one.

Thanks.

FOTA flow in sleeping nodes - need two cycles?

21

12.0k

11.2k

113.4k