Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

MySensors serial GW not sending time #5163

Closed
Luc3as opened this issue Jan 3, 2017 · 14 comments
Closed

MySensors serial GW not sending time #5163

Luc3as opened this issue Jan 3, 2017 · 14 comments
Labels
waiting-for-reply

Comments

@Luc3as
Copy link

Luc3as commented Jan 3, 2017

Home Assistant release (hass --version):
0.35.3

Python release (python3 --version):
Python 3.4.2

Component/platform:
MySensors

Description of problem:
MySensors serial gateway is not sending time to node when requested

Expected:
HASS should send time through GW in seconds since epoch.

Problem-relevant configuration.yaml entries and steps to reproduce:

mysensors:
  gateways:
    - device: '/dev/arduino'
      persistence_file: '/home/homeassistant/.homeassistant/mysensors.json'
      baud_rate: 115200
  version: 2.0
  debug: false
  persistence: true
  optimistic: true
  1. I have serial GW connected to raspberry pi where is HASS installed
  2. I have mysensors node , with time requesting sketch uploaded, I tried TimeAware sensor and any others like this one https://www.mysensors.org/build/display
  3. after requesting time from controller, I can see in serial output of node it is requesting time but no answer is handled by HASS.
  4. I also tried to connect the same gateway to MysController on windows and time was received every single time, even after first call of requestTime ( there is 10 attempts in sketch after 1 seconds). So I assume sketch and everything else is correct. I was able to get time from HASS once from cca 200 attempts.

here is serial log from node requesting time:

Presentation complete
6277 MCO:REG:REQ
6283 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
6291 TSF:MSG:READ,0-0-5,s=255,c=3,t=27,pt=1,l=1,sg=0:1
6297 MCO:PIM:NODE REG=1
6299 MCO:BGN:STP
6311 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
7321 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
8329 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
9338 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
10358 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
11364 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
12374 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
13383 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
14391 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
15400 TSF:MSG:SEND,5-5-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time.
Time status: 0

I tried to disconnect GW from HASS and listen to serial port on RasPi:

root@luc3as-ha:~# tail -f  /dev/arduino
0;255;3;0;9;MCO:BGN:INIT GW,CP=RNNGA--,VER=2.1.0
0;255;3;0;9;TSM:INIT
0;255;3;0;9;TSF:WUR:MS=0
0;255;3;0;9;TSM:INIT:TSP OK
0;255;3;0;9;TSM:INIT:GW MODE
0;255;3;0;9;TSM:READY:ID=0,PAR=0,DIS=0
0;255;3;0;9;MCO:REG:NOT NEEDED
0;255;3;0;14;Gateway startup complete.
0;255;0;0;18;2.1.0
0;255;3;0;9;MCO:BGN:STP
0;255;3;0;9;MCO:BGN:INIT OK,TSP=1


0;255;3;0;9;TSF:MSG:READ,5-5-255,s=255,c=3,t=7,pt=0,l=0,sg=0:
0;255;3;0;9;TSF:MSG:BC
0;255;3;0;9;TSF:MSG:FPAR REQ,ID=5
0;255;3;0;9;TSF:PNG:SEND,TO=0
0;255;3;0;9;TSF:CKU:OK
0;255;3;0;9;TSF:MSG:GWL OK
0;255;3;0;9;TSF:MSG:SEND,0-0-5-5,s=255,c=3,t=8,pt=1,l=1,sg=0,ft=0,st=OK:0
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=24,pt=1,l=1,sg=0:1
0;255;3;0;9;TSF:MSG:PINGED,ID=5,HP=1
0;255;3;0;9;TSF:MSG:SEND,0-0-5-5,s=255,c=3,t=25,pt=1,l=1,sg=0,ft=0,st=OK:1
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
0;255;3;0;9;TSF:MSG:SEND,0-0-5-5,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=0,t=17,pt=0,l=5,sg=0:2.1.0
5;255;0;0;17;2.1.0
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=6,pt=1,l=1,sg=0:0
5;255;3;0;6;0
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=11,pt=0,l=15,sg=0:Weather_Station
5;255;3;0;11;Weather_Station
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=12,pt=0,l=3,sg=0:1.4
5;255;3;0;12;1.4
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=0,c=0,t=7,pt=0,l=0,sg=0:
5;0;0;0;7;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=1,c=0,t=6,pt=0,l=0,sg=0:
5;1;0;0;6;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=2,c=0,t=8,pt=0,l=0,sg=0:
5;2;0;0;8;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=3,c=0,t=8,pt=0,l=0,sg=0:
5;3;0;0;8;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=4,c=0,t=30,pt=0,l=0,sg=0:
5;4;0;0;30;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=5,c=0,t=30,pt=0,l=0,sg=0:
5;5;0;0;30;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=6,c=0,t=35,pt=0,l=0,sg=0:
5;6;0;0;35;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=7,c=0,t=10,pt=0,l=0,sg=0:
5;7;0;0;10;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=8,c=0,t=1,pt=0,l=0,sg=0:
5;8;0;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=26,pt=1,l=1,sg=0:2
0;255;3;0;9;TSF:MSG:SEND,0-0-5-5,s=255,c=3,t=27,pt=1,l=1,sg=0,ft=0,st=OK:1
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=1,pt=0,l=0,sg=0:
5;255;3;0;1;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=8,c=2,t=24,pt=0,l=0,sg=0:
5;8;2;0;24;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=8,c=2,t=25,pt=0,l=0,sg=0:
5;8;2;0;25;
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=7,c=1,t=24,pt=7,l=5,sg=0:0.0
5;7;1;0;24;0.0
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=7,c=1,t=25,pt=7,l=5,sg=0:60.0
5;7;1;0;25;60.0
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=7,c=1,t=26,pt=7,l=5,sg=0:60.0
5;7;1;0;26;60.0
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=7,c=1,t=27,pt=7,l=5,sg=0:60.0
5;7;1;0;27;60.0
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=7,c=1,t=28,pt=7,l=5,sg=0:60.0
5;7;1;0;28;60.0
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=0,pt=1,l=1,sg=0:208
5;255;3;0;0;208
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=4,c=1,t=38,pt=7,l=5,sg=0:5.63
5;4;1;0;38;5.63
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=5,c=1,t=38,pt=7,l=5,sg=0:0.07
5;5;1;0;38;0.07
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=2,c=1,t=4,pt=7,l=5,sg=0:1017.3
5;2;1;0;4;1017.3
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=2,c=1,t=43,pt=0,l=3,sg=0:hPa
5;2;1;0;43;hPa
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=3,c=1,t=5,pt=0,l=7,sg=0:unknown
5;3;1;0;5;unknown
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=1,c=1,t=0,pt=7,l=5,sg=0:22.4
5;1;1;0;0;22.4
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=0,c=1,t=1,pt=7,l=5,sg=0:46
5;0;1;0;1;46
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=8,c=1,t=16,pt=1,l=1,sg=0:1
5;8;1;0;16;1
0;255;3;0;9;TSF:MSG:READ,5-5-0,s=255,c=3,t=22,pt=5,l=4,sg=0:11436
5;255;3;0;22;11436

Here is log from HASS, it has no information about time request:

Jan 03 18:37:32 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.temperature_sensor_4_0, old_state=<state sensor.temperature_sensor_4_0=17.8; battery_level=74, V_TEMP=17.8, node_id=4, child_id=0, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Temperature Sensor 4 0 @ 2017-01-03T18:37:31.434318+01:00>, new_state=<state sensor.temperature_sensor_4_0=17.8; battery_level=74, V_TEMP=17.8, node_id=4, child_id=0, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Temperature Sensor 4 0 @ 2017-01-03T18:37:32.427782+01:00>>
Jan 03 18:37:32 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.temperature_sensor_4_17, old_state=<state sensor.temperature_sensor_4_17=3.87; battery_level=74, node_id=4, child_id=17, unit_of_measurement=V, V_VOLTAGE=3.87, device=/dev/arduino, description=, friendly_name=Temperature Sensor 4 17 @ 2017-01-03T18:37:31.671612+01:00>, new_state=<state sensor.temperature_sensor_4_17=3.88; battery_level=74, node_id=4, child_id=17, unit_of_measurement=V, V_VOLTAGE=3.88, device=/dev/arduino, description=, friendly_name=Temperature Sensor 4 17 @ 2017-01-03T18:37:32.557556+01:00>>
Jan 03 18:37:33 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sun.sun, old_state=<state sun.sun=below_horizon; next_rising=2017-01-04T06:40:44+00:00, azimuth=262.46, next_setting=2017-01-04T15:04:04+00:00, elevation=-24.09, friendly_name=Slniečko @ 2017-01-03T18:24:26.770790+01:00>, new_state=<state sun.sun=below_horizon; next_rising=2017-01-04T06:40:44+00:00, azimuth=262.64, next_setting=2017-01-04T15:04:04+00:00, elevation=-24.26, friendly_name=Slniečko @ 2017-01-03T18:24:26.770790+01:00>>
Jan 03 18:38:00 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.cpu_use, old_state=<state sensor.cpu_use=26; icon=mdi:memory, unit_of_measurement=%, friendly_name=CPU Use @ 2017-01-03T18:37:30.765827+01:00>, new_state=<state sensor.cpu_use=31; icon=mdi:memory, unit_of_measurement=%, friendly_name=CPU Use @ 2017-01-03T18:38:00.569122+01:00>>
Jan 03 18:38:00 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.since_last_boot, old_state=<state sensor.since_last_boot=3 days, 0:26:12.932689; icon=mdi:clock, friendly_name=Since Last Boot @ 2017-01-03T18:37:31.040991+01:00>, new_state=<state sensor.since_last_boot=3 days, 0:26:42.614145; icon=mdi:clock, friendly_name=Since Last Boot @ 2017-01-03T18:38:00.665189+01:00>>
Jan 03 18:38:00 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.ram_use, old_state=<state sensor.ram_use=83.1; icon=mdi:memory, unit_of_measurement=%, friendly_name=RAM Use @ 2017-01-03T18:37:31.248335+01:00>, new_state=<state sensor.ram_use=83.0; icon=mdi:memory, unit_of_measurement=%, friendly_name=RAM Use @ 2017-01-03T18:38:00.819922+01:00>>
Jan 03 18:38:01 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_0, old_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:36:43.645219+01:00>, new_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:01.744799+01:00>>
Jan 03 18:38:01 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_1, old_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:36:43.744724+01:00>, new_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:01.842532+01:00>>
Jan 03 18:38:02 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_2, old_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:36:43.835350+01:00>, new_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:02.022083+01:00>>
Jan 03 18:38:02 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_3, old_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:36:43.913592+01:00>, new_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:02.144897+01:00>>
Jan 03 18:38:02 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_4, old_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:36:44.008332+01:00>, new_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:02.325600+01:00>>
Jan 03 18:38:02 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_5, old_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:36:44.090404+01:00>, new_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:02.487995+01:00>>
Jan 03 18:38:02 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7, old_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:36:44.166414+01:00>, new_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:02.616724+01:00>>
Jan 03 18:38:02 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7_2, old_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:36:44.286545+01:00>, new_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:02.788298+01:00>>
Jan 03 18:38:03 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_0, old_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:01.744799+01:00>, new_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:03.270051+01:00>>
Jan 03 18:38:03 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_1, old_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:01.842532+01:00>, new_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:03.410961+01:00>>
Jan 03 18:38:03 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_2, old_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:02.022083+01:00>, new_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:03.552649+01:00>>
Jan 03 18:38:03 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_3, old_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:02.144897+01:00>, new_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:03.713672+01:00>>
Jan 03 18:38:03 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_4, old_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:02.325600+01:00>, new_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:03.848175+01:00>>
Jan 03 18:38:04 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_5, old_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:02.487995+01:00>, new_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:03.994010+01:00>>
Jan 03 18:38:04 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7, old_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:02.616724+01:00>, new_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:04.188959+01:00>>
Jan 03 18:38:04 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7_2, old_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:02.788298+01:00>, new_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:04.363161+01:00>>
Jan 03 18:38:05 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 0 already exists in children of node 5, cannot add child
Jan 03 18:38:05 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 1 already exists in children of node 5, cannot add child
Jan 03 18:38:05 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 2 already exists in children of node 5, cannot add child
Jan 03 18:38:05 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 3 already exists in children of node 5, cannot add child
Jan 03 18:38:06 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 4 already exists in children of node 5, cannot add child
Jan 03 18:38:06 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 5 already exists in children of node 5, cannot add child
Jan 03 18:38:06 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 6 already exists in children of node 5, cannot add child
Jan 03 18:38:06 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 7 already exists in children of node 5, cannot add child
Jan 03 18:38:07 luc3as-ha hass[15228]: WARNING:mysensors.mysensors:child_id 8 already exists in children of node 5, cannot add child
Jan 03 18:38:12 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_0, old_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:03.270051+01:00>, new_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:12.420046+01:00>>
Jan 03 18:38:12 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_1, old_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:03.410961+01:00>, new_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:12.525631+01:00>>
Jan 03 18:38:12 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_2, old_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:03.552649+01:00>, new_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:12.629901+01:00>>
Jan 03 18:38:12 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_3, old_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:03.713672+01:00>, new_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:12.715685+01:00>>
Jan 03 18:38:12 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_4, old_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:03.848175+01:00>, new_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:12.809272+01:00>>
Jan 03 18:38:12 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_5, old_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:03.994010+01:00>, new_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:12.895058+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7, old_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:04.188959+01:00>, new_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:13.006590+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7_2, old_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:04.363161+01:00>, new_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:13.108396+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_0, old_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:12.420046+01:00>, new_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:13.406379+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_1, old_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:12.525631+01:00>, new_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:13.488418+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_2, old_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:12.629901+01:00>, new_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:13.586585+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_3, old_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:12.715685+01:00>, new_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:13.674568+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_4, old_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:12.809272+01:00>, new_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:13.760069+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_5, old_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:12.895058+01:00>, new_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:13.848523+01:00>>
Jan 03 18:38:13 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7, old_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:13.006590+01:00>, new_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:13.951320+01:00>>
Jan 03 18:38:14 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7_2, old_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:13.108396+01:00>, new_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:14.048669+01:00>>
Jan 03 18:38:14 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_0, old_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:13.406379+01:00>, new_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:14.386768+01:00>>
Jan 03 18:38:14 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_1, old_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:13.488418+01:00>, new_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:14.462297+01:00>>
Jan 03 18:38:14 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_2, old_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:13.586585+01:00>, new_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:14.568429+01:00>>
Jan 03 18:38:14 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_3, old_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:13.674568+01:00>, new_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:14.696860+01:00>>
Jan 03 18:38:14 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_4, old_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:13.760069+01:00>, new_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:14.792504+01:00>>
Jan 03 18:38:14 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_5, old_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:13.848523+01:00>, new_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:14.884054+01:00>>
Jan 03 18:38:15 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7, old_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:13.951320+01:00>, new_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:14.983586+01:00>>
Jan 03 18:38:15 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7_2, old_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:14.048669+01:00>, new_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:15.083690+01:00>>
Jan 03 18:38:15 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_0, old_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:14.386768+01:00>, new_state=<state sensor.weather_station_5_0=71; battery_level=67, node_id=5, child_id=0, unit_of_measurement=%, V_HUM=71, device=/dev/arduino, description=, friendly_name=Vonkajšia vlhosť @ 2017-01-03T18:38:15.400525+01:00>>
Jan 03 18:38:15 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_1, old_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:14.462297+01:00>, new_state=<state sensor.weather_station_5_1=18.2; battery_level=67, V_TEMP=18.2, node_id=5, child_id=1, unit_of_measurement=°C, device=/dev/arduino, description=, friendly_name=Vonkajšia teplota @ 2017-01-03T18:38:15.495294+01:00>>
Jan 03 18:38:15 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_2, old_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:14.568429+01:00>, new_state=<state sensor.weather_station_5_2=1017.2; battery_level=67, node_id=5, child_id=2, unit_of_measurement=hPa, device=/dev/arduino, V_PRESSURE=1017.2, V_UNIT_PREFIX=hPa, description=, friendly_name=Barometrický tlak @ 2017-01-03T18:38:15.594217+01:00>>
Jan 03 18:38:15 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_3, old_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:14.696860+01:00>, new_state=<state sensor.weather_station_5_3=unknown; battery_level=67, V_FORECAST=unknown, node_id=5, child_id=3, device=/dev/arduino, description=, friendly_name=Predpoveď @ 2017-01-03T18:38:15.722821+01:00>>
Jan 03 18:38:15 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_4, old_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:14.792504+01:00>, new_state=<state sensor.weather_station_5_4=3.79; battery_level=67, node_id=5, child_id=4, unit_of_measurement=V, V_VOLTAGE=3.79, device=/dev/arduino, description=, friendly_name=Napätie batérie @ 2017-01-03T18:38:15.883684+01:00>>
Jan 03 18:38:16 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_5, old_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:14.884054+01:00>, new_state=<state sensor.weather_station_5_5=0.75; battery_level=67, node_id=5, child_id=5, unit_of_measurement=V, V_VOLTAGE=0.75, device=/dev/arduino, description=, friendly_name=Napätie sol. panelu @ 2017-01-03T18:38:16.052686+01:00>>
Jan 03 18:38:16 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7, old_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:14.983586+01:00>, new_state=<state sensor.weather_station_5_7=0.6; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:16.193206+01:00>>
Jan 03 18:38:16 luc3as-ha hass[15228]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: entity_id=sensor.weather_station_5_7_2, old_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:15.083690+01:00>, new_state=<state sensor.weather_station_5_7_2=472.0; battery_level=67, node_id=5, V_VAR4=60.6, child_id=7, V_RAINRATE=472.0, V_VAR1=0.6, V_VAR3=60.6, V_VAR5=60.6, V_RAIN=0.6, V_VAR2=60.6, device=/dev/arduino, description=, friendly_name=Weather_Station 5 7 @ 2017-01-03T18:38:16.368441+01:00>>

Sidenote feature request :
I would suggest to send local system time instead of UTC, because now the system is supposed to send UTC time, but I have different timezone and daylight saving time so time received from controller is different as real time in some timezones.

I am not sure but it could be done in
elif msg.sub_type == self.const.Internal.I_TIME:
return msg.copy(ack=0, payload=int(time.time()))

with time.altzone , or time.localtime() conversion to seconds since epoch.

@MartinHjelmare thanks for amazing work ;)
@MartinHjelmare
Copy link
Member

MartinHjelmare commented Jan 3, 2017 •
edited

Hi!
Looks like you're sending a heartbeat response from node 5 in the end of the gateway log. If this is not the case, please post your sketch.

After the first heartbeat is received from a node, HASS/pymysensors will treat the node as smartsleeping and only send messages after receiving a heartbeat. New requested state will be stored and other message types will be queued, and all messages sent from controller to node only upon heartbeat.

Time response is implemented since early in the pymysensors history and hasn't changed, so I think it should be working. Existing unit test for this is green. Let me know if you still experience problems even without sending any heartbeat from the node, or if you don't get the queued messages when sending the heartbeat.

PS. Please set debug option for mysensors and log level to debug for the mysensors package and component in the logger component, to get a more verbose log.

logger:
  default: info
  logs:
    mysensors: debug
    homeassistant.components.mysensors: debug

mysensors:
  debug: true

@MartinHjelmare
Copy link
Member

MartinHjelmare commented Jan 3, 2017 •
edited

Thinking about this some more, and it probably makes more sense to answer requests immediately, even for smartsleeping nodes. Queuing a message with a time report is pretty useless anyhow. 😝

@Luc3as
Copy link
Author

Luc3as commented Jan 4, 2017

hello,
here is simplified sketch from arduino node

at the end I am using smart sleep, am i supposed to send heartbeat somewhere on start of loop or it is done automatically with smartsleep ?

I slightly modified the sketch, I request time on setup, and if it is not set, I call it every wakeup on start of loop.

With debug turned on I can see gateway is sending time at very end of all request, when the node is sleeping, but it is not received after wakeup .

/**
 * 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.
 *
 *******************************
 *
 */
// Enable MY_DEBUG flag for MY_DEBUG prints. This will add a lot to the size of the final sketch but good
// to see what is actually is happening when developing
#define MY_DEBUG 


// Enable and select radio type attached
#define MY_RADIO_NRF24

#include <SPI.h>
#include <MySensors.h>  
#include <Wire.h>
#include <SI7021.h>
#include <Adafruit_BMP085.h>
#include <math.h>
#include <TimeLib.h>

#define MY_NODE_ID 2
#define CHILD_ID_HUM 0
#define CHILD_ID_TEMP 1
#define CHILD_ID_BARO 2
#define CHILD_ID_FOREC 3
#define CHILD_ID_VBATT 4
#define CHILD_ID_VSOLAR 5
#define CHILD_ID_MOISTURE 6
#define CHILD_ID_RAIN_LOG 7  // Keeps track of accumulated rainfall
#define CHILD_ID_TRIPPED_INDICATOR 8  // Indicates Tripped when rain detected

#define CALIBRATE_FACTOR 60 // amount of rain per rain bucket tip e.g. 5 is .05mm
#define EEPROM_BUFFER_LOCATION 0  // location of the EEPROM circular buffer
#define E_BUFFER_LENGTH 240
#define RAIN_BUCKET_SIZE 120
int BATTERY_SENSE_PIN = A2;  // select the input pin for the battery sense point
int SOLAR_SENSE_PIN = A3;  // select the input pin for the solar panel sense point
int MOISTURE_SENSE_PIN = A1;  // select the input pin for the soil mosture sensor
int TIP_SENSOR_PIN = 3; // input pin where reed switch or hall effect sensor is attached
int eepromIndex;

// Constants
#define BATTERY_MAX_VOLTAGE 4.21 // V, nominal voltage at battery for powering up device
#define BATTERY_MIN_VOLTAGE 2.9 // V, minimal voltage at which sensor still works
unsigned long SLEEP_TIME = 60000; // Sleep time between reads (in milliseconds)
const int ALTITUDE = 242; // <-- adapt this value to your own location's altitude.

const char *weather[] = { "stable", "sunny", "cloudy", "unstable", "thunderstorm", "unknown" };
enum FORECAST
{
  STABLE = 0,     // "Stable Weather Pattern"
  SUNNY = 1,      // "Slowly rising Good Weather", "Clear/Sunny "
  CLOUDY = 2,     // "Slowly falling L-Pressure ", "Cloudy/Rain "
  UNSTABLE = 3,   // "Quickly rising H-Press",     "Not Stable"
  THUNDERSTORM = 4, // "Quickly falling L-Press",    "Thunderstorm"
  UNKNOWN = 5     // "Unknown (More Time needed)
};

const unsigned long oneHour = 3600000UL;
unsigned long lastTipTime;
unsigned long lastRainTime; //Used for rainRate calculation
unsigned int rainBucket [RAIN_BUCKET_SIZE] ; /* 24 hours x 5 Days = 120 hours */
unsigned int rainRate = 0;
uint8_t rainWindow = 72;         //default rain window in hours.  Will be overwritten with msgTrippedVar1.
volatile int wasTippedBuffer = 0;
int rainSensorThreshold = 50; //default rain sensor sensitivity in hundredths.  Will be overwritten with msgTrippedVar2.
uint8_t state = 0;
uint8_t oldState = 2; //Setting the default to something other than 1 or 0
unsigned int lastRainRate = 0;
int lastMeasure = 0;
bool gotTime = false;
uint8_t lastHour;
uint8_t currentHour;

Adafruit_BMP085 bmp;
float lastTemperature;
float lastHumidity;
boolean metric = true; 
int oldBatteryPcnt = 0;
float oldVBatt = 0;
float oldVSolar = 0;
int oldMoisture = 0;
float lastPressure = -1;
int lastForecast = -1;

const int LAST_SAMPLES_COUNT = 5;
float lastPressureSamples[LAST_SAMPLES_COUNT];

// this CONVERSION_FACTOR is used to convert from Pa to kPa in forecast algorithm
// get kPa/h be dividing hPa by 10 
#define CONVERSION_FACTOR (1.0/10.0)

SI7021 sisensor;

int minuteCount = 0;
bool firstRound = true;
// average value is used in forecast algorithm.
float pressureAvg;
// average after 2 hours is used as reference value for the next iteration.
float pressureAvg2;
float dP_dt;

MyMessage msgHumidity(CHILD_ID_HUM, V_HUM);
MyMessage msgTemperature(CHILD_ID_TEMP, V_TEMP);
MyMessage pressureMsg(CHILD_ID_BARO, V_PRESSURE);
MyMessage forecastMsg(CHILD_ID_FOREC, V_FORECAST);
MyMessage msgPrefix(CHILD_ID_BARO, V_UNIT_PREFIX);  // Custom unit message.
MyMessage msgVBatt(CHILD_ID_VBATT, V_VOLTAGE);
MyMessage msgVSolar(CHILD_ID_VSOLAR, V_VOLTAGE);
MyMessage msgMoisture(CHILD_ID_MOISTURE, V_LEVEL);
MyMessage msgMoisturePrefix(CHILD_ID_MOISTURE, V_UNIT_PREFIX);  // Custom unit message.
MyMessage msgRainRate(CHILD_ID_RAIN_LOG, V_RAINRATE);
MyMessage msgRain(CHILD_ID_RAIN_LOG, V_RAIN);
MyMessage msgRainVAR1(CHILD_ID_RAIN_LOG, V_VAR1);
MyMessage msgRainVAR2(CHILD_ID_RAIN_LOG, V_VAR2);
MyMessage msgRainVAR3(CHILD_ID_RAIN_LOG, V_VAR3);
MyMessage msgRainVAR4(CHILD_ID_RAIN_LOG, V_VAR4);
MyMessage msgRainVAR5(CHILD_ID_RAIN_LOG, V_VAR5);
MyMessage msgTripped(CHILD_ID_TRIPPED_INDICATOR, V_TRIPPED);
MyMessage msgTrippedVar1(CHILD_ID_TRIPPED_INDICATOR, V_VAR1);
MyMessage msgTrippedVar2(CHILD_ID_TRIPPED_INDICATOR, V_VAR2);


void presentation()
{
  // Send the Sketch Version Information to the Gateway
  sendSketchInfo("Weather_Station", "1.4");

  // Register all sensors to gw (they will be created as child devices)
  present(CHILD_ID_HUM, S_HUM);
  present(CHILD_ID_TEMP, S_TEMP);
  present(CHILD_ID_BARO, S_BARO);
  present(CHILD_ID_FOREC, S_BARO);
  present(CHILD_ID_VBATT, S_MULTIMETER);
  present(CHILD_ID_VSOLAR, S_MULTIMETER);
  present(CHILD_ID_MOISTURE, S_MOISTURE);
  present(CHILD_ID_RAIN_LOG, S_RAIN);
  present(CHILD_ID_TRIPPED_INDICATOR, S_MOTION);
  #ifdef MY_DEBUG
    Serial.println(F("Presentation complete"));
  #endif
}

void setup()  
{ 
  // use the 1.1 V internal reference for voltage measurement 
  #if defined(__AVR_ATmega2560__)
     analogReference(INTERNAL1V1);
  #else
     analogReference(INTERNAL);
  #endif

  // setup BMP sensor
  if (!bmp.begin()) 
  {
    Serial.println(F("Could not find a valid BMP180 sensor, check wiring!"));
  }
  metric = getConfig().isMetric;

  // setup SI7027 sensor
  if (!sisensor.begin()) 
  {
    Serial.println(F("Could not find a valid SI7021 sensor, check wiring!"));
  }

  // Set up the IO
  pinMode(TIP_SENSOR_PIN, INPUT_PULLUP);
  attachInterrupt (digitalPinToInterrupt(TIP_SENSOR_PIN), sensorTipped, FALLING);  // depending on location of the hall effect sensor may need CHANGE

  
  //Sync time with the server
  requestTime();
  #ifdef MY_DEBUG
    Serial.println(F("Requesting time"));
  #endif
  
  currentHour = hour();
  lastHour = hour();  


} // END Setup

void loop() {  
  // if we don't have time , request it from controller
  if (gotTime == false)
  {
    requestTime();
    #ifdef MY_DEBUG
      Serial.println(F("Requesting time"));
    #endif
    currentHour = hour();
  }

  // get the battery Voltage
  int batteryRead = analogRead(BATTERY_SENSE_PIN);
   
  // voltage divider across battery and using internal ADC ref voltage of 1.1V
  // Sense point is bypassed with 0.1 uF cap to reduce noise at that point
  // 3.94 M ohm a 421 k ohm , ref 1,1v Vmax at battery 11.395V , use http://www.raltron.com/cust/tools/voltage_divider.asp for max V calculation
  // 11.395/1023 = Volts per bit = 0,01113880742913000977517106549365
  float batteryV  = batteryRead * 0.01113880742913000977517106549365;
  int batteryPcnt = ((batteryV - BATTERY_MIN_VOLTAGE) / (BATTERY_MAX_VOLTAGE - BATTERY_MIN_VOLTAGE)) * 100 ;
  if (batteryPcnt <= 0 ) {
    batteryPcnt = 0;
  }

  #ifdef MY_DEBUG
    Serial.print(F("Analog read battery: "));
    Serial.println(batteryRead);
      
    Serial.print(F("Battery Voltage: "));
    Serial.print(batteryV);
    Serial.println(" V");
  
    Serial.print(F("Battery percent: "));
    Serial.print(batteryPcnt);
    Serial.println(F(" %"));
  #endif

  // send battery %
  if (oldBatteryPcnt != batteryPcnt) {
    sendBatteryLevel(batteryPcnt);
    oldBatteryPcnt = batteryPcnt;
  }

  // send battery voltage
  if (oldVBatt != batteryV) {
    send(msgVBatt.set(batteryV, 2));
    oldVBatt = batteryV;
  }




  // SI7027 Sensor
  // temperature 
  float temperature = sisensor.getCelsiusHundredths();
  temperature = temperature /100 ;
   
  // humidity 
  float humidity = sisensor.getHumidityBasisPoints();
  humidity = humidity /100 ;


  #ifdef MY_DEBUG
    Serial.print(F("Temperature SI7020 = "));
    Serial.print(temperature);
    Serial.println(F(" *C"));
    
    Serial.print(F("Humidity SI7020 = "));
    Serial.print(humidity);
    Serial.println(F(" %"));
  #endif

  // send temperature reading
  if (temperature != lastTemperature) 
  {
    send(msgTemperature.set(temperature, 1));
    lastTemperature = temperature;
  }

  // send humidity reading
  if (humidity != lastHumidity) 
  {
    send(msgHumidity.set(humidity, 0));
    lastHumidity = humidity;
  }


  // all done, sleep a bit        
  #ifdef MY_DEBUG
    Serial.println(F("=========================== sweet dreams  =============================")); 
  #endif
  smartSleep(SLEEP_TIME); //sleep a bit
} // End Loop


void receive(const MyMessage &message)
{
  if (message.sensor == CHILD_ID_RAIN_LOG)
  {
    // nothing to do here
  }
  else if (message.sensor == CHILD_ID_TRIPPED_INDICATOR)
  {
    if (message.type == V_VAR1)
    {
      rainWindow = atoi(message.data);
      if (rainWindow > 120)
      {
        rainWindow = 120;
      }
      else if (rainWindow < 1)
      {
        rainWindow = 1;
      }
      if (rainWindow != atoi(message.data))   // if I changed the value back inside the boundries, push that number back to Controller
      {
        send(msgTrippedVar1.set(rainWindow));
      }
    }
    else if (message.type == V_VAR2)
    {
      rainSensorThreshold = atoi(message.data);
      if (rainSensorThreshold > 10000)
      {
        rainSensorThreshold = 10000;
      }
      else if (rainSensorThreshold < 1)
      {
        rainSensorThreshold = 1;
      }
      if (rainSensorThreshold != atoi(message.data))  // if I changed the value back inside the boundries, push that number back to Controller
      {
        send(msgTrippedVar2.set(rainSensorThreshold));
      }
    }
  }
} // End receive

void receiveTime(unsigned long newTime)
{
  setTime(newTime);
  char theTime[6];
  sprintf(theTime, "%d:%2d", hour(), minute());
  Serial.println(F("Time received from controller..."));
  Serial.println(theTime);
  gotTime = true; 
} // End receiveTime

here is complete logger log , I connected the node at time 17:58:40
http://pastebin.com/074MWuJv

@MartinHjelmare
Copy link
Member

MartinHjelmare commented Jan 4, 2017 •
edited

All three time requests in the log were answered after the two heartbeats, but both times the second counter in the log changed to the next second, which could indicate that the reply came too late and the wait timer on the node (MY_SMART_SLEEP_WAIT_DURATION_MS) had expired and the node gone back to sleep. How long MY_SMART_SLEEP_WAIT_DURATION_MS are you using? I think default is 500 ms.

It would be interesting to time this with higher precision to really know how long time passed between home assistant receiving the heartbeat, and home assistant sending the queued responses.

During my testing when developing the feature I didn't experience a lag. I've looked over the relevant parts of the code, and I don't think anything should block or sleep during this part of the logic. We are using a queue to put things that should be sent from home assistant via gateway to nodes, to make things thread safe. Getting a task from the queue will block if there's nothing in the queue with default settings. But we check that the queue is not empty before calling the queue, and it's always the same thread that calls the queue to get tasks, so it would be weird if it was empty when the check says it's not empty.

It seems I have to test this to figure this out, if we think there really is a lag, so it might take some time before I can resolve this.

@Luc3as
Copy link
Author

Luc3as commented Jan 5, 2017

So I tried to override MY_SMART_SLEEP_WAIT_DURATION_MS, default was 500ms, I used 2500ms, and results was still the same, I tried to call requestTime just once from looop, still not getting anything, relly don't understand it.

@MartinHjelmare
Copy link
Member

I've done some testing. I've only tested a stripped sketch, persistence turned off and no other mysensors devices, so it's possible my environment is too simple. Anyway...

I'm running hass version: 0.36.0.dev0: cb85128

Here's the sketch. Note that you have to add a wait call if you're expecting to receive message during setup, cause during setup wait is not called in the background. Also note that I always set gotTime to false, just to test requesting time from loop and receiving it after heartbeat. Without this, time was already received during setup.

/**
 *
 * Documentation: http://www.mysensors.org
 * Support Forum: http://forum.mysensors.org
 *
 */
// Enable MY_DEBUG flag for MY_DEBUG prints. This will add a lot to the size of the final sketch but good
// to see what is actually is happening when developing
#define MY_DEBUG

// Enable and select radio type attached
#define MY_RADIO_NRF24
#define MY_RF24_CHANNEL	78

#include <SPI.h>
#include <MySensors.h>

unsigned long SLEEP_TIME = 30000; // Sleep time between reads (in milliseconds)
boolean gotTime = false;

void presentation()
{
  // Send the Sketch Version Information to the Gateway
  sendSketchInfo("TestRecTime", "1.0");

  // Register all sensors to gw (they will be created as child devices)

  #ifdef MY_DEBUG
    Serial.println(F("Presentation complete"));
  #endif
}

void setup()
{

  #ifdef MY_DEBUG
    Serial.println(F("Requesting time"));
  #endif
  //Sync time with the server
  requestTime();
  wait(2000, C_INTERNAL, I_TIME);

} // END Setup

void loop() {
  // if we don't have time , request it from controller
  if (gotTime == false)
  {
    requestTime();
    #ifdef MY_DEBUG
      Serial.println(F("Requesting time"));
    #endif
  }

  // all done, sleep a bit
  #ifdef MY_DEBUG
    Serial.println(F("=========================== sweet dreams  ============================="));
  #endif
  smartSleep(SLEEP_TIME); //sleep a bit
} // End Loop


void receive(const MyMessage &message)
{

} // End receive

void receiveTime(unsigned long newTime)
{
  Serial.println(F("Time received from controller..."));
  Serial.println(newTime);
  gotTime = false;
} // End receiveTime

Serial log of node:

0 MCO:BGN:INIT NODE,CP=RNNNA--,VER=2.1.0
3 TSM:INIT
4 TSF:WUR:MS=0
11 TSM:INIT:TSP OK
13 TSF:SID:OK,ID=254
14 TSM:FPAR
51 TSF:MSG:SEND,254-254-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
248 TSF:MSG:READ,0-0-254,s=255,c=3,t=8,pt=1,l=1,sg=0:0
253 TSF:MSG:FPAR OK,ID=0,D=1
2058 TSM:FPAR:OK
2059 TSM:ID
2060 TSM:ID:OK
2062 TSM:UPL

2065 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2075 TSF:MSG:READ,0-0-254,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2080 TSF:MSG:PONG RECV,HP=1
2082 TSM:UPL:OK
2084 TSM:READY:ID=254,PAR=0,DIS=1
2088 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
2096 TSF:MSG:READ,0-0-254,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
2106 TSF:MSG:SEND,254-254-0-0,s=255,c=0,t=17,pt=0,l=5,sg=0,ft=0,st=OK:2.1.0
2114 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
2127 TSF:MSG:READ,0-0-254,s=255,c=3,t=6,pt=0,l=1,sg=0:M
2135 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=11,pt=0,l=11,sg=0,ft=0,st=OK:TestRecTime
2144 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.0
Presentation complete
2151 MCO:REG:REQ
2156 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
2162 TSF:MSG:READ,0-0-254,s=255,c=3,t=27,pt=1,l=1,sg=0:1
2168 MCO:PIM:NODE REG=1
2170 MCO:BGN:STP
Requesting time
2173 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
2188 TSF:MSG:READ,0-0-254,s=255,c=3,t=1,pt=0,l=10,sg=0:1483680568
Time received from controller...
1483680568
2195 MCO:BGN:INIT OK,TSP=1
2202 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=1,pt=0,l=0,sg=0,ft=0,st=OK:
Requesting time
=========================== sweet dreams  =============================
2210 MCO:SLP:MS=30000,SMS=1,I1=255,M1=255,I2=255,M2=255
2223 TSF:MSG:SEND,254-254-0-0,s=255,c=3,t=22,pt=5,l=4,sg=0,ft=0,st=OK:51
2230 TSF:MSG:READ,0-0-254,s=255,c=3,t=1,pt=0,l=10,sg=0:1483680568
Time received from controller...
1483680568
2731 MCO:SLP:TPD

So with this testing environment and sketch I can't replicate your issues. Can you try this sketch and see what you get? Note that you should change radio channel to match your gateway, and perhaps define a node id.

@Luc3as
Copy link
Author

Luc3as commented Jan 6, 2017

Hello, I did some tests too, with your basic sketch I can say it is working as expected, so I tried to add some more and more to this basic sketch, and it looks like at setup it is handling all presentations and it is not quickly enough to send time back in time window, in controller log the time is handled at the end, so I put all 10 presentations for sensors, and not sending any data just receiving time. after 3 wake ups it is working and time is receiving.
so could we try to put higher priority or something to time request handling on gateway or something?
I think this problem is caused by not enough time when you have more sensors and data transmissions.

@MartinHjelmare
Copy link
Member

MartinHjelmare commented Jan 7, 2017 •
edited

I've done some more testing and added presentation of 9 sensors and sending of 12 values during setup and loop combined before going to sleep. Now I can also see that sometimes the time isn't received at the node after the heartbeat before going to sleep. But via extended logging it seems the controller always react within milliseconds when receiving a request for time, and sends the time, unless it knows that the node is smartSleeping, in which case it will wait for a heartbeat. I think the lag problem lies at the arduino gateway.

I'm pretty sure that the problem is that we are saturating the radio's buffer when we start sending a lot of messages in quick succession. According to a thread at mysensors forum the radio can hold 3 messages in a buffer. This matches with what is said in the datasheet for the NRF24L01+ (" nRF24L01+ can have three ACK packet payloads pending in the TX FIFO (PRX) at the same time"). After testing I think at least the gateway will have trouble emptying this buffer fast enough. On the sender side, node, the NRF24 will automatically resend messages (packets) three times that are not acknowledged, by ACK packet by the recipient. So most messages will eventually get through. But the congestion in the RX FIFO creates congestion in the TX FIFO as well, cause the radio wants to acknowledge all received packages. This is, I think, why there's a lag, and it's created at the gateway. Until the congestion in the TX FIFO has cleared the gateway can't send the time message, and by then the node might be sleeping.

During my testing my gateway sometimes restarted during the time when it was receiving lots of messages and been asked to send a reply with time, which I think might be due to the radio drawing a lot of power for a long time.

So what you can do is avoid sending a lot of messages with no wait in between. Ie, add a short wait, maybe 10-50 ms between sending messages. This is more important if you don't do anything else that takes time between sending messages. Eg calling a sensor and measuring something probably takes some time. Also, if you're expecting to receive an importing message, always call wait immediately.

Please let me know if you see something that can disprove what I suggest above.

I've put on my todo, to change the behavior of answering requests, so that they are answered immediately even for smartsleeping nodes. I think this will make it more predictable when writing a sketch how the controller will behave, cause you can then always do a wait after a request and be sure that the controller sends the value. Of course, with the caveat regarding possible radio congestion described above.

Edit: You can choose between wait and sleep, if you want to delay something, eg delay sending a message to avoid hammering the gateway. If you don't need to receive messages during the delay and you want to save battery, you should use sleep instead of wait.

@Luc3as
Copy link
Author

Luc3as commented Jan 7, 2017

So I tried to add wait and later sleep after every single radio transmission, even with 500ms of wait there was no big difference . I saw earlier at log of HASS that it goes like crazy and like all data was repeating about 3 times, so I think you diagnosed the problem right.

After endless night I ended up waiting for monstrous 30 seconds at the end of loop, waiting for time to arrive.

// wait for time from controller
  unsigned long functionTimeout = millis();
  if (gotTime == false) {
    #ifdef MY_DEBUG
      Serial.print(F("Waiting for time to arrive from controller "));
    #endif
    while (gotTime == false && millis() - functionTimeout < 30000UL)
    {
      wait(1000, C_INTERNAL, I_TIME); // call once per second
      #ifdef MY_DEBUG
        Serial.print(F("."));
      #endif
    }
    #ifdef MY_DEBUG
      Serial.println(F(""));
    #endif
  }

luckily I have big enough battery to hold this at first startup , and then every hour for re-sync of time because I am counting time with sleeps and it can get little off by hour.

If you would came up with something new, I can try and see what we will get.

in meantime, thanks for help 👍

@MartinHjelmare
Copy link
Member

MartinHjelmare commented Jan 7, 2017 •
edited

I added a wait call directly after the request for time both in setup and loop. I then could reliably get both time reports immediately every time I restarted both hass and the node. I restarted hass so that it wouldn't treat the node as smartsleeping. If you can't replicate that, you might have a different problem than what I think and we should continue troubleshooting.

@MartinHjelmare
Copy link
Member

Something that you can try is to compare persistence off vs on. Does it make a difference if you set persistence to false in home assistant config?

@Luc3as
Copy link
Author

Luc3as commented Jan 8, 2017

No , persistence on or off, still same results.

@balloobbot
Copy link

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.

Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍

@balloobbot
Copy link

This issue will be auto-closed because there hasn't been any activity for a few months. Feel free to open a new one if you still experience this problem 👍

@home-assistant home-assistant locked and limited conversation to collaborators Jul 17, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
waiting-for-reply
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@MartinHjelmare @Luc3as @balloobbot