SW_Signing failing: !TSF:MSG:SIGN FAIL

[Anticimex]

@joaoabs ok. Well, it sure sounds strange. And there are no issues if you just disable signing? Perhaps a dodgy power supply that destabilize something when the radio needs to work a bit harder perhaps (just speculation). Signing does put strain on the radio in the sense that it needs to transmit full sized payloads.

[joaoabs]

With an arduino UNO (same processor type: mega 328p) as GW the behaviour is the same.

This is just the arduino board connected to a laptop, via an USB3 port (should have enough power). I've also added a 47uF capacitor between 5v and GND, but the behaviour is the same. (the NRFs already have their own 4.7uF capacitor)

Any idea/suggestuin?

Thanks,

[Anticimex]

@joaoabs no, I am afraid I am out of options. Did you do a comparison with and without signing, just to rule out if signing is the cause of the radio seemingly failing at either end?
The radio also have verbose debug flags. Perhaps someone with more knowledge about radio debugging could draw conclusions from those.

[Anticimex]

@joaoabs one thing I see is that you did not include the ram usage on the GW, just the flash usage. Is the ram usage within reasonable levels? (at least below 75%)

[joaoabs]

Hello,

The GW sketch is the simplest possible. It is the SerialGateway.ino example just with the added flags for the signing.
It seems to have enough resources

Sketch uses 21440 bytes (66%) of program storage space. Maximum is 32256 bytes.
Global variables use 1401 bytes (68%) of dynamic memory, leaving 647 bytes for local variables. Maximum is 2048 bytes.

The node sketch is the Relay example sketch, where I then added, one by one, the code from other examples such as Door/Win/Button (tripwire), Temperature (DS18B20), Temp/Hum (DHT22) and Motion (HC-SR501).

I have a pretty basic version control, so for each new sensor type I was adding I was just creating another file. Since all the signature process was done (and written in the eeprom), I went back to the basics (sketch with Relay + Door) with the signing flags enabled and could confirm it worked with signatures (so it must be something I added). I then went version-by-version, enabling the flags and confirmed it was still working as I was progressing.
I've now reached a point where I just have the last sensor to add (Motion HC-SR501) but the available memory is concerning:

Build options changed, rebuilding all
Sketch uses 28030 bytes (91%) of program storage space. Maximum is 30720 bytes.
Global variables use 1542 bytes (75%) of dynamic memory, leaving 506 bytes for local variables. Maximum is 2048 bytes.
Low memory available, stability problems may occur.

I'll leave as it is, (disabling the signing debug, the memory use drops to 71%). Just out of curiosity, I checked the memory use on the original node sketch (without signing debug) and it was 73%.

Still not sure if it was an issue related with the memory or with the additional code I added for the Motion Sensor.
However, the strange conclusion is that it was really on the node, and not on the gateway as we thought.

I'll leave it on during the night in order to see if it hangs or something.

Thanks for your help!
Joaoabs

[Anticimex]

@joaoabs I am glad that you at least came to some form of conclusion. I suspect this is just another example of the sketch running out of ram for the stack. The symptoms can be really weird and unpredictable. Just a slight change on the execution path and something that worked fine just before simply explodes or, executed something completely different.

We really are pushing it with signing on atmega328p, because the library also grows in size with time (new features come in).

I'd say, and I will probably soon update the documentation with it, that signing/security does technically work on atmega328p, but due to the limited ram, it's usability is very limited to just basic sketches.

Thanks for reporting this. It adds to the hive mind of knowledge and experience in troubleshooting :+1:

[joaoabs]

Thanks,

The node is still sending periodic updates after 8h uptime. I guess I can considered it as stable.

By the way, I have a couple of ATSHA204A-STUCZ-T ordered. I think I can easily migrate to HW signing as soon as I get them.
Will the HW signing unload the AT328p?

Thanks

[Anticimex]

@joaoabs yes, but you need to redo personalization for it, but you have that under control so it should be easy for you.
Yes, the atsha will put less strain on the atmega328p. Difficult to say how much and if it will resolve your issue but I'd say it's worth a try :)

[tekka]

@joaoabs Could you post the full sketch where signing fails? I assume one of the external libraries may interfere with SPI communication. To confirm, please test this PR with the failing sketch and upload the full debug log here.

https://github.com/mysensors/MySensors/pull/1116

[tekka]

@joaoabs Any updates on the issue?

[joaoabs]

Hi,

Sorry for the delayed answer, I was making sure I had a better testing enviroment:

Controller/Gateway: RPI3 with OpenHab2 and NRF24L01+ connected directly to the pin header. The NRF has a 4.7uF capacitor soldered to it and is the simple + model (not PA+NLA)

Node: Arduino mini pro 3v 8MHz, in a prototype board with:

• Hi-Link power supply (220AC to 5V DC)
• 2200uF capactior to stabilize 5V (and also a pico range one to filter high frequencies)
• 3.3V regulator
• 100uf capacitor to stabilize 3.3V (and also a pico range one to filter high frequencies)
• NRF24L01+ feed from the 3.3V regulator and with an additional 4.7uF capacitor
• Connections made by wire around the board
• The board is supposed to:
  • Interact with a 4-relay module
  • Read the temperature of several DS18B20's (only used 1 in the testing)
  • Detect presence in 3 motion sensors
  • Read temperature/Humidity from a DHT22
• The node is ~6m away of the GW/Controller with line of sight
• The pins and skecth options are in its own comments.
• The " && transportSanityCheck());" patch was applied
• Signing is activated

Code:

/**
 * The MySensors Arduino library handles the wireless radio link and protocol
 * between your home built sensors/actuators and HA controller of choice.
 * The sensors forms a self healing radio network with optional repeaters. Each
 * repeater and gateway builds a routing tables in EEPROM which keeps track of the
 * network topology allowing messages to be routed to nodes.
 *
 * Created by Henrik Ekblad <henrik.ekblad@mysensors.org>
 * Copyright (C) 2013-2015 Sensnology AB
 * Full contributor list: https://github.com/mysensors/Arduino/graphs/contributors
 *
 * Documentation: http://www.mysensors.org
 * Support Forum: http://forum.mysensors.org
 *
 * This program is free software; you can redistribute it and/orlçyovzwqi71234567890ll
 * modify it under the terms of the GNU General Public License
 * version 2 as published by the Free Software Foundation.
 *
 *******************************
 *
 * REVISION HISTORY
 * Version 1.0 
 *
 * DESCRIPTION
 * Combined sketch with: 
 *      - NODE ID 44
 *      - Relay sketch, base sketch for all          - PIN 3,4,5,6  -   Child ID from 1,2,3,4
 *      - DOOR sketch (trip alarm), added code       - PIN A0,A1    -   Child ID 30,31
 *      - TEMP sketch (DS18B20), added code          - PIN 8        -   Child ID from 10 to 18  (defined 8 as MAX)
 *      - Hum sketch (DHT22), added code             - PIN A7       -   Child ID 50 (Temp) and 60 (Hum)
 *      - MOTION sketch, added code                  - PIN A6       -   Child ID 70
 *      
 *      
 * BOARD
 * 
 * D0 - RX (not used - but can be used with a plug on the programing header))
 * D1 - TX (not used - but can be used with a plug on the programing header))
 * D2 - NRF24 IRQ
 * D3 - RJ-45 (3)
 * D4 - 1-W (RJ-45 (4) & pin header)
 * D5 - Relay (5) (relay pin header has 6 pins where 6 is 5v and 1 is GND)
 * D6 - Relay (4)
 * D7 - Relay (3)
 * D8 - Relay (2)
 * D9 - NRF CE
 * D10- NRF CS
 * D11- NRF MOSI
 * D12- NRF MISO
 * D13- NRF SCK
 * A0 - RJ-45 (6)  (DOOR Sketch) 
 * A1 - RJ-45 (2)  (DOOR Sketch)
 * A2 - RJ-45 (1)
 * A3 - RJ-45 (4)
 * A4 - I2C
 * A5 - I2C
 * A6 - PIR (pin header)  (MOTION Sketch)
 * A7 - DHT (pin header)  
 * 
 *      
 *      
 *      
 *      
 * All sketches copied from http://www.mysensors.org
 *
 * signing "hidden" page: https://www.mysensors.org/apidocs-beta/group__MySigninggrpPub.html
 * 
 * 
 */
 
// Enable debug prints to serial monitor
#define MY_DEBUG

// Static node ID definition
#define MY_NODE_ID 44

// Enable and select radio type attached
#define MY_RADIO_NRF24
//#define MY_RADIO_NRF5_ESB
//#define MY_RADIO_RFM69
//#define MY_RADIO_RFM95

// Enable repeater functionality for this node
//#define MY_REPEATER_FEATURE  

//CODE FOR SIGNING************************************************
//#define MY_SIGNING_WEAK_SECURITY 
#define MY_SIGNING_SOFT
#define MY_SIGNING_SOFT_RANDOMSEED_PIN A4
#define MY_SIGNING_REQUEST_SIGNATURES  // will inform the gateway that I expect it to sign all messages to me
//#define MY_DEBUG_VERBOSE_SIGNING

#include <MySensors.h>

//What features/Sketches to use?  ************************************************
#define RELAY
//#define DHTCODE
#define DOOR
#define MOTION
//#define TEMP


//CODE OF DOOR SKETCH************************************************
#ifdef DOOR
#include <Bounce2.h>
#define CHILD_ID_A 30
#define CHILD_ID_B 31
#define BUTTON_PIN_A  A0  // Arduino Digital I/O pin for button/reed switch
#define BUTTON_PIN_B  A1  // Arduino Digital I/O pin for button/reed switch

Bounce debouncer_a = Bounce(); 
Bounce debouncer_b = Bounce(); 
int oldValue_a=-1;
int oldValue_b=-1;
// Change to V_LIGHT if you use S_LIGHT in presentation below
MyMessage msg_door_a(CHILD_ID_A,V_TRIPPED);  
MyMessage msg_door_b(CHILD_ID_B,V_TRIPPED);     
#endif

//CODE OF MOTION SKETCH************************************************
#ifdef MOTION
int oldMotion_a=-1;

//uint32_t SLEEP_TIME = 120000; // Sleep time between reports (in milliseconds)
#define DIGITAL_INPUT_SENSOR_MOTION_A A6   // The digital input you attached your motion sensor.  (Only 2 and 3 generates interrupt!)
#define CHILD_ID_MOTION_A 70   // Id of the sensor child

// Initialize motion message
MyMessage msg_motion_a(CHILD_ID_MOTION_A, V_TRIPPED);
#endif


//CODE OF TEMP SKETCH************************************************
#ifdef TEMP
#include <MySensors.h>  
#include <DallasTemperature.h>
#include <OneWire.h>
#define ONE_WIRE_BUS 4 // Pin where dallase sensor is connected 
#define MAX_ATTACHED_DS18B20 10
unsigned long SLEEP_TIME = 30000; // Sleep time between reads (in milliseconds)
OneWire oneWire(ONE_WIRE_BUS); // Setup a oneWire instance to communicate with any OneWire devices (not just Maxim/Dallas temperature ICs)
DallasTemperature sensors(&oneWire); // Pass the oneWire reference to Dallas Temperature. 
float lastTemperature[MAX_ATTACHED_DS18B20];
int numSensors=0;
bool receivedConfig = false;
bool metric = true;
// Initialize temperature message
MyMessage msg_temp(0,V_TEMP);
#define COMPARE_TEMP 1 // Send temperature only if changed? 1 = Yes 0 = No
#endif

//CODE FOR LOOP************************************************
long x = 327670;
int y = 32767;

  
//CODE OF RELAY SKETCH************************************************
#ifdef RELAY
#define RELAY_PIN 5  // Arduino Digital I/O pin number for first relay (second on pin+1 etc)
#define NUMBER_OF_RELAYS 4 // Total number of attached relays
#define RELAY_ON 1  // GPIO value to write to turn on attached relay
#define RELAY_OFF 0 // GPIO value to write to turn off attached relay
#endif

//CODE OF DHT SKETCH************************************************
#ifdef DHTCODE
//#include "DHT.h"
#include <DHT.h>

// Set this to the pin you connected the DHT's data pin to
#define DHT_DATA_PIN A7

// Set this offset if the sensor has a permanent small offset to the real temperatures
#define SENSOR_TEMP_OFFSET 0

// Sleep time between sensor updates (in milliseconds)
// Must be >1000ms for DHT22 and >2000ms for DHT11
static const uint64_t UPDATE_INTERVAL = 60000;

// Force sending an update of the temperature after n sensor reads, so a controller showing the
// timestamp of the last update doesn't show something like 3 hours in the unlikely case, that
// the value didn't change since;
// i.e. the sensor would force sending an update every UPDATE_INTERVAL*FORCE_UPDATE_N_READS [ms]
static const uint8_t FORCE_UPDATE_N_READS = 10;

#define CHILD_ID_HUM 50
#define CHILD_ID_TEMP 60

float lastTempdht;
float lastHumdht;
uint8_t nNoUpdatesTempdht;
uint8_t nNoUpdatesHumdht;
//bool metric = true;

MyMessage msgHum(CHILD_ID_HUM, V_HUM);
MyMessage msgTemp(CHILD_ID_TEMP, V_TEMP);
DHT dht;
#endif

void before()
{
 
 //CODE OF RELAY SKETCH************************************************
 #ifdef RELAY
 for (int sensor=1, pin=RELAY_PIN; sensor<=NUMBER_OF_RELAYS; sensor++, pin++) {
        // Then set relay pins in output mode
        pinMode(pin, OUTPUT);
        // Set relay to last known state (using eeprom storage)
        digitalWrite(pin, loadState(sensor)?RELAY_ON:RELAY_OFF);
 }
 #endif
//CODE OF TEMP SKETCH************************************************
 #ifdef TEMP
 sensors.begin();
 #endif
}

void setup()
{
//CODE OF DOOR SKETCH************************************************
#ifdef DOOR
  // Setup the button A
  pinMode(BUTTON_PIN_A,INPUT);
  // Activate internal pull-up
  digitalWrite(BUTTON_PIN_A,HIGH);

  // After setting up the button, setup debouncer
  debouncer_a.attach(BUTTON_PIN_A);
  debouncer_a.interval(5);

  // Setup the button B
  pinMode(BUTTON_PIN_B,INPUT);
  // Activate internal pull-up
  digitalWrite(BUTTON_PIN_B,HIGH);

  // After setting up the button, setup debouncer
  debouncer_b.attach(BUTTON_PIN_B);
  debouncer_b.interval(5);
#endif


//CODE OF MOTION SKETCH************************************************
#ifdef MOTION
  pinMode(DIGITAL_INPUT_SENSOR_MOTION_A, INPUT);      // sets the motion sensor digital pin as input
#endif
  

//CODE OF TEMP SKETCH************************************************
#ifdef TEMP
  sensors.setWaitForConversion(false);
#endif

//CODE OF DHT SKETCH************************************************
#ifdef DHTCODE
  dht.setup(DHT_DATA_PIN); // set data pin of DHT sensor
  if (UPDATE_INTERVAL <= dht.getMinimumSamplingPeriod()) {
    Serial.println("Warning: UPDATE_INTERVAL is smaller than supported by the sensor!");
  }
  // Sleep for the time of the minimum sampling period to give the sensor time to power up
  // (otherwise, timeout errors might occure for the first reading)
  sleep(dht.getMinimumSamplingPeriod());
 #endif
}


void presentation()
{
// Send the sketch version information to the gateway and Controller
   sendSketchInfo("MIXED JOAOABS SOTAO", "1.0");
   
//CODE OF RELAY SKETCH************************************************
//FOR RELAY: Child ID from 1 to 4
#ifdef RELAY
   for (int sensor=1, pin=RELAY_PIN; sensor<=NUMBER_OF_RELAYS; sensor++, pin++) {
        // Register all sensors to gw (they will be created as child devices)
        //  present(sensor, S_BINARY);
         present(sensor, S_BINARY, "RELAYS", true);  // forcing ack for this child's messages
    }
#endif

//CODE OF DOOR SKETCH************************************************
//FOR DOOR: Child ID 30
#ifdef DOOR
 // present(CHILD_ID_A, S_DOOR);  
 // present(CHILD_ID_B, S_DOOR);  
  present(CHILD_ID_A, S_DOOR, "DOOR_A", true);  // CHILD ID = 30 and forcing ack for this child's messages
  present(CHILD_ID_B, S_DOOR, "DOOR_B", true);  // CHILD ID = 31 and forcing ack for this child's messages
#endif

//CODE OF MOTION SKETCH************************************************
#ifdef MOTION
present(CHILD_ID_MOTION_A, S_MOTION, "PIR", true); // CHILD ID =  70 and forcing ack for this child's messages
#endif

//CODE OF TEMP SKETCH************************************************
//FOR TEMP: Child ID from 10 to 18  (defined 8 as MAX)
// Fetch the number of attached temperature sensors  
#ifdef TEMP
  numSensors = sensors.getDeviceCount();

  // Present all sensors to controller
     int a;
  for (int i=0; i<numSensors && i<MAX_ATTACHED_DS18B20; i++) {  
     a=i+10;  
     present(a, S_TEMP);   
  }
#endif

//CODE OF DHT SKETCH************************************************
#ifdef DHTCODE
//FOR DHT: Child ID 50 and 60
  // Register all sensors to gw (they will be created as child devices)
  present(CHILD_ID_HUM, S_HUM);
  present(CHILD_ID_TEMP, S_TEMP);
  metric = getControllerConfig().isMetric;
#endif
}

void loop()
{
//CODE OF DOOR SKETCH************************************************
#ifdef DOOR
//For DOOR A
debouncer_a.update();
  // Get the update value
  int value_a = debouncer_a.read();

  if (value_a != oldValue_a) {
     // Send in the new value
     send(msg_door_a.set(value_a==HIGH ? 1 : 0));
     oldValue_a = value_a;
  }

//For DOOR B
debouncer_b.update();
  // Get the update value
  int value_b = debouncer_b.read();

  if (value_b != oldValue_b) {
     // Send in the new value
     send(msg_door_b.set(value_b==HIGH ? 1 : 0));
     oldValue_b = value_b;
  }
#endif

#ifdef MOTION
    // Read digital motion value
    int valueMotion_a = digitalRead(DIGITAL_INPUT_SENSOR_MOTION_A);
    if (valueMotion_a != oldMotion_a)
    {
     #ifdef MY_DEBUG
     Serial.println(valueMotion_a);
     #endif MY_DEBUG
     send(msg_motion_a.set(valueMotion_a?"1":"0"));  // Send tripped value to gw
     oldMotion_a = valueMotion_a;
    }

#endif

//Loop Code ************************************************
//Resets every 1-2 minutes
  if (x>0)
  {
    x=x-1;
  }
  else
  {
    y=y-1;
    if (x==0 && y==0)
    {
     #ifdef MY_DEBUG
  Serial.println("****** counters reached 0 **************");
     #endif
     x = 1600000;
     y = 32767;

//CODE OF TEMP SKETCH************************************************
// So Let's fetch temperatures from Dallas sensors
#ifdef TEMP
  sensors.requestTemperatures();

  // query conversion time and sleep until conversion completed
  int16_t conversionTime = sensors.millisToWaitForConversion(sensors.getResolution());
  // sleep() call can be replaced by wait() call if node need to process incoming messages (or if node is repeater)
  sleep(conversionTime);

  // Read temperatures and send them to controller 
  for (int i=0; i<numSensors && i<MAX_ATTACHED_DS18B20; i++) {

    // Fetch and round temperature to one decimal
    float temperature = static_cast<float>(static_cast<int>((getControllerConfig().isMetric?sensors.getTempCByIndex(i):sensors.getTempFByIndex(i)) * 10.)) / 10.;

 //   Serial.println("temperature:");
 //   Serial.println(temperature);

   // Only send data if temperature has changed and no error
    #if COMPARE_TEMP == 1
    if (lastTemperature[i] != temperature && temperature != -127.00 && temperature != 85.00) {
    #else
    if (temperature != -127.00 && temperature != 85.00) {
    #endif
     
     int a=i+10; 
      // Send in the new temperature
      send(msg_temp.setSensor(a).set(temperature,1));
      // Save new temperatures for next compare
      lastTemperature[i]=temperature;    
      
    }
   }    
   #endif

    #ifdef DHTCODE
    //CODE OF DHT SKETCH************************************************
    // Force reading sensor, so it works also after sleep()
    dht.readSensor(true);
    delay(2000);
    // Get temperature from DHT library
    float temperaturedht = dht.getTemperature();
    if (isnan(temperaturedht))
    {
     Serial.println("Failed reading temperature from DHT!");
    }
    else if (temperaturedht != lastTempdht || nNoUpdatesTempdht == FORCE_UPDATE_N_READS)
    {
     // Only send temperature if it changed since the last measurement or if we didn't send an update for n times
     lastTempdht = temperaturedht;
     if (!metric)
     {
      temperaturedht = dht.toFahrenheit(temperaturedht);
     }
     // Reset no updates counter
     nNoUpdatesTempdht = 0;
     temperaturedht += SENSOR_TEMP_OFFSET;
     send(msgTemp.set(temperaturedht, 1));
     #ifdef MY_DEBUG
     Serial.print("T: ");
     Serial.println(temperaturedht);
     #endif
    } 
    else 
    {
     // Increase no update counter if the temperature stayed the same
     nNoUpdatesTempdht++;
    }

    // Get humidity from DHT library
    float humiditydht = dht.getHumidity();
    if (isnan(humiditydht))
    {
     Serial.println("Failed reading humidity from DHT");
    } 
   else if (humiditydht != lastHumdht || nNoUpdatesHumdht == FORCE_UPDATE_N_READS) {
   // Only send humidity if it changed since the last measurement or if we didn't send an update for n times
   lastHumdht = humiditydht;
   // Reset no updates counter
   nNoUpdatesHumdht = 0;
   send(msgHum.set(humiditydht, 1));

   #ifdef MY_DEBUG
   Serial.print("H: ");
   Serial.println(humiditydht);
   #endif
   } 
   else
   {
    // Increase no update counter if the humidity stayed the same
    nNoUpdatesHumdht++;
   }
   #endif
  }
 }
}


void receive(const MyMessage &message)
{
    //CODE OF RELAY SKETCH************************************************
    //THERE IS ONLY RECEIVE CODE for RELAY.  DOOR, TEMP and HUM are just sent periodically and not on-demand
    // We only expect one type of message from controller. But we better check anyway.
    if (message.type==V_STATUS) {
        // Change relay state
        digitalWrite(message.sensor-1+RELAY_PIN, message.getBool()?RELAY_ON:RELAY_OFF);
        // Store state in eeprom
        saveState(message.sensor, message.getBool());
        // Write some debug info
        Serial.print("Incoming change for sensor:");
        Serial.print(message.sensor);
        Serial.print(", New status: ");
        Serial.println(message.getBool());
    }
}

If we only choose the relay-related code, I can feel some reliability. Every command that is sent is executed.

If I activate just the temperature code, I start having signature failures when trying to open/close relays. Not always, but often, so reliability is affected. Example of trying to change the relay 4 (44:4).

May  3 18:31:32 nettemp mysgw: GWT:RFC:C=0,MSG=44;3;1;1;2;1
May  3 18:31:32 nettemp mysgw: !TSF:MSG:SEND,0-0-44-44,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=NACK:
May  3 18:31:32 nettemp mysgw: !TSF:MSG:SIGN FAIL
May  3 18:31:32 nettemp mysgw: GWT:RFC:C=0,MSG=
May  3 18:31:32 nettemp mysgw: GWT:RFC:C=0,MSG=44;3;1;1;2;1
May  3 18:31:32 nettemp mysgw: !TSF:MSG:SEND,0-0-44-44,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=NACK:
May  3 18:31:32 nettemp mysgw: !TSF:MSG:SIGN FAIL
May  3 18:31:32 nettemp mysgw: GWT:RFC:C=0,MSG=
May  3 18:31:32 nettemp mysgw: GWT:RFC:C=0,MSG=44;3;1;1;2;1
May  3 18:31:32 nettemp mysgw: !TSF:MSG:SEND,0-0-44-44,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=NACK:
May  3 18:31:32 nettemp mysgw: !TSF:MSG:SIGN FAIL
May  3 18:31:32 nettemp mysgw: GWT:RFC:C=0,MSG=
May  3 18:31:33 nettemp mysgw: GWT:RFC:C=0,MSG=44;3;1;1;2;1
May  3 18:31:33 nettemp mysgw: !TSF:MSG:SEND,0-0-44-44,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=NACK:
May  3 18:31:33 nettemp mysgw: !TSF:MSG:SIGN FAIL
May  3 18:31:33 nettemp mysgw: GWT:RFC:C=0,MSG=
May  3 18:31:34 nettemp mysgw: GWT:RFC:C=0,MSG=44;3;1;1;2;1
May  3 18:31:34 nettemp mysgw: !TSF:MSG:SEND,0-0-44-44,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=NACK:
May  3 18:31:34 nettemp mysgw: !TSF:MSG:SIGN FAIL
May  3 18:31:34 nettemp mysgw: GWT:RFC:C=0,MSG=

(nothing appears in the node log, as it haven't received anything).

 
 __  __       ____
|  \/  |_   _/ ___|  ___ _ __  ___  ___  _ __ ___
| |\/| | | | \___ \ / _ \ `_ \/ __|/ _ \| `__/ __|
| |  | | |_| |___| |  __/ | | \__ \  _  | |  \__ \
|_|  |_|\__, |____/ \___|_| |_|___/\___/|_|  |___/
        |___/                      2.2.0

16 MCO:BGN:INIT NODE,CP=RNNNAS--,VER=2.2.0
25 MCO:BGN:BFR
69 TSM:INIT
70 TSF:WUR:MS=0
77 TSM:INIT:TSP OK
79 TSM:INIT:STATID=44
81 TSF:SID:OK,ID=44
82 TSM:FPAR
102 TSF:MSG:SEND,44-44-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
159 TSF:MSG:READ,0-0-44,s=255,c=3,t=8,pt=1,l=1,sg=0:0
164 TSF:MSG:FPAR OK,ID=0,D=1
2109 TSM:FPAR:OK
2110 TSM:ID
2111 TSM:ID:OK
2113 TSM:UPL
2115 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2122 TSF:MSG:READ,0-0-44,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2127 TSF:MSG:PONG RECV,HP=1
2129 TSM:UPL:OK
2131 TSM:READY:ID=44,PAR=0,DIS=1
2136 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0101
2142 TSF:MSG:READ,0-0-44,s=255,c=3,t=15,pt=6,l=2,sg=0:0101
2152 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=16,pt=0,l=0,sg=0,ft=0,st=OK:
2158 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=0:<NONCE>
2246 TSF:MSG:SEND,44-44-0-0,s=255,c=0,t=17,pt=0,l=5,sg=1,ft=0,st=OK:2.2.0
2255 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2262 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
2352 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=6,pt=1,l=1,sg=1,ft=0,st=OK:0
2360 TSF:MSG:READ,0-0-44,s=255,c=3,t=16,pt=0,l=0,sg=1:
2382 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
2397 TSF:MSG:READ,0-0-44,s=255,c=3,t=6,pt=0,l=1,sg=1:M
2485 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2491 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
2581 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=11,pt=0,l=19,sg=1,ft=0,st=OK:MIXED JOAOABS SOTAO
2591 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2598 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
2685 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=12,pt=0,l=3,sg=1,ft=0,st=OK:1.0
2694 TSF:MSG:SEND,44-44-0-0,s=1,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2701 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
2791 TSF:MSG:SEND,44-44-0-0,s=1,c=0,t=3,pt=0,l=6,sg=1,ft=0,st=OK:RELAYS
2801 TSF:MSG:SEND,44-44-0-0,s=2,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2807 TSF:MSG:READ,0-0-44,s=1,c=0,t=3,pt=0,l=6,sg=0:RELAYS
2812 TSF:MSG:ACK
2814 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
2904 TSF:MSG:SEND,44-44-0-0,s=2,c=0,t=3,pt=0,l=6,sg=1,ft=0,st=OK:RELAYS
2914 TSF:MSG:SEND,44-44-0-0,s=3,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
2920 TSF:MSG:READ,0-0-44,s=2,c=0,t=3,pt=0,l=6,sg=0:RELAYS
2926 TSF:MSG:ACK
2927 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
3015 TSF:MSG:SEND,44-44-0-0,s=3,c=0,t=3,pt=0,l=6,sg=1,ft=0,st=OK:RELAYS
3024 TSF:MSG:SEND,44-44-0-0,s=4,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
3031 TSF:MSG:READ,0-0-44,s=3,c=0,t=3,pt=0,l=6,sg=0:RELAYS
3036 TSF:MSG:ACK
3038 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
3125 TSF:MSG:SEND,44-44-0-0,s=4,c=0,t=3,pt=0,l=6,sg=1,ft=0,st=OK:RELAYS
3134 TSF:MSG:SEND,44-44-0-0,s=30,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
3140 TSF:MSG:READ,0-0-44,s=4,c=0,t=3,pt=0,l=6,sg=0:RELAYS
3145 TSF:MSG:ACK
3147 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
3234 TSF:MSG:SEND,44-44-0-0,s=30,c=0,t=0,pt=0,l=6,sg=1,ft=0,st=OK:DOOR_A
3244 TSF:MSG:SEND,44-44-0-0,s=31,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
3250 TSF:MSG:READ,0-0-44,s=30,c=0,t=0,pt=0,l=6,sg=0:DOOR_A
3256 TSF:MSG:ACK
3257 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
3344 TSF:MSG:SEND,44-44-0-0,s=31,c=0,t=0,pt=0,l=6,sg=1,ft=0,st=OK:DOOR_B
3353 TSF:MSG:SEND,44-44-0-0,s=70,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
3360 TSF:MSG:READ,0-0-44,s=31,c=0,t=0,pt=0,l=6,sg=0:DOOR_B
3365 TSF:MSG:ACK
3367 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
3460 TSF:MSG:SEND,44-44-0-0,s=70,c=0,t=1,pt=0,l=3,sg=1,ft=0,st=OK:PIR
3467 MCO:REG:REQ
3470 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=26,pt=1,l=1,sg=1,ft=0,st=OK:2
3476 TSF:MSG:READ,0-0-44,s=70,c=0,t=1,pt=0,l=3,sg=0:PIR
3481 TSF:MSG:ACK
3483 TSF:MSG:READ,0-0-44,s=255,c=3,t=16,pt=0,l=0,sg=1:
3510 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
3524 TSF:MSG:READ,0-0-44,s=255,c=3,t=27,pt=1,l=1,sg=1:1
3609 MCO:PIM:NODE REG=1
3611 MCO:BGN:STP
3613 MCO:BGN:INIT OK,TSP=1
3619 TSF:MSG:SEND,44-44-0-0,s=30,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
3627 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
3714 TSF:MSG:SEND,44-44-0-0,s=30,c=1,t=16,pt=2,l=2,sg=1,ft=0,st=OK:1
3722 TSF:MSG:SEND,44-44-0-0,s=31,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
3734 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
3822 TSF:MSG:SEND,44-44-0-0,s=31,c=1,t=16,pt=2,l=2,sg=1,ft=0,st=OK:1
0
3832 TSF:MSG:SEND,44-44-0-0,s=70,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
3844 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
3932 TSF:MSG:SEND,44-44-0-0,s=70,c=1,t=16,pt=0,l=1,sg=1,ft=0,st=OK:0
26080 TSF:MSG:READ,0-0-44,s=1,c=3,t=16,pt=0,l=0,sg=1:
26106 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
26120 TSF:MSG:READ,0-0-44,s=1,c=1,t=2,pt=0,l=1,sg=1:0
26205 TSF:MSG:ACK REQ
26209 TSF:MSG:SEND,44-44-0-0,s=1,c=1,t=2,pt=0,l=1,sg=0,ft=0,st=OK:0
Incoming change for sensor:1, New status: 0
26216 TSF:MSG:READ,0-0-44,s=1,c=3,t=16,pt=0,l=0,sg=1:
26240 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
26250 TSF:MSG:READ,0-0-44,s=1,c=1,t=2,pt=0,l=1,sg=1:0
26334 TSF:MSG:ACK REQ
26339 TSF:MSG:SEND,44-44-0-0,s=1,c=1,t=2,pt=0,l=1,sg=0,ft=0,st=OK:0
Incoming change for sensor:1, New status: 0
29867 TSF:MSG:READ,0-0-44,s=2,c=3,t=16,pt=0,l=0,sg=1:
29888 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
29902 TSF:MSG:READ,0-0-44,s=2,c=1,t=2,pt=0,l=1,sg=1:0
29986 TSF:MSG:ACK REQ
29991 TSF:MSG:SEND,44-44-0-0,s=2,c=1,t=2,pt=0,l=1,sg=0,ft=0,st=OK:0
Incoming change for sensor:2, New status: 0
29999 TSF:MSG:READ,0-0-44,s=2,c=3,t=16,pt=0,l=0,sg=1:
30022 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
30031 TSF:MSG:READ,0-0-44,s=2,c=1,t=2,pt=0,l=1,sg=1:0
30116 TSF:MSG:ACK REQ
30120 TSF:MSG:SEND,44-44-0-0,s=2,c=1,t=2,pt=0,l=1,sg=0,ft=0,st=OK:0
Incoming change for sensor:2, New status: 0
31344 TSF:MSG:READ,0-0-44,s=3,c=3,t=16,pt=0,l=0,sg=1:
31366 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
31373 TSF:MSG:READ,0-0-44,s=3,c=1,t=2,pt=0,l=1,sg=1:0
31457 TSF:MSG:ACK REQ
31464 TSF:MSG:SEND,44-44-0-0,s=3,c=1,t=2,pt=0,l=1,sg=0,ft=0,st=OK:0
Incoming change for sensor:3, New status: 0
31471 TSF:MSG:READ,0-0-44,s=3,c=3,t=16,pt=0,l=0,sg=1:
31498 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
31510 TSF:MSG:READ,0-0-44,s=3,c=1,t=2,pt=0,l=1,sg=1:0
31594 TSF:MSG:ACK REQ
31597 TSF:MSG:SEND,44-44-0-0,s=3,c=1,t=2,pt=0,l=1,sg=0,ft=0,st=OK:0
Incoming change for sensor:3, New status: 0
32621 TSF:MSG:READ,0-0-44,s=4,c=3,t=16,pt=0,l=0,sg=1:
32643 TSF:MSG:SEND,44-44-0-0,s=255,c=3,t=17,pt=6,l=25,sg=1,ft=0,st=OK:<NONCE>
32657 TSF:MSG:READ,0-0-44,s=4,c=1,t=2,pt=0,l=1,sg=1:0
Incoming change for sensor:4, New status: 0
32752 TSF:MSG:SEND,44-44-0-0,s=31,c=3,t=16,pt=0,l=0,sg=1,ft=0,st=OK:
32758 TSF:MSG:READ,0-0-44,s=255,c=3,t=17,pt=6,l=25,sg=1:<NONCE>
32845 TSF:MSG:SEND,44-44-0-0,s=31,c=1,t=16,pt=2,l=2,sg=1,ft=0,st=OK:0
****** counters reached 0 **************
33015 MCO:SLP:MS=94,SMS=0,I1=255,M1=255,I2=255,M2=255
33020 TSF:TDI:TSL
33022 MCO:SLP:WUP=-1
33025 TSF:TRI:TSB
****** counters reached 0 **************
160429 MCO:SLP:MS=94,SMS=0,I1=255,M1=255,I2=255,M2=255
160434 TSF:TDI:TSL
160436 MCO:SLP:WUP=-1
160438 TSF:TRI:TSB

I'll keep doing some more tests and will report it here. Meanwhile if there is anything else you'd like me to try, do let me know.

Thanks,
Joaoabs

[Anticimex]

@joaoabs the failures you see are not signing failures. It is NACKs. Messages are not reaching its destination, and when that happens signing won't work. So you also get errors relating to signing as a consequence.
It is the rf link that is unstable in your latest log.

[joaoabs]

Thanks Anticimex for replying back,

I understand now the root cause is not related with the signing itself. It makes sense.
I may have wrongly associated to it becasue I read somewhere that the radio communication can be affected by signing because the packets are full and therefore the probability to have a missed bit in the between is bigger.

However, the RF link is the same in test 1 and test 2 (~6m with line of sight), and the result is totally different... It must be something on the code, not in the RF link, don't you think?

Thanks,
Joaoabs

[Anticimex]

@joaoabs well, I agree that it should not affect the airborne part of it, but one way or another it prevents the messages from coming through. Perhaps your sensor communication induce some disturbance in the radio supply?

[joaoabs]

Hi,

Some more testing:
I realised I was doing a rookie mistake: When testing, I changed PC and the default options to compile the mini-pro were 16MHz/5V on the new PC, while mine is 8MHz/3.3v.
I guess this difference in the clock was messing up the timmings on the 1-W bus, hence the eractic behaviour.
Now the sketch with the door/motion, relay and temp(DS18B20) seems to be more stable. Adding the DHT code, we get back to erratic behaviour, as the initial post, althought the used memory without "MY_DEBUG" is 70% used.

I'll be doing more tests and report back.

Thanks,

[Anticimex]

@joaoabs thanks for reporting. Is this with or without @tekka's patch?

[tekka]

@joaoabs Please post then full debug log when you observe the erratic behaviour (previously mentioned patch must be applied).

[joaoabs]

@tekka What debug flag should I activate for this?

When I see the erratic behavior there isn't nothing appearing in the serial console, even with the MY_DEBUG on, so I guess there should be other that is of your interest...

Thanks