search

tobof / openhab-addons

The next-generation open Home Automation Bus (openHAB)
Eclipse Public License 2.0
39 stars 30 forks source link

Binding 2.4.0 I_TIME Duplicates & Wrong Times #125

Closed itbeyond closed 5 years ago

itbeyond commented 5 years ago

itbeyond 16 minutes ago 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.

itbeyond commented 5 years ago

Just captured it again on Node2: 2018-10-09 10:47:13.337 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 2, answering...

318857 9/10/2018 10:47:19 RX 2 - Irrigation Ctrl (2) INTERNAL C_INTERNAL NO I_TIME
318858 9/10/2018 10:47:19 TX 2 - Irrigation Ctrl (2) INTERNAL C_INTERNAL NO I_TIME 1539082039 318859 9/10/2018 10:47:19 TX 2 - Irrigation Ctrl (2) INTERNAL C_INTERNAL NO I_TIME "1539053233

" Again the quotes but I also caught this in the MYSController Debug: 9/10/2018 10:47:19 RX 2;255;3;0;1; 9/10/2018 10:47:19 INFO Reply time request 9/10/2018 10:47:19 TX 2;255;3;0;1;1539082039 9/10/2018 10:47:19 FWD 2;255;3;0;1;1539053233 9/10/2018 10:47:19 TX 2;255;3;0;1;1539053233

I am using mySensors 2.3.0 if this helps or highlights anything.

tobof commented 5 years ago

I can't reproduce the problem. My I_TIME request is only answered once via the binding. I suspect MYSController is sending the additional answer? Or any other controller? There should be an additional output in the debug log of the binding in OpenHAB if the I_TIME response is sent twice.

itbeyond commented 5 years ago

I do agree but the interesting thing is I was having this issue without MYSController as my devices where resolving to UTC and not local time - I have made the irrigation controller with the LCD display with the time and this was UTC hence picking up the second send prior to installing the MYSController which I added to capture the issue. I have posted on mySensors asking about the FWD and different time it is providing to see if it is somehow coming from the library. Using 2.3.0 by the way, thinking I should test with 2.2.0 as I have seen a few strange behaviours with 2.3.0.

tobof commented 5 years ago

There is only one method to answer an I_TIME request here: Link

I don't see how the same method could possible give two different responses. :smile:

Please attach the debug output from OH2 and the MySensors binding so I'm able to take a deeper look.

itbeyond commented 5 years ago

@tobof - Hi Tim, See below my entire mysensors.things file I am having this issue across every time using node in this setup 2, 3, 12 and a new test node 22 which I have not setup in the binding but it still received I_TIME requests - this is a clock node to LCD panel. 

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 ]

  waterMeter  MasterBedroom_Shower_Shel  "Ensuite Shel Shower Flow" @ "Bedroom" [ nodeId=21, 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 also concur that this should not be occurring (I am a software dev and have read and checked your code a number of times) as the requested line with associated log output is only run once and responds with the local time however it appears that for every node requesting the time in my setup I am getting this FWD with the UTC time. I am at a lose as to where this FWD comes from and have posted in the mySensors forum https://forum.mysensors.org/topic/4833/serial-protocol-2-x/42 but have had no replies as yet in 10 days. I am using the latest release of 2.4.0 with a mod from tekka see https://forum.mysensors.org/topic/9642/nrf24-transmission-of-data-works-fine-but-constant-nack-s-produced/10 to correct a radio problem.

In terms of logs I have just recovered from a drop out of my persistence service (NAS firmware upgrade) so my logs are full of persistence error reports. I was able to collect the following from openhab.log.

2018-10-19 04:49:47.430 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 2, answering...
2018-10-19 04:50:43.925 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 22, answering...
2018-10-19 04:59:59.398 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 3, answering...
2018-10-19 05:00:00.036 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[python3, /etc/openhab2/scripts/Weather.py]'
2018-10-19 05:49:48.085 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 2, answering...
2018-10-19 05:50:40.861 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 22, answering...
2018-10-19 05:52:55.515 [INFO ] [clipse.smarthome.model.script.Blinds] - Blinds Night has finished!
2018-10-19 05:59:59.052 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 3, answering...
2018-10-19 06:00:00.014 [INFO ] [ipse.smarthome.model.script.Watering] - 6AM rule trigerred!
2018-10-19 06:00:00.032 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[python3, /etc/openhab2/scripts/Weather.py]'
2018-10-19 06:00:00.080 [INFO ] [ipse.smarthome.model.script.Watering] - Zone:  Water_Zone1 to ON
2018-10-19 06:00:00.161 [INFO ] [ipse.smarthome.model.script.Watering] - Zone:  Water_All_Zones to ON
2018-10-19 06:18:14.787 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 12, answering...
2018-10-19 06:49:48.731 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 2, answering...
2018-10-19 06:50:37.794 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 22, answering...
2018-10-19 06:59:58.709 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 3, answering...
2018-10-19 07:00:00.019 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[python3, /etc/openhab2/scripts/Weather.py]'
2018-10-19 07:38:39.564 [INFO ] [se.smarthome.model.script.Waterpumps] - Ensuite Shower On
2018-10-19 07:49:49.388 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 2, answering...
2018-10-19 07:50:34.719 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 22, answering...
2018-10-19 07:59:58.347 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 3, answering...
2018-10-19 08:00:00.022 [INFO ] [clipse.smarthome.model.script.Blinds] - 8AM rule trigerred!
2018-10-19 08:00:00.031 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[python3, /etc/openhab2/scripts/Weather.py]'
2018-10-19 08:49:50.042 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 2, answering...
2018-10-19 08:50:31.668 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 22, answering...
2018-10-19 08:59:58.002 [INFO ] [rs.internal.gateway.MySensorsGateway] - I_TIME request received from 3, answering...
2018-10-19 09:00:00.033 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[python3, /etc/openhab2/scripts/Weather.py]'
2018-10-19 09:00:00.095 [INFO ] [se.smarthome.model.script.Waterpumps] - Hours To Run: 2.5 - Today Runtime: 0
2018-10-19 09:00:00.129 [INFO ] [se.smarthome.model.script.Waterpumps] - Pool Pump: OFF - Main Watts: 21 - Light Level: 8524
2018-10-19 09:10:00.048 [INFO ] [se.smarthome.model.script.Waterpumps] - Hours To Run: 2.5 - Today Runtime: 0.14995694444444446
2018-10-19 09:10:00.084 [INFO ] [se.smarthome.model.script.Waterpumps] - Pool Pump: ON - Main Watts: 21 - Light Level: 9006
2018-10-19 09:20:00.022 [INFO ] [se.smarthome.model.script.Waterpumps] - Hours To Run: 2.5 - Today Runtime: 0.31661666666666666
2018-10-19 09:20:00.034 [INFO ] [se.smarthome.model.script.Waterpumps] - Pool Pump: ON - Main Watts: 29 - Light Level: 9272

Is there a specific logging function I should run to collect the best data for you. I am only a month or so into openHab and still feeling my way - I assume there is a karaf console command or something to enable the best logs of this but not 100% sure - would appreciate your advice on this?

I have a work around for the issue right now but it seems wrong to have to have it but for your information here is my work around in the receiveTime() callback - it will take the first time it receives set this as the time and only allow a time change if the next time is within 10000ms (hence a update but with 28800 for my timezone it will throw the UTC away):

unsigned long lasttime;

void receiveTime(unsigned long newTime)
{
  if (now() - newTime > -10000ul || now() - newTime < 10000ul || lasttime == 0) {
    lasttime = millis();
    // Time is within 10s so not that different to current time allow update
    setTime(newTime);
  }
  timeReceived = true;
}
itbeyond commented 5 years ago

OK so last night I removed MYSContoller from the loop and when I looked this morning at the clock on my desk it has gone to GMT even with the mod I had installed to force it to use the first time. So the problem seems to be that the mySensors binding is sending out GMT and not the local time when a request is made for the time. MYSController may have been sending the local time to the nodes in addition to the GMT from the binding. Does the binding only deliver GMT - I have the openHab RPI setup with GMT +8 and the date command shows:

[09:43:34] openhabian@openHABianPi:~$ date Wed 24 Oct 09:43:39 AWST 2018

Which is correct however my clock test node is currently showing 01:43:39 (minus 8 hours). I have also checked in the Paper UI SETTINGS and it reports GMT +8 as the setup zone. I will pull the mod out of my nodes now and again add the 28800 seconds to the receiveTime and it will show the right time again. So in conclusion the MYSController did in fact seem to send a Time however it sent the right TZ corrected time earlier than the binding reponded to the request which was sending GMT, by removing MYSController my nodes are now sitting on GMT.

itbeyond commented 5 years ago

@tobof please excuse my lack of understanding here but how do I go about compiling this add-on or how do I get to the latest version of the binding to use this updated functionality. IS there a jar store or something as the links to jars you have published only reference specific versions and there seems to be no listing of the jars that are available anyway that I can find?

tobof commented 5 years ago

@itbeyond There is no such archive of jars. As far as I know, there is a automatic build process for pull requests to the upstream branch. I agree, that this is something that would be useful!

I've uploaded the current compile to the familar location.