homebridge-vera icon indicating copy to clipboard operation
homebridge-vera copied to clipboard

Characteristic Warnings

Open tsfischer opened this issue 4 years ago • 22 comments

Homebridge 1.3.1 (latest)

Getting many messages in the log of the following form. The embedded link says to report to the plugin developer:

[2/24/2021, 8:44:15 AM] [homebridge-vera] This plugin generated a warning from the characteristic 'On': SET handler returned write response value, though the characteristic doesn't support write response. See https://git.io/JtMGR for more info. [Dining Room Lights@Dining Room Lights@On] SET handler returned write response value, though the characteristic doesn't support write response [2/24/2021, 8:44:16 AM] [homebridge-vera] This plugin generated a warning from the characteristic 'On': SET handler returned write response value, though the characteristic doesn't support write response. See https://git.io/JtMGR for more info. [Dining Room Lights@Dining Room Lights@On] SET handler returned write response value, though the characteristic doesn't support write response [2/24/2021, 8:44:17 AM] [homebridge-vera] This plugin generated a warning from the characteristic 'On': SET handler returned write response value, though the characteristic doesn't support write response. See https://git.io/JtMGR for more info. [Dining Room Lights@Dining Room Lights@Brightness] SET handler returned write response value, though the characteristic doesn't support write response

tsfischer avatar Feb 24 '21 15:02 tsfischer

Looked into this further. I'm just beginning to come up to speed on Homebridge plugin coding, but I believe the offending code is in lib/types/Dimmer.js. The setters should not be returning a value with the callback calls. If you look at other types such as switch.js they are not. I'd prefer someone more experienced confirm this before I would attempt to create a fix PR.

tsfischer avatar Feb 24 '21 17:02 tsfischer

You are spot on. This was coded long ago and more recently this has become an anti pattern. Glad to see verbose and helpful debugging. That said, I encourage you to submit a PR. It sounds like it will largely just be a few lines removed. 🙂

drewcovi avatar Feb 24 '21 20:02 drewcovi

Well I tried doing the changes myself, and I must be missing something subtle with how this all works because changing the setter callback from something like callback(null, value) to either callback(null) or callback() causes weird things to happen when controlling the lights. For example I turn the light on, and it immediately turns back off. Sometimes off and on multiple times. When I go back to the original version of the code all is well.

So maybe HB is still using the value being passed back, even though it complains about it?

tsfischer avatar Feb 24 '21 21:02 tsfischer

Super strange... I know that in homebridge-hubitat it’s often just callback(null); in the setter, and that works great for most use cases. So the debugging seems aligned with the direction you’re headed. That callback really deals more with updating the HomeKit state than any calls to Vera. So I’m surprised to hear it’s impacting your lights.

drewcovi avatar Feb 24 '21 22:02 drewcovi

Yeah, I was wondering if maybe the state wasn't getting updated properly without explicitly passing it into the callback, and therefore HK retried the command or some such?

I'm still trying to wrap my head around how the plugin architecture works so I may be way off.

tsfischer avatar Feb 24 '21 22:02 tsfischer

I’ve never seen it re-attempt unprompted. If you don’t use the callback it usually fails. So definitely worth digging into. Just leverage a lot of console logs to see where it might be getting called. I’ll give some thought to how the status check (which refreshes quite frequently) might be impacting this update. But everything you’re doing seems right.

drewcovi avatar Feb 24 '21 22:02 drewcovi

Further note on this: you’ll see some logic that waits a beat before returning the callback. That’s meant to ensure the status polling doesn’t cause the ui to get confused (setting a “sending” flag to prevent polling temporarily and then resuming it after the change is reflected in the status).

drewcovi avatar Feb 24 '21 22:02 drewcovi

Played with this a bit more tonight. The following is an example of what's logged in debug mode during 'flaky' behavior:

Fri, 26 Feb 2021 05:19:28 GMT VeraLink Caching status... Fri, 26 Feb 2021 05:19:29 GMT VeraLink Caching status... Fri, 26 Feb 2021 05:19:30 GMT VeraLink Dining Room Lights Power state changed to false Fri, 26 Feb 2021 05:19:30 GMT VeraLink Requesting: http://192.168.10.99:3480/data_request?id=lu_action&output_format=json Fri, 26 Feb 2021 05:19:30 GMT VeraLink Dining Room Lights Power state changed to true Fri, 26 Feb 2021 05:19:30 GMT VeraLink Requesting: http://192.168.10.99:3480/data_request?id=lu_action&output_format=json Fri, 26 Feb 2021 05:19:30 GMT VeraLink Caching status... Fri, 26 Feb 2021 05:19:31 GMT VeraLink Caching status... Fri, 26 Feb 2021 05:19:32 GMT VeraLink Caching status... Fri, 26 Feb 2021 05:19:33 GMT VeraLink Caching status...

In this case, I'm trying to turn the light off, and it immediately (within a second) turns back on. When I revert back to the shipping version, it works 100% of the time.

Can you tell me where the "VeraLink Caching status..." message is coming from? I can't seem to find it in the code.

tsfischer avatar Feb 26 '21 05:02 tsfischer

It’s a shared function for all devices to ensure status is updated. Vera didn’t (might now) have websockets in their api. So we poll the status api and refesh the status of all devices. so you’ll find it in the functions file (one dir higher). Which line are you altering?

drewcovi avatar Feb 26 '21 12:02 drewcovi

I just wasn't seeing the code that actually outputted that debug string, which made me feel like I was missing something. If you get a chance can you point me to a file/line # where that message gets logged?

I'm attaching a patch file for the code that I'm changing. For now it's only in the dimmer type, this will need to be done with a number of other types too but I'm just trying to get this working first. characteristingwarn.diff.zip

tsfischer avatar Feb 26 '21 16:02 tsfischer

you may be comparing the installed npm package to the master branch here, which will show you the latest in the beta tags. I'd check which version you're on and checkout that tag to see a 1:1 reflection of the code in the plugin.

drewcovi avatar Feb 26 '21 16:02 drewcovi

I haven't tagged what's on master quite yet, as it's not entirely ready for prime time.

drewcovi avatar Feb 26 '21 16:02 drewcovi

Got it. I'm not a node/Javascript/et all guy (I'm a Mac/iOS app developer, and have done Windows in the past) so I'm more than a bit out of my element. But I'm trying to learn lol.

tsfischer avatar Feb 26 '21 16:02 tsfischer

@tsfischer it's definitely worth the effort, particularly when you can feel a degree of ownership over your own home automation. here's where I had pulled it out to reduce noise (it was getting to the point where it wasn't really adding value and simply filling up logs) https://github.com/damianxd/homebridge-vera/commit/7f3a99f46b78df5146b9e8c15ab2e3f4d27964e7#

drewcovi avatar Feb 26 '21 16:02 drewcovi

Oh perfect! So it was just a versioning thing. I thought I was missing something bigger.

Yeah, that was a pretty chatty log message :)

tsfischer avatar Feb 26 '21 16:02 tsfischer

Wow I hadn't even noticed that the latest official release is 5 years old. What are the plans going forward for this plugin? Even the PR mentioned above is a couple years old.

tsfischer avatar Feb 26 '21 16:02 tsfischer

Has it been that long??? Plans are honestly somewhat limited. @damianxd has since moved on to Homey (I believe and he’ll keep me honest). I finally pulled the trigger on Hubitat to get Z-Wave 700 support (and lower level control with Groovy drivers).

I can say before the switch I was running the beta without issue. But yes. Happy to embrace the support of the community here. Pass the torch since I really can’t confidently verify code changes on my end. I’ll likely update the readme with a request, and then we can add folks as collaborators (and also provide collaborator access to NPM).

drewcovi avatar Feb 26 '21 16:02 drewcovi

Actually I'm running 0.8.2 (3 years ago) which isn't even tagged in this repo so . I'm not clear on how things are being done with this repo.

tsfischer avatar Feb 26 '21 16:02 tsfischer

You can always install custom versions by updating your package.json. Or even install master and get bleeding edge.

drewcovi avatar Feb 26 '21 17:02 drewcovi

Well good news, I figured out the error of my ways. I was uploading code to my HB server improperly and ending up with a mix of code from various versions.

So now if I were to do a PR, which branch/tag should I base it on?

tsfischer avatar Feb 27 '21 23:02 tsfischer

Master would be lovely, and I’d imagine we’re due for a new npm release soon 😁

drewcovi avatar Feb 27 '21 23:02 drewcovi

Do you need access to npm? El 27 de feb. de 2021 20:40 -0300, Drew Covi [email protected], escribió:

Master would be lovely, and I’d imagine we’re due for a new npm release soon 😁

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHubhttps://github.com/damianxd/homebridge-vera/issues/186#issuecomment-787204664, or unsubscribehttps://github.com/notifications/unsubscribe-auth/AAEIXNVNR3QOJIXQFUWRGC3TBF7GBANCNFSM4YEVTOYA.

damianxd avatar Feb 27 '21 23:02 damianxd