Dimmable / RGB lights on MySensors2.0 : can turn off, can't turn on

brahmafear · January 3, 2017, 3:50pm

Seeing issue with MySensors Dimmable and RGB lights.

Setting brightness or rgb values via Developer Tools, Services menu works. Using default_view toggle to switch lights OFF works. What does not work is using the toggle to switch the light back on. The toggle briefly moves to the on position then returns to off after about 1 second. No MySensors message is sent to the node. The gateway does not receive any instruction from HA.

Tested on multiple nodes using both S_RGB_LIGHT and S_DIMMER. Same behavior on both.

HA 0.35.3 running on Rpi3.
Relevant lines from config:

mysensors:
 gateways:
  - device: '127.0.0.1'
    persistence_file: '/srv/hass/cfg/mysensors3.json'
    tcp_port: 5003
  debug: true
  version: 2.0
  persistence: false
  optimistic: false

(Persistence disabled while testing.)

Mysensors 2.20beta
Testing with “DimmableLight” sketch from MySensors examples.

Light entry from States list:

light.dimmable_light_253_1	off	
supported_features: 145
device: 127.0.0.1
friendly_name: Dimmable Light 253 1
description: 
battery_level: 0
V_PERCENTAGE: 0
node_id: 253
child_id: 1

This manual JSON works:

{ "entity_id" : "light.dimmable_light_253_1", "brightness" : "250" }

Result from serial console on node:

116226 TSF:MSG:READ,0-0-253,s=1,c=1,t=3,pt=0,l=2,sg=0:98
V_DIMMER command received...
Light state: ON, Level: 98
116233 TSF:MSG:SEND,253-253-0-0,s=1,c=1,t=3,pt=2,l=2,sg=0,ft=0,st=OK:98

Clicking toggle to OFF works.
Result from serial console on node:

156280 TSF:MSG:READ,0-0-253,s=1,c=1,t=3,pt=0,l=1,sg=0:0
V_DIMMER command received...
Light state: OFF
156288 TSF:MSG:SEND,253-253-0-0,s=1,c=1,t=3,pt=2,l=2,sg=0,ft=0,st=OK:0

Clicking toggle to ON does not work. No message received on node.

During all of these tests, nothing logged to console of running hass binary.

Any ideas? Thanks in advance.

brahmafear · January 3, 2017, 4:18pm

Additional info: After switching toggle to OFF or sliding brightness slider to 0, brightness slider disappears and does not reappear unless JSON used to manually set light.

Similar behavior on RGB light – color selector disappears when light is toggled off and will not reappear unless JSON used to manually set color.

brahmafear · January 3, 2017, 10:28pm

Found this later on in the logs.

17-01-03 17:25:27 mysensors.mysensors: range() arg 3 must not be zero
Traceback (most recent call last):
  File "/srv/hass/cfg/deps/mysensors/mysensors.py", line 290, in alert
    self.event_callback('sensor_update', nid)
  File "/srv/hass/lib/python3.4/site-packages/homeassistant/components/mysensors.py", line 256, in node_update
    callback(self, node_id)
  File "/srv/hass/lib/python3.4/site-packages/homeassistant/components/mysensors.py", line 190, in mysensors_callback
    devices[key].update_ha_state(True)
  File "/srv/hass/lib/python3.4/site-packages/homeassistant/helpers/entity.py", line 187, in update_ha_state
    self.update()
  File "/srv/hass/lib/python3.4/site-packages/homeassistant/components/light/mysensors.py", line 304, in update
    self._update_rgb_or_w()
  File "/srv/hass/lib/python3.4/site-packages/homeassistant/components/light/mysensors.py", line 239, in _update_rgb_or_w
    color_list = rgb_hex_to_rgb_list(value)
  File "/srv/hass/lib/python3.4/site-packages/homeassistant/util/color.py", line 301, in rgb_hex_to_rgb_list
    len(hex_string) // 3)]
ValueError: range() arg 3 must not be zero

ReneTode · January 3, 2017, 10:49pm

seems like the trouble comes when you set a color (or brightness) to 0.
you could try if setting it manually to 0 would also cause trouble.

i have no arduino’s controling my (rgb or dimmable) lights, so i cant check anything.

but if the problem stays maybe @martinhjelmare could help you.

he will probable want to see your sketch too

martinhjelmare · January 3, 2017, 11:20pm

@brahmafear

Hi!
Please capture a debug log from hass and at the same time a serial log from the node in question. I’d like to see the log after start of hass + node (including presentation) and then for some toggle tests, where you toggle the button on/off. Use these settings for the logger component in hass:

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

Please post configs and logs within codeblock markdown. That’s three backtics, newline, code, newline, three backtics. You can edit your posts above and put the logs etc within codeblocks.

brahmafear · January 3, 2017, 11:52pm

Thanks in advance for your assistance with this. (And thanks for the tip on using codeblocks.)

I slimmed down my HA setup to just have the mysensors and logger components.

I restarted the mysgw process and restarted HA. Once HA had started, I reset the node which was running the DimmableLight Arduino example. After device appeared in State view, I pressed the toggle to turn on. The toggle slid to the on position for approximately 1 second, then slid back. During these operations, I saw some lines added to the HA log, but no logging in the node serial console. I am listing both below.

HomeAssistant log from boot to termination of process:

Config directory: /srv/hass/cfg
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_off>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_on>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=toggle>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=reload_core_config>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=create>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.bootstrap] Home Assistant core initialized
17-01-03 18:43:44 INFO (MainThread) [homeassistant.loader] Loaded http from homeassistant.components.http
17-01-03 18:43:44 INFO (MainThread) [homeassistant.loader] Loaded mysensors from homeassistant.components.mysensors
17-01-03 18:43:44 INFO (MainThread) [homeassistant.loader] Loaded frontend from homeassistant.components.frontend
17-01-03 18:43:44 INFO (MainThread) [homeassistant.loader] Loaded api from homeassistant.components.api
17-01-03 18:43:44 INFO (MainThread) [homeassistant.loader] Loaded websocket_api from homeassistant.components.websocket_api
17-01-03 18:43:44 INFO (MainThread) [homeassistant.loader] Loaded logger from homeassistant.components.logger
17-01-03 18:43:44 INFO (MainThread) [homeassistant.loader] Loaded zeroconf from homeassistant.components.zeroconf
17-01-03 18:43:44 INFO (MainThread) [homeassistant.bootstrap] Setting up logger
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=logger>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.bootstrap] Setting up http
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=http>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.bootstrap] Setting up mysensors
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=mysensors>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.bootstrap] Setting up api
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=api>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.bootstrap] Setting up websocket_api
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=websocket_api>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.bootstrap] Setting up frontend
17-01-03 18:43:44 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=frontend>
17-01-03 18:43:44 INFO (MainThread) [homeassistant.bootstrap] Setting up zeroconf
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=zeroconf>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.loader] Loaded sensor from homeassistant.components.sensor
17-01-03 18:43:45 INFO (MainThread) [homeassistant.bootstrap] Setting up sensor
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=sensor>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: platform=mysensors, service=load_platform.sensor, discovered=>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.loader] Loaded switch from homeassistant.components.switch
17-01-03 18:43:45 INFO (MainThread) [homeassistant.loader] Loaded sensor.mysensors from homeassistant.components.sensor.mysensors
17-01-03 18:43:45 INFO (MainThread) [homeassistant.bootstrap] Setting up switch
17-01-03 18:43:45 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mysensors
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=switch, service=turn_off>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=switch, service=turn_on>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=switch, service=toggle>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=switch>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: platform=mysensors, service=load_platform.switch, discovered=>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.loader] Loaded light from homeassistant.components.light
17-01-03 18:43:45 INFO (MainThread) [homeassistant.loader] Loaded switch.mysensors from homeassistant.components.switch.mysensors
17-01-03 18:43:45 INFO (MainThread) [homeassistant.bootstrap] Setting up light
17-01-03 18:43:45 INFO (MainThread) [homeassistant.components.switch] Setting up switch.mysensors
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=switch, service=mysensors_send_ir_code>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=light, service=turn_on>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=light, service=turn_off>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=light, service=toggle>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=light>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: platform=mysensors, service=load_platform.light, discovered=>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.loader] Loaded binary_sensor from homeassistant.components.binary_sensor
17-01-03 18:43:45 INFO (MainThread) [homeassistant.loader] Loaded light.mysensors from homeassistant.components.light.mysensors
17-01-03 18:43:45 INFO (MainThread) [homeassistant.bootstrap] Setting up binary_sensor
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=binary_sensor>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: platform=mysensors, service=load_platform.binary_sensor, discovered=>
17-01-03 18:43:45 INFO (MainThread) [homeassistant.components.light] Setting up light.mysensors
17-01-03 18:43:46 INFO (MainThread) [homeassistant.loader] Loaded climate from homeassistant.components.climate
17-01-03 18:43:46 INFO (MainThread) [homeassistant.loader] Loaded binary_sensor.mysensors from homeassistant.components.binary_sensor.mysensors
17-01-03 18:43:46 INFO (MainThread) [homeassistant.bootstrap] Setting up climate
17-01-03 18:43:46 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.mysensors
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_away_mode>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_aux_heat>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_temperature>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_humidity>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_fan_mode>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_operation_mode>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=climate, service=set_swing_mode>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=climate>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: platform=mysensors, service=load_platform.climate, discovered=>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.loader] Loaded cover from homeassistant.components.cover
17-01-03 18:43:46 INFO (MainThread) [homeassistant.loader] Loaded climate.mysensors from homeassistant.components.climate.mysensors
17-01-03 18:43:46 INFO (MainThread) [homeassistant.bootstrap] Setting up cover
17-01-03 18:43:46 INFO (MainThread) [homeassistant.components.climate] Setting up climate.mysensors
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=cover, service=set_cover_tilt_position>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=cover, service=close_cover>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=cover, service=stop_cover_tilt>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=cover, service=set_cover_position>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=cover, service=close_cover_tilt>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=cover, service=stop_cover>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=cover, service=open_cover_tilt>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=cover, service=open_cover>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=cover>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: platform=mysensors, service=load_platform.cover, discovered=>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.loader] Loaded cover.mysensors from homeassistant.components.cover.mysensors
17-01-03 18:43:46 INFO (MainThread) [homeassistant.components.cover] Setting up cover.mysensors
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Starting Home Assistant core loop
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Starting Home Assistant
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=stop>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=restart>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>
17-01-03 18:43:46 INFO (MainThread) [homeassistant.core] Timer:starting
17-01-03 18:43:46 INFO (Thread-12) [mysensors.mysensors] Trying to connect to ('127.0.0.1', 5003)
17-01-03 18:43:46 INFO (Thread-12) [mysensors.mysensors] Connected to ('127.0.0.1', 5003)
17-01-03 18:43:46 DEBUG (Thread-12) [mysensors.mysensors] Received 0;255;3;0;14;Gateway startup complete.
0;255;0;0;18;2.2.0-beta

17-01-03 18:43:46 DEBUG (Thread-12) [homeassistant.components.mysensors] Update sensor_update: node 0
17-01-03 18:43:46 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 18:43:46 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 18:43:46 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 18:43:46 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 18:43:46 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 18:43:46 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 18:43:49 INFO (MainThread) [homeassistant.components.http] Serving /api/websocket to 192.168.9.91 (auth: True)
17-01-03 18:43:49 INFO (MainThread) [homeassistant.components.http] Serving /api/bootstrap to 192.168.9.91 (auth: True)
17-01-03 18:44:00 DEBUG (Thread-12) [mysensors.mysensors] Received 123;255;0;0;17;2.2.0-beta
123;255;3;0;6;0

17-01-03 18:44:00 DEBUG (Thread-12) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 18:44:00 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 18:44:00 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 18:44:00 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 18:44:00 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 18:44:00 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 18:44:00 INFO (Thread-12) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 18:44:00 DEBUG (Thread-12) [mysensors.mysensors] Sending 123;255;3;0;6;I

17-01-03 18:44:00 DEBUG (Thread-12) [mysensors.mysensors] Received 123;255;3;0;11;Dimable Light
123;255;3;0;12;1.0
123;1;0;0;4;

17-01-03 18:44:00 DEBUG (Thread-12) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 18:44:00 DEBUG (Thread-12) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 18:44:00 DEBUG (Thread-12) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 18:44:00 DEBUG (Thread-12) [mysensors.mysensors] Received 123;1;1;0;3;0

17-01-03 18:44:00 DEBUG (Thread-12) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 18:44:00 INFO (Thread-12) [homeassistant.components.mysensors] Adding new devices: <Entity Dimable Light 123 1: off>
17-01-03 18:44:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.dimable_light_123_1, old_state=None, new_state=<state light.dimable_light_123_1=unavailable; friendly_name=Dimable Light 123 1 @ 2017-01-03T18:44:00.927235-05:00>>
17-01-03 18:44:00 INFO (MainThread) [homeassistant.loader] Loaded group from homeassistant.components.group
17-01-03 18:44:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=None, new_state=<state group.all_lights=unknown; hidden=True, entity_id=('light.dimable_light_123_1',), friendly_name=all lights, auto=True, order=0 @ 2017-01-03T18:44:00.934553-05:00>>
17-01-03 18:44:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.dimable_light_123_1, old_state=<state light.dimable_light_123_1=unavailable; friendly_name=Dimable Light 123 1 @ 2017-01-03T18:44:00.927235-05:00>, new_state=<state light.dimable_light_123_1=off; supported_features=145, friendly_name=Dimable Light 123 1, description=, node_id=123, battery_level=0, child_id=1, device=127.0.0.1, V_PERCENTAGE=0 @ 2017-01-03T18:44:00.942291-05:00>>
17-01-03 18:44:00 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=unknown; hidden=True, entity_id=('light.dimable_light_123_1',), friendly_name=all lights, auto=True, order=0 @ 2017-01-03T18:44:00.934553-05:00>, new_state=<state group.all_lights=off; hidden=True, entity_id=('light.dimable_light_123_1',), friendly_name=all lights, auto=True, order=0 @ 2017-01-03T18:44:00.951275-05:00>>
17-01-03 18:45:04 INFO (MainThread) [homeassistant.components.http] Serving /api/services/homeassistant/turn_on to 192.168.9.91 (auth: True)
17-01-03 18:45:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_call_id=1976215984-1, service_data=entity_id=light.dimable_light_123_1>
17-01-03 18:45:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_call_id=1976215984-2, service_data=entity_id=['light.dimable_light_123_1']>
17-01-03 18:45:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976215984-2>
17-01-03 18:45:04 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976215984-1>
17-01-03 18:45:38 INFO (MainThread) [homeassistant.components.http] Serving /api/services/homeassistant/turn_on to 192.168.9.91 (auth: True)
17-01-03 18:45:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_call_id=1976215984-3, service_data=entity_id=light.dimable_light_123_1>
17-01-03 18:45:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_call_id=1976215984-4, service_data=entity_id=['light.dimable_light_123_1']>
17-01-03 18:45:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976215984-4>
17-01-03 18:45:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976215984-3>
^C17-01-03 18:46:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_stop[L]>
17-01-03 18:46:05 INFO (Thread-6) [mysensors.mysensors] Stopping thread
17-01-03 18:46:05 INFO (Thread-12) [mysensors.mysensors] Closing socket at ('127.0.0.1', 5003).
17-01-03 18:46:05 INFO (Thread-12) [mysensors.mysensors] Socket closed at ('127.0.0.1', 5003).
^CException ignored in: <module 'threading' from '/usr/lib/python3.4/threading.py'>
Traceback (most recent call last):
  File "/usr/lib/python3.4/threading.py", line 1294, in _shutdown
    t.join()
  File "/usr/lib/python3.4/threading.py", line 1060, in join
    self._wait_for_tstate_lock()
  File "/usr/lib/python3.4/threading.py", line 1076, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt
hass@pi:/srv/hass/cfg $ exit

Script done on Tue 03 Jan 2017 06:46:10 PM EST

Serial console of DimmableLight node:

0 MCO:BGN:INIT NODE,CP=RNNNA--,VER=2.2.0-beta
4 TSM:INIT
4 TSF:WUR:MS=0
11 TSM:INIT:TSP OK
13 TSM:INIT:STATID=123
15 TSF:SID:OK,ID=123
17 TSM:FPAR
53 TSF:MSG:SEND,123-123-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
920 TSF:MSG:READ,0-0-123,s=255,c=3,t=8,pt=1,l=1,sg=0:0
925 TSF:MSG:FPAR OK,ID=0,D=1
2061 TSM:FPAR:OK
2062 TSM:ID
2063 TSM:ID:OK
2065 TSM:UPL
2070 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2076 TSF:MSG:READ,0-0-123,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2082 TSF:MSG:PONG RECV,HP=1
2084 TSM:UPL:OK
2086 TSM:READY:ID=123,PAR=0,DIS=1
2091 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=15,pt=6,l=2,sg=0,ft=0,st=OK:0100
2098 TSF:MSG:READ,0-0-123,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
2106 TSF:MSG:SEND,123-123-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.2.0-beta
2115 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
2160 TSF:MSG:READ,0-0-123,s=255,c=3,t=6,pt=0,l=1,sg=0:I
2167 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=11,pt=0,l=13,sg=0,ft=0,st=OK:Dimable Light
2177 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.0
2186 TSF:MSG:SEND,123-123-0-0,s=1,c=0,t=4,pt=0,l=0,sg=0,ft=0,st=OK:
2192 MCO:REG:REQ
2195 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
2203 TSF:MSG:READ,0-0-123,s=255,c=3,t=27,pt=1,l=1,sg=0:1
2208 MCO:PIM:NODE REG=1
2210 MCO:BGN:STP
Light state: OFF
2216 TSF:MSG:SEND,123-123-0-0,s=1,c=1,t=3,pt=2,l=2,sg=0,ft=0,st=OK:0
Node ready to receive messages...
2223 MCO:BGN:INIT OK,TSP=1

brahmafear · January 4, 2017, 12:11am

Second test. I modified the Arduino sketch so node would start in ON state rather than previous state (which was off in last test). The logs below show HA bootup, node announcement, clicking on approximately 50% on dimmer slider, then 25%, then 75%, the clicking toggle to turn slider off, the two attempts to click slider to turn slider on.

HA log

Config directory: /srv/hass/cfg
17-01-03 19:06:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=turn_off, domain=homeassistant>
17-01-03 19:06:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=turn_on, domain=homeassistant>
17-01-03 19:06:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=toggle, domain=homeassistant>
17-01-03 19:06:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=reload_core_config, domain=homeassistant>
17-01-03 19:06:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=create, domain=persistent_notification>
17-01-03 19:06:01 INFO (MainThread) [homeassistant.bootstrap] Home Assistant core initialized
17-01-03 19:06:01 INFO (MainThread) [homeassistant.loader] Loaded mysensors from homeassistant.components.mysensors
17-01-03 19:06:01 INFO (MainThread) [homeassistant.loader] Loaded http from homeassistant.components.http
17-01-03 19:06:01 INFO (MainThread) [homeassistant.loader] Loaded logger from homeassistant.components.logger
17-01-03 19:06:01 INFO (MainThread) [homeassistant.loader] Loaded zeroconf from homeassistant.components.zeroconf
17-01-03 19:06:02 INFO (MainThread) [homeassistant.loader] Loaded api from homeassistant.components.api
17-01-03 19:06:02 INFO (MainThread) [homeassistant.loader] Loaded frontend from homeassistant.components.frontend
17-01-03 19:06:02 INFO (MainThread) [homeassistant.loader] Loaded websocket_api from homeassistant.components.websocket_api
17-01-03 19:06:02 INFO (MainThread) [homeassistant.bootstrap] Setting up logger
17-01-03 19:06:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=logger>
17-01-03 19:06:02 INFO (MainThread) [homeassistant.bootstrap] Setting up mysensors
17-01-03 19:06:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=mysensors>
17-01-03 19:06:02 INFO (MainThread) [homeassistant.bootstrap] Setting up http
17-01-03 19:06:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=http>
17-01-03 19:06:02 INFO (MainThread) [homeassistant.bootstrap] Setting up api
17-01-03 19:06:02 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=api>
17-01-03 19:06:02 INFO (MainThread) [homeassistant.bootstrap] Setting up zeroconf
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=zeroconf>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.bootstrap] Setting up websocket_api
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=websocket_api>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.bootstrap] Setting up frontend
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=frontend>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded sensor from homeassistant.components.sensor
17-01-03 19:06:03 INFO (MainThread) [homeassistant.bootstrap] Setting up sensor
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=sensor>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.sensor, platform=mysensors, discovered=>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded switch from homeassistant.components.switch
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded sensor.mysensors from homeassistant.components.sensor.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.bootstrap] Setting up switch
17-01-03 19:06:03 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=turn_off, domain=switch>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=turn_on, domain=switch>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=toggle, domain=switch>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=switch>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.switch, platform=mysensors, discovered=>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded light from homeassistant.components.light
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded switch.mysensors from homeassistant.components.switch.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.bootstrap] Setting up light
17-01-03 19:06:03 INFO (MainThread) [homeassistant.components.switch] Setting up switch.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=mysensors_send_ir_code, domain=switch>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=turn_on, domain=light>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=turn_off, domain=light>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=toggle, domain=light>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=light>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.light, platform=mysensors, discovered=>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded binary_sensor from homeassistant.components.binary_sensor
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded light.mysensors from homeassistant.components.light.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.bootstrap] Setting up binary_sensor
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=binary_sensor>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.binary_sensor, platform=mysensors, discovered=>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded climate from homeassistant.components.climate
17-01-03 19:06:03 INFO (MainThread) [homeassistant.components.light] Setting up light.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded binary_sensor.mysensors from homeassistant.components.binary_sensor.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.bootstrap] Setting up climate
17-01-03 19:06:03 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_away_mode, domain=climate>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_aux_heat, domain=climate>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_temperature, domain=climate>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_humidity, domain=climate>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_fan_mode, domain=climate>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_operation_mode, domain=climate>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_swing_mode, domain=climate>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=climate>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.climate, platform=mysensors, discovered=>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded cover from homeassistant.components.cover
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded climate.mysensors from homeassistant.components.climate.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.bootstrap] Setting up cover
17-01-03 19:06:03 INFO (MainThread) [homeassistant.components.climate] Setting up climate.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=open_cover_tilt, domain=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_cover_position, domain=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=close_cover, domain=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=set_cover_tilt_position, domain=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=stop_cover, domain=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=close_cover_tilt, domain=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=open_cover, domain=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=stop_cover_tilt, domain=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=cover>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event platform_discovered[L]: service=load_platform.cover, platform=mysensors, discovered=>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.loader] Loaded cover.mysensors from homeassistant.components.cover.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.components.cover] Setting up cover.mysensors
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Starting Home Assistant core loop
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Starting Home Assistant
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=stop, domain=homeassistant>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: service=restart, domain=homeassistant>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>
17-01-03 19:06:03 INFO (MainThread) [homeassistant.core] Timer:starting
17-01-03 19:06:03 INFO (Thread-11) [mysensors.mysensors] Trying to connect to ('127.0.0.1', 5003)
17-01-03 19:06:03 INFO (Thread-11) [mysensors.mysensors] Connected to ('127.0.0.1', 5003)
17-01-03 19:06:03 DEBUG (Thread-11) [mysensors.mysensors] Received 0;255;3;0;14;Gateway startup complete.
0;255;0;0;18;2.2.0-beta

17-01-03 19:06:03 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 0
17-01-03 19:06:03 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 19:06:03 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 19:06:03 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 19:06:03 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 19:06:03 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 19:06:03 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 0
17-01-03 19:06:11 INFO (MainThread) [homeassistant.components.http] Serving /api/websocket to 192.168.9.91 (auth: True)
17-01-03 19:06:11 INFO (MainThread) [homeassistant.components.http] Serving /api/bootstrap to 192.168.9.91 (auth: True)
17-01-03 19:06:18 DEBUG (Thread-11) [mysensors.mysensors] Received 123;255;0;0;17;2.2.0-beta
123;255;3;0;6;0

17-01-03 19:06:18 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:06:18 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 19:06:18 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 19:06:18 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 19:06:18 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 19:06:18 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 19:06:18 INFO (Thread-11) [homeassistant.components.mysensors] No sketch_name: node 123
17-01-03 19:06:18 DEBUG (Thread-11) [mysensors.mysensors] Sending 123;255;3;0;6;I

17-01-03 19:06:18 DEBUG (Thread-11) [mysensors.mysensors] Received 123;255;3;0;11;Dimable Light
123;255;3;0;12;1.0
123;1;0;0;4;

17-01-03 19:06:18 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:06:18 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:06:18 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:06:18 DEBUG (Thread-11) [mysensors.mysensors] Received 123;1;1;0;3;100

17-01-03 19:06:18 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:06:18 INFO (Thread-11) [homeassistant.components.mysensors] Adding new devices: <Entity Dimable Light 123 1: off>
17-01-03 19:06:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state light.dimable_light_123_1=unavailable; friendly_name=Dimable Light 123 1 @ 2017-01-03T19:06:18.644530-05:00>, old_state=None, entity_id=light.dimable_light_123_1>
17-01-03 19:06:18 INFO (MainThread) [homeassistant.loader] Loaded group from homeassistant.components.group
17-01-03 19:06:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state group.all_lights=unknown; friendly_name=all lights, order=0, auto=True, entity_id=('light.dimable_light_123_1',), hidden=True @ 2017-01-03T19:06:18.652482-05:00>, old_state=None, entity_id=group.all_lights>
17-01-03 19:06:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state light.dimable_light_123_1=on; friendly_name=Dimable Light 123 1, device=127.0.0.1, battery_level=0, V_PERCENTAGE=100, node_id=123, child_id=1, brightness=255, supported_features=145, description= @ 2017-01-03T19:06:18.660841-05:00>, old_state=<state light.dimable_light_123_1=unavailable; friendly_name=Dimable Light 123 1 @ 2017-01-03T19:06:18.644530-05:00>, entity_id=light.dimable_light_123_1>
17-01-03 19:06:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state group.all_lights=on; friendly_name=all lights, order=0, auto=True, entity_id=('light.dimable_light_123_1',), hidden=True @ 2017-01-03T19:06:18.668010-05:00>, old_state=<state group.all_lights=unknown; friendly_name=all lights, order=0, auto=True, entity_id=('light.dimable_light_123_1',), hidden=True @ 2017-01-03T19:06:18.652482-05:00>, entity_id=group.all_lights>
17-01-03 19:06:42 INFO (MainThread) [homeassistant.components.http] Serving /api/services/light/turn_on to 192.168.9.91 (auth: True)
17-01-03 19:06:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_on, domain=light, service_call_id=1976609200-1, service_data=entity_id=light.dimable_light_123_1, brightness=120>
17-01-03 19:06:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-1>
17-01-03 19:06:42 DEBUG (Thread-11) [mysensors.mysensors] Sending 123;1;1;0;3;47

17-01-03 19:06:42 DEBUG (Thread-11) [mysensors.mysensors] Received 123;1;1;0;3;47

17-01-03 19:06:42 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:06:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state light.dimable_light_123_1=on; friendly_name=Dimable Light 123 1, device=127.0.0.1, battery_level=0, V_PERCENTAGE=47, node_id=123, child_id=1, brightness=120, supported_features=145, description= @ 2017-01-03T19:06:18.660841-05:00>, old_state=<state light.dimable_light_123_1=on; friendly_name=Dimable Light 123 1, device=127.0.0.1, battery_level=0, V_PERCENTAGE=100, node_id=123, child_id=1, brightness=255, supported_features=145, description= @ 2017-01-03T19:06:18.660841-05:00>, entity_id=light.dimable_light_123_1>
17-01-03 19:06:51 INFO (MainThread) [homeassistant.components.http] Serving /api/services/light/turn_on to 192.168.9.91 (auth: True)
17-01-03 19:06:51 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_on, domain=light, service_call_id=1976609200-2, service_data=entity_id=light.dimable_light_123_1, brightness=56>
17-01-03 19:06:51 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-2>
17-01-03 19:06:51 DEBUG (Thread-11) [mysensors.mysensors] Sending 123;1;1;0;3;22

17-01-03 19:06:52 DEBUG (Thread-11) [mysensors.mysensors] Received 123;1;1;0;3;22

17-01-03 19:06:52 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:06:52 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state light.dimable_light_123_1=on; friendly_name=Dimable Light 123 1, device=127.0.0.1, battery_level=0, V_PERCENTAGE=22, node_id=123, child_id=1, brightness=56, supported_features=145, description= @ 2017-01-03T19:06:18.660841-05:00>, old_state=<state light.dimable_light_123_1=on; friendly_name=Dimable Light 123 1, device=127.0.0.1, battery_level=0, V_PERCENTAGE=47, node_id=123, child_id=1, brightness=120, supported_features=145, description= @ 2017-01-03T19:06:18.660841-05:00>, entity_id=light.dimable_light_123_1>
17-01-03 19:06:57 INFO (MainThread) [homeassistant.components.http] Serving /api/services/light/turn_on to 192.168.9.91 (auth: True)
17-01-03 19:06:57 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_on, domain=light, service_call_id=1976609200-3, service_data=entity_id=light.dimable_light_123_1, brightness=193>
17-01-03 19:06:57 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-3>
17-01-03 19:06:57 DEBUG (Thread-11) [mysensors.mysensors] Sending 123;1;1;0;3;76

17-01-03 19:06:57 DEBUG (Thread-11) [mysensors.mysensors] Received 123;1;1;0;3;76

17-01-03 19:06:57 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:06:57 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state light.dimable_light_123_1=on; friendly_name=Dimable Light 123 1, device=127.0.0.1, battery_level=0, V_PERCENTAGE=76, node_id=123, child_id=1, brightness=194, supported_features=145, description= @ 2017-01-03T19:06:18.660841-05:00>, old_state=<state light.dimable_light_123_1=on; friendly_name=Dimable Light 123 1, device=127.0.0.1, battery_level=0, V_PERCENTAGE=22, node_id=123, child_id=1, brightness=56, supported_features=145, description= @ 2017-01-03T19:06:18.660841-05:00>, entity_id=light.dimable_light_123_1>
17-01-03 19:07:01 INFO (MainThread) [homeassistant.components.http] Serving /api/services/homeassistant/turn_off to 192.168.9.91 (auth: True)
17-01-03 19:07:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_off, domain=homeassistant, service_call_id=1976609200-4, service_data=entity_id=light.dimable_light_123_1>
17-01-03 19:07:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_off, domain=light, service_call_id=1976609200-5, service_data=entity_id=['light.dimable_light_123_1']>
17-01-03 19:07:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-5>
17-01-03 19:07:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-4>
17-01-03 19:07:01 DEBUG (Thread-11) [mysensors.mysensors] Sending 123;1;1;0;3;0

17-01-03 19:07:01 DEBUG (Thread-11) [mysensors.mysensors] Received 123;1;1;0;3;0

17-01-03 19:07:01 DEBUG (Thread-11) [homeassistant.components.mysensors] Update sensor_update: node 123
17-01-03 19:07:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state light.dimable_light_123_1=off; friendly_name=Dimable Light 123 1, child_id=1, description=, battery_level=0, V_PERCENTAGE=0, supported_features=145, node_id=123, device=127.0.0.1 @ 2017-01-03T19:07:01.105143-05:00>, old_state=<state light.dimable_light_123_1=on; friendly_name=Dimable Light 123 1, device=127.0.0.1, battery_level=0, V_PERCENTAGE=76, node_id=123, child_id=1, brightness=194, supported_features=145, description= @ 2017-01-03T19:06:18.660841-05:00>, entity_id=light.dimable_light_123_1>
17-01-03 19:07:01 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state group.all_lights=off; friendly_name=all lights, order=0, auto=True, entity_id=('light.dimable_light_123_1',), hidden=True @ 2017-01-03T19:07:01.109500-05:00>, old_state=<state group.all_lights=on; friendly_name=all lights, order=0, auto=True, entity_id=('light.dimable_light_123_1',), hidden=True @ 2017-01-03T19:06:18.668010-05:00>, entity_id=group.all_lights>
17-01-03 19:07:07 INFO (MainThread) [homeassistant.components.http] Serving /api/services/homeassistant/turn_on to 192.168.9.91 (auth: True)
17-01-03 19:07:07 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_on, domain=homeassistant, service_call_id=1976609200-6, service_data=entity_id=light.dimable_light_123_1>
17-01-03 19:07:07 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_on, domain=light, service_call_id=1976609200-7, service_data=entity_id=['light.dimable_light_123_1']>
17-01-03 19:07:07 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-7>
17-01-03 19:07:07 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-6>
17-01-03 19:07:13 INFO (MainThread) [homeassistant.components.http] Serving /api/services/homeassistant/turn_on to 192.168.9.91 (auth: True)
17-01-03 19:07:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_on, domain=homeassistant, service_call_id=1976609200-8, service_data=entity_id=light.dimable_light_123_1>
17-01-03 19:07:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: service=turn_on, domain=light, service_call_id=1976609200-9, service_data=entity_id=['light.dimable_light_123_1']>
17-01-03 19:07:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-9>
17-01-03 19:07:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=1976609200-8>
^C17-01-03 19:07:42 INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_stop[L]>
17-01-03 19:07:42 INFO (Thread-7) [mysensors.mysensors] Stopping thread
17-01-03 19:07:42 INFO (Thread-11) [mysensors.mysensors] Closing socket at ('127.0.0.1', 5003).
17-01-03 19:07:42 INFO (Thread-11) [mysensors.mysensors] Socket closed at ('127.0.0.1', 5003).
^CException ignored in: <module 'threading' from '/usr/lib/python3.4/threading.py'>
Traceback (most recent call last):
  File "/usr/lib/python3.4/threading.py", line 1294, in _shutdown
    t.join()
  File "/usr/lib/python3.4/threading.py", line 1060, in join
    self._wait_for_tstate_lock()
  File "/usr/lib/python3.4/threading.py", line 1076, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt
hass@pi:/srv/hass/cfg $ exit

Script done on Tue 03 Jan 2017 07:07:47 PM EST

Node console

0 MCO:BGN:INIT NODE,CP=RNNNA--,VER=2.2.0-beta
4 TSM:INIT
4 TSF:WUR:MS=0
11 TSM:INIT:TSP OK
13 TSM:INIT:STATID=123
15 TSF:SID:OK,ID=123
17 TSM:FPAR
53 TSF:MSG:SEND,123-123-255-255,s=255,c=3,t=7,pt=0,l=0,sg=0,ft=0,st=OK:
273 TSF:MSG:READ,0-0-123,s=255,c=3,t=8,pt=1,l=1,sg=0:0
278 TSF:MSG:FPAR OK,ID=0,D=1
2061 TSM:FPAR:OK
2062 TSM:ID
2063 TSM:ID:OK
2065 TSM:UPL
2068 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=24,pt=1,l=1,sg=0,ft=0,st=OK:1
2074 TSF:MSG:READ,0-0-123,s=255,c=3,t=25,pt=1,l=1,sg=0:1
2079 TSF:MSG:PONG RECV,HP=1
2082 TSM:UPL:OK
2083 TSM:READY:ID=123,PAR=0,DIS=1
2088 TSF:MSG:SEND,123-123-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-123,s=255,c=3,t=15,pt=6,l=2,sg=0:0100
2104 TSF:MSG:SEND,123-123-0-0,s=255,c=0,t=17,pt=0,l=10,sg=0,ft=0,st=OK:2.2.0-beta
2113 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=6,pt=1,l=1,sg=0,ft=0,st=OK:0
2160 TSF:MSG:READ,0-0-123,s=255,c=3,t=6,pt=0,l=1,sg=0:I
2167 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=11,pt=0,l=13,sg=0,ft=0,st=OK:Dimable Light
2178 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=12,pt=0,l=3,sg=0,ft=0,st=OK:1.0
2186 TSF:MSG:SEND,123-123-0-0,s=1,c=0,t=4,pt=0,l=0,sg=0,ft=0,st=OK:
2192 MCO:REG:REQ
2195 TSF:MSG:SEND,123-123-0-0,s=255,c=3,t=26,pt=1,l=1,sg=0,ft=0,st=OK:2
2205 TSF:MSG:READ,0-0-123,s=255,c=3,t=27,pt=1,l=1,sg=0:1
2210 MCO:PIM:NODE REG=1
2213 MCO:BGN:STP
Light state: ON, Level: 100
2220 TSF:MSG:SEND,123-123-0-0,s=1,c=1,t=3,pt=2,l=2,sg=0,ft=0,st=OK:100
Node ready to receive messages...
2226 MCO:BGN:INIT OK,TSP=1
25995 TSF:MSG:READ,0-0-123,s=1,c=1,t=3,pt=0,l=2,sg=0:47
V_DIMMER command received...
Light state: ON, Level: 47
26003 TSF:MSG:SEND,123-123-0-0,s=1,c=1,t=3,pt=2,l=2,sg=0,ft=0,st=OK:47
35651 TSF:MSG:READ,0-0-123,s=1,c=1,t=3,pt=0,l=2,sg=0:22
V_DIMMER command received...
Light state: ON, Level: 22
35660 TSF:MSG:SEND,123-123-0-0,s=1,c=1,t=3,pt=2,l=2,sg=0,ft=0,st=OK:22
40934 TSF:MSG:READ,0-0-123,s=1,c=1,t=3,pt=0,l=2,sg=0:76
V_DIMMER command received...
Light state: ON, Level: 76
40946 TSF:MSG:SEND,123-123-0-0,s=1,c=1,t=3,pt=2,l=2,sg=0,ft=0,st=OK:76
44735 TSF:MSG:READ,0-0-123,s=1,c=1,t=3,pt=0,l=1,sg=0:0
V_DIMMER command received...
Light state: OFF
44744 TSF:MSG:SEND,123-123-0-0,s=1,c=1,t=3,pt=2,l=2,sg=0,ft=0,st=OK:0

martinhjelmare · January 4, 2017, 12:36am

Thanks for the good logs!

The problem on your end is that you only send a V_PERCENTAGE value and no V_STATUS value. The mysensors light platform requires both those V_TYPES to function properly.

The problem on my end is that this is only documented, and not handled very good in the logic. Ideally the device should not even be allowed to be added to hass, without all required V_TYPES. Minimum would be an error logged.

I’ll put this on my todo, to enhance how this is handled.

For now to fix this, just send a V_STATUS value with payload ‘0’ at the same time as you send the initial value for V_PERCENTAGE, in your sketch. Also feedback changes for both types to hass when the state at the device changes.

The docs for this are here:

PS look at the example sketch in the link above for details.

brahmafear · January 4, 2017, 2:08am

Thanks so much from the speedy response! Forgive me a few questions as I’m new to the hass/mysensors integration:

The sketch I was using on arduino side is the one included with the MySensors code from GitHub. Are you saying there is a problem with that code?

Confused as to the first statement about only sending a V_PERCENTAGE and not V_STATUS. Is it required to send multiple messages for each update? And as I understand it, these are just status updates from node to host, not control commands.

I did closely examine the MySensors Light page you linked, but didn’t follow exactly as the code meant for the nodes on that page seems to be for a different (older?) version of the MySensors library. For instance, in all of the code I have used, there is no MySensors object but instead direct calls to functionality. Ie, present() rather gw.present(). I’m new to MySensors; is this how it worked pre-2.0?

Thanks again for your help. I’ll try modifying the DimmableLight sketch from GitHub in the way you suggest to see if it has an effect.

Just for quicker reference, here is the arduino sketch I am using, taken from https://github.com/mysensors/MySensors/tree/master.

/**
 * 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 <[email protected]>
 * Copyright (C) 2013-2015 Sensnology AB
 * Full contributor list: https://github.com/mysensors/Arduino/graphs/contributors
 *
 * Documentation: http://www.mysensors.org
 * Support Forum: http://forum.mysensors.org
 *
 * This program is free software; you can redistribute it and/or
 * modify it under the terms of the GNU General Public License
 * version 2 as published by the Free Software Foundation.
 *
 *******************************
 *
 * REVISION HISTORY
 * Version 1.0 - January 30, 2015 - Developed by GizMoCuz (Domoticz)
 *
 * DESCRIPTION
 * This sketch provides an example how to implement a Dimmable Light
 * It is pure virtual and it logs messages to the serial output
 * It can be used as a base sketch for actual hardware.
 * Stores the last light state and level in eeprom.
 *
 */


// Enable debug prints
#define MY_DEBUG

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

#include <MySensors.h>

#define CHILD_ID_LIGHT 1

#define EPROM_LIGHT_STATE 1
#define EPROM_DIMMER_LEVEL 2

#define LIGHT_OFF 0
#define LIGHT_ON 1

#define SN "Dimable Light"
#define SV "1.0"

int16_t LastLightState=LIGHT_OFF;
int16_t LastDimValue=100;

MyMessage lightMsg(CHILD_ID_LIGHT, V_LIGHT);
MyMessage dimmerMsg(CHILD_ID_LIGHT, V_DIMMER);

void setup()
{
	//Retreive our last light state from the eprom
	//int LightState=loadState(EPROM_LIGHT_STATE);
  int LightState = 1;
	if (LightState<=1) {
		LastLightState=LightState;
		int DimValue=loadState(EPROM_DIMMER_LEVEL);
		if ((DimValue>0)&&(DimValue<=100)) {
			//There should be no Dim value of 0, this would mean LIGHT_OFF
			LastDimValue=DimValue;
		}
	}

	//Here you actualy switch on/off the light with the last known dim level
	SetCurrentState2Hardware();

	Serial.println( "Node ready to receive messages..." );
}

void presentation()
{
	// Send the Sketch Version Information to the Gateway
	sendSketchInfo(SN, SV);

	present(CHILD_ID_LIGHT, S_DIMMER );
}

void loop()
{
}

void receive(const MyMessage &message)
{
	if (message.type == V_LIGHT) {
		Serial.println( "V_LIGHT command received..." );

		int lstate= atoi( message.data );
		if ((lstate<0)||(lstate>1)) {
			Serial.println( "V_LIGHT data invalid (should be 0/1)" );
			return;
		}
		LastLightState=lstate;
		saveState(EPROM_LIGHT_STATE, LastLightState);

		if ((LastLightState==LIGHT_ON)&&(LastDimValue==0)) {
			//In the case that the Light State = On, but the dimmer value is zero,
			//then something (probably the controller) did something wrong,
			//for the Dim value to 100%
			LastDimValue=100;
			saveState(EPROM_DIMMER_LEVEL, LastDimValue);
		}

		//When receiving a V_LIGHT command we switch the light between OFF and the last received dimmer value
		//This means if you previously set the lights dimmer value to 50%, and turn the light ON
		//it will do so at 50%
	} else if (message.type == V_DIMMER) {
		Serial.println( "V_DIMMER command received..." );
		int dimvalue= atoi( message.data );
		if ((dimvalue<0)||(dimvalue>100)) {
			Serial.println( "V_DIMMER data invalid (should be 0..100)" );
			return;
		}
		if (dimvalue==0) {
			LastLightState=LIGHT_OFF;
		} else {
			LastLightState=LIGHT_ON;
			LastDimValue=dimvalue;
			saveState(EPROM_DIMMER_LEVEL, LastDimValue);
		}
	} else {
		Serial.println( "Invalid command received..." );
		return;
	}

	//Here you set the actual light state/level
	SetCurrentState2Hardware();
}

void SetCurrentState2Hardware()
{
	if (LastLightState==LIGHT_OFF) {
		Serial.println( "Light state: OFF" );
	} else {
		Serial.print( "Light state: ON, Level: " );
		Serial.println( LastDimValue );
	}

	//Send current state to the controller
	SendCurrentState2Controller();
}

void SendCurrentState2Controller()
{
	if ((LastLightState==LIGHT_OFF)||(LastDimValue==0)) {
		send(dimmerMsg.set((int16_t)0));
	} else {
		send(dimmerMsg.set(LastDimValue));
	}
}

Thanks.

brahmafear · January 4, 2017, 2:59am

Quick update. Based on the suggestion, I added:

send(lightMsg.set((int16_t)0));

to SendCurrentState2Controller() below

send(dimmerMsg.set((int16_t)0));

This seems to work as I then have a functioning Dimmer in hass. I’ve also tested the same concept on a S_RGB_LIGHT - including a V_STATUS update with every V_RGB update seems to make everything work.

One more note – just something that caused some additional confusion while testing. If the sketch periodically calls sendHeartbeat(), hass will eventually start showing huge delays in acting upon commands to mysensor objects - in the 20 second range. These delays go away as soon as the call to sendHeartbeat() is removed. Weird.

Thanks again for all your help.

martinhjelmare · January 4, 2017, 5:00pm

I’m not sure of there is a problem with the example sketch on the mysensors github page, but it won’t work directly with home assistant. Side note: It’s strange that the sketch initializes a V_LIGHT/V_STATUS msg variable (lightMsg) but doesn’t use it later in the sketch.

Home assistant has some requirements due to how the integration with mysensors is done, which requires some changes to most example sketches taken directly from the mysensors repo. How to present a mysensors device to home assistant is described here:

The platform specific requirements are described on the respective mysensors platform pages in the home assistant docs.

The mysensors light platform requires (besides V_PERCENTAGE or V_RGB or V_RGBW) a V_STATUS/V_LIGHT value to be sent among the initial values and V_STATUS should also be implemented in the receive function. Ie if home assistant sends a V_STATUS value to the device, the device should be able to react on that, turning the light on/off.

In general you should also always feedback a state change in the device from the device to home assistant. Ie after changing state on/off or dimmer value, you send the new value to home assistant, even if the initial request to change state came from home assistant. This workflow ensures that home assistant knows the true state of the device. Since we are using radio transport to carry messages between device and controller, messages might get lost in transport. This is why when turning on a switch/light in the home assistant GUI, it will turn back to off after 2 seconds, if a message from the device hasn’t confirmed the requested state change. You can turn this behavior off for actuator mysensors platforms with the optimistic setting, but I advice you to instead use the feedback workflow.

The light example sketch on the mysensors light platform page in the docs, is for mysensors version 1.5. Unfortunately I haven’t had time to add 2.0 example sketches for all platforms yet. PRs to help keep the docs up to date are very welcome.

Sending a heartbeat from the device to home assistant activates the smartSleep functionality in home assistant. This means that messages are buffered and only sent to the device upon receiving a heartbeat from the device. State changes are stored so that only the last requested state change is sent to the device. Other types of messages are queued in a FIFO queue. This behavior is not documented yet, so is also something that needs to be done via PR.

SmartSleep is useful if you want to sleep an actuator, eg to be able to have it battery powered.

Good that you got your devices working. Let me know if anything else is weird or not working for you.

brahmafear · January 4, 2017, 6:38pm

Thanks for all the detailed answers! All makes sense now.

I’m not very good at git, but I’ll see if I can figure it out enough to make some documentation updates and issue a pull request. At the very least, I should be able to provide some MySensor 2.0 examples.

And thanks for the heartbeat information. Makes sense for those using battery powered sensors.