FOTA flow in sleeping nodes - need two cycles?

[manutremo]

@scalz Many thanks, let me know if I can help further with the testing.

Regarding your comment on blocking the sleep - how would that be done? I thought the conditional in my sketch (shown above) would already be blocking it.

[scalz]

@manutremo you're right. i need to take a look

[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.