Error in lutron.py -- Hass.io loses ability to control LutronRA2 entities

[grantalewis]

Home Assistant release with the issue: 0.85.1

Last working Home Assistant release (if known): 0.84.6

Operating environment (Hass.io/Docker/Windows/etc.): RPi3, Hass.io

Component/platform: https://www.home-assistant.io/components/lutron/

Description of problem:

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/homeassistant/helpers/service.py", line 287, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/usr/local/lib/python3.6/concurrent/futures/thread.py", line 56, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/light/lutron.py", line 73, in turn_off
    self._lutron_device.level = 0
  File "/usr/local/lib/python3.6/site-packages/pylutron/__init__.py", line 591, in level
    Output._ACTION_ZONE_LEVEL, "%.2f" % new_level)
  File "/usr/local/lib/python3.6/site-packages/pylutron/__init__.py", line 392, in send
    self._conn.send(op + out_cmd)
  File "/usr/local/lib/python3.6/site-packages/pylutron/__init__.py", line 91, in send
    self._send_locked(cmd)
  File "/usr/local/lib/python3.6/site-packages/pylutron/__init__.py", line 81, in _send_locked
    self._telnet.write(cmd.encode('ascii') + b'\r\n')
  File "/usr/local/lib/python3.6/telnetlib.py", line 290, in write
    self.sock.sendall(buffer)
TimeoutError: [Errno 110] Operation timed out

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

lutron:
  host: 192.168.1.225
  username: lutron
  password: integration

Traceback (if applicable):

Additional information:

[grantalewis]

OK, when the problem appeared with my downstairs hallway lights, I conducted the test:

Last login: Sat Aug 24 11:34:45 on ttys000
Office-iMac:~ grantlewis$ telnet 192.168.1.225
Trying 192.168.1.225...
Connected to 192.168.1.225.
Escape character is '^]'.
login: lutron
password: integration

GNET> sudo tcpdump -A -ni eth0

Since the problem occurs for me across all Lutron entities, I chose to then test my office fan light since it hadn't been operated since the problem began. That light was off when I started. I toggled the UI switch to ON. The light turned on and stayed on. The UI switch toggled itself back to OFF.

Terminal window result:

~OUTPUT,9,1,50.00
~OUTPUT,9,29,6
~OUTPUT,9,30,1,50.00

Next, with the light ON and the UI switch in the OFF position, I clicked the switch in the UI once again. The UI switch toggled ON and back OFF but the light did not respond. There was no result in the terminal window.

Tests in the States page were identical. With the light ON and the UI switch in the OFF position, I clicked the switch in the UI once. The UI switch toggled ON and back OFF but the light did not respond. There was no result in the terminal window.

The Services page allows me to operate the light correctly. The image below shows only homeassistant.toggle, but turn_on and turn_off also worked.

~OUTPUT,9,1,0.00
~OUTPUT,9,29,6
~OUTPUT,9,30,1,0.00

I noted that even though Services operated the light correctly, the HA UI did not accurately reflect the state of the light.

[grantalewis]

I thought I'd made an important discovery after my prior reply and made a "eureka" post about it. I thought I'd found something suspcious with OmniLinkBridge. But then I realized I could just disable OLB entirely, so I did that and rebooted. Contrary to what I expected, the problem persists, so OLB is not to blame. So I'm now heavily editing that post to correct my former assumption.

Having eliminated that distraction, there's still more story to tell.

I don't think I mentioned this before, but each of my entities shows up in the HA States page twice: once with its Lutron name, and once with its Omni name (thanks to OLB). For example:

Downstairs hallway lights

• Lutron: light.main_stairs_main_hall
• Omni: light.hall_light

Family room window lamp

• Lutron: light.family_room_window_lamp
• Omni: light.front_lamp

Here's a video that shows how those two Family room window lamp entites behave in HA:

https://www.dropbox.com/s/292iqg0n7dpn5qa/demo_of_lutron_problem.mp4?dl=0

I only point to the Lutron entities in my HA configuration. I can see all of the Omni entities in States, but for sake of simplicity and consistency, I've always just pretended they're not there.

But get this: what I've discovered is that it's the Lutron entity that fails in HA. The corresponding Omni entry continues to work just fine in HA. And in fact, the Lutron dimming controls work as well -- it's only the Lutron on/off toggles that malfunction in the HA UI. (Keep in mind that this problem doesn't occur in 0.84.6, all the same hardware and configuration.)

So that doesn't really give me a solution at this point, but it does provide some pretty important insight.

If a fix for the pylutron problem doesn't come along, it looks like I could point to Omni entities instead. A bit of headache for sure, but that at least would give me a path forward.

[Tangston311]

@grantalewis I have to give it to you, you make excellent troubleshooting videos :). Interesting if the duplicate entities wind up being the root of the problem. That shouldn’t be the issue for mine as while I have Savant independently hooked into Lutron, it’s not hooked up to HA so I only have one entity per Lutron light/switch/shade appearing in HA.

[grantalewis]

@grantalewis I have to give it to you, you make excellent troubleshooting videos :). Interesting if the duplicate entities wind up being the root of the problem. That shouldn’t be the issue for mine as while I have Savant independently hooked into Lutron, it’s not hooked up to HA so I only have one entity per Lutron light/switch/shade appearing in HA.

I just edited the post with the video link in it pretty heavily -- made an important discovery that changed the landscape quite a bit.

[grantalewis]

I upgraded to 0.98.0 this morning:

• I tested a light using a toggle in the UI; everything worked for about 20 minutes
• I tested another light using a toggle in the UI; the toggle stayed in the ON position but the light did not operate
• went to Services and tested there; the light worked correctly
• went back to the UI and tried there; the light worked
• tried a couple of others and those worked, too

After 3 hours, the setup was still working and so I took a snapshot and restored it to my RPi3. Unfortunately that caused the problem to occur once again. I'm now going to go back to the Virtual Box install to see if that causes any different behavior.

EDIT 2 hours later: still solid, no problems. I'll probably leave it running on Virtual Box to see how it behaves for the rest of the night. Then I'll try the RPi3 again tomorrow.

[grantalewis]

0.98.0 crapped out about 8PM last night, so I went back to 0.84.6 to avoid any problems overnight.

I just finished upgrading the Virtual Box install to 0.98.1 and am going to let it run for a while today to see how it behaves. Seems to be OK right now.

[grantalewis]

5 hours later, same problem exists.

[cdheiser]

Are you running in docker or using hass.io?

On Fri, Aug 30, 2019 at 11:56 AM grantalewis notifications@github.com wrote:

5 hours later, same problem exists.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWQTIX5TE4OEN34QFBDQHFUO3A5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5SPUEA#issuecomment-526711312, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWVHVYZOKCK3KPZALULQHFUO3ANCNFSM4GR2ZVYA .

[grantalewis]

Hass.io

[cdheiser]

If you know how to add a custom component to hass.io, I think I can give you a version of the lutron component with more instrumentation to figure out what's going on.

On Fri, Aug 30, 2019 at 1:43 PM grantalewis notifications@github.com wrote:

Hass.io

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWRWSKQZDSMLWN5DI2LQHGBAZA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5SXNKA#issuecomment-526743208, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWX5KIPMNHJDRDPSI5DQHGBAZANCNFSM4GR2ZVYA .

[grantalewis]

I use a media_player custom component for Alexa and so am familiar with the process.

I'm certainly willing to try.

[cdheiser]

Ok... I'm close to having something really simple, with some exception logging, and converting all debug logging to info logging since AFAICT, the logger doesn't properly set components to debug, custom or otherwise.

On Fri, Aug 30, 2019 at 2:05 PM grantalewis notifications@github.com wrote:

I use a media_player custom component for Alexa and so am familiar with the process.

[image: Screen Shot 2019-08-30 at 5 01 43 PM] https://user-images.githubusercontent.com/9505044/64051188-465b8e80-cb48-11e9-87eb-03343c624a0e.png

I'm certainly willing to try.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWVVJCJNVOKGJ3QFEQTQHGDSZA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5SZBLI#issuecomment-526749869, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWRPWGZHK3PBFRSPJJLQHGDSZANCNFSM4GR2ZVYA .

[cdheiser]

Download: https://www.dropbox.com/s/xgbaa27l7cqq6qw/lutron-custom.tar.gz?dl=0

Untar it in your custom_components directory. Restart home assistant and when it breaks, pull the logs.

On Fri, Aug 30, 2019 at 2:17 PM Chris Heiser chris.heiser@gmail.com wrote:

Ok... I'm close to having something really simple, with some exception logging, and converting all debug logging to info logging since AFAICT, the logger doesn't properly set components to debug, custom or otherwise.

On Fri, Aug 30, 2019 at 2:05 PM grantalewis notifications@github.com wrote:

I use a media_player custom component for Alexa and so am familiar with the process.

[image: Screen Shot 2019-08-30 at 5 01 43 PM] https://user-images.githubusercontent.com/9505044/64051188-465b8e80-cb48-11e9-87eb-03343c624a0e.png

I'm certainly willing to try.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWVVJCJNVOKGJ3QFEQTQHGDSZA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5SZBLI#issuecomment-526749869, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWRPWGZHK3PBFRSPJJLQHGDSZANCNFSM4GR2ZVYA .

[grantalewis]

OK, I've got the file. To clarify, I'll have

custom_components --| media_player --| lutron ----| (all untarred files)

Is that correct?

[cdheiser]

right... in addition to all the lutron component python files, there will be a cdhlutron.py which is replacing the dependency on pylutron in that component so we can add/remove logging and tweak as we go through a few iterations of failure and log debugging

On Fri, Aug 30, 2019 at 3:12 PM grantalewis notifications@github.com wrote:

OK, have the file. To clarify, I'll have

custom_components --| media_player --| lutron ----| (all untarred files)

Is that correct?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWQJZRENHK75KAZVZTLQHGLONA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5S4Z7Y#issuecomment-526765311, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWXSOZXEV5RUJKP5VHLQHGLONANCNFSM4GR2ZVYA .

[grantalewis]

OK, great. Got it up and running. I'll report back when the problem shows up again.

[grantalewis]

I posted earlier and then deleted it... but maybe should not have. I started noticing problems around 9:25 PM (about 20 minutes ago), but the log's last entry was around 9:05 - 9:10 PM. Seems strange. Anyway, .zip is attached.

home-assistant.log.zip

[cdheiser]

Well I see 2 issues:

1) That log doesn't even have the first log messages for initializing the lutron module.

I expect to at least see a line that says: "Custom Lutrong Debug Mode by cdheiser@github!!!"

2) There are a lot of exceptions being thrown in the main thread. It might be worth stripping the config back to just the lutron module and see if that improves things.

On Fri, Aug 30, 2019 at 6:45 PM grantalewis notifications@github.com wrote:

I posted earlier and then deleted it... but maybe should not have. I started noticing problems around 9:25 PM (about 20 minutes ago), but the log's last entry was around 9:05 - 9:10 PM. Seems strange. Anyway, .zip is attached.

home-assistant.log.zip https://github.com/home-assistant/home-assistant/files/3561961/home-assistant.log.zip

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWR7RFNXCMNZGYAPMILQHHEMPA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5TCZBI#issuecomment-526789765, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWWJDQ6TA65UCBODSE3QHHEMPANCNFSM4GR2ZVYA .

[grantalewis]

Maybe I messed up something with your custom component? Here's my config folder:

I did what you suggested and stripped back my configuration.yaml:

homeassistant:
  name: Home
  latitude: !secret my_latituide
  longitude: !secret my_longitude
  elevation: 228
  unit_system: imperial
  time_zone: America/New_York
  customize: !include customize.yaml
  packages: !include_dir_named packages

http:
  api_password: !secret http_password
  base_url: !secret http_base_url
  ssl_certificate: /ssl/fullchain.pem
  ssl_key: /ssl/privkey.pem

hacs:
  token: !secret hacs_api_token
  sidepanel_title: Community

config:

system_health:

zone: !include zones.yaml

frontend:

discovery:
   ignore:
     - plex_mediaserver
     - netgear_router
     - igd
     - roku
     - samsung_tv

logbook:

emulated_hue:
  host_ip: 192.168.1.35
  listen_port: 8300
  expose_by_default: true
  exposed_domains:
    - light
    - switch
    - input_boolean

sensor: !include sensors.yaml

lutron:
  host: 192.168.1.225
  username: <redacted>
  password: <redacted>

owntracks:
  track_new_devices: no
  max_gps_accuracy: 100
  waypoints: true

mqtt:
  broker: localhost
  username: !secret mqtt_username
  password: !secret mqtt_password
  discovery: true
  discovery_prefix: homeassistant

input_boolean:
  dog_needs_food:
    name: Dog needs food
    icon: mdi:dog
  sitter_needs_greeting:
  bounty_switch:
  enable_zone7:

input_select:
  alarm_time:
    name: Alarm Time
    options:
      - Skip Tomorrow
      - 06:15
      - 06:30
      - 06:45
      - 07:00
      - 07:15
      - 07:30
      - Vacation
    icon: mdi:alarm

group: !include groups.yaml
switch: !include switch.yaml

Even so, I'm not seeing anything about Custom Lutron Debug Mode or cdheiser. Just a log entry for "You are using a custom integration for lutron."

2019-08-31 09:41:23 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant.
2019-08-31 09:41:23 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for lutron which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant.
2019-08-31 09:41:24 WARNING (MainThread) [homeassistant.components.http] Configuring api_password via the http integration has been deprecated. Use the legacy api password auth provider instead. For instructions, see https://www.home-assistant.io/docs/authentication/providers/#legacy-api-password
2019-08-31 09:41:24 WARNING (MainThread) [homeassistant.components.http.auth] legacy_api_password support has been enabled.
2019-08-31 09:41:24 WARNING (Recorder) [homeassistant.components.recorder] Ended unfinished session (id=16 from 2019-08-31 13:31:01.840605)
2019-08-31 09:41:54 ERROR (MainThread) [homeassistant.components.mqtt.climate] Exception in async_discover when dispatching 'mqtt_discovery_new_climate_mqtt': ({'current_temperature_topic': 'omnilink/thermostat1/current_temperature', 'temperature_low_state_topic': 'omnilink/thermostat1/temperature_heat_state', 'temperature_low_command_topic': 'omnilink/thermostat1/temperature_heat_command', 'temperature_high_state_topic': 'omnilink/thermostat1/temperature_cool_state', 'temperature_high_command_topic': 'omnilink/thermostat1/temperature_cool_command', 'min_temp': '45', 'max_temp': '95', 'mode_state_topic': 'omnilink/thermostat1/mode_state', 'mode_command_topic': 'omnilink/thermostat1/mode_command', 'modes': ['auto', 'off', 'cool', 'heat'], 'fan_mode_state_topic': 'omnilink/thermostat1/fan_mode_state', 'fan_mode_command_topic': 'omnilink/thermostat1/fan_mode_command', 'fan_modes': ['auto', 'on', 'cycle'], 'hold_state_topic': 'omnilink/thermostat1/hold_state', 'hold_command_topic': 'omnilink/thermostat1/hold_command', 'name': 'Lower Tstat', 'state_topic': None, 'availability_topic': 'omnilink/status', 'platform': 'mqtt'},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/climate.py", line 244, in async_discover
    config = PLATFORM_SCHEMA(discovery_payload)
  File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 272, in __call__
    return self._compiled([], data)
  File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 594, in validate_dict
    return base_validate(path, iteritems(data), out)
  File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 432, in validate_mapping
    raise er.MultipleInvalid(errors)
voluptuous.error.MultipleInvalid: extra keys not allowed @ data['state_topic']

2019-08-31 09:41:54 ERROR (MainThread) [homeassistant.components.mqtt.climate] Exception in async_discover when dispatching 'mqtt_discovery_new_climate_mqtt': ({'current_temperature_topic': 'omnilink/thermostat2/current_temperature', 'temperature_low_state_topic': 'omnilink/thermostat2/temperature_heat_state', 'temperature_low_command_topic': 'omnilink/thermostat2/temperature_heat_command', 'temperature_high_state_topic': 'omnilink/thermostat2/temperature_cool_state', 'temperature_high_command_topic': 'omnilink/thermostat2/temperature_cool_command', 'min_temp': '45', 'max_temp': '95', 'mode_state_topic': 'omnilink/thermostat2/mode_state', 'mode_command_topic': 'omnilink/thermostat2/mode_command', 'modes': ['auto', 'off', 'cool', 'heat'], 'fan_mode_state_topic': 'omnilink/thermostat2/fan_mode_state', 'fan_mode_command_topic': 'omnilink/thermostat2/fan_mode_command', 'fan_modes': ['auto', 'on', 'cycle'], 'hold_state_topic': 'omnilink/thermostat2/hold_state', 'hold_command_topic': 'omnilink/thermostat2/hold_command', 'name': 'Upper Tstat', 'state_topic': None, 'availability_topic': 'omnilink/status', 'platform': 'mqtt'},)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/mqtt/climate.py", line 244, in async_discover
    config = PLATFORM_SCHEMA(discovery_payload)
  File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 272, in __call__
    return self._compiled([], data)
  File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 594, in validate_dict
    return base_validate(path, iteritems(data), out)
  File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 432, in validate_mapping
    raise er.MultipleInvalid(errors)
voluptuous.error.MultipleInvalid: extra keys not allowed @ data['state_topic']

2019-08-31 09:42:00 WARNING (MainThread) [homeassistant.setup] Setup of lutron is taking over 10 seconds.
2019-08-31 09:42:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity
    raise HomeAssistantError(msg)
2019-08-31 09:42:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity
    raise HomeAssistantError(msg)
2019-08-31 09:42:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity
    raise HomeAssistantError(msg)
2019-08-31 09:42:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity
    raise HomeAssistantError(msg)
2019-08-31 09:42:22 WARNING (MainThread) [homeassistant.components.template.sensor] Could not render template Family Room, the state is unknown.
2019-08-31 09:42:22 WARNING (MainThread) [homeassistant.components.template.sensor] Could not render template Master Bedroom, the state is unknown.

[cdheiser]

I think I know what the problem is. I'll send an updated custom component later today.

On Sat, Aug 31, 2019, 6:58 AM grantalewis notifications@github.com wrote:

Maybe I messed up something with your custom component? Here's my config folder:

[image: Screen Shot 2019-08-31 at 9 52 56 AM] https://user-images.githubusercontent.com/9505044/64064890-3fc72880-cbd5-11e9-8036-4a6f0890db98.png

I did what you suggested and stripped back by configuration.yaml:

homeassistant: name: Home latitude: !secret my_latituide longitude: !secret my_longitude elevation: 228 unit_system: imperial time_zone: America/New_York customize: !include customize.yaml packages: !include_dir_named packages

http: api_password: !secret http_password base_url: !secret http_base_url ssl_certificate: /ssl/fullchain.pem ssl_key: /ssl/privkey.pem

hacs: token: !secret hacs_api_token sidepanel_title: Community

config:

system_health:

zone: !include zones.yaml

frontend:

discovery: ignore:

• plex_mediaserver
• netgear_router
• igd
• roku
• samsung_tv

logbook:

emulated_hue: host_ip: 192.168.1.35 listen_port: 8300 expose_by_default: true exposed_domains:

• light
• switch
• input_boolean

sensor: !include sensors.yaml

lutron: host: 192.168.1.225 username: password:

owntracks: track_new_devices: no max_gps_accuracy: 100 waypoints: true

mqtt: broker: localhost username: !secret mqtt_username password: !secret mqtt_password discovery: true discovery_prefix: homeassistant

input_boolean: dog_needs_food: name: Dog needs food icon: mdi:dog sitter_needs_greeting: bounty_switch: enable_zone7:

input_select: alarm_time: name: Alarm Time options:

• Skip Tomorrow
• 06:15
• 06:30
• 06:45
• 07:00
• 07:15
• 07:30
• Vacation icon: mdi:alarm

group: !include groups.yaml switch: !include switch.yaml

Even so, I'm not seeing anything about Custom Lutron Debug Mode or cdheiser. Just a log entry for "You are using a custom integration for lutron."

2019-08-31 09:41:23 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant. 2019-08-31 09:41:23 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for lutron which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you do experience issues with Home Assistant. 2019-08-31 09:41:24 WARNING (MainThread) [homeassistant.components.http] Configuring api_password via the http integration has been deprecated. Use the legacy api password auth provider instead. For instructions, see https://www.home-assistant.io/docs/authentication/providers/#legacy-api-password 2019-08-31 https://www.home-assistant.io/docs/authentication/providers/#legacy-api-password2019-08-31 09:41:24 WARNING (MainThread) [homeassistant.components.http.auth] legacy_api_password support has been enabled. 2019-08-31 09:41:24 WARNING (Recorder) [homeassistant.components.recorder] Ended unfinished session (id=16 from 2019-08-31 13:31:01.840605) 2019-08-31 09:41:54 ERROR (MainThread) [homeassistant.components.mqtt.climate] Exception in async_discover when dispatching 'mqtt_discovery_new_climate_mqtt': ({'current_temperature_topic': 'omnilink/thermostat1/current_temperature', 'temperature_low_state_topic': 'omnilink/thermostat1/temperature_heat_state', 'temperature_low_command_topic': 'omnilink/thermostat1/temperature_heat_command', 'temperature_high_state_topic': 'omnilink/thermostat1/temperature_cool_state', 'temperature_high_command_topic': 'omnilink/thermostat1/temperature_cool_command', 'min_temp': '45', 'max_temp': '95', 'mode_state_topic': 'omnilink/thermostat1/mode_state', 'mode_command_topic': 'omnilink/thermostat1/mode_command', 'modes': ['auto', 'off', 'cool', 'heat'], 'fan_mode_state_topic': 'omnilink/thermostat1/fan_mode_state', 'fan_mode_command_topic': 'omnilink/thermostat1/fan_mode_command', 'fan_modes': ['auto', 'on', 'cycle'], 'hold_state_topic': 'omnilink/thermostat1/hold_state', 'hold_command_topic': 'omnilink/thermostat1/hold_command', 'name': 'Lower Tstat', 'state_topic': None, 'availability_topic': 'omnilink/status', 'platform': 'mqtt'},) Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/climate.py", line 244, in async_discover config = PLATFORM_SCHEMA(discovery_payload) File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 272, in call return self._compiled([], data) File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 594, in validate_dict return base_validate(path, iteritems(data), out) File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 432, in validate_mapping raise er.MultipleInvalid(errors) voluptuous.error.MultipleInvalid: extra keys not allowed @ data['state_topic']

2019-08-31 09:41:54 ERROR (MainThread) [homeassistant.components.mqtt.climate] Exception in async_discover when dispatching 'mqtt_discovery_new_climate_mqtt': ({'current_temperature_topic': 'omnilink/thermostat2/current_temperature', 'temperature_low_state_topic': 'omnilink/thermostat2/temperature_heat_state', 'temperature_low_command_topic': 'omnilink/thermostat2/temperature_heat_command', 'temperature_high_state_topic': 'omnilink/thermostat2/temperature_cool_state', 'temperature_high_command_topic': 'omnilink/thermostat2/temperature_cool_command', 'min_temp': '45', 'max_temp': '95', 'mode_state_topic': 'omnilink/thermostat2/mode_state', 'mode_command_topic': 'omnilink/thermostat2/mode_command', 'modes': ['auto', 'off', 'cool', 'heat'], 'fan_mode_state_topic': 'omnilink/thermostat2/fan_mode_state', 'fan_mode_command_topic': 'omnilink/thermostat2/fan_mode_command', 'fan_modes': ['auto', 'on', 'cycle'], 'hold_state_topic': 'omnilink/thermostat2/hold_state', 'hold_command_topic': 'omnilink/thermostat2/hold_command', 'name': 'Upper Tstat', 'state_topic': None, 'availability_topic': 'omnilink/status', 'platform': 'mqtt'},) Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/mqtt/climate.py", line 244, in async_discover config = PLATFORM_SCHEMA(discovery_payload) File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 272, in call return self._compiled([], data) File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 594, in validate_dict return base_validate(path, iteritems(data), out) File "/usr/local/lib/python3.7/site-packages/voluptuous/schema_builder.py", line 432, in validate_mapping raise er.MultipleInvalid(errors) voluptuous.error.MultipleInvalid: extra keys not allowed @ data['state_topic']

2019-08-31 09:42:00 WARNING (MainThread) [homeassistant.setup] Setup of lutron is taking over 10 seconds. 2019-08-31 09:42:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity raise HomeAssistantError(msg) 2019-08-31 09:42:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity raise HomeAssistantError(msg) 2019-08-31 09:42:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity raise HomeAssistantError(msg) 2019-08-31 09:42:17 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 399, in _async_add_entity raise HomeAssistantError(msg) 2019-08-31 09:42:22 WARNING (MainThread) [homeassistant.components.template.sensor] Could not render template Family Room, the state is unknown. 2019-08-31 09:42:22 WARNING (MainThread) [homeassistant.components.template.sensor] Could not render template Master Bedroom, the state is unknown.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWQQSWO7EGNU5ZKS2VLQHJ2JBA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5TNIWI#issuecomment-526832729, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWXDYKFQGEMPWGALMKLQHJ2JBANCNFSM4GR2ZVYA .

[grantalewis]

FYI I just noticed that the problem is occurring again. These are the log entries since my earlier post:

2019-08-31 11:21:18 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140373725576208] Client exceeded max pending messages [2]: 512
2019-08-31 13:21:12 WARNING (MainThread) [homeassistant.components.http.ban] Login attempt or request with invalid authentication from 71.81.123.246
2019-08-31 13:56:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140373720430928] Client exceeded max pending messages [2]: 512
2019-08-31 14:27:05 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_protocol.py", line 418, in start
    resp = await task
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_app.py", line 458, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_middlewares.py", line 119, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/real_ip.py", line 40, in real_ip_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 73, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 231, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 128, in handle
    result = await result
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 37, in get
    return await WebSocketHandler(request.app["hass"], request).async_handle()
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 199, in async_handle
    await self._writer_task
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 66, in _writer
    await self.wsock.send_json(message, dumps=JSON_DUMP)
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_ws.py", line 296, in send_json
    await self.send_str(dumps(data), compress=compress)
  File "/usr/local/lib/python3.7/site-packages/aiohttp/web_ws.py", line 283, in send_str
    await self._writer.send(data, binary=False, compress=compress)
  File "/usr/local/lib/python3.7/site-packages/aiohttp/http_websocket.py", line 643, in send
    await self._send_frame(message, WSMsgType.TEXT, compress)
  File "/usr/local/lib/python3.7/site-packages/aiohttp/http_websocket.py", line 620, in _send_frame
    await self.protocol._drain_helper()
  File "/usr/local/lib/python3.7/site-packages/aiohttp/base_protocol.py", line 81, in _drain_helper
    await waiter
  File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 883, in _write_ready
    n = self._sock.send(self._buffer)
BrokenPipeError: [Errno 32] Broken pipe

[cdheiser]

Hah... These are all error or warnings. Can you set the default logging level to info?

On Sat, Aug 31, 2019, 1:04 PM grantalewis notifications@github.com wrote:

FYI I just noticed that the problem is occurring again. These are the log entries since my earlier post:

2019-08-31 11:21:18 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140373725576208] Client exceeded max pending messages [2]: 512 2019-08-31 13:21:12 WARNING (MainThread) [homeassistant.components.http.ban] Login attempt or request with invalid authentication from 71.81.123.246 2019-08-31 13:56:15 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140373720430928] Client exceeded max pending messages [2]: 512 2019-08-31 14:27:05 ERROR (MainThread) [aiohttp.server] Error handling request Traceback (most recent call last): File "/usr/local/lib/python3.7/site-packages/aiohttp/web_protocol.py", line 418, in start resp = await task File "/usr/local/lib/python3.7/site-packages/aiohttp/web_app.py", line 458, in _handle resp = await handler(request) File "/usr/local/lib/python3.7/site-packages/aiohttp/web_middlewares.py", line 119, in impl return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/real_ip.py", line 40, in real_ip_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 73, in ban_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 231, in auth_middleware return await handler(request) File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 128, in handle result = await result File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 37, in get return await WebSocketHandler(request.app["hass"], request).async_handle() File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 199, in async_handle await self._writer_task File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 66, in _writer await self.wsock.send_json(message, dumps=JSON_DUMP) File "/usr/local/lib/python3.7/site-packages/aiohttp/web_ws.py", line 296, in send_json await self.send_str(dumps(data), compress=compress) File "/usr/local/lib/python3.7/site-packages/aiohttp/web_ws.py", line 283, in send_str await self._writer.send(data, binary=False, compress=compress) File "/usr/local/lib/python3.7/site-packages/aiohttp/http_websocket.py", line 643, in send await self._send_frame(message, WSMsgType.TEXT, compress) File "/usr/local/lib/python3.7/site-packages/aiohttp/http_websocket.py", line 620, in _send_frame await self.protocol._drain_helper() File "/usr/local/lib/python3.7/site-packages/aiohttp/base_protocol.py", line 81, in _drain_helper await waiter File "/usr/local/lib/python3.7/asyncio/selector_events.py", line 883, in _write_ready n = self._sock.send(self._buffer) BrokenPipeError: [Errno 32] Broken pipe

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWUIZ5KW42UWD3WWQHDQHLFFLA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5TUJIA#issuecomment-526861472, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWXJH3ARTVNBGBJEL2LQHLFFLANCNFSM4GR2ZVYA .

[thecynic]

I'm gonna look at this stuff later today too. The on/off vs dim is suspicious, and I think it's related to how the events get sequenced (like first we get an on event and then a brightness state). It may be interacting funky with the fact that hass doesn't have a separate on/off vs brightness for dimmable devices.

[thecynic]

@grantalewis Ok I found some funky interactions between doing various things with on/off and brightness, which kind of hinted in your logs. Note that I'm not blaming omni at all, but I am finding a funky interaction between on/off and brightness, and your logs pointed me to it. I saw your more recent update, so with omni completely disconnected from homeassistant, you still see issues? But you said you still get entities from omni updated... I'd love to understand if you ever see the problem if you have HASS stop talking to omni regarding lights completely. I wasn't sure if that's what you tried.

I'm pretty sure I found an issue, but not quite yet sure how to fix it and whether or not it's the cause. I'm pretty sure there's a bug in the way we manage prev_brightness and how it interacts with caching levels for off. @grantalewis I'm going to make a patch for you to try to log extra crap and see if we can catch something.

Now, I can't make things break un-recoverably, but I think that's because I'm not trying too hard.
For instance, the front end doesn't know how to disambiguate between brightness = 0 and off. So, you can send an "on" command with brightness 0 and the frontend will still show off. This is what happens when omni sends (via mqtt) an "on" event when it sees light turn on (when it itself sees the lutron transitions on its own connection).

Some command line I've been playing with.

>>> url_base = "http://localhost:8123"
>>> url = '%s/api/services/light/turn_on' % url_base
>>> service_data='{"entity_id": "light.foyer_foyer_downlights", "brightness": "0"}'
>>> print(post(url=url, headers=headers, data=service_data).text)
[]

[cdheiser]

@grantalewis download from dropbox again. I've tweaked the custom component a little

And also add to your config:

logger: default: info

[thecynic]

@grantalewis try this tree: https://github.com/thecynic/home-assistant/tree/dev-debug-lutron It's pretty verbose, but hopefully can give me some hints.

I know @cdheiser and I both have things for you to try, so I'm sorry to pile on.

When the issue does happen, it would be good to mention time when you noticed the problem (i.e. when it stopped working, so I can find it in log), and also an approximate time when you think it last worked.

My logger config is as follows (that I'd like to see from you):

logger:         
    default: info
    logs: 
       homeassistant.core: debug
       homeassistant.components.light: debug
       homeassistant.components.lutron.light: debug
       pylutron: debug

[grantalewis]

Sorry -- was out yesterday afternoon and evening. I'll be able to troubleshoot more today.

I'd love to understand if you ever see the problem if you have HASS stop talking to omni regarding lights completely. I wasn't sure if that's what you tried.

It's a good suggestion to experiment with the OmniLinkBridge component disabled. I'll do that, and that will break communication between the Omni and HA (via MQTT), but keep in mind that as system is a kind of two-headed beast, Lutron will still be communicating to the Omni. I can't disable that or my whole house would be unusable. Just FYI.

I'll download the new custom component from @cdheiser and will use the more complete logger config as suggested by @thecynic.

try this tree: https://github.com/thecynic/home-assistant/tree/dev-debug-lutron It's pretty verbose, but hopefully can give me some hints. <

Apologies but I'll need more explanation as to what you're after here.

it would be good to mention time when you noticed the problem (i.e. when it stopped working, so I can find it in log), and also an approximate time when you think it last worked. <

I always post logs as soon as I see the problem, so whatever time entries are in those logs are reliable. For instance, I saw the problem in my prior post at 2019-08-31 14:27:05.

Thanks for your continued efforts. I'll post again when I have more info.

[grantalewis]

Question: I'm seeing entries like this in the log: 2019-09-01 07:47:58 INFO (MainThread) [homeassistant.components.mqtt.discovery] Found new component: sensor omnilink zone13

I believe that's due to retained MQTT information. Do you want me to clear that out?

[grantalewis]

OK, it just happened, and so I immediately pulled the logs.

The first entity I saw exhibit the problem was light.family_room_family_fan, this entry in the log: 2019-09-01 11:16:25 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.family_room_family_fan>

Next I tried turning on light.main_stairs_main_hall, this entry in the log: 2019-09-01 11:16:46 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.main_stairs_main_hall>

Full log is attached. home-assistant.log.zip

[cdheiser]

There are no obvious errors or exceptions being thrown. I've upped some of the debug logging in pylutron to see what it says, as I can see in the home assistant module that it's trying to turn on the fam and the main hall.

So if you can pull the tar.gz again and update.

Also, it's curious that your fan is a light and not a switch. I'm guessing this is a fan switch that has speed control?

On Sun, Sep 1, 2019 at 8:33 AM grantalewis notifications@github.com wrote:

OK, it just happened, and so I immediately pulled the logs.

The first entity I saw exhibit the problem was light.family_room_family_fan, this entry in the log: 2019-09-01 11:16:25 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.family_room_family_fan>

Next I tried turning on light.main_stairs_main_hall, this entry in the log: 2019-09-01 11:16:46 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.main_stairs_main_hall>

Full log is attached. home-assistant.log.zip https://github.com/home-assistant/home-assistant/files/3563652/home-assistant.log.zip

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWRVITTJQPYQUFPGW2LQHPOCXA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5UEWGI#issuecomment-526928665, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWRQZUQRV437TNDTDFLQHPOCXANCNFSM4GR2ZVYA .

[thecynic]

Sorry -- was out yesterday afternoon and evening. I'll be able to troubleshoot more today.

I'd love to understand if you ever see the problem if you have HASS stop talking to omni regarding lights completely. I wasn't sure if that's what you tried.

It's a good suggestion to experiment with the OmniLinkBridge component disabled. I'll do that, and that will break communication between the Omni and HA (via MQTT), but keep in mind that as system is a kind of two-headed beast, Lutron will still be communicating to the Omni. I can't disable that or my whole house would be unusable. Just FYI.

No no, I just meant have it not interact with HASS. You can keep it interacting with lutron, that should be fine since that will look to hass as if lutron is turning things on and off via light switches. But that's a separate debugging step. If issues go away with this step, we'll know its some funky interaction, but the bug must still be in the lutron component somewhere so we'll want to still debug with it integrated the way it is now.

I'll download the new custom component from @cdheiser and will use the more complete logger config as suggested by @thecynic.

Your log you posted didn't have the logs I would have expected if logging was turned on the way I proposed :(

try this tree: https://github.com/thecynic/home-assistant/tree/dev-debug-lutron It's pretty verbose, but hopefully can give me some hints. <

Apologies but I'll need more explanation as to what you're after here.

Sorry, should have been more clear. I'd like you to sync and run my tree instead of just dev. Do you currently run things out of git, with a tag? Or do you download a package somewhere?

If you run out of a git tree, I can give you quick instructions on how to add a new remote and pull my tree, if you don't already know how to do that.

But basically, @cdheiser and I are roughly requesting the same things as we are just instrumenting the lutron light component in hopes of getting some hints. We are juts going about it in different ways. @cdheiser is asking you to use a custom component, I'm just patching the existing component. @cdheiser maybe we can combine forces? If @grantalewis is not a git user, maybe you can grab my version of the extra logging to wrap into your custom component?

it would be good to mention time when you noticed the problem (i.e. when it stopped working, so I can find it in log), and also an approximate time when you think it last worked. <

I always post logs as soon as I see the problem, so whatever time entries are in those logs are reliable. For instance, I saw the problem in my prior post at 2019-08-31 14:27:05.

Perfect!

Thanks for your continued efforts. I'll post again when I have more info.

Thanks for being the guinea pig :)

[grantalewis]

Also, it's curious that your fan is a light and not a switch. I'm guessing this is a fan switch that has speed control?

Yes, that's right.

[grantalewis]

Sorry, should have been more clear. I'd like you to sync and run my tree instead of just dev. Do you currently run things out of git, with a tag? Or do you download a package somewhere?

If you run out of a git tree, I can give you quick instructions on how to add a new remote and pull my tree, if you don't already know how to do that.

Oh man, you are so far over my head...! I'm running Hass.io on Virtual Box (Ubuntu 64). Afraid I'm going to need some hand-holding on the whole "sync and run my tree instead of just dev" maneuver.

That I'm running a virtual install might make things easier as I can just create another to experiment.

[grantalewis]

Your log you posted didn't have the logs I would have expected if logging was turned on the way I proposed :(

Here's the relevant portion of my configuration.yaml:

logger:         
    default: info
    logs: 
       homeassistant.core: debug
       homeassistant.components.light: debug
       homeassistant.components.lutron.light: debug
       pylutron: debug

[grantalewis]

Question: I'm seeing entries like this in the log: 2019-09-01 07:47:58 INFO (MainThread) [homeassistant.components.mqtt.discovery] Found new component: sensor omnilink zone13

I believe that's due to retained MQTT information. Do you want me to clear that out?

FYI I'm still seeing entities associated with OmniLinkBridge both in the log (list of omni-only entries attached) and in the UI. For instance, these door sensors are all Omni entries:

Normally if the Bridge goes down, those either show in yellow or, after a period of time, disappear from the UI entirely. So I'm still wondering should I should try to eliminate those? omni_log_entries.txt.zip

[grantalewis]

I'm upgrading to 0.98.2 and have downloaded/updated the custom lutron component, @cdheiser. I'm still using that scaled-back configuration posted above. I'll watch things for a while and will report back.

[JonGilmore]

Normally if the Bridge goes down, those either show in yellow or, after a period of time, disappear from the UI entirely. So I'm still wondering should I should try to eliminate those?

I don't know this for sure, but it sounds like those mqtt messages are marked with retain = true. That would make it such that when you reboot, and even though the integration isnt running, it'd still get the last messages from mqtt. Probably nothing to worry about, but if you want to be sure, you can download something like mqtt explorer and remove all those old topics.

[grantalewis]

I have MQTT explorer and have enough working knowledge of how to do that. Those entities will all come back when I re-enable the bridge, right? (Don’t want to wreck anything irrevocably.)

[JonGilmore]

I have MQTT explorer and have enough working knowledge of how to do that. Those entities will all come back when I re-enable the bridge, right? (Don’t want to wreck anything irrevocably.)

yeah - but you should double check that they're marked with retain before removing them. If they are, you should remove them, then restart home assistant, then you shouldn't see the last updated status.

[grantalewis]

@JonGilmore thanks. I've removed all of the retained MQTT info and and restarted. I'm now seeing "Unavailable" next to all of those Omni entities. 👌🏼

[grantalewis]

Didn't have to wait long for the problem to occur again at 09:33. Look for these entities / log entries:

light.family_room_family_recessed 2019-09-02 09:33:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.family_room_family_recessed>

light.dining_room_dining_pendant 2019-09-02 09:33:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.dining_room_dining_pendant>

home-assistant.log.zip

As before, UI entities toggle themselves back to OFF while the light stays on. Commands sent from Services work as they should.

[cdheiser]

Well this is not what I expected... There are no exceptions. As far as pylutron is concerned, it's sending the commands to your lutron bridge:

2019-09-02 09:33:33 INFO (SyncWorker_9) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,37,1,50.00

On Mon, Sep 2, 2019 at 6:59 AM grantalewis notifications@github.com wrote:

Didn't have to wait long for the problem to occur again at 09:33. Look for these entities / log entries:

light.family_room_family_recessed 2019-09-02 09:33:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.family_room_family_recessed>

light.dining_room_dining_pendant 2019-09-02 09:33:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.dining_room_dining_pendant>

home-assistant.log.zip https://github.com/home-assistant/home-assistant/files/3566290/home-assistant.log.zip

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/20348?email_source=notifications&email_token=ACQARWV5GXWXLBCSY6DHY2TQHUL4TA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5V4WUY#issuecomment-527158099, or mute the thread https://github.com/notifications/unsubscribe-auth/ACQARWVRIZH5PKM46L52NODQHUL4TANCNFSM4GR2ZVYA .

[grantalewis]

Not sure this will shed any light, but here's a step-by-step of what I was doing for these log entries:

(Earlier, probably before problem begins) 2019-09-02 09:09:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.family_room_family_recessed, old_state=None, new_state=<state light.family_room_family_recessed=off; lutron_integration_id=25, friendly_name=Family Room Recessed, supported_features=1 @ 2019-09-02T09:09:35.191745-04:00>>

2019-09-02 09:09:36 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.dining_room_dining_pendant, old_state=None, new_state=<state light.dining_room_dining_pendant=off; lutron_integration_id=37, friendly_name=Dining Room Pendant, supported_features=1 @ 2019-09-02T09:09:36.396001-04:00>>

First attempt to operate light.family_room_family_recessed via the UI toggle: 2019-09-02 09:33:21 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.family_room_family_recessed>

2019-09-02 09:33:21 INFO (SyncWorker_3) [custom_components.lutron.light] Turining on of Family Room Family Recessed

2019-09-02 09:33:21 INFO (SyncWorker_3) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,25,1,50.00

Seeing the toggle for that entry returning to OFF, attempt to operate light.dining_room_dining_pendant via the UI toggle: 2019-09-02 09:33:33 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.dining_room_dining_pendant>

2019-09-02 09:33:33 INFO (SyncWorker_9) [custom_components.lutron.light] Turining on of Dining Room Dining Pendant

2019-09-02 09:33:33 INFO (SyncWorker_9) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,37,1,50.00

Test to see if entities will turn off via Services (successful): 2019-09-02 09:41:12 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.family_room_family_recessed>

2019-09-02 09:41:12 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.family_room_family_recessed']>

2019-09-02 09:41:12 INFO (SyncWorker_4) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,25,1,0.00

2019-09-02 09:41:24 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.dining_room_dining_pendant>

2019-09-02 09:41:24 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.dining_room_dining_pendant']>

2019-09-02 09:41:24 INFO (SyncWorker_7) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,37,1,0.00

Repeat the process from the UI: Turn the entities ON, notice that they return to OFF: 2019-09-02 09:41:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.dining_room_dining_pendant>

2019-09-02 09:41:41 INFO (SyncWorker_5) [custom_components.lutron.light] Turining on of Dining Room Dining Pendant

2019-09-02 09:41:41 INFO (SyncWorker_5) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,37,1,50.00

2019-09-02 09:41:53 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.family_room_family_recessed>

2019-09-02 09:41:53 INFO (SyncWorker_4) [custom_components.lutron.light] Turining on of Family Room Family Recessed

2019-09-02 09:41:53 INFO (SyncWorker_4) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,25,1,50.00

Test to see if entities will turn off via Services (successful): 2019-09-02 09:42:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.dining_room_dining_pendant>

2019-09-02 09:42:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.dining_room_dining_pendant']>

2019-09-02 09:42:14 INFO (SyncWorker_6) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,37,1,0.00

2019-09-02 09:42:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.family_room_family_recessed>

2019-09-02 09:42:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.family_room_family_recessed']>

2019-09-02 09:42:23 INFO (SyncWorker_0) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,25,1,0.00

[grantalewis]

Is it relevant that each successful attempt via Services results in two log entries? For example:

2019-09-02 09:42:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_off, service_data=entity_id=light.dining_room_dining_pendant>

2019-09-02 09:42:14 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_off, service_data=entity_id=['light.dining_room_dining_pendant']>

[thecynic]

@grantalewis sorry for the confusing requests with the code tree, I wasn't sure what kind of installation you have. @cdheiser already sorted out the best way for you to run custom code :). I'm wondering if we can just drop in my copy of light.py (https://github.com/thecynic/home-assistant/blob/dev-debug-lutron/homeassistant/components/lutron/light.py) into your custom_components/lutron/light.py. @cdheiser thoughts?

@grantalewis Ok, thanks for the logs, this is super useful. Though you are sending commands as @cdheiser noted, you stop receiving updates into home assistant from pylutron (since debug logging still isn't on in pylutron, I can't see what it's doing.. see below for recommendation). Note that we only update internal lutron component HASS state after we receive update from the main repeater. Setting the system to ON doesn't actually update the internal state of the light until after we receive a status update from lutron saying the light is on. This allows us to always be synchronized to the state of the lutron system itself, so that we don't get into weird oscillating cycles between hass and lutron when they disagree slightly (or can't keep up with rapid state changes, i.e. the dimmer slider test). This exactly explains your symptoms: you can use service calls to control the entity (since commands get sent out), but the internal home assistant state fails to get updated.

(On a side note, what happens to the omni entities? Do they accurately reflect the correct state? And do omni updates eventually end up updating the lutron entities? Or are they entirely independent?)

For example, normally, you should be seeing events into homassistant.core when your light changes state, like so:

2019-09-02 09:14:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event 
call_service[L]: domain=mqtt, service=publish, 
service_data=topic=cmnd/sonoff_basic_04/power, qos=1, retain=True, payload=OFF>
2019-09-02 09:14:55 INFO (SyncWorker_2) [custom_components.lutron.cdhlutron] Sending: 
#OUTPUT,63,1,0.00
2019-09-02 09:14:55 INFO (Thread-2) [custom_components.lutron] Update callback for Family 
Room Holiday Lights
2019-09-02 09:14:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event 
state_changed[L]: entity_id=switch.family_room_holiday_lights, old_state=<state 
switch.family_room_holiday_lights=on; lutron_integration_id=63, friendly_name=Family Room 
Holiday, icon=mdi:snowflake @ 2019-09-02T09:09:38.801997-04:00>, new_state=<state 
switch.family_room_holiday_lights=off; lutron_integration_id=63, friendly_name=Family Room 
Holiday, icon=mdi:snowflake @ 2019-09-02T09:14:55.472425-04:00>>

As mentioner above, I'm still not seeing debug code from pylutron directly :( Weird. Looks like cdhlutron is used instead of pylutron? @cdheiser please confirm. If so, maybe try adding this clause to your logger config as well:

custom_components.lutron.cdhlutron: debug

or maybe

homeassistant.custom_components.lutron.cdhlutron: debug

not sure how the logger module namespaces these :) Try both :smiley:

Another interesting bit is that this log entry happens to be the last time you got an update from pylutron for lights so the timing there should be interesting to explore.

2019-09-02 09:30:58 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event 
state_changed[L]: entity_id=light.family_room_family_fan, old_state=<state 
light.family_room_family_fan=on; brightness=191, lutron_integration_id=26, friendly_name=Family 
Room Fan, supported_features=1, icon=mdi:fan @ 2019-09-02T09:09:38.294765-04:00>, 
new_state=<state light.family_room_family_fan=off; lutron_integration_id=26, 
friendly_name=Family Room Fan, supported_features=1, icon=mdi:fan @ 2019-09- 
02T09:30:58.990274-04:00>>

This doesn't seem like bad state inside the pylutron itself. The only thing that can cause these symptoms in pylutron is if the receive poller thread died or locked up. I don't see any exceptions related to this in the logs at all, and it never seems to die with the lock held which would lock up the send side as well. I'll really need proper debugging enabled in pylutron (cdhlutron in your case) to confirm.

[thecynic]

@grantalewis we should get on discord and do a live debug session at some point hehe

[grantalewis]

Certainly willing. And today would be a good day being a holiday.

[thecynic]

@grantalewis Great! Though, I can't for a few hours as got some family stuff to do, but let's hook up later in the day :smile:

Also, I've pushed version 0.2.4 to pypi which has my better disconnect detect code that's much more robust than what's there previously. I'll send an PR to home-assistant for the version bump.

[grantalewis]

I’m busy for the next hour or two myself, so no prob.

[grantalewis]

(On a side note, what happens to the omni entities? Do they accurately reflect the correct state? And do omni updates eventually end up updating the lutron entities? Or are they entirely independent?)

Yes, Omni entities accurately reflect whatever the Lutron entities are doing and vice-versa. That's by virtue of whatever "native" conversation those two controllers are having -- not by virtue of OmniLinkBridge. OLB is only there to make Omni entities accessible via MQTT to HA that would otherwise be inaccessible. (Not trying to run that point into the ground -- just wanting to be clear.)