search

tonesto7 / homebridge-hubitat-tonesto7

Hubitat Homebridge Plugin
107 stars 34 forks source link

500 Error when turning lights on/off using Cloud API #26

Closed jorhett closed 3 years ago

jorhett commented 4 years ago

Verify the following before opening an trouble issue

Go over all the following points, and put an x in all the boxes that apply. If you're unsure about any of these, don't hesitate to ask. We're here to help!

About Your Setup

Expected Behavior

Tell us what you think should be happening

When I turn off a light, it should turn off IRL When I turn on a light, it should turn on IRL

Current Behavior

What happens instead of the expected behavior?

The change shows up in Apple Home app, the change is logged on Hubitat... but it doesn't actually happen.

Steps to Reproduce (for bugs)

Provide a link to a live example, or an unambiguous set of steps to reproduce this bug. Include code to reproduce, if relevant

  1. Tap light switch to turn on or off does not work
  2. Set level does work

Please include a copy of any relevant log output to assist in tracking down the bug

Logs on Homebridge show a 500 error for on/off operations but not for setlevel

11/7/2020, 5:06:44 am] [Hubitat-v2] NOTICE: Sending Device Command: on | Name: (Living Room Backlights) | DeviceID: (42) | LocalCommand: (false)
[11/7/2020, 5:06:45 am] [Hubitat-v2] ERROR: sendDeviceCommand Error: [object Object] | Message: Request failed with status code 500
[11/7/2020, 5:06:45 am] [Hubitat-v2] NOTICE: Sending Device Command: setLevel | Value: {"value1":92} | Name: (Living Room Backlights) | DeviceID: (42) | LocalCommand: (false)
[11/7/2020, 5:06:47 am] [Hubitat-v2] INFO: [Device Event]: (Living Room Backlights) [LEVEL] is 92

Logs on Hubitat show only the setLevel event:

app:712 2020-11-07 05:07:46.063 am debugHomebridge (v2.0.8) | Code versions: [plugin:2.0.8, mainApp:2.0.8]
app:712 2020-11-07 05:06:47.835 am debugHomebridge (v2.0.8) | Sending DEVICE Event (Living Room Backlights | LEVEL: 92%)  to Homebridge at (172.31.2.128:8000)
app:712 2020-11-07 05:06:47.745 am info Homebridge (v2.0.8) | Command Successful for Device Living Room Backlights | Command [setLevel(92)]
dev:42 2020-11-07 05:06:47.736 am infoLiving Room Backlights level was set to 92%
app:712 2020-11-07 05:06:47.681 am info Homebridge (v2.0.8) | Process Command | DeviceId: 42 | Command: (setLevel) | Param1: (92)
tonesto7 commented 4 years ago

You have a communication issue likely caused by a firewall.
These are really basic HTTP requests so if the devices are online and the config is correct they should work unless a firewall is blocking the port on the plugin side

jorhett commented 4 years ago

You have a communication issue likely caused by a firewall. These are really basic HTTP requests so if the devices are online and the config is correct they should work unless a firewall is blocking the port on the plugin side

Look at the logs I supplied again. How does something blocking a port let through fader operations but not on/off?

I can assure you there is no firewall in place. I'm happy to assist you with debugging.

jorhett commented 4 years ago

![Uploading Screen Shot 2020-11-07 at 11.40.02 AM.png…]()

jorhett commented 4 years ago

Of note, FYI I'm not quite sure at least for this purpose that your GOOD debug logging has much value. It seems to be echoing a code block, rather than showing us the data sent or received.

[11/7/2020, 4:59:10 am] [Hubitat-v2] GOOD: [CHARACTERISTIC (function On() {
        var _this = _super.call(this, 'On', On.UUID) || this;
        _this.setProps({
            format: "bool" /* BOOL */,
            perms: ["pr" /* READ */, "pw" /* WRITE */, "ev" /* NOTIFY */]
        });
        _this.value = _this.getDefaultValue();
        return _this;
    }) GET] switch (P3 - Crystals) | LastUpdate: (Sat Nov 07 2020 04:56:56 GMT-0800 (Pacific Standard Time)) | Value: (false)

Shouldn't this perhaps be DEBUG, while some of the much more concise DEBUG logs would seem to be more useful?

[11/7/2020, 12:02:37 pm] [Hubitat-v2] DEBUG: sendStartDirect Resp: {"status":"OK"}

This is a bit confused I think (as per my edits on this message) by the choice to send GOOD logs when debug is enabled:

 if (this.logConfig.debug === true) this.log.good(`[CHARACTERISTIC (${char}) GET]

And of note, when an operation fails there is no debug output--which seems like the ideal time to dump some data.

[11/7/2020, 4:59:07 am] [Hubitat-v2] NOTICE: Sending Device Command: on | Name: (P4 - Breeze Fan) | DeviceID: (809) | LocalCommand: (false)
[11/7/2020, 4:59:08 am] [Hubitat-v2] ERROR: sendDeviceCommand Error: [object Object] | Message: Request failed with status code 500
jorhett commented 4 years ago

27 is IMHO a logging improvement. It doesn't seem likely to cause other issues but your judgement call

jorhett commented 4 years ago

Okay, some more debugging. Don't know if the initial registration is the problem, but disabling Cloud now works for local devices. And switch on/off works fine locally! Flip back to cloud, on/off doesn't work. Back to local it works fine. So something is wrong with the Cloud update for on/off that doesn't affect setLevel

It appears err.response is undefined when a 500 error happens, so replacing that with JSON.stringify(err) I get this output:

DEBUG: Sending {"method":"post","url":"https://cloud.hubitat.com/api/2020abcd-1a2b-3c4d-5e6f-123456abcdef/apps/512/808/command/on","params":{"access_token":"1a2b3c4d-9f8e-1a2b-3c4d-9f8e7d6d5c4b1fdd71"},"headers":{"evtsource":"Homebridge_Hubitat-v2_512","evttype":"hkCommand"},"timeout":5000}

ERROR: sendDeviceCommand {"message":"Request failed with status code 500","name":"Error","stack":"Error: Request failed with status code 500\n at createError (/homebridge/node_modules/homebridge-hubitat-tonesto7/node_modules/axios/lib/core/createError.js:16:15)\n at settle (/homebridge/node_modules/homebridge-hubitat-tonesto7/node_modules/axios/lib/core/settle.js:17:12)\n at IncomingMessage.handleStreamEnd (/homebridge/node_modules/homebridge-hubitat-tonesto7/node_modules/axios/lib/adapters/http.js:244:11)\n at IncomingMessage.emit (events.js:327:22)\n at endReadableNT (_stream_readable.js:1220:12)\n at processTicksAndRejections (internal/process/task_queues.js:84:21)","config":{"url":"https://cloud.hubitat.com/api/2020abcd-1a2b-3c4d-5e6f-123456abcdef/apps/712/808/command/on","method":"post","headers":{"Accept":"application/json, text/plain, */*","Content-Type":"application/x-www-form-urlencoded","evtsource":"Homebridge_Hubitat-v2_512","evttype":"hkCommand","User-Agent":"axios/0.21.0"},"params":{"access_token":"1a2b3c4d-9f8e-1a2b-3c4d-9f8e7d6d5c4b1fdd71"},"transformRequest":[null],"transformResponse":[null],"timeout":5000,"xsrfCookieName":"XSRF-TOKEN","xsrfHeaderName":"X-XSRF-TOKEN","maxContentLength":-1,"maxBodyLength":-1}} | Message: Request failed with status code 500

tonesto7 commented 4 years ago

You've been busy :) Thanks for working on this stuff... I'm not sure why you are seeing so many errors, but I'm glad someone is reviewing the logging to make it more readable useful.

I'm in the middle of working on v2.1.0 of the main app and I will make sure to merge any more finding you make into v2.1.0 of the plugin.

I just tested using cloud and I'm able to duplicate your finding of the 500 errors. I will investigate and get the fix out in the next release

jorhett commented 4 years ago

Thank you for developing this! It been been tremendously useful.

I really suspect my errors were around regenerating and regenerating the access token. The last two times I was super careful to regenerate then completely exit the app and I've had no problems (other than the 500 for this)

Everything else is working fantastically!

tonesto7 commented 4 years ago

I tracked the issue down. It's because I wasn't passing the header key 'Content-Type': 'application/json' :(

tonesto7 commented 3 years ago

This issue is now resolved and the fix is in the latest code