Core: 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]

Still occurring in 0.86.1

ERROR (MainThread) [homeassistant.core] 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')
AttributeError: 'NoneType' object has no attribute 'write'

[cdheiser]

This sounds like https://github.com/thecynic/pylutron/issues/17

[cdheiser]

I've created https://github.com/thecynic/pylutron/pull/23 to patch the pylutron library and hopefully resolve this bug. Once that patch is accepted, we still need to wait for a new version to get published and update home-assistant to use the new version.

[grantalewis]

Still seeing this in 0.87.1

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 289, 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')
AttributeError: 'NoneType' object has no attribute 'write'

(Apologies if my attempts to get this noticed are in the wrong place. I'm surprised this isn't getting much uptake. Is no one else is seeing this problem?)

[JonGilmore]

I'll not seeing this error. Can you describe the behavior in more detail? Does it work at all? Does it stop working?

[grantalewis]

I'll not seeing this error. Can you describe the behavior in more detail? Does it work at all? Does it stop working?

After rebooting things seem to be OK for a short period of time -- maybe as much as 30 minutes. Then on/off commands from Hass.io start failing. There's a second or two of hesitation when clicking a light toggle, no result, and then the toggle returns to its prior position. Checking the logs shows the above error.

[cdheiser]

Do you reprogram or make other changes to your RadioRA setup at all? I've only experienced the behavior you describe when updating the programming in the main repeater, or otherwise suffer some odd network problem.

I know it's annoying, and I'd love to get this fixed, but right now it's at the mercy of the pylutron maintainer. We could consider forking the library, or asking the maintainer if they would consider adding additional people to accept/reject pull requests.

[grantalewis]

@cdheiser I really do appreciate the feedback and willingness to help. Yes, I make changes to my setup fairly frequently, but before now it seemed that cold-restarting everything usually resolved any issues. This problem does seem different.

Yesterday I did a completely new setup of HA 0.87.1 on a newly formatted SD card. It ran well for a few hours, but by bedtime, toggling lights was beginning to flake out again. Then by this morning the toggles were completely unresponsive. Slightly different symptom: the toggle would stay in the ON position, but the Lutron entity was unaffected.

The logs show this familiar info:

2019-02-17 06:53:07 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.1875282512] Error handling message: {'type': 'call_service', 'domain': 'light', 'service': 'turn_on', 'service_data': {'entity_id': 'light.main_stairs_main_hall'}, 'id': 16}
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/websocket_api/decorators.py", line 17, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/websocket_api/commands.py", line 148, in handle_call_service
    connection.context(msg))
  File "/usr/local/lib/python3.6/site-packages/homeassistant/core.py", line 1130, in async_call
    self._execute_service(handler, service_call))
  File "/usr/local/lib/python3.6/site-packages/homeassistant/core.py", line 1152, in _execute_service
    await handler.func(service_call)
  File "/usr/local/lib/python3.6/site-packages/homeassistant/components/light/__init__.py", line 287, in async_handle_light_on_service
    await light.async_turn_on(**pars)
  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 69, in turn_on
    self._lutron_device.level = to_lutron_level(brightness)
  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

I'll just revert to 0.84.6 and wait it out. That version is pretty much rock-solid for me.

Again, my thanks.

[ToddNJ]

I had this same problem. Works for me in 0.86.4, failed when I updated to 0.88.1, I rolled back.
I'm running HASS.IO in docker on Ubuntu 18.0.4 on a Laptop.
Lutron Bridge is model L-BDG2

Error Log Entry:

2019-02-27 20:02:14 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/homeassistant/helpers/service.py", line 289, in _handle_service_platform_call
    await getattr(entity, func)(**data)
  File "/usr/local/lib/python3.7/site-packages/homeassistant/components/lutron_caseta/switch.py", line 33, in async_turn_on
    self._smartbridge.turn_on(self._device_id)
  File "/usr/local/lib/python3.7/site-packages/pylutron_caseta/smartbridge.py", line 190, in turn_on
    return self.set_value(device_id, 100)
  File "/usr/local/lib/python3.7/site-packages/pylutron_caseta/smartbridge.py", line 182, in set_value
    return self._writer.write(cmd)
AttributeError: 'NoneType' object has no attribute 'write'

[stale[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[grantalewis]

This is still an unresolved issue in 95.4.

[JonGilmore]

@ToddNJ your issue looks different than this one, appears your using caseta? @grantalewis is using RadioRa2, and a different library altogether. I'd suggest you open another issue for yours.

@grantalewis can you describe your setup a bit? I'm afraid the troubleshooting that @cdheiser is doing _may possibly_ provide a workaround for your issue, but I don't think it addresses the root cause: why is your HASS instance losing connection to your Ra2 main receiver?

I believe we've chatted about this before on Reddit, but I'll add that my RadioRa2 install is working well with the latest home assistant release (still), so I think we need to diagnose the why.

[grantalewis]

The core of my system is OmniPro II / Lutron RadioRA2. Nearly all of my light and fan controls are Lutron. I got my start with Home Assistant in 2017 (v0.7x-ish). I started on Hasbian, moved to Hass.io, and then have gone back/forth a couple of times since. I enjoyed a very smooth HA experience until January, 2019 with v0.85x at which time I had to revert to 0.84.6. I've been stuck on that version since January. (Despite its increasing age and ever-growing list of missing features, 0.84.6 still performs really well for me.)

I needed an environment that would let me experiment more and so moved Hass.io to VirtualBox earlier this year (Ubuntu 64). That didn't provide me with a solution to my Lutron problem, but it at least gave me a way to test new versions while still having an easy road back to my stable 0.84.6.

I also keep an RPi3 updated with the latest HA release in case a solution suddenly becomes available. (I hope to eventually be able to use Hass.io on RPi3 as my day-to-day system.)

I've tried literally every release since 0.84.6, and they all exhibit exactly the same issue. After rebooting, the system seems to be fine for the first hour or two and then I'll notice that the UI begins losing the ability to control entities. This video demonstrates the problem ( <-- Dropbox link to MP4 video). When the issue begins happening, I can control an entity 1 more time using its toggle. The entity will reflect the change, but the toggle will revert to its prior state as if somehow indicating that the change was unsuccessful. At that point, the entity will not respond to any additional changes from the UI. The only way to regain control is to reboot.

Sorry if this is long-winded but I didn't want to leave anything out. I'm happy to help in any way I'm able, so please feel free to call on me for testing, more information, etc.

[JonGilmore]

Thats a good explanation, I appreciate it. The video helps me understand the behavior, which is different than I was understanding from your previous stuff in writing. Going to continue our convo on discord to keep this issue clean, if we come up with anything, we can post it here.

[Tangston311]

I’m glad I found this because I’m experiencing exactly the same issue with HA and Ra2. At first everything seems to work just fine, but after an hour or so I experience the exact behavior seen in the video. My automations and service calls seems to still work just fine, but controlling through the front end becomes unusable.

Happy to do what I can to provide more info to help troubleshoot.

I’m on 93.1 using Hass.io.

[thecynic]

@Tangston311 Interesting. So in your case the actual communication with the lutron controller itself is not affected? Just that frontend gets out of sync? If it's the latter than I'll need some help from someone who's more higher-level stack in HASS oriented to help figuring that part out.

@grantalewis Do you happen to have logs for when this happens? I'd also be curious to see if manual service calls work fine as well. Would be good to identify where in the stack the issue is creeping in.

[thecynic]

@grantalewis Oh I see the stacks above. Ok, yes, my pylutron PR should help with that. The connection management previously was very optimistic with respect to how well things remain connected, and thus was not really robust. I wonder if your network is somewhat flaky. Maybe you have things on wifi and they drop, etc? Doesn't really matter, just curious as to why you see it so much more often.

[grantalewis]

@thecynic, @JonGilmore suggested debug logging via Discord DM, so I'll do that. Going with

logger:
   default: debug

for now but let me know if you want other options enabled, etc.

It seems that @Tangston311 and I are seeing the exact same symptoms. UI misbehaves but entities still respond to homeassistant.toggle, homeassistant.turn_on, homeassistant.turn_off, etc. via the Services panel.

Network: I suppose it could be network-related, but that doesn't account for rock-solid performance from 0.84.6. It's like night and day: fantastic performance with 0.84.6 and before; completely predictable failure with every version since.

[Tangston311]

@thecynic , @grantalewis is correct, I think we're both experiencing the same behavior. I have a few automatons that work by simply turning things on or off (regardless of current state) with "turn_on" or "turn_off" service calls, but controlling through the UI becomes inoperable. Additionally, when this happens, HA no longer knows the current state of a light, so if I attempt to create an automation based on the current state of an entity it won't work because it thinks the light is currently off when it's actually on, or vice versa.

Network issues could definitely be a factor for me: I noticed that sometimes the Ra2 Inclusive software couldn't find the main repeater, so I tried relocated the main repeater to a different location. Now the Ra2 software can always find the main repeater, and I noticed this lengthened the period of time that the HA UI would function: it went from bombing out after ~30 minutes to lasting most of the day, but inevitably it still exhibits the same behavior. I can't explain why because the main repeater was hard-wired in both locations, but it does point to some network instability that may be causing the issue.

[grantalewis]

I don't mean to be stubborn, but unless 0.84.6 is just more tolerant of borderline network issues, I just don't think it's network related. I have no problems with 0.84.6 whatsoever -- not one, not ever.

[grantalewis]

OK, let 0.97.2 run for a while today. As soon as I saw the problem occur, I grabbed the logs from 3 or so minutes prior. I deleted a lot of log entries that I'm fairly certain are not involved in the issue. The .txt file is attached. Thanks for taking a look.

log.txt

[JonGilmore]

OK, let 0.97.2 run for a while today. As soon as I saw the problem occur, I grabbed the logs from 3 or so minutes prior. I deleted a lot of log entries that I'm fairly certain are not involved in the issue. The .txt file is attached. Thanks for taking a look.

Hm, this log doesn't include the "normal" stack trace. I'm curious, did it show up again this time? I'll go through it just in case, but I'm not sure this capture is going to be much help.

[grantalewis]

In my configuration.yaml:

logger:
   default: debug

As soon as I saw the problem occur I grabbed the logs from the prior 3 minutes. Maybe I need to back up further?

[thecynic]

@grantalewis You aren't being stubborn :) I wanted to confirm whether or not we were losing communication with the lutron main repeater or if the issue is somewhere in HASS. Given that you can continue to change state via the API/service calls, it means that the underlying comms are good and the issue is in the HASS integration somewhere (either in HASS or in the callback mechanisms from pylutron)

@Tangston311 trying to reconcile your answer with @grantalewis... hmm

[cdheiser]

I was hoping to see an exception thrown, and thus we could blame some
failure for killing a thread.

On Fri, Aug 16, 2019 at 10:12 AM thecynic [e-mail] wrote:

@grantalewis https://github.com/grantalewis You aren't being stubborn
:) I wanted to confirm whether or not we were losing communication with the
lutron main repeater or if the issue is somewhere in HASS. Given that you
can continue to change state via the API/service calls, it means that the
underlying comms are good and the issue is in the HASS integration
somewhere (either in HASS or in the callback mechanisms from pylutron)

—
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=ACQARWWO5TUQORHLTUATENLQE3NYHA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD4PFWSY#issuecomment-522083147,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWWYRCMQHN4DDSMOD63QE3NYHANCNFSM4GR2ZVYA
.

[grantalewis]

I’m going to give it another go later on this afternoon. Maybe in an effort to get rid of extraneous login entries I deleted something important.

[Tangston311]

@thecynic , it's admittedly strange. This most recent iteration the lights worked for almost exactly 24 hours before the issue appeared again. I tried setting my logger to "debug", but after a few hours the log was so big that HA kept crashing when I tried to load it. So instead I tried to set my logger as follows to only get stuff related to Lutron:

```
logger:
default: error
logs:
homeassistant.components.lutron: debug
homeassistant.components.lutron.light: debug
homeassistant.components.lutron.switch: debug
homeassistant.components.lutron.cover: debug
homeassistant.components.light: debug
homeassistant.components.cover: debug
homeassistant.components.switch: debug
````

...but none of the actions I take (like turning a light on or off) appear in the log when it's set like that.

I was looking at integrating another component and stumbled across this description of how lights work on the frontend, taken from here:

When you turn a light off in Home Assistant, the Home Assistant state immediately turns to off, so that the switch in the frontend reflects that you turned the light off. Then, the off command is actually sent to the light, and depending on the type of light it either waits for a response back confirming the command or it polls the device (or does nothing). Sometimes what will happen is the state will briefly change to on before the lights actually turn off and the state is updated back to off. This can often be seen in the frontend where you turn a light off and the switch briefly goes back to on and off again.

It sounds like in our case the actual response back from the light is just failing for some reason. Or perhaps this is totally unrelated...just thought I'd share!

Let me know I can provide any detail (or adjust my logger or something) to be helpful.

[grantalewis]

OK, here's the next set of logs. Had an odd thing happen on startup that I won't go into because I suspect it's a red herring. I can give more info if you like on that.

I tried to be a lot more sparing with what I removed from the log entries. This time I included the entire log from boot up to the first occurrence of the problem. The only references I removed were those containing family members' names, my domain name, longitude or latitude, or references to email addresses.

The two entities that first showed the problem were

light.main_stairs_main_hall
light.office_office_fan_light

Good luck -- Thanks!

(edited file to remove info; see below)

[JonGilmore]

OK, here's the next set of logs. Had an odd thing happen on startup that I won't go into because I suspect it's a red herring. I can give more info if you like on that.

I tried to be a lot more sparing with what I removed from the log entries. This time I included the entire log from boot up to the first occurrence of the problem. The only references I removed were those containing family members' names, my domain name, longitude or latitude, or references to email addresses.

The two entities that first showed the problem were

light.main_stairs_main_hall
light.office_office_fan_light

Good luck -- Thanks!

Just took a cursory glance at this, you may want to remove API keys and other PII. Your address is in there...

[grantalewis]

Edited log file.
home-assistant.log.zip

[thecynic]

@grantalewis ok, there's definitely some odd sequences here that I'd love to explore. No idea if it's related yet, but it smells fishy.

There are a lot of continuous omnilink status messages spamming homeassistant. is that expected?

In the middle of those, something is forcing us to requery the main repeater continuously. That may be related to the change by @JonGilmore that requeries the MR for all status checks and should be better with PR #25939 . But since you say that the backend works, we may be hitting a race condition somewhere that is getting exposed by the stream of queries? No idea yet.

One question i have is the interaction between omnilink and lutron modules. Do you have something that ties them together somehow? Like omnilink makes a query, and you service that query via lutron? Not exactly sure what questions to ask yet.

An example excerpt:

2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/status (retained): b'online'
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/status (retained): b'online'
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/status (retained): b'online'
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/unit21/state (retained): b'OFF'
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.family_room_mantel_lamp, old_state=None, new_state=<state light.family_room_mantel_lamp=off; lutron_integration_id=47, friendly_name=Mantel Lamp, supported_features=1, icon=mdi:lamp @ 2019-08-16T17:11:26.373377-04:00>>
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/status (retained): b'online'
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/status (retained): b'online'
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/status (retained): b'online'
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/unit22/state (retained): b'OFF'
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Subscribing to omnilink/unit453/state
2019-08-16 17:11:26 DEBUG (SyncWorker_3) [pylutron] Sending: ?OUTPUT,32,1
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/status (retained): b'online'
2019-08-16 17:11:26 DEBUG (Thread-6) [pylutron] handle_update 32 -- ['1', '0.00']
2019-08-16 17:11:26 DEBUG (Thread-6) [pylutron] Updating 32(Bookcase Lights): s=1 l=0.000000
2019-08-16 17:11:26 DEBUG (SyncWorker_3) [pylutron] Sending: ?OUTPUT,32,1
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Subscribing to omnilink/button16/state
2019-08-16 17:11:26 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/status (retained): b'online'
2019-08-16 17:11:26 DEBUG (Thread-6) [pylutron] handle_update 32 -- ['1', '0.00']
2019-08-16 17:11:26 DEBUG (Thread-6) [pylutron] Updating 32(Bookcase Lights): s=1 l=0.000000

@Tangston311 I assume you don't use omnilink? Could you also provide some debug logs?

[thecynic]

@grantalewis Yeah, there's definitely an interaction between omnilink and lutron that I have certainly never tested and don't yet know exactly how to debug without the system. For example, here you set the office light from home assistant, which gets sent to lutron. Almost immediately it gets an update from omnilink saying that the light is on and has the new brightness.

I'll have to dig and see whether or not this can be a problem? Not sure how other components handle these multi-master issues.

2019-08-16 17:23:15 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.office_office_fan_light>
2019-08-16 17:23:15 DEBUG (SyncWorker_1) [pylutron] Sending: #OUTPUT,9,1,50.00
2019-08-16 17:23:15 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/unit40/state: b'ON'
2019-08-16 17:23:16 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.office_light, old_state=<state light.office_light=off; friendly_name=Office Light, supported_features=1 @ 2019-08-16T17:11:01.515717-04:00>, new_state=<state light.office_light=on; brightness=0.0, friendly_name=Office Light, supported_features=1 @ 2019-08-16T17:23:16.003862-04:00>>
2019-08-16 17:23:16 DEBUG (MainThread) [homeassistant.components.mqtt] Received message on omnilink/unit40/brightness_state: b'50'
2019-08-16 17:23:16 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.office_light, old_state=<state light.office_light=on; brightness=0.0, friendly_name=Office Light, supported_features=1 @ 2019-08-16T17:23:16.003862-04:00>, new_state=<state light.office_light=on; brightness=128, friendly_name=Office Light, supported_features=1 @ 2019-08-16T17:23:16.003862-04:00>>

[thecynic]

@grantalewis Hmm, I wonder.... Once the badness happens, does it happen to all lutron entities all at once? Or do lights drop out over time? In other words, when this office_office_fan_light starts exhibting issues, do the other lights work as expected still?

[grantalewis]

There are a lot of continuous omnilink status messages spamming homeassistant. is that expected?

OmniLinkBridge
https://github.com/excaliburpartners/OmniLinkBridge

is a service that makes OmniLink entities available to Home Assistant that would not be otherwise (flags, buttons, sensors, thermostats for instance). I would assume that the amount of traffic is the same regardless of HA version but can't comment on that much since it works without a hitch on 0.84.6 and I haven't had occasion to generate a debug log. It's possible that I could request that the developer add an "exclude" option -- possibly useful in my case since all Omni entities are mirrored on the RA2 side. So exclude all entites that would be duplicated by RA2, while leaving flags, buttons, etc. available.

One question i have is the interaction between omnilink and lutron modules. Do you have something that ties them together somehow?

@JonGilmore asked me pretty much the same question on Discord and I had to plead ignorance. I can try to get information from my installer if that would be helpful. This firmware release writeup might shed some light:

http://www.homeauto.com/Downloads/Products/AutomationControllers/OmniProII/haiprivate/20I04-16UPGV2-7.pdf

Best guess: I think it's a physical serial connection, but I'm not sure of the communications protocol.

Once the badness happens, does it happen to all lutron entities all at once? Or do lights drop out over time?

When one entity starts misbehaving, they all start misbehaving.

If the entity is off when the problem starts:

• the entity will turn on
• but the toggle returns to OFF (while the light stays on)
• from then on, the toggle won't operate the entity again until I reboot

If the entity is on when the problem starts, the opposite holds true:

• the entity will turn off
• but the toggle returns to ON (while the light stays off)
• from then on, the toggle won't operate the entity again until I reboot

However, all entities can still be controlled via the States panel, no odd behavior.

[Tangston311]

@thecynic, I don't use OmniLink, but I DO have Lutron also integrated with a Savant system. Savant hooks up with Lutron via IP just like Home Assistant, but I rarely interact with Lutron via Savant - it's almost exclusively through HA and/or Homekit (I should also mention that I have a Connect Bridge to surface the Lutron entities to Homekit).

I'll try and pull some logs as well - my only issue last time was it takes a day or more now for my system to exhibit this behavior, and by that time the debug log was so big it caused my browser and HA to crash. I'll give it another shot though.

[JonGilmore]

@thecynic something I'd mentioned to @grantalewis to check on (which relates to @Tangston311 as well) was to make sure only 1 service was using a Lutron username/password. So, for example, Savant should be using a user, and HA should be using a different user. If I can recall, @grantalewis was able to confirm that this was not the issue (he was previously using a shared user/passwd). Lutron doesn't recommend this.
On another point - @thecynic do you also use a connect bridge? I don't have one in my setup, maybe it's related somehow? Admittedly, I know nothing about them...

[grantalewis]

FYI to chime in: (1) I do have a connect bridge, and (2) after @JonGilmore's recommendation I created and am using a second user login/password for the lutron entry in my config.

[Tangston311]

Ok I just added a second HA user for Lutron and applied that to my config as well.

[JonGilmore]

Ok I just added a second HA user for Lutron and applied that to my config as well.

I'm hopeful this will at least help.... When I was testing last night with 2 diff HA setups using the same lutron username/password, I did see disconnects on the 2nd instance that started (but the instance kept re-connecting b/c of the re-connect code, lol)

[thecynic]

@Tangston311 Does Savant integrate with HA? Just curious.

@JonGilmore glad to hear reconnect code working well for you too. I'll
merge it soon.

Also, I do not have a connect bridge. But as far as HA is concerned, we
only talk to the Main repeater, and never the connect bridge, right?

[Tangston311]

@thecynic , unfortunately not (to my knowledge anyway), but they did just come out with HomeKit compatibility for some of their products so perhaps someday it’ll be possible to integrate once the HomeKit Controller is updated to handle remotes. That would be cool.

[JonGilmore]

Also, I do not have a connect bridge. But as far as HA is concerned, we only talk to the Main repeater, and never the connect bridge, right?

Right, that's correct. I'm just trying to figure out why only 2 people are facing this issue while others continue without issue. I imagine something _has_ to be different/unique with their setups...

[cdheiser]

The only time I ever suffer connection issues is when I reprogram or
otherwise power cycle the main repeater.

On Sun, Aug 18, 2019 at 11:02 AM Jon Gilmore [e-mail]
wrote:

Also, I do not have a connect bridge. But as far as HA is concerned, we
only talk to the Main repeater, and never the connect bridge, right?

Right, that's correct. I'm just trying to figure out why only 2 people are
facing this issue while others continue without issue. I imagine something
has to be different/unique with their setups...

—
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=ACQARWUCLPQBL5EYY7AFB2LQFGFETA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD4RE7TQ#issuecomment-522342350,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWW56OBOBRJVULOQOKDQFGFETANCNFSM4GR2ZVYA
.

[grantalewis]

Noticed this tonight in the logs. Not sure if it's relevant.

Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 68, in uvloop.loop.Handle._run
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 96, in state_change_listener
    event.data.get("new_state"),
  File "/usr/src/homeassistant/homeassistant/core.py", line 372, in async_run_job
    target(*args)
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 171, in state_for_cancel_listener
    if not async_check_same_func(entity, from_state, to_state):
  File "/usr/src/homeassistant/homeassistant/components/automation/state.py", line 115, in <lambda>
    lambda _, _2, to_state: to_state.state == to_s.state,
AttributeError: 'NoneType' object has no attribute 'state'
2019-08-19 20:13:53 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <function async_track_state_change.<locals>.state_change_listener at 0x6e214468>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 68, in uvloop.loop.Handle._run
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 96, in state_change_listener
    event.data.get("new_state"),
  File "/usr/src/homeassistant/homeassistant/core.py", line 372, in async_run_job
    target(*args)
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 171, in state_for_cancel_listener
    if not async_check_same_func(entity, from_state, to_state):
  File "/usr/src/homeassistant/homeassistant/components/automation/state.py", line 115, in <lambda>
    lambda _, _2, to_state: to_state.state == to_s.state,
AttributeError: 'NoneType' object has no attribute 'state'
2019-08-19 20:13:53 ERROR (MainThread) [homeassistant.core] Error doing job: Exception in callback <function async_track_state_change.<locals>.state_change_listener at 0x6e688738>
Traceback (most recent call last):
  File "uvloop/cbhandles.pyx", line 68, in uvloop.loop.Handle._run
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 96, in state_change_listener
    event.data.get("new_state"),
  File "/usr/src/homeassistant/homeassistant/core.py", line 372, in async_run_job
    target(*args)
  File "/usr/src/homeassistant/homeassistant/helpers/event.py", line 171, in state_for_cancel_listener
    if not async_check_same_func(entity, from_state, to_state):
  File "/usr/src/homeassistant/homeassistant/components/automation/state.py", line 115, in <lambda>
    lambda _, _2, to_state: to_state.state == to_s.state,
AttributeError: 'NoneType' object has no attribute 'state'
2019-08-19 20:14:49 WARNING (MainThread) [homeassistant.core] Unable to remove unknown listener <function async_track_point_in_utc_time.<locals>.point_in_time_listener at 0x6de17bb8>

[Tangston311]

@grantalewis , just checking to see how creating the unique HA username is working for you. I've been running for 3 days now without the issue....just curious if you're experiencing the same?

[JonGilmore]

@grantalewis , just checking to see how creating the unique HA username is working for you. I've been running for 3 days now without the issue....just curious if you're experiencing the same?

wow, this is great news! Please keep us posted. I'd love it if this was the cause...

[thecynic]

@grantalewis , just checking to see how creating the unique HA username is working for you. I've been running for 3 days now without the issue....just curious if you're experiencing the same?

wow, this is great news! Please keep us posted. I'd love it if this was the cause...

Still not sure how that would cause the symptoms. It's as if we stop getting remote updates, but it's not clear if MR stops sending or we stop reading. It'd be interesting to maybe capture some packet traces via tcpdump to see if we are receiving the remote packets. The debug logs should have shown to us that we are receiving updates. hmm.

Maybe try with:
sudo tcpdump -A -ni eth0 'tcp and ip host IP_OF_MAIN_REPEATER'
while trying to flip the toggle in HASS.

If you can provide those logs, it'll be pretty clear if we are even trying to send/receive data or not.

[Tangston311]

@thecynic , @JonGilmore , well yesterday the issue appeared again, although this time slightly differently: my automatons with Lutron service calls didn't work either (until I restarted HA). So it worked for about 4 days, then I noticed the issue re-appear from my phone, and when I got home I noticed none of my Lutron automations had worked either. I pulled the logs, attached, but the recorder was set to "error". On pg. 237 you can see Lutron start appearing a bunch. It's possible this was a separate issue because of the different symptoms, but thought I'd post.

I'm happy to try that command - do I just run it in terminal via ssh and then flip the toggle in the Hassio interface?

Aug22904pmlogs.docx

[JonGilmore]

Just by giving this a once over, it looks like you're having network issues. Lutron isn't mentioned until the very end, but it looks like alarm.com is having connectivity issues, as well as darksky and lutron... total guess, it's hard to tell whats going on with this.

[grantalewis]

@grantalewis , just checking to see how creating the unique HA username is working for you. I've been running for 3 days now without the issue....just curious if you're experiencing the same?

Sorry for the silence -- really busy work week. I've been using unique HA credentials for a couple of weeks now. No improvement, unfortunately.

I'm going to try to capture more logs this morning as @thecynic suggests above. Will report back.

[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 [e-mail]
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 [e-mail]
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 [e-mail]
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 [e-mail] 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 [e-mail]
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 [e-mail]
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 [e-mail]
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 [e-mail] 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 [e-mail] 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 [e-mail] 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
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
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 [e-mail] 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
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
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.)

[grantalewis]

maybe try adding this clause to your logger config as well:

OK, my configuration.yaml now has:

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

I'm now seeing log entries like these:

2019-09-02 16:44:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=group.game_room, old_state=<state group.game_room=unknown; entity_id=('light.game_room_game_room_fan', 'light.game_room_game_room_hallway_light', 'light.game_room_game_room_recessed'), order=39, friendly_name=Game Room @ 2019-09-02T16:44:15.072052-04:00>, new_state=<state group.game_room=off; entity_id=('light.game_room_game_room_fan', 'light.game_room_game_room_hallway_light', 'light.game_room_game_room_recessed'), order=39, friendly_name=Game Room @ 2019-09-02T16:44:41.110877-04:00>>
2019-09-02 16:44:41 INFO (SyncWorker_3) [custom_components.lutron.cdhlutron] Sending: ?OUTPUT,37,1
2019-09-02 16:44:41 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 37 -- ['1', '0.00']
2019-09-02 16:44:41 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] Updating 37(Dining Pendant): s=1 l=0.000000
2019-09-02 16:44:41 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-02T16:44:41.213732-04:00>>
2019-09-02 16:44:41 INFO (SyncWorker_6) [custom_components.lutron.cdhlutron] Sending: ?OUTPUT,97,1
2019-09-02 16:44:41 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 97 -- ['1', '0.00']
2019-09-02 16:44:41 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] Updating 97(Master Bath Vanity Lights): s=1 l=0.000000
2019-09-02 16:44:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.master_bathroom_master_bath_vanity_lights, old_state=None, new_state=<state light.master_bathroom_master_bath_vanity_lights=off; lutron_integration_id=97, friendly_name=Master Bathroom Light, supported_features=1 @ 2019-09-02T16:44:41.309201-04:00>>
2019-09-02 16:44:41 INFO (SyncWorker_0) [custom_components.lutron.cdhlutron] Sending: ?OUTPUT,22,1
2019-09-02 16:44:41 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 22 -- ['1', '0.00']

So perhaps that'll produce some helpful results.

[grantalewis]

home-assistant.log.zip
Well, the good news is that it's no longer taking hours for the problem to occur. This time it happened only about 8 minutes after rebooting (maybe due to the heavy-duty logging tasks?).

The two entities I experimented with this time:

light.main_stairs_main_hall
light.office_office_fan_light

Same results as before: turn the toggle on, the light goes on and stays on; the toggle returns to off; further changes to the entity can't be made using the toggle; but changes are successful via Services

These seem to be the relevant log entries:

2019-09-02 16:44:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.main_stairs_main_hall, old_state=None, new_state=<state light.main_stairs_main_hall=off; lutron_integration_id=18, friendly_name=Downstairs Hallway, supported_features=1 @ 2019-09-02T16:44:41.008955-04:00>>
2019-09-02 16:44:41 INFO (SyncWorker_8) [custom_components.lutron.cdhlutron] Sending: ?OUTPUT,45,1
2019-09-02 16:44:41 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 45 -- ['1', '0.00']

2019-09-02 16:44:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.office_office_fan_light, old_state=None, new_state=<state light.office_office_fan_light=off; lutron_integration_id=9, friendly_name=Office Fan Light, supported_features=1 @ 2019-09-02T16:44:40.410877-04:00>>
2019-09-02 16:44:40 INFO (SyncWorker_3) [custom_components.lutron.cdhlutron] Sending: ?OUTPUT,25,1
2019-09-02 16:44:40 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 25 -- ['1', '0.00']

[thecynic]

Ok, interesting. Yeah we completely stop getting updates from lutron....

This is what setting the state is supposed to look like. We send command, then handle_update for the remote end to send us the status. Coincidentally, this is the last time we see an update... Hmmm.

2019-09-02 16:47:06 INFO (SyncWorker_7) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,75,1,0.00
2019-09-02 16:47:06 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 75 -- ['1', '0.00']
2019-09-02 16:47:06 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] Updating 75(FR Shades Indicator): s=1 l=0.000000
2019-09-02 16:47:06 INFO (Thread-2) [custom_components.lutron] Update callback for Family Room FR Shades Indicator
2019-09-02 16:47:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=switch.family_room_fr_shades_indicator, old_state=<state switch.family_room_fr_shades_indicator=on; lutron_integration_id=75, friendly_name=Family Room, icon=mdi:blinds @ 2019-09-02T16:44:46.018080-04:00>, new_state=<state switch.family_room_fr_shades_indicator=off; lutron_integration_id=75, friendly_name=Family Room, icon=mdi:blinds @ 2019-09-02T16:47:06.613872-04:00>>
2019-09-02 16:47:06 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 75 -- ['29', '6']
2019-09-02 16:47:06 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 75 -- ['30', '1', '0.00']

What is this shade indicator? It's plumbed as a switch, is that how lutron exposes shades? What does hass? Is it a shade? How does that work? Gotta go look at that code, it's not one of the things I added originally :smile:

[thecynic]

@grantalewis forgot to tag you in message above.

[thecynic]

@grantalewis Actually, I lied. This is the last update we see, so lutron was still sending status till at least then:

```
2019-09-02 16:50:23 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 100 -- ['1', '100.00']
2019-09-02 16:50:23 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] Updating 100(Isaac Bedroom Fan Light): s=1 l=100.000000
2019-09-02 16:50:23 INFO (Thread-2) [custom_components.lutron] Update callback for Isaac Bedroom Isaac Bedroom Fan Light
2019-09-02 16:50:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling , new_state=>
2019-09-02 16:50:23 DEBUG (MainThread) [homeassistant.core] Bus:Handling , new_state=>
2019-09-02 16:50:23 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 100 -- ['29', '6']
2019-09-02 16:50:23 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 100 -- ['30', '1', '100.00']
2019-09-02 16:50:24 INFO (Thread-2) [custom_components.lutron.cdhlutron] Updating 79(Alexa Automation 2): c=88 a=9 params=[1]
2019-09-02 16:50:24 INFO (Thread-2) [custom_components.lutron.cdhlutron] Keypad: "Alexa Automation 2" LED keypad: "Alexa Automation 2" name: "LED 8" num: 8 component_num: 88" Action: 9 Params: [1]"

[grantalewis]

What is this shade indicator?

The shades are controlled via a serial connection to the Omni. Adding the Lutron phantom switch you're referencing allows me to control them through both Lutron and Alexa as well.

[cdheiser]

I think we need to get full logging from pyluton to see what's going on in
the main repeater. Part of me believes that something is disabling the
monitoring state on the main repeater. Either way, if we get full debug
output from cdhlutron (or pylutron), that should tell us if we're still
getting comms back, and what it says.

@thecynic's log config should be correct (although I can never get the
logger module to behave properly).

There's one extra thing I'd like you to do if/when it hits again: Go
manually turn a device or two on and off.

On Mon, Sep 2, 2019 at 6:13 PM grantalewis [e-mail] wrote:

What is this shade indicator?

The shades are controlled via a serial connection to the Omni. Adding the
Lutron phantom switch you're referencing allows me to control them through
both Lutron and Alexa.

—
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=ACQARWVS3DBJFWGMJNAGKOLQHW22FA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5WXQHI#issuecomment-527267869,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWWZTGWAUUUTCDJ7XALQHW22FANCNFSM4GR2ZVYA
.

[thecynic]

@grantalewis Ah, ok. cool. So, it seems that either:
1) thread is stuck
2) lutron stops sending us updates

This (this is an off event) should always happen when you toggle a switch remotely (i.e. not via HASS):

2019-09-02 20:20:17 DEBUG (Thread-2) [pylutron] handle_update 37 -- ['1', '0.00']
2019-09-02 20:20:17 DEBUG (Thread-2) [pylutron] Updating 37(Under-cabinet lights): s=1 l=0.000000

@grantalewis next time this happens to be stuck, what happens when you externally toggle the light via a physical switch or via the Lutron App where HASS is not the source of the event. Do we get the logs we want in pylutron and does the entity update? Or does it stay stuck?

@grantalewis we could try to test the theory that the thread is stuck. Are you able to install a newer pypi version of pylutron? I pushed 0.2.4 which has my new reconnect code. You'd have to update the required component version in requirements_all.txt, by changing

    pylutron==0.2.2

to

    pylutron==0.2.4

Then, when your stuff gets stuck, you can go and powercycle the main repeater (wait for 5-10 seconds with it off for pylutron to notice). If, once we reconnect, pylutron detects the disconnect, reconnects and everything starts working again (i.e. the thread will notice that we died, and reconnect) then we know that at least the thread is alive and noticing timeouts. During this time, try not to operate anything else that may cause us to send comands to lutron via hass so that we don't kick the connection from the HASS thread.

Sorry, lots of things to try with a bit of a scatter shot. Trying to rule a few things out.

We can also skip physical switches and telnet into MR manually and send it commands like #OUTPUT,,1,100.0 or #OUTPUT,,1,0.0 to turn things on/off and see if it kicks our thread. One thing at a time though.

[thecynic]

I think we need to get full logging from pyluton to see what's going on in the main repeater. Part of me believes that something is disabling the monitoring state on the main repeater. Either way, if

@cdheiser That's an interesting thought. Monitoring state should be per-connection, unless there's a bug in the lutron firmware (shocker...) Or... What if we are sooo slow reading out state and handling updates on our side that their send buffer fills up? That sounds pretty ludicrous though as it would have to be super tiny. Don't know how their firmware handles multiple connections and sending updates/responses... Just round-robin through all the connections? I can see them having some failsafes when downstream clients misbehave. We can query monitoring state say every 10 commands we send?

we get full debug output from cdhlutron (or pylutron), that should tell us if we're still getting comms back, and what it says. @thecynic's log config should be correct (although I can never get the logger module to behave properly). There's one extra thing I'd like you to do if/when it hits again:

With the two debug lines @grantalewis just added, I'm getting all the logging i expect from pylutron/cdhlutron (see my latest update).

[grantalewis]

@grantalewis we could try to test the theory that the thread is stuck. Are you able to install a newer pypi version of pylutron? I pushed 0.2.4 which has my new reconnect code. You'd have to update the required component version in requirements_all.txt, by changing...

No idea of how to do this, but I follow instructions like a champ. ;)

Then, when your stuff gets stuck, you can go and powercycle the main repeater (wait for 5-10 seconds with it off for pylutron to notice)

Waiting for the glitch to show up and then I'll chime in w/ info on what I find.

[grantalewis]

The two entities I experimented with this time:

light.main_stairs_main_hall
light.kitchen_pendant_lights

2:27 PM tried the kitchen pendants using the HA iPhone app. Saw the problem. (Not to introduce a red herring, but I believe I first saw the problem yesterday when using the HA iPhone app. Coincidence?)

2:27 PM tried the downstairs hallway and confirmed that the problem was seen there as well.

2:29 PM successfully confirmed that I could still operate the lights with the physical Lutron wall switches.

2:30 PM tried to turn on the kitchen pendants using the HA browser UI. They did not respond. This is new - normally they will turn on, just not off.

2:31 PM tried the downstairs hallway using the HA browser UI. They did not respond, either. Again, first time I've seen this particular failure.

2:32 PM successfully confirmed that I could still operate both lights with the physical Lutron wall switches.

2:31 PM tried the downstairs hallway via the Services panel but was unsuccessful. This is new as well - normally calls from Services continue to work.

2:35 PM same failed result when attempting to turn the light.kitchen_pendant_lights on via the Services panel.

2:36 PM successfully confirmed that the Lutron iPhone app could still operate both lights.

The last entry for light.main_stairs_main_hall is 14:33:

2019-09-03 14:33:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.main_stairs_main_hall>
2019-09-03 14:33:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.main_stairs_main_hall']>
2019-09-03 14:33:41 INFO (SyncWorker_1) [custom_components.lutron.light] Turining on of Main Stairs Main Hall

The last entry for light.kitchen_pendant_lights is 14:35:

2019-09-03 14:35:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=homeassistant, service=turn_on, service_data=entity_id=light.kitchen_pendant_lights>
2019-09-03 14:35:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=['light.kitchen_pendant_lights']>
2019-09-03 14:35:00 INFO (SyncWorker_4) [custom_components.lutron.light] Turining on of Kitchen Pendant Lights

home-assistant.log.zip

[cdheiser]

Ok... it's still a black hole, so here comes a hail mary.

I've updated the dropbox version again:

• It now logs every line coming back from the main repeater
• It also merges in @thecynic's changes to light.py
• It also emits a debug line for every run through the main lutron loop.

So there's gonna be a lotta logs.

On Tue, Sep 3, 2019 at 11:55 AM grantalewis [e-mail]
wrote:

The two entities I experimented with this time:

light.main_stairs_main_hall
light.kitchen_pendant_lights

2:27 PM tried the kitchen pendants using the HA iPhone app. Saw the
problem. (Not to introduce a red herring, but I believe I first saw the
problem yesterday when using the HA iPhone app. Coincidence?)

2:27 PM tried the downstairs hallway and confirmed that the problem was
seen there as well.

2:29 PM successfully confirmed that I could still operate the lights with
the physical Lutron wall switches.

2:30 PM tried to turn on the kitchen pendants using the HA browser UI.
They did not respond. This is new - normally they will turn on, just not
off.

2:31 PM tried the downstairs hallway using the HA browser UI. They did not
respond, either. Again, first time I've seen this particular failure.

2:32 PM successfully confirmed that I could still operate both lights with
the physical Lutron wall switches.

2:31 PM tried the downstairs hallway via the Services panel but was
unsuccessful. This is new as well - normally calls from Services continue
to work.

2:35 PM same failed result when attempting to turn the
light.kitchen_pendant_lights on via the Services panel.

2:36 PM successfully confirmed that the Lutron iPhone app could still
operate both lights.

The last entry for light.main_stairs_main_hall is 14:33:

2019-09-03 14:33:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling
2019-09-03 14:33:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling 2019-09-03 14:33:41 INFO (SyncWorker_1) [custom_components.lutron.light] Turining on of Main Stairs Main Hall

The last entry for light.kitchen_pendant_lights is 14:35:

2019-09-03 14:35:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling
2019-09-03 14:35:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling 2019-09-03 14:35:00 INFO (SyncWorker_4) [custom_components.lutron.light] Turining on of Kitchen Pendant Lights

home-assistant.log.zip
https://github.com/home-assistant/home-assistant/files/3570995/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=ACQARWVGCYNH3CFZW2L4T5DQH2XLRA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5ZGPPA#issuecomment-527591356,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWVXR5W3ZAH3WH7XHFDQH2XLRANCNFSM4GR2ZVYA
.

[grantalewis]

OK, downloaded and installed the new version of those files, @cdheiser. Rebooted and let things run for a while.

I started seeing problems around 6:30 PM but because it's my wife's birthday, this wasn't the day to become preoccupied with geekery. So the soonest I was able to make any purposeful experimentation was shortly after 7:00 PM.

Here are the two entities I experimented with:

light.dining_room_dining_pendant
light.family_room_family_recessed

7:06 PM turned off light.family_room_family_recessed, then tried turning it back on with HA browser UI. The light was unresponsive. I was able to turn it on both with the wall switch as well as in the Lutron app. I was not able to turn it on via Services.

7:09 PM light.dining_room_dining_pendant was already off. I was able to turn it on with HA browser UI, but the toggle moved back to OFF as the light stayed on. I was able to turn it on both with the wall switch as well as in the Lutron app. I WAS able to turn it OFF, then ON, then OFF via Services. I was then able to turn it ON with the HA browser UI, but as before, the toggle moved back to OFF as the light stayed on.

Last log entry for light.dining_room_dining_pendant:

2019-09-03 19:11:35 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-03 19:11:35 INFO (SyncWorker_5) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,37,1,49.02
2019-09-03 19:11:35 INFO (SyncWorker_5) [custom_components.lutron.cdhlutron] Sending: #OUTPUT,37,1,49.02 DONE

Last log entry for light.family_room_family_recessed:

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

home-assistant.log.zip

[grantalewis]

This thought occurs: since I'm fairly unsure of what I'm looking for, there is the possibility that I'm inadvertently deleting something from the logs that I shouldn't be. I don't mind sharing my unaltered logs with you privately if you think that's useful.

[cdheiser]

I think everything is there. This is really interesting. The last run of
the background loop is at 17:55

2019-09-03 17:55:48 DEBUG (Thread-3) [custom_components.lutron.cdhlutron]
Main run loop

It reads a change at 17:56:
2019-09-03 17:56:52 DEBUG (Thread-3) [custom_components.lutron.cdhlutron]
Received line ~DEVICE,128,2,40
2019-09-03 17:56:52 INFO (Thread-3) [custom_components.lutron.cdhlutron]
Updating 128(Fans 1): c=2 a=40 params=[]
2019-09-03 17:56:52 INFO (Thread-3) [custom_components.lutron.cdhlutron]
Keypad: "Fans 1" Button name: "FamilyFan" num: 2 type: "Toggle" direction:
"None" Action: 40 Params: []"

And then Thread-3 just goes silent... as if it's wedged on something, or
it's just dead...

Once I don't have a toddler nagging me, I'll update the custom component
one more time with some more instrumentation to see what's happening to
that thread. My guess is we're throwing an uncaught exception, and it's
just killing the thread, and not getting logged.

On Tue, Sep 3, 2019 at 5:48 PM grantalewis [e-mail] wrote:

This thought occurs: since I'm fairly unsure of what I'm looking for,
there is the possibility that I'm inadvertently deleting something from the
logs that I shouldn't be. I don't mind sharing my unaltered logs with you
privately if you think that's useful.

—
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=ACQARWRYBRZMSKDB77ECYS3QH4AT7A5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5Z7OZA#issuecomment-527693668,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWRP2U4OE2DDKHSPXIDQH4AT7ANCNFSM4GR2ZVYA
.

[grantalewis]

I wish I knew enough about this stuff to be more than the water boy. In particular, it’d be really interesting to (eventually) figure out what happened since 0.84.6 that screwed things up.

[cdheiser]

Ok... I've updated the custom component again. It should catch any
exception in the main loop and log it before re-raising it. If this
doesn't log something interseting, then I might be stumped.

On Tue, Sep 3, 2019 at 6:31 PM grantalewis [e-mail] wrote:

I wish I knew enough about this stuff to be more than the water boy. In
particular, it’d be really interesting to (eventually) figure out what
happened since 0.84.6 that screwed things up.

—
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=ACQARWWDUELUXDP52AYI3F3QH4FV5A5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD52BO4Y#issuecomment-527701875,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWUW7XPBKCSOLNGIQQDQH4FV5ANCNFSM4GR2ZVYA
.

[grantalewis]

I've had this new version running since 11AM Eastern -- 5.5+ hours, no glitches. Did you make any changes that might have resulted in a fix?

[grantalewis]

Never mind. Problem just occurred.

5:41 PM tried turning on

light.dining_room_dining_pendant
light.family_room_family_recessed
light.kitchen_kitchen_recessed

Lights would turn ON, but respective UI sliders toggled back to OFF

Was able to use Services to turn the entities off.

Light switches continued to work as did the Lutron app.

Sorry for the brevity -- running out the door.

home-assistant.log.zip

[cdheiser]

HAH!!!

2019-09-04 17:14:15 DEBUG (Thread-3) [custom_components.lutron.cdhlutron]
Uncaught exception: %d format: a number is required, not str

Of course... my logging of the exception is terrible so I don't know yet
exactly where it hit...

On Wed, Sep 4, 2019 at 2:57 PM grantalewis [e-mail] wrote:

Never mind. Problem just occurred.

5:41 PM tried turning on

light.dining_room_dining_pendant
light.family_room_family_recessed
light.kitchen_kitchen_recessed

Lights would turn ON, but respective UI sliders toggled back to OFF

Was able to use Services to turn the entities off.

Light switches continued to work as did the Lutron app.

home-assistant.log.zip
https://github.com/home-assistant/home-assistant/files/3576646/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=ACQARWXGPWSLXDUIEL2NW7LQIAVN3A5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD55D3OY#issuecomment-528104891,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWU4BHN2FQ637BTQW23QIAVN3ANCNFSM4GR2ZVYA
.

[cdheiser]

I found the bug. Proposing an edit now.

On Wed, Sep 4, 2019 at 3:04 PM Chris Heiser [e-mail] wrote:

HAH!!!

2019-09-04 17:14:15 DEBUG (Thread-3) [custom_components.lutron.cdhlutron]
Uncaught exception: %d format: a number is required, not str

Of course... my logging of the exception is terrible so I don't know yet
exactly where it hit...

On Wed, Sep 4, 2019 at 2:57 PM grantalewis [e-mail]
wrote:

Never mind. Problem just occurred.

5:41 PM tried turning on

light.dining_room_dining_pendant
light.family_room_family_recessed
light.kitchen_kitchen_recessed

Lights would turn ON, but respective UI sliders toggled back to OFF

Was able to use Services to turn the entities off.

Light switches continued to work as did the Lutron app.

home-assistant.log.zip
https://github.com/home-assistant/home-assistant/files/3576646/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=ACQARWXGPWSLXDUIEL2NW7LQIAVN3A5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD55D3OY#issuecomment-528104891,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWU4BHN2FQ637BTQW23QIAVN3ANCNFSM4GR2ZVYA
.

[cdheiser]

https://github.com/thecynic/pylutron/pull/38

Man I don't know how to use github...

On Wed, Sep 4, 2019 at 3:07 PM Chris Heiser [e-mail] wrote:

I found the bug. Proposing an edit now.

On Wed, Sep 4, 2019 at 3:04 PM Chris Heiser [e-mail]
wrote:

HAH!!!

2019-09-04 17:14:15 DEBUG (Thread-3) [custom_components.lutron.cdhlutron]
Uncaught exception: %d format: a number is required, not str

Of course... my logging of the exception is terrible so I don't know yet
exactly where it hit...

On Wed, Sep 4, 2019 at 2:57 PM grantalewis [e-mail]
wrote:

Never mind. Problem just occurred.

5:41 PM tried turning on

light.dining_room_dining_pendant
light.family_room_family_recessed
light.kitchen_kitchen_recessed

Lights would turn ON, but respective UI sliders toggled back to OFF

Was able to use Services to turn the entities off.

Light switches continued to work as did the Lutron app.

home-assistant.log.zip
https://github.com/home-assistant/home-assistant/files/3576646/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=ACQARWXGPWSLXDUIEL2NW7LQIAVN3A5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD55D3OY#issuecomment-528104891,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWU4BHN2FQ637BTQW23QIAVN3ANCNFSM4GR2ZVYA
.

[cdheiser]

Ok, I have updated the custom component in dropbox. It should fix the
problem, and if it doesn't, well, there's better exception logging.

On Mon, Sep 2, 2019 at 2:36 PM grantalewis [e-mail] wrote:

Well, the good news is that it's no longer taking hours for the problem to
occur. This time it happened only about 8 minutes after rebooting (maybe
due to the heavy-duty logging tasks?).

The two entities I experimented with this time:

light.main_stairs_main_hall
light.office_office_fan_light

Same results as before: turn the toggle on, the light goes on and stays
on; the toggle returns to off; further changes to the entity can't be made
using the toggle; but changes are successful via Services

These seem to be the relevant log entries:

2019-09-02 16:44:41 DEBUG (MainThread) [homeassistant.core] Bus:Handling >
2019-09-02 16:44:41 INFO (SyncWorker_8) [custom_components.lutron.cdhlutron] Sending: ?OUTPUT,45,1
2019-09-02 16:44:41 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 45 -- ['1', '0.00']

2019-09-02 16:44:40 DEBUG (MainThread) [homeassistant.core] Bus:Handling >
2019-09-02 16:44:40 INFO (SyncWorker_3) [custom_components.lutron.cdhlutron] Sending: ?OUTPUT,25,1
2019-09-02 16:44:40 DEBUG (Thread-2) [custom_components.lutron.cdhlutron] handle_update 25 -- ['1', '0.00']

—
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=ACQARWV4Y6HXLG6CW5VAQXDQHWBN5A5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD5WSIXQ#issuecomment-527246430,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWWK64I4XDBHOCVC5RLQHWBN5ANCNFSM4GR2ZVYA
.

[cdheiser]

Note once pylutron is updated, it will still require another push to Pypi and an update of the component dependencies.

[JonGilmore]

I found the bug. Proposing an edit now.

.... wait - is this the cause of all of @grantalewis issues? Or just a logging bug that is hiding his issues?

[cdheiser]

AFAICT, it's definitely what's breaking it now. So there's an updated
custom component, and the logging is still in the custom component, and we
can see if it breaks again or if this actually fixes the issue.

It would make sense, as the keypads and leds were a major addition to
pylytron 0.2, which is where the exception appears to be coming from. What
I don't understand is why my own system doesn't throw these errors, as I
have pico remotes and seetouch keypads. Something about the fan switches
perhaps?

On Wed, Sep 4, 2019 at 4:45 PM Jon Gilmore [e-mail] wrote:

I found the bug. Proposing an edit now.

.... wait - is this the cause of all of @grantalewis
https://github.com/grantalewis issues? Or just a logging bug that is
hiding his issues?

—
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=ACQARWUVNNJUDFYWV4X375DQIBCAVA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD55LK3A#issuecomment-528135532,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWXGKWKN3NFDEVSXIB3QIBCAVANCNFSM4GR2ZVYA
.

[JonGilmore]

Interesting - I don't think it has anything to do with fans as I have 5 of them, and don't see these issues either. FWIW, I have picos, hybrid seetouch keypads, 10 key seetouch keypad, and dimmers/switches and have never seen this. Regardless, awesome find!

[grantalewis]

Pretty excited about this! Fingers crossed. I've got the new custom component installed on 0.98.3 and am going to let it run overnight. I also re-enabled my customary (non-mimimal) configuration.yaml, the OmniProBridge, and all automations, so I admit to throwing caution to the wind a bit. If things are still working in the AM, that'll be a very good sign.

I still have all of the loggers enabled in case something goes wrong.

[cdheiser]

And if they're not, we'll have more logs

On Wed, Sep 4, 2019, 6:43 PM grantalewis [e-mail] wrote:

Pretty excited about this! Fingers crossed. I've got the new custom
component installed on 0.98.3 and am going to let it run overnight. I also
re-enabled my customary (non-mimimal) configuration.yaml, the
OmniProBridge, and all automations, so I admit to throwing caution to the
wind a bit. If things are still working in the AM, that'll be a very good
sign.

—
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=ACQARWV5L2U3LEC266S6KZTQIBP5PA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD55RFEA#issuecomment-528159376,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWRXMX7W2BPOPGKWPZTQIBP5PANCNFSM4GR2ZVYA
.

[grantalewis]

Everything's still working this morning! I will of course keep tabs on it throughout the day, but the outlook seems positive.

[thecynic]

Fantastic, nice find @cdheiser. I'll post feedback on the patch tonight. I
hate python for these kind of dynamic landmines :(

[grantalewis]

Checking in to say that it's been smooth sailing all day long. Completely _stoked_ to have this problem finally taken care of! Thanks to @cdheiser and @thecynic for your determination and patience.

I'd appreciate a recommendation on how long to leave the issue open. And also I'd appreciate your giving me a heads up on when to remove the custom component. (I know it's not yet, but if you happen to know the version # that will include the fixed pylutron, please let me know.)

Once again, my thanks. If you guys were in my neighborhood I'd buy you a beer. Or three.

[Tangston311]

This is awesome - just want to echo @grantalewis comments to say it’s amazing to see how dedicated all of you have been to solving this. This is why HA and this community are so incredible.

[cdheiser]

Once we go over the patch and get it submitted, the process is as follows:

1) Update the version and push to pypi
2) Submit a pull request to HA to update the version of pylutron. That
pull request will be linked to this issue.
3) HA will eventually release a new version, and include this issue as
fixed in the release notes. That will be the time to remove the custom
component.

On Thu, Sep 5, 2019 at 2:11 PM Tangston311 [e-mail] wrote:

This is awesome - just want to echo @grantalewis
https://github.com/grantalewis comments to say it’s amazing to see how
dedicated all of you have been to solving this. This is why HA and this
community are so incredible.

—
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=ACQARWT4LKJ4LVDZ47GWYOLQIFYYNA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD6AYWIQ#issuecomment-528583458,
or mute the thread
https://github.com/notifications/unsubscribe-auth/ACQARWWPTVPSFV5NU5GTL3LQIFYYNANCNFSM4GR2ZVYA
.

[JonGilmore]

Checking in to say that it's been smooth sailing all day long. Completely _stoked_ to have this problem finally taken care of! Thanks to @cdheiser and @thecynic for your determination and patience.

I'd appreciate a recommendation on how long to leave the issue open. And also I'd appreciate your giving me a heads up on when to remove the custom component. (I know it's not yet, but if you happen to know the version # that will include the fixed pylutron, please let me know.)

Once again, my thanks. If you guys were in my neighborhood I'd buy you a beer. Or three.

WOOHHOOO! This is great news! I assume this is the longest you've gone without issues since 0.86.4? If so, do you think you can confidently say it's solved?

[grantalewis]

Yes, this is definitely the longest I've gone without problems, and I am nearly certain the problem is solved. I couldn't say this to most people and expect them to understand, but I know you guys can relate: this is huge. It's like having a weight off my shoulders. I am a happy man!

[thecynic]

I've pushed version 0.2.5 to pypi, will need to update HASS for new version and hopefully we can close this.

[Tangston311]

Thanks @thecynic ! Does this mean 99.2 contains the fix, or will it be the next version?

[thecynic]

Thanks @thecynic ! Does this mean 99.2 contains the fix, or will it be the next version?

@Tangston311 Will be in the next version.

[amattas]

Still happening in Home Assistant 0.101.3

[grantalewis]

I'm running 0.103.6 and have not encountered the problem I first described since 9/5/2019.

@amattas I've seen something similar if my RA2 system loses power/connectivity. I suggest shutting down HA, restarting your Lutron system, waiting for ~5 mins, and then rebooting HA.

[amattas]

Correct, this happens if the controller becomes disconnected from the Lutron system. If connectivity is interrupted it should eventually reconnect instead of crashing the plugin and requiring a reboot of HA. If I go out of town for a week, and on day one it loses connectivity – all of my automations would stop running until I returned and can reset the system.

From: grantalewis [e-mail]
Reply-To: home-assistant/home-assistant [e-mail]
Date: Monday, January 13, 2020 at 11:08 AM
To: home-assistant/home-assistant [e-mail]
Cc: Anthony Mattas [e-mail], Mention [e-mail]
Subject: Re: [home-assistant/home-assistant] Error in lutron.py -- Hass.io loses ability to control LutronRA2 entities (#20348)

I'm running 0.103.6 and have not encountered the problem I first described since 9/15/2019.

@amattashttps://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Famattas&data=01%7C01%7Canthony%40mattas.net%7C9cec4c6b44c841e534a008d7985bef59%7C20e5b14899e942519006662b26413b94%7C1&sdata=tNnLADd27jpIey3P7Hc6Trza6KD4KPvaAfID2H58Jdo%3D&reserved=0 I've seen something similar if my RA2 system loses power/connectivity. I suggest shutting down HA, restarting your Lutron system, waiting for ~5 mins, and then rebooting HA.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fhome-assistant%2Fhome-assistant%2Fissues%2F20348%3Femail_source%3Dnotifications%26email_token%3DACQEUJEV24AMRJVZWBGHKCDQ5S3ZXA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEIZ5A6Y%23issuecomment-573821051&data=01%7C01%7Canthony%40mattas.net%7C9cec4c6b44c841e534a008d7985bef59%7C20e5b14899e942519006662b26413b94%7C1&sdata=hZb3DIdj4aaCl7dto%2F90eUznozD2kcHtmOLRUiCIow0%3D&reserved=0, or unsubscribehttps://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FACQEUJAR2E22SFBKRZTKUU3Q5S3ZXANCNFSM4GR2ZVYA&data=01%7C01%7Canthony%40mattas.net%7C9cec4c6b44c841e534a008d7985bef59%7C20e5b14899e942519006662b26413b94%7C1&sdata=Lo3YxugeB8BxwVOLiviftLG1P5YLkbd1Vqnr%2BDWyNwE%3D&reserved=0.

[grantalewis]

The initial issue was due to a typo:

Uncaught exception: %d format: a number is required, not str

That's been fixed. It appears you're after something else, so you might want to create a new thread.

[amattas]

Which version was this merged in? I had originally opened another issue for this https://github.com/home-assistant/home-assistant/issues/29642#issuecomment-563044790

From: grantalewis [e-mail]
Reply-To: home-assistant/home-assistant [e-mail]
Date: Monday, January 13, 2020 at 11:22 AM
To: home-assistant/home-assistant [e-mail]
Cc: Anthony Mattas [e-mail], Mention [e-mail]
Subject: Re: [home-assistant/home-assistant] Error in lutron.py -- Hass.io loses ability to control LutronRA2 entities (#20348)

The initial issue was due to a typo:

Uncaught exception: %d format: a number is required, not str

That's been fixed. It appears you're after something else, so you might want to create a new thread.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHubhttps://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fhome-assistant%2Fhome-assistant%2Fissues%2F20348%3Femail_source%3Dnotifications%26email_token%3DACQEUJC6H5W7NEGJDSBRDETQ5S5QHA5CNFSM4GR2ZVYKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEIZ6ROI%23issuecomment-573827257&data=01%7C01%7Canthony%40mattas.net%7C1a4e12a3d53547ff60e108d7985df6e6%7C20e5b14899e942519006662b26413b94%7C1&sdata=iEKgLUC5lRvwiCtBm%2B%2BE5a13q0%2BuDgTAcU2ZjsuE1pw%3D&reserved=0, or unsubscribehttps://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fnotifications%2Funsubscribe-auth%2FACQEUJDLN6KCD6B2UDMHJDDQ5S5QHANCNFSM4GR2ZVYA&data=01%7C01%7Canthony%40mattas.net%7C1a4e12a3d53547ff60e108d7985df6e6%7C20e5b14899e942519006662b26413b94%7C1&sdata=PrfwAq3Tct%2FMc3xNTEtkbwq1cq4crtbPOm%2BScU69QME%3D&reserved=0.

[grantalewis]

I'm neither a Github guru nor a competent lutron.py programmer so I'm going to leave this in others' hands. I'll just say that from my perspective the initial problem mentioned in this thread is resolved and is unrelated to your #29642. I'm guessing you're likely to get more traction in that other thread.