Binding 2.4.0 Variable Problem

I posted something in the thread https://forum.mysensors.org/topic/9346/getting-mysensors-mqtt-gateway-working-on-openhab-2-2-stable/40 but just did another full round of testing to be sure so adding a new thread to get the conversation started. I have just set a test node that sits on my desk and have added the var1 item to an already well working test node - it is a switch and was not using any vars etc. So I edited the node code and added a loop request for var1 every 30 seconds.

Here is the code for this node

/**
 * 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/or
 * 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 - Henrik Ekblad
 *
 * DESCRIPTION
 * Example sketch showing how to control physical relays.
 * This example will remember relay state after power failure.
 * http://www.mysensors.org/build/relay
 */

// Enable debug prints to serial monitor
#define MY_DEBUG

// Enable and select radio type attached
#define MY_RADIO_NRF24
#define MY_RF24_CHANNEL 82
#define MY_RF24_IRQ_PIN 2
#define MY_RX_MESSAGE_BUFFER_FEATURE

#define MY_NODE_ID 27  // Set this to fix your Radio ID or use Auto

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

#include <MySensors.h>

#define RELAY_1  3  // Arduino Digital I/O pin number for first relay (second on pin+1 etc)
#define NUMBER_OF_RELAYS 1 // Total number of attached relays
#define RELAY_ON 0  // GPIO value to write to turn on attached relay
#define RELAY_OFF 1 // GPIO value to write to turn off attached relay
#define RELAY_UNKNOWN 2

int CurrentState[] = {RELAY_UNKNOWN, RELAY_UNKNOWN, RELAY_UNKNOWN, RELAY_UNKNOWN};
int SetState[] = {RELAY_OFF, RELAY_OFF, RELAY_OFF, RELAY_OFF};

unsigned long requestVar1Last = millis();
unsigned long requestVar1Time = 30000;

MyMessage relayMsg(0, V_STATUS);

void before() {
  wdt_enable(WDTO_2S);
}

void setup()
{
  for (int sensor=1, pin=RELAY_1; sensor<=NUMBER_OF_RELAYS; sensor++, pin++) {
    // Then set relay pins in output mode
    pinMode(pin, OUTPUT);
    SetState[sensor] = RELAY_OFF;
    request(sensor, V_STATUS);
    delay(50); 
    request(sensor, V_VAR1);
  }
}
void presentation()
{
  // Send the sketch version information to the gateway and Controller
  sendSketchInfo("Power Socket (7)", "4.1");

  for (int sensor=1; sensor<=NUMBER_OF_RELAYS; sensor++) {
    // Register all sensors to gw (they will be created as child devices)
    present(sensor, S_BINARY);
  }
}

void loop()
{
  wdt_reset();

  for (int sensor=1, pin=RELAY_1; sensor<=NUMBER_OF_RELAYS; sensor++, pin++) {
      if (CurrentState[sensor] != SetState[sensor] && SetState[sensor] != RELAY_UNKNOWN) {
        digitalWrite(pin, SetState[sensor]?RELAY_ON:RELAY_OFF);
        CurrentState[sensor] = SetState[sensor];   
        resend(relayMsg.setSensor(sensor).set(CurrentState[sensor]), 5);  
      }
    }

  if (requestVar1Last + requestVar1Time < millis()) {
     request(1, V_VAR1);
     requestVar1Last = millis();
  }
}

void resend(MyMessage &msg, int repeats)
{
  int repeat = 1;
  int repeatdelay = 0;
  boolean sendOK = false;

  while ((sendOK == false) and (repeat < repeats)) {
    if (send(msg)) {
      sendOK = true;
    } else {
      sendOK = false;
      Serial.print("Send Failed: ");
      Serial.println(repeat);
      repeatdelay += 50;
    } repeat++; wait(repeatdelay);
  }
}

void receive(const MyMessage &message)
{
  int sensor = message.sensor;
  // We only expect one type of message from controller. But we better check anyway.
  if (message.type==V_STATUS) {
    // Change relay state
    SetState[sensor] = message.getBool();

    // Write some debug info
    Serial.print(F("Incoming change for sensor:"));
    Serial.print(message.sensor);
    Serial.print(F(", New status: "));
    Serial.println(message.getBool());
  }
  if (message.type == V_VAR1) {
    int variable1 = atoi(message.data);// RUN_ALL_ZONES time
    Serial.print(F("Recieved variable1: "));
    Serial.println(variable1);     
  }
}

I added the item to openHab as follows:

Switch   Desktop_Debug_Light "Desktop Debug Light" <light> (gDevices,gRoom_Office) [ "iss:type:DevSwitch", "iss:room:Entry" ]  {channel="mysensors:light:gateway:Desktop_Debug_Light:status"}
Number  Desktop_Debug_Var1 "Desktop Debug Light- Var1 [%d]" <selfruntime>  (gDevices,gRoom_Office)   {channel="mysensors:light:gateway:Desktop_Debug_Light:var1"}

I used Paper UI and set the variable to 10 - this pushed the update to the node correctly. I then rebooted openHab which using persistence restores the variable 1 value back to 10 however when the node requests var1 from the controller after the reboot it receives 0. I have found this to be the same if I do an postUpdate. The var1 container on openHab has the 10 value in it I have confirmed this with a Rest API commnd the GET the item.

Here is the logs from the openHab log:tail and also the node I have added comments where the reboot happened and you will see the results:

2018-08-28 08:23:22.581 [.ItemChannelLinkAddedEvent] - Link 'Desktop_Debug_Var1-mysensors:light:gateway:Desktop_Debug_Light:var1' has been added.
2018-08-28 08:24:08.812 [ome.event.ItemCommandEvent] - Item 'Desktop_Debug_Var1' received command 10
2018-08-28 08:24:08.829 [vent.ItemStateChangedEvent] - Desktop_Debug_Var1 changed from NULL to 10
REBOOTED THE OPENHAB SERVER
2018-08-28 08:27:40.145 [temChannelLinkRemovedEvent] - Link 'Desktop_Debug_Var1 => mysensors:light:gateway:Desktop_Debug_Light:var1' has been removed.
2018-08-28 08:28:57.469 [.ItemChannelLinkAddedEvent] - Link 'Desktop_Debug_Var1-mysensors:light:gateway:Desktop_Debug_Light:var1' has been added.
2018-08-28 08:29:08.389 [vent.ItemStateChangedEvent] - Desktop_Debug_Var1 changed from NULL to 10.0

2280 TSF:MSG:SEND,27-27-0-0,s=1,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
2286 MCO:BGN:INIT OK,TSP=1
2290 TSF:MSG:SEND,27-27-0-0,s=1,c=1,t=2,pt=2,l=2,sg=0,ft=0,st=OK:1
2317 TSF:MSG:READ,0-0-27,s=1,c=1,t=2,pt=0,l=1,sg=0:1
Incoming change for sensor:1, New status: 1
2521 TSF:MSG:READ,0-0-27,s=1,c=1,t=24,pt=0,l=2,sg=0:10
Recieved variable1: 10
30002 TSF:MSG:SEND,27-27-0-0,s=1,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
30026 TSF:MSG:READ,0-0-27,s=1,c=1,t=24,pt=0,l=2,sg=0:10
Recieved variable1: 10
***** REBOOT OF OPENHAB SERVER *******
60010 TSF:MSG:SEND,27-27-0-0,s=1,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
90018 TSF:MSG:SEND,27-27-0-0,s=1,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
120026 TSF:MSG:SEND,27-27-0-0,s=1,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
150038 TSF:MSG:SEND,27-27-0-0,s=1,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
***** OPENHAB UP AGAIN ********
150090 TSF:MSG:READ,0-0-27,s=1,c=1,t=24,pt=0,l=1,sg=0:0
Recieved variable1: 0
180046 TSF:MSG:SEND,27-27-0-0,s=1,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
180071 TSF:MSG:READ,0-0-27,s=1,c=1,t=24,pt=0,l=1,sg=0:0
Recieved variable1: 0
210054 TSF:MSG:SEND,27-27-0-0,s=1,c=2,t=24,pt=0,l=0,sg=0,ft=0,st=OK:
210073 TSF:MSG:READ,0-0-27,s=1,c=1,t=24,pt=0,l=1,sg=0:0
Recieved variable1: 0

You can see the PaperUI update at 2018-08-28 08:24:08.829 which corresponds with the 30026 TSF:MSG:READ,0-0-27,s=1,c=1,t=24,pt=0,l=2,sg=0:10. I then rebooted and the server restored the value of 10 but the node continues to receive 0 and does so for ever - it never gets the value 10.

Here is the output of the item using the REST API which is taken well after the reboot and after many request(1,V_VAR1)'s is still reporting 0.

http://openhabianpi:8080/rest/items/Desktop_Debug_Var1
{
  "link": "http://openhabianpi:8080/rest/items/Desktop_Debug_Var1",
  "state": "10.0",
  "stateDescription": {
    "pattern": "%d",
    "readOnly": false,
    "options": []
  },
  "editable": false,
  "type": "Number",
  "name": "Desktop_Debug_Var1",
  "label": "Desktop Debug Light- Var1",
  "category": "selfruntime",
  "tags": [],
  "groupNames": [
    "gDevices",
    "gRoom_Office"
  ]
}

http://openhabianpi:8080/rest/items/Desktop_Debug_Var1/state
10.0

As mentioned the variable received at the node never updates also if we use a postUpdate in openHab it will continue to receive 0 until we issue a sendCommand at which time it will update until the next postUpdate or server reboot.

tobof / openhab-addons

Binding 2.4.0 Variable Problem #126