openHAB binding 2.4.0 I_TIME Duplicates & Wrong Times

[itbeyond]

I have been using the 2.4.0 binding for a few months now and was going to report this issue a while back however I have now seen exactly what is going on. When a node performs a requestTime() I am seeing this reported in the logtail correctly as:

2018-10-09 09:00:01.310 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 3, answering...

Looks perfect and the node receives the time however I was curious as to why sometimes the node would receive GMT and at other times my local timezone GMT+8. I decided to run the gateway via MYSContoller so I could monitor and log the traffic and I have found the problem. When the Gateway receives the request it responds twice within a few ms of each other, for what reason I do not know but the first response send the local time zone response (GMT+8) and the second is a GMT response. The logs for the above logtail report are as follows:

314155 9/10/2018 9:00:06 RX 3 - Rain Gauge (3) INTERNAL C_INTERNAL NO I_TIME
314156 9/10/2018 9:00:06 TX 3 - Rain Gauge (3) INTERNAL C_INTERNAL NO I_TIME 1539075607
314163 9/10/2018 9:00:07 TX 3 - Rain Gauge (3) INTERNAL C_INTERNAL NO I_TIME "1539046801"

Now the above is a copy and paste so not even sure where the quotes came from (cannot see them in MYSController - but they copied from the GMT response only). I was not quick enough the capture the details in the MYSController Debug area. However you will see the two sets of results returned from the one request within a few ms of each other. If you do the maths you will note that they are 28806 ms apart - 8 hours and some 6 seconds. This is the difference between GMT and my local time so it sends Local first then GMT which does an override in my node. In my nodes I have coded to add 28800 to the received time to try to get around the problem however if my node misses the second send it will be ahead by 8 hours.

Anyway I am not sure why this is occurring and it does seem a lot like a bug of some sort.

For completeness my bridge binding is as follows:

Bridge mysensors:bridge-eth:gateway [ ipAddress="192.168.100.136", tcpPort=5003, sendDelay=200,  startupCheckEnabled=true,  networkSanCheckEnabled=true, networkSanCheckInterval=1, networkSanCheckConnectionFailAttempts=1 ] {
  light       Courtyard_Pond_Pump      "Courtyard Pond Pump" @ "Courtyard"      [ nodeId=1, childId=1 ] 
  light       Courtyard_Garden_Lights  "Courtyard Garden Lights" @ "Courtyard"  [ nodeId=1, childId=2 ]
  
  light       Water_All_Zones  "Water - All Zones"  @ "Backyard"    [ nodeId=2, childId=0 ] 
  light       Water_Zone_1     "Water - Zone 1"     @ "Backyard"    [ nodeId=2, childId=1 ]
  light       Water_Zone_2     "Water - Zone 2"     @ "Backyard"    [ nodeId=2, childId=2 ]
  light       Water_Zone_3     "Water - Zone 3"     @ "Backyard"    [ nodeId=2, childId=3 ]  
  light       Water_Zone_4     "Water - Zone 4"     @ "Backyard"    [ nodeId=2, childId=4 ]
  light       Water_Zone_5     "Water - Zone 5"     @ "Backyard"    [ nodeId=2, childId=5 ]
  light       Water_Zone_6     "Water - Zone 6"     @ "Backyard"    [ nodeId=2, childId=6 ]

  humidity    Courtyard_Outside_Humidity      "Courtyard Outside Humidity" @ "Courtyard" [ nodeId=3, childId=0 ]
  temperature Courtyard_Outside_TempDHT       "Courtyard Outside Temp"     @ "Courtyard" [ nodeId=3, childId=1 ]
  light-level Courtyard_Outside_Light         "Courtyard Outside Light"    @ "Courtyard" [ nodeId=3, childId=2 ]
  rain        Courtyard_Outside_Rain          "Courtyard Outside Rain"     @ "Courtyard" [ nodeId=3, childId=3 ]  
  motion      Courtyard_Outside_RainDetected  "Courtyard Rain Detected"    @ "Courtyard" [ nodeId=3, childId=4 ]
  baro        Courtyard_Outside_Baro          "Courtyard Outside Baro"     @ "Courtyard" [ nodeId=3, childId=5 ] 
  temperature Courtyard_Outside_Temp          "Courtyard Outside Temp"     @ "Courtyard" [ nodeId=3, childId=6 ] 

  cover       Courtyard_Door_Blind  "Courtyard Door Blind"  @ "Courtyard" [ nodeId=4, childId=1 ]
  cover       Office_Front_Blinds   "Office Front Blinds"   @ "Office"    [ nodeId=4, childId=2 ]
  cover       Office_Side_Blinds    "Office Side Blinds"    @ "Office"    [ nodeId=4, childId=3 ]
  cover       Courtyard_LHS_Blinds   "Courtyard LHS Blinds" @ "Courtyard" [ nodeId=4, childId=4 ]
  cover       Courtyard_RHS_Blinds   "Courtyard RHS Blinds" @ "Courtyard" [ nodeId=4, childId=5 ]
  
  power       Power_Phase1  "Energy Phase 1"  @ "Garage"  [ nodeId=5, childId=0 ]
  power       Power_Phase2  "Energy Phase 2"  @ "Garage"  [ nodeId=5, childId=1 ]
  power       Power_Phase3  "Energy Phase 3"  @ "Garage"  [ nodeId=5, childId=2 ]
  power       Power_Main    "Energy Main"     @ "Garage"  [ nodeId=5, childId=8 ]

  scene       MasterBedroom_SceneController_8Way  "MasterBedroom_SceneController_8Way" @ "Bedroom"  [ nodeId=6, childId=0 ]

  light       Entry_FrontGarden_Lights    "Power Socket Relay" @ "Entry"  [ nodeId=7, childId=1 ]

  dimmer      Lounge_Front_Lights   "Lounge Front Lights"   @ "Lounge"  [ nodeId=8, childId=0 ] 
  dimmer      Lounge_Centre_Lights  "Lounge Centre Lights"  @ "Lounge"  [ nodeId=8, childId=1 ]
  dimmer      Lounge_Left_Lights    "Lounge Left Lights"    @ "Lounge"  [ nodeId=8, childId=2 ]
  dimmer      Lounge_Right_Lights   "Lounge Right Lights"   @ "Lounge"  [ nodeId=8, childId=3 ]

  light       MasterBedroom_Main_Light    "Bedroom Main Light"          @ "Bedroom" [ nodeId=9, childId=0 ]
  light       MasterBedroom_Robe_Light    "MBedroom Robe Light"         @ "Bedroom" [ nodeId=9, childId=1 ]
  light       MasterBedroom_Bedside_David "MasterBedroom Bedside David" @ "Bedroom" [ nodeId=9, childId=2 ]  
  light       MasterBedroom_Bedside_Shel  "MasterBedroom Bedside Shel"  @ "Bedroom" [ nodeId=9, childId=3 ]
  temperature MasterBedroom_Roof_Temp     "MasterBedroom Roof Temp"     @ "Bedroom" [ nodeId=9, childId=4 ]

  motion      Garage_Landcruiser    "Garage Landcruiser"  @ "Garage" [ nodeId=10, childId=1 ]
  motion      Garage_CLA250         "Garage CLA250"       @ "Garage" [ nodeId=10, childId=2 ]
  light       Garage_Door           "Garage Door"         @ "Garage" [ nodeId=10, childId=3 ] 
  temperature Garage_Internal_Temp  "Garage Temp"         @ "Garage" [ nodeId=10, childId=4 ]
  
  light       Backyard_Pool_Pump      "Backyard Pool Pump"     @ "Backyard" [ nodeId=11, childId=1 ]
  light       Backyard_Garden_Lights  "Backyard Garden Lights" @ "Backyard" [ nodeId=11, childId=2 ]

  dimmer      MasterBedroom_Ensuite_Light "MasterBedroom Ensuite Light" @ "Bedroom"  [ nodeId=12, childId=0 ] 
  light       MasterBedroom_Ensuite_Fan   "MasterBedroom Ensuite Fan"   @ "Bedroom" [ nodeId=12, childId=1 ]
  light       MasterBedroom_Ensuite_Heat1 "MasterBedroom Ensuite Heat1" @ "Bedroom" [ nodeId=12, childId=2 ]
  light       MasterBedroom_Ensuite_Heat2 "MasterBedroom Ensuite Heat2" @ "Bedroom" [ nodeId=12, childId=3 ]

  light       Office_Door   "Office Door Controller" @ "Office"  [ nodeId=13, childId=1 ]

  light       Bathroom_Main_TowelRail    "Power Socket Relay" @ "Bathroom"  [ nodeId=14, childId=1 ]

  light       Hallway_Bedroom_Lights    "Hallway_Bedroom_Lights"  @ "Hallways"  [ nodeId=15, childId=0 ]
  light       Backyard_PoolSpot_Light   "Backyard PoolSpot Light" @ "Backyard"  [ nodeId=15, childId=1 ]
  light       Kitchen_Pantry_Lights     "Kitchen Pantry Lights"   @ "Kitchen"   [ nodeId=15, childId=2 ]
  light       Hallway_FrontDoor_Lights "Hallway_FrontDoor_Lights" @ "Hallways"  [ nodeId=15, childId=3 ]
  temperature Kitchen_Roof_Temp       "Kitchen Roof Temp"         @ "Kitchen"   [ nodeId=15, childId=4 ]

  dimmer      Kitchen_WineRack_Lights   "Kitchen WineRack Lights" @ "Kitchen"  [ nodeId=16, childId=0 ] 

  light       Bathroom_Ensuite_TowelRail    "Power Socket Relay" @ "Bathroom"  [ nodeId=18, childId=1 ]

  dimmer      Alfresco_Outer_Lights "Alfresco Outer Lights" @ "Alfresco"  [ nodeId=19, childId=0 ] 
  dimmer      Alfresco_Inner_Lights "Alfresco Inner Lights" @ "Alfresco"  [ nodeId=19, childId=1 ]
  dimmer      Backyard_Eve_Lights   "Backyard Eve Lights"   @ "Backyard"  [ nodeId=19, childId=2 ]
  dimmer      Kitchen_Main_Lights   "Kitchen Main Lights"   @ "Kitchen"   [ nodeId=19, childId=3 ]
  
  dimmer      Kitchen_Island_Light  "Kitchen Island Light" @ "Kitchen" [ nodeId=20, childId=0 ] 
  dimmer      Kitchen_Swirl_Light   "Kitchen Swirl Light"  @ "Kitchen" [ nodeId=20, childId=1 ]

  light       Desktop_Debug_Light   "Power Socket Relay" @ "Office"  [ nodeId=27, childId=1 ]

  motion      Kitchen_Pantry_PIR    "Kitchen Pantry PIR" @ "Kitchen" [ nodeId=100, childId=0 ]

  motion      MasterBedroom_Robe_PIR      "MasterBedroom Robe PIR"    @ "Bedroom" [ nodeId=101, childId=0 ]
  motion      MasterBedroom_Ensuite_PIR   "MasterBedroom Ensuite PIR" @ "Bedroom" [ nodeId=102, childId=0 ]
}

I have a number of nodes as you can see and 2, 4 & 9 all use time and have the same exact problem. If I reboot or setup a test case I always get two times returned from the one request and it always is Local followed by GMT. I guess a node based work around would be to trash the second result if received within 30 seconds or something but when playing with time it is not a simple method as millis() may change between loading.

Anyone else see this or now how to fix it?

[itbeyond]

@itbeyond said in openHAB binding 2.4.0 I_TIME Duplicates & Wrong Times:

Bug report submitted in issues https://github.com/tobof/openhab2-addons/issues/125