Core: flux_led incorrect states, not updating, not switching - inconsistently

Created on 10 Jan 2018 · 15Comments · Source: home-assistant/core

Make sure you are running the latest version of Home Assistant before reporting an issue.

You should only file an issue if you found a bug. Feature and enhancement requests should go in the Feature Requests section of our community forum:

Home Assistant release (hass --version):
0.60.1

Python release (python3 --version):
3.5.3

Component/platform:
flux_led

Description of problem:
I've spent a little time trying to pin down the nature of this problem along with unsuccessfully trying to get hass to dump out some useful debug messages for this component. Issues observed:

On hass startup _sometimes_ it warns it's taking more than 10 seconds to start: 2018-01-10 13:25:14 WARNING (MainThread) [homeassistant.components.light] Setup of platform flux_led is taking over 10 seconds.
When trying to turn lights on and off via hass, sometimes it logs that update is taking more than 10 seconds: Update of light.morgan_zone_1 is taking over 10 seconds.
(Note: I have 2 different MagicHome WiFi LED Controllers at present, a UFO (ZF-WFUF-170F) and a Sunix SU705). To date I've only see the update error from the UFO.)
Sometimes when turning the light on, the slider moves to on, then switches back to off. Despite the light being on.
The state of the controls in the UI is not always correct. Even if controlled via hass, the magic home app or via the flux_led python module.

Note: Controlling and reporting the state of the WiFi modules is always correct when using the python module: /srv/hass/lib/python3.5/site-packages/flux_led indicating it's something related to either the UI or the integration between the module and hass.

Expected:
None of the issues above. Control should always work and the reported status should be accurate.

Additional info:
If you can provide guidance on how to get more complete debug information? I've tried running with --debug and it's not showing anything relating to flux_led except the startup warning.

Source

shortbloke

All 15 comments

Note I've also tried this with a stripped back setup. I pointed hass at a new empty directory, then modified the configuration file to have just the couple of flux_led's and once I did this I'm still having the same issues. On starting I managed to get to turn one of the two sets of lights on, but not the 2nd, but I then couldn't turn the 1st off via the UI. Checking with the flux_led module I can see the correct state and still control the LEDs correctly.
Simple config:

## Core Config ##
homeassistant:
  name: Home
  latitude: !secret latitude_loc_home
  longitude: !secret longitude_loc_home
  elevation: !secret evelation_loc_home
  time_zone: Europe/London
  temperature_unit: C
  unit_system: metric
#  customize: !include customize.yaml
#  customize_glob: !include customize_glob.yaml

## Hass Web Config ##
http:
  api_password: !secret http_api_password
  ssl_certificate: !secret http_ssl_certificate
  ssl_key: !secret http_ssl_key
  base_url: !secret http_base_url

# Enables the frontend
frontend:

# Enables configuration UI
config:

light:
  - platform: flux_led
    automatic_add: False
    devices:
      192.168.200.31:
        name: Morgan_Zone_1
        mode: "rgbw"
      192.168.200.32:
        name: Morgan_Zone_2
        mode: "rgbw"

shortbloke on 10 Jan 2018

Ok despite restarting my RPi, and running with the simple config. what appears to be happening is that it correctly reads the state on hass startup. If the lights are on I can manipulate the colours via the UI. If I use the UI or the service to change the on/off state then the light changes state once, but this isn't reflected in the UI and I then can't change the on/off state again since it thinks it's in the desired state already. So I suspect the problem is with reading back or tracking state.

shortbloke on 10 Jan 2018

These bulbs are very cheap and a bit unreliable. So I do not think it much we can do to fix this.

Regarding the slow startup and update, the bulbs sometimes do not answer when HA tries to connect. Then we have to try several times, and it takes time

Danielhiversen on 11 Jan 2018

@Danielhiversen I don't think it's the bulbs as everything works fine via the MagicHome app and via the python module HA is using.

shortbloke on 11 Jan 2018

Hello everyone!

I am also having problems with my LED Wifi Controller. The controller does not respond to some of my commands and shows inconssitant status updates. Everything works just fine with the MagicHome app.

Here are some of my logs:

Update of light.ledsaladesktop is taking over 10 seconds
15:13 core.py (WARNING)
Update of light.ledsaladesktop is taking over 10 seconds
15:13 core.py (WARNING)
Update of light.ledsaladesktop is taking over 10 seconds
15:12 core.py (WARNING)

I get dozens of these...

Using the app, I can see that the version of the controller is 4.

Thanks a lot!

tatunts on 14 Jan 2018

I'm starting to look into debugging what is going on. I've sync'd the latest dev branch and will start looking more closely at what is going on. I think I'm starting to get a clearer idea on what is occurring. Using either the standard web UI or via IOS when I make a request to turn the light on or off, the initial change will happen immediately. But the UI bounces back the original state. This then may correct itself but it can take minutes for this to occur. If the light is changed outside HomeAssistant, then I've seen sometimes it does update in the UI but most of the time it doesn't. I'm yet to determine if using Alexa to control the light via emulated Hue also create a similar issue.

I believe I have got the system into a state where it believes the current state and new desired state is the same, so doesn't then change it.

I noticed a recent discussion on this pull request https://github.com/home-assistant/home-assistant/pull/11270 that mentions hue causing the UI to be inaccurate/delayed and bouncing the UI on/off button similar to what I'm seeing. I'm not sure if there is something common underlying this. (Note I've tested on 0.61 and the problem persists).

If you look at the logs below you'll see long delays between the service event being executed and the state change being applied.

martin@nano-hass-dev:~/src/home-assistant$ bin/hass --debug
Config directory: /home/martin/.homeassistant
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_off>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_on>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=toggle>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=stop>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=restart>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=check_config>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=reload_core_config>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=create>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=dismiss>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.bootstrap] Home Assistant core initialized
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded frontend from homeassistant.components.frontend
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded api from homeassistant.components.api
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded http from homeassistant.components.http
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded websocket_api from homeassistant.components.websocket_api
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded system_log from homeassistant.components.system_log
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setting up http
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setup of domain http took 0.0 seconds.
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=http>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setting up api
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setting up websocket_api
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setup of domain websocket_api took 0.0 seconds.
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=websocket_api>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setting up system_log
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=system_log, service=clear>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setup of domain system_log took 0.0 seconds.
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=system_log>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setup of domain api took 0.0 seconds.
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=api>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setting up frontend
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setup of domain frontend took 0.0 seconds.
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=frontend>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded config from homeassistant.components.config
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded light from homeassistant.components.light
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded group from homeassistant.components.group
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded light.flux_led from homeassistant.components.light.flux_led
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setting up group
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=group, service=reload>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=group, service=set>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=group, service=remove>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=group, service=set_visibility>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setup of domain group took 0.0 seconds.
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=group>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setting up config
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded config.automation from homeassistant.components.config.automation
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.automation>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded config.script from homeassistant.components.config.script
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.script>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded config.customize from homeassistant.components.config.customize
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.customize>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded config.core from homeassistant.components.config.core
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.core>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded config.group from homeassistant.components.config.group
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config.group>
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.loader] Loaded config.hassbian from homeassistant.components.config.hassbian
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setting up light
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.setup] Setup of domain config took 0.1 seconds.
2018-01-15 21:38:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=config>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.components.light] Setting up light.flux_led
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=None, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:38:37.340270+00:00>>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=group, service=set, service_data=object_id=all_lights, name=all lights, entities=['light.morgan_zone_1'], visible=False, service_call_id=139678606529200-1>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=None, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:38:37.344041+00:00>>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-1>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=light, service=turn_on>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=light, service=turn_off>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=light, service=toggle>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.setup] Setup of domain light took 0.4 seconds.
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=light>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 1.36s
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Starting Home Assistant core loop
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Starting Home Assistant
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>
2018-01-15 21:38:37 INFO (MainThread) [homeassistant.core] Timer:starting
2018-01-15 21:38:41 INFO (MainThread) [homeassistant.components.http] Serving /states to 192.168.200.40 (auth: False)
2018-01-15 21:38:47 INFO (MainThread) [homeassistant.components.http] Serving /api/websocket to 192.168.200.40 (auth: False)
2018-01-15 21:38:47 INFO (MainThread) [homeassistant.loader] Loaded persistent_notification from homeassistant.components.persistent_notification
2018-01-15 21:38:47 INFO (MainThread) [homeassistant.components.http] Serving /api/themes to 192.168.200.40 (auth: True)
2018-01-15 21:38:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-2>
2018-01-15 21:38:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-3>
2018-01-15 21:38:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:38:37.340270+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:38:50.730379+00:00>>
2018-01-15 21:38:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:38:37.344041+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:38:50.733835+00:00>>
2018-01-15 21:38:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-3>
2018-01-15 21:38:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-2>
2018-01-15 21:38:59 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-4>
2018-01-15 21:38:59 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-5>
2018-01-15 21:38:59 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-5>
2018-01-15 21:38:59 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-4>
2018-01-15 21:39:07 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:38:50.730379+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:39:07.372318+00:00>>
2018-01-15 21:39:07 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:38:50.733835+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:39:07.373285+00:00>>
2018-01-15 21:39:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-6>
2018-01-15 21:39:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-7>
2018-01-15 21:39:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-7>
2018-01-15 21:39:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-6>
2018-01-15 21:40:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:39:07.372318+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:40:09.495669+00:00>>
2018-01-15 21:40:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:39:07.373285+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:40:09.496487+00:00>>
2018-01-15 21:40:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-8>
2018-01-15 21:40:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-9>
2018-01-15 21:40:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-9>
2018-01-15 21:40:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-8>
2018-01-15 21:41:11 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:40:09.495669+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:11.388287+00:00>>
2018-01-15 21:41:11 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:40:09.496487+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:11.389203+00:00>>
2018-01-15 21:41:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-10>
2018-01-15 21:41:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-11>
2018-01-15 21:41:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-11>
2018-01-15 21:41:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-10>
2018-01-15 21:41:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-12>
2018-01-15 21:41:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-13>
2018-01-15 21:41:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:11.388287+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:37.258361+00:00>>
2018-01-15 21:41:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:11.389203+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:37.262532+00:00>>
2018-01-15 21:41:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-13>
2018-01-15 21:41:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-12>
2018-01-15 21:41:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-14>
2018-01-15 21:41:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-15>
2018-01-15 21:41:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:37.258361+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:38.094411+00:00>>
2018-01-15 21:41:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:37.262532+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:38.095832+00:00>>
2018-01-15 21:41:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-15>
2018-01-15 21:41:38 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-14>
2018-01-15 21:41:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-16>
2018-01-15 21:41:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-17>
2018-01-15 21:41:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:38.094411+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:40.346470+00:00>>
2018-01-15 21:41:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:38.095832+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:40.347226+00:00>>
2018-01-15 21:41:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-17>
2018-01-15 21:41:40 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-16>
2018-01-15 21:41:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-18>
2018-01-15 21:41:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-19>
2018-01-15 21:41:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:40.346470+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:41.369898+00:00>>
2018-01-15 21:41:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:40.347226+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:41.370586+00:00>>
2018-01-15 21:41:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-19>
2018-01-15 21:41:41 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-18>
2018-01-15 21:42:06 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-20>
2018-01-15 21:42:06 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-21>
2018-01-15 21:42:06 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-21>
2018-01-15 21:42:06 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-20>
2018-01-15 21:42:12 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:41:41.369898+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:42:12.375605+00:00>>
2018-01-15 21:42:12 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:41:41.370586+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:42:12.376410+00:00>>
2018-01-15 21:42:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-22>
2018-01-15 21:42:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-23>
2018-01-15 21:42:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:42:12.375605+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:42:28.542212+00:00>>
2018-01-15 21:42:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:42:12.376410+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:42:28.546043+00:00>>
2018-01-15 21:42:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-23>
2018-01-15 21:42:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-22>
2018-01-15 21:43:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-24>
2018-01-15 21:43:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-25>
2018-01-15 21:43:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-25>
2018-01-15 21:43:36 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-24>
2018-01-15 21:44:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:42:28.542212+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:44:45.370785+00:00>>
2018-01-15 21:44:45 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:42:28.546043+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:44:45.372465+00:00>>
2018-01-15 21:45:59 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-26>
2018-01-15 21:45:59 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-27>
2018-01-15 21:45:59 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-27>
2018-01-15 21:45:59 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-26>
2018-01-15 21:47:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:44:45.370785+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:47:18.667429+00:00>>
2018-01-15 21:47:18 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:44:45.372465+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:47:18.668348+00:00>>
2018-01-15 21:47:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-28>
2018-01-15 21:47:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-29>
2018-01-15 21:47:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-29>
2018-01-15 21:47:50 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-28>
2018-01-15 21:48:19 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:47:18.667429+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:48:19.496243+00:00>>
2018-01-15 21:48:19 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:47:18.668348+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:48:19.497831+00:00>>
2018-01-15 21:49:11 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-30>
2018-01-15 21:49:11 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-31>
2018-01-15 21:49:11 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-31>
2018-01-15 21:49:11 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-30>
2018-01-15 21:49:51 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:48:19.496243+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:49:51.369199+00:00>>
2018-01-15 21:49:51 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:48:19.497831+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:49:51.370278+00:00>>
2018-01-15 21:50:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-32>
2018-01-15 21:50:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-33>
2018-01-15 21:50:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-33>
2018-01-15 21:50:05 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-32>
2018-01-15 21:50:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.morgan_zone_1, brightness=114, service_call_id=139678606529200-34>
2018-01-15 21:50:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-34>
2018-01-15 21:50:22 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:49:51.369199+00:00>, new_state=<state light.morgan_zone_1=on; brightness=0, min_mireds=154, max_mireds=500, rgb_color=(0, 0, 0), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>>
2018-01-15 21:50:22 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:49:51.370278+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:50:22.481266+00:00>>
2018-01-15 21:50:26 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.morgan_zone_1, rgb_color=[255, 0, 0], service_call_id=139678606529200-35>
2018-01-15 21:50:26 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=0, min_mireds=154, max_mireds=500, rgb_color=(0, 0, 0), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(255, 0, 0), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>>
2018-01-15 21:50:26 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-35>
2018-01-15 21:50:27 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.morgan_zone_1, rgb_color=[128, 255, 0], service_call_id=139678606529200-36>
2018-01-15 21:50:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(255, 0, 0), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(128, 255, 0), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>>
2018-01-15 21:50:28 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-36>
2018-01-15 21:50:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.morgan_zone_1, rgb_color=[0, 191, 255], service_call_id=139678606529200-37>
2018-01-15 21:50:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(128, 255, 0), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 191, 255), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>>
2018-01-15 21:50:31 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-37>
2018-01-15 21:50:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.morgan_zone_1, rgb_color=[0, 0, 255], service_call_id=139678606529200-38>
2018-01-15 21:50:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 191, 255), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 0, 255), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>>
2018-01-15 21:50:33 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-38>
2018-01-15 21:51:32 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-39>
2018-01-15 21:51:32 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-40>
2018-01-15 21:51:32 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-40>
2018-01-15 21:51:32 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-39>
2018-01-15 21:52:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-41>
2018-01-15 21:52:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-42>
2018-01-15 21:52:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 0, 255), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:50:22.478388+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:52:03.564380+00:00>>
2018-01-15 21:52:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:50:22.481266+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:52:03.565210+00:00>>
2018-01-15 21:52:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-42>
2018-01-15 21:52:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-41>
2018-01-15 21:52:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.morgan_zone_1, service_call_id=139678606529200-43>
2018-01-15 21:52:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.morgan_zone_1'], service_call_id=139678606529200-44>
2018-01-15 21:52:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-44>
2018-01-15 21:52:09 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_executed[L]: service_call_id=139678606529200-43>
2018-01-15 21:52:55 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:52:03.564380+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 0, 255), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:52:55.457997+00:00>>
2018-01-15 21:52:55 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:52:03.565210+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:52:55.459943+00:00>>
2018-01-15 21:53:25 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 0, 255), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:52:55.457997+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:53:25.362434+00:00>>
2018-01-15 21:53:25 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:52:55.459943+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:53:25.363175+00:00>>
2018-01-15 21:54:57 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:53:25.362434+00:00>, new_state=<state light.morgan_zone_1=on; brightness=191, min_mireds=154, max_mireds=500, rgb_color=(191, 64, 0), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:54:57.363003+00:00>>
2018-01-15 21:54:57 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:53:25.363175+00:00>, new_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:54:57.363728+00:00>>
2018-01-15 21:59:03 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=191, min_mireds=154, max_mireds=500, rgb_color=(191, 64, 0), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:54:57.363003+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 0, 255), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:54:57.363003+00:00>>
2018-01-15 22:01:37 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 0, 255), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:54:57.363003+00:00>, new_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:54:57.363003+00:00>>
2018-01-15 22:07:14 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.morgan_zone_1, old_state=<state light.morgan_zone_1=on; brightness=255, min_mireds=154, max_mireds=500, rgb_color=(0, 255, 64), friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T21:54:57.363003+00:00>, new_state=<state light.morgan_zone_1=off; friendly_name=Morgan_Zone_1, supported_features=21 @ 2018-01-15T22:07:14.676109+00:00>>
2018-01-15 22:07:14 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.all_lights, old_state=<state group.all_lights=on; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T21:54:57.363728+00:00>, new_state=<state group.all_lights=off; entity_id=('light.morgan_zone_1',), order=0, auto=True, friendly_name=all lights, hidden=True, assumed_state=False @ 2018-01-15T22:07:14.677312+00:00>>

shortbloke on 15 Jan 2018

You could try to add self._bulb.update_state(retry=2)
after the state of the light is changed; https://github.com/home-assistant/home-assistant/blob/e980ced0b74bb283543a7dcef58265da292f72b2/homeassistant/components/light/flux_led.py#L230

Danielhiversen on 15 Jan 2018

Adding self._bulb.update_state(retry=2) to bot the turn_on and turn_off methods seems to address the UI delay issue when changes are made via HASS. And removes the "bounce" I was seeing.

There remains an issue if the light state is changed outside of HASS. I assume that's expected as perhaps Update is only called on some sort of poll. I've not yet looked into that.

shortbloke on 15 Jan 2018

Still investigating this one, but it looks like the problem is in the underlying python flux_led module.
I added some simple lines to dump out the sent and received raw data using utils.dump_bytes. When I call this module from a simple app that loops on update, it works and the changes in state are reflected in the raw data:

import flux_led
from time import sleep
light = flux_led.WifiLedBulb("192.168.200.170")
while True:
    light.update_state(retry=2)
    power_state = light.raw_state[2]
    if power_state == 0x23:
        print("ON")
    elif power_state == 0x24:
        print("OFF")
    sleep(5)

Gives me an output:

Sending:
81 8a 8b 96
Reading - expected: 14
Read Remaining: 0 Chunk Size: 14
Chunk:
81 04 24 61 01 01 ff 00 00 00 04 00 00 0f
Read:
81 04 24 61 01 01 ff 00 00 00 04 00 00 0f
OFF
Sending:
81 8a 8b 96
Reading - expected: 14
Read Remaining: 0 Chunk Size: 14
Chunk:
81 04 23 61 01 01 ff 00 00 00 04 00 00 0e
Read:
81 04 23 61 01 01 ff 00 00 00 04 00 00 0e
ON

However at the same time HASS is calling the same module against the same LED and showing the power state as 0x24 (off):

Sending:
81 8a 8b 96
Reading - expected: 14
Read Remaining: 0 Chunk Size: 14
Chunk:
81 04 24 61 01 01 ff 00 00 00 04 00 00 0f
Read:
81 04 24 61 01 01 ff 00 00 00 04 00 00 0f

However, if I increase the sleep from 5 to 30 seconds in my test app, then I get the same wrong data being returned. i.e. the state isn't updated or correctly reflected for several minutes.

shortbloke on 17 Jan 2018

Investigation note:

Increasing socket timeout to be > than poll interval, doesn't help.
Close function is not being called between updates.
Calling connect in query_state before doing a send does get the correct information each time. (?Something killing the socket connection and not triggering an exception?)

shortbloke on 17 Jan 2018

@tatunts Could you test this fix: https://github.com/Danielhiversen/flux_led/pull/52

Danielhiversen on 18 Jan 2018

👍1

@tatunts If you're not sure how to test it from that location, here's some basic instructions to do it manually.

Navigate to your home-assistant install directory (i.e. /srv/hass)
Then under this navigate to the location of the flux_led python packages used (i.e. /srv/hass/lib/python3.5/site-packages/flux_led)
backup the file __main__.py
Replace __main__.py with the contents of the updated version: https://raw.githubusercontent.com/shortbloke/flux_led/bf312a96285c61d1a07108a94d04ffd6230bbd6d/flux_led/__main__.py
Restart home-assistant.

Let me know if it a) it still works with your lights b) improves/resolves the issue you were having?

shortbloke on 18 Jan 2018

👍1

Hello @shortbloke and @Danielhiversen!

I am really sorry that I could not reply you sooner...

I am running Hassio right now, can you please tell me how to try this fix using Hassio?

It would be so nice to finally have these controllers working properly...

Thank you very much for your time! I really appreciate it.

tatunts on 19 Jan 2018

@tatunts I'm not sure how to make any changed to Hassio. However the proposed change I suggested has been accepted, so hopefully will make the next release. If you upgrade then and see if it improves anything for you. The underlying issue I was experiencing was rather odd, and something I'm not able to explain, but did at least get it working reliably with my change.

shortbloke on 20 Jan 2018

🎉1

Thank you @shortbloke! I will wait for the next update. Have a great day!

tatunts on 20 Jan 2018

Was this page helpful?

0 / 5 - 0 ratings