Pico Remotes not responding about homebridge-lutron-caseta-leap HOT 117 CLOSED

Yes, let it run for a while, and when you notice it not working, give me a big dump. It's probably better to save it to a text file and then attach the file here.

from homebridge-lutron-caseta-leap.

No issues since upgrading to v2.3.2 and am just now upgrading to v2.3.3. I’ll report back in a couple days if any issues.

from homebridge-lutron-caseta-leap.

@thenewwazoo First off I love this plugin and being able to use my pico remotes for other things is great. I wanted to let you know I did a clean install on homebridge. Same issue as other users have had using 2.3.3. Restarting homebridge fixes the problem temporarily. Just wanted to let you know it's still happening.

from homebridge-lutron-caseta-leap.

many many thanks to @monitron for catching what I believe to be the bug that's causing this problem! v2.3.4 was just released and should fix it once and for all. please let me know if it recurs.

from homebridge-lutron-caseta-leap.

I'm having this problem as well. It happens when one of my Apple TV Hubs is "offline" - the first Apple TV to be setup as a HomeKit hub works with the Pico remotes, another HomeKit hub doesn't work if the first hub configured goes offline.

I don't think that's the same issue. The issue referenced in this thread happens when all other bridges/accessories are still online. You might want to open a new incident to avoid cluttering this one with unrelated logs/comments.

from homebridge-lutron-caseta-leap.

Okay, I spent some time thinking and refactored how the whole ping loop stuff works. I think @gautamvasudevan was on to something - if it takes a long time to write to the socket, that can cause improper timeouts. See the commit message for a bit more on what changed.

I've published 2.3.5 that adopts this new version of the client lib and would greatly appreciate feedback. And, as always, thank you all for the reports and help.

I just installed the new release, I should know within a few hours if it solved the issue or not, at least in my environment.

from homebridge-lutron-caseta-leap.

Two hours in and still going strong! By now, it would usually stop working. Looks like we might be in the green, I will update tonight at 9pm EST.

from homebridge-lutron-caseta-leap.

That’s fantastic news, thank you for the report. I’ll let it bake a bit longer before I close the issue but I’m optimistic!

from homebridge-lutron-caseta-leap.

@MoTechnicalities I actually recently got a donation from a gracious user, and your comment reminded me to (finally) buy a development Smart Bridge device (the only other one I have is "in production") using that money. So hopefully I'll be able to fix that problem soon! :)

Thanks to you both for the updates. I'm sad that the bug is still being seen in the wild. :(

from homebridge-lutron-caseta-leap.

Thank you both so much for the support, both monetarily and helping test so many times. I'm just a dude who likes writing code and it's so encouraging to feel appreciated.

from homebridge-lutron-caseta-leap.

Thank you for the report! If you could enable debug logging (see the readme) and include that output here, that will help.

from homebridge-lutron-caseta-leap.

Thanks for the help and big thanks for developing this awesome plugin! This was what ultimately made me get HomeBridge setup. I enabled the leap:* debug option and restarted. I'm not sure what part of the logs you want but here is what happens when I trigger a Pico button. Of course since I just restarted HomeBridge it works as expected. Do you want me to provide some other logs or should I try to capture the logs the next time it fails?

2022-03-09T16:21:37.843Z leap:responseparser handling data {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/128/status/event","ClientTag":"7b1eccf1-a54b-4e59-affa-d21edc2c52fb"},"Body":{"ButtonStatus":{"Button":{"href":"/button/128"},"ButtonEvent":{"EventType":"Press"}}}}

2022-03-09T16:21:37.843Z leap:responseparser buffer is 
2022-03-09T16:21:37.843Z leap:responseparser parsing line {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/128/status/event","ClientTag":"7b1eccf1-a54b-4e59-affa-d21edc2c52fb"},"Body":{"ButtonStatus":{"Button":{"href":"/button/128"},"ButtonEvent":{"EventType":"Press"}}}}
2022-03-09T16:21:37.843Z leap:message:bodytype parsing body type OneButtonStatusEvent with data: {
  ButtonStatus: {
    Button: { href: '/button/128' },
    ButtonEvent: { EventType: 'Press' }
  }
}
2022-03-09T16:21:37.843Z leap:protocol got response to tag 7b1eccf1-a54b-4e59-affa-d21edc2c52fb
2022-03-09T16:21:37.844Z leap:protocol tag 7b1eccf1-a54b-4e59-affa-d21edc2c52fb  not in flight
2022-03-09T16:21:37.844Z leap:protocol tag 7b1eccf1-a54b-4e59-affa-d21edc2c52fb  has a subscription
2022-03-09T16:21:38.150Z leap:protocol got data from socket: {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/128/status/event","ClientTag":"7b1eccf1-a54b-4e59-affa-d21edc2c52fb"},"Body":{"ButtonStatus":{"Button":{"href":"/button/128"},"ButtonEvent":{"EventType":"Release"}}}}

2022-03-09T16:21:38.151Z leap:responseparser handling data {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/128/status/event","ClientTag":"7b1eccf1-a54b-4e59-affa-d21edc2c52fb"},"Body":{"ButtonStatus":{"Button":{"href":"/button/128"},"ButtonEvent":{"EventType":"Release"}}}}

2022-03-09T16:21:38.151Z leap:responseparser buffer is 
2022-03-09T16:21:38.151Z leap:responseparser parsing line {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/128/status/event","ClientTag":"7b1eccf1-a54b-4e59-affa-d21edc2c52fb"},"Body":{"ButtonStatus":{"Button":{"href":"/button/128"},"ButtonEvent":{"EventType":"Release"}}}}
2022-03-09T16:21:38.151Z leap:message:bodytype parsing body type OneButtonStatusEvent with data: {
  ButtonStatus: {
    Button: { href: '/button/128' },
    ButtonEvent: { EventType: 'Release' }
  }
}
2022-03-09T16:21:38.151Z leap:protocol got response to tag 7b1eccf1-a54b-4e59-affa-d21edc2c52fb
2022-03-09T16:21:38.154Z leap:protocol tag 7b1eccf1-a54b-4e59-affa-d21edc2c52fb  not in flight
2022-03-09T16:21:38.154Z leap:protocol tag 7b1eccf1-a54b-4e59-affa-d21edc2c52fb  has a subscription
[3/9/2022, 10:21:38 AM] [Lutron] Button  /button/128 on Pico remote Office Pico was released; notifying Homekit
2022-03-09T16:21:38.373Z leap:protocol got data from socket: {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/7/status/level"},"Body":{"ZoneStatus":{"href":"/zone/7/status","Level":0,"Zone":{"href":"/zone/7"},"StatusAccuracy":"Good"}}}

2022-03-09T16:21:38.373Z leap:responseparser handling data {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/7/status/level"},"Body":{"ZoneStatus":{"href":"/zone/7/status","Level":0,"Zone":{"href":"/zone/7"},"StatusAccuracy":"Good"}}}

2022-03-09T16:21:38.373Z leap:responseparser buffer is 
2022-03-09T16:21:38.373Z leap:responseparser parsing line {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/7/status/level"},"Body":{"ZoneStatus":{"href":"/zone/7/status","Level":0,"Zone":{"href":"/zone/7"},"StatusAccuracy":"Good"}}}
2022-03-09T16:21:38.373Z leap:message:bodytype parsing body type OneZoneStatus with data: {
  ZoneStatus: {
    href: '/zone/7/status',
    Level: 0,
    Zone: { href: '/zone/7' },
    StatusAccuracy: 'Good'
  }
}
2022-03-09T16:21:38.373Z leap:protocol got untagged, unsolicited response
2022-03-09T16:21:38.373Z leap:bridge bridge 01f1cdde got unsolicited message:
2022-03-09T16:21:38.373Z leap:bridge Response {
  Header: {
    MessageBodyType: 'OneZoneStatus',
    StatusCode: ResponseStatus { message: 'OK', code: 200 },
    Url: '/zone/7/status/level'
  },
  CommuniqueType: 'ReadResponse',
  Body: OneZoneStatus {
    ZoneStatus: {
      href: '/zone/7/status',
      Level: 0,
      Zone: [Object],
      StatusAccuracy: 'Good'
    }
  }
}
2022-03-09T16:21:38.408Z leap:protocol got data from socket: {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/5/status/level"},"Body":{"ZoneStatus":{"href":"/zone/5/status","Level":0,"SwitchedLevel":"Off","Zone":{"href":"/zone/5"},"StatusAccuracy":"Good"}}}

2022-03-09T16:21:38.409Z leap:responseparser handling data {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/5/status/level"},"Body":{"ZoneStatus":{"href":"/zone/5/status","Level":0,"SwitchedLevel":"Off","Zone":{"href":"/zone/5"},"StatusAccuracy":"Good"}}}

2022-03-09T16:21:38.409Z leap:responseparser buffer is 
2022-03-09T16:21:38.409Z leap:responseparser parsing line {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/5/status/level"},"Body":{"ZoneStatus":{"href":"/zone/5/status","Level":0,"SwitchedLevel":"Off","Zone":{"href":"/zone/5"},"StatusAccuracy":"Good"}}}
2022-03-09T16:21:38.409Z leap:message:bodytype parsing body type OneZoneStatus with data: {
  ZoneStatus: {
    href: '/zone/5/status',
    Level: 0,
    SwitchedLevel: 'Off',
    Zone: { href: '/zone/5' },
    StatusAccuracy: 'Good'
  }
}
2022-03-09T16:21:38.409Z leap:protocol got untagged, unsolicited response
2022-03-09T16:21:38.409Z leap:bridge bridge 01f1cdde got unsolicited message:
2022-03-09T16:21:38.409Z leap:bridge Response {
  Header: {
    MessageBodyType: 'OneZoneStatus',
    StatusCode: ResponseStatus { message: 'OK', code: 200 },
    Url: '/zone/5/status/level'
  },
  CommuniqueType: 'ReadResponse',
  Body: OneZoneStatus {
    ZoneStatus: {
      href: '/zone/5/status',
      Level: 0,
      SwitchedLevel: 'Off',
      Zone: [Object],
      StatusAccuracy: 'Good'
    }
  }
}
2022-03-09T16:21:38.424Z leap:protocol got data from socket: {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/5/status/level"},"Body":{"ZoneStatus":{"href":"/zone/5/status","Level":0,"SwitchedLevel":"Off","Zone":{"href":"/zone/5"},"StatusAccuracy":"Good"}}}

2022-03-09T16:21:38.424Z leap:responseparser handling data {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/5/status/level"},"Body":{"ZoneStatus":{"href":"/zone/5/status","Level":0,"SwitchedLevel":"Off","Zone":{"href":"/zone/5"},"StatusAccuracy":"Good"}}}

2022-03-09T16:21:38.424Z leap:responseparser buffer is 
2022-03-09T16:21:38.424Z leap:responseparser parsing line {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OneZoneStatus","StatusCode":"200 OK","Url":"/zone/5/status/level"},"Body":{"ZoneStatus":{"href":"/zone/5/status","Level":0,"SwitchedLevel":"Off","Zone":{"href":"/zone/5"},"StatusAccuracy":"Good"}}}
2022-03-09T16:21:38.424Z leap:message:bodytype parsing body type OneZoneStatus with data: {
  ZoneStatus: {
    href: '/zone/5/status',
    Level: 0,
    SwitchedLevel: 'Off',
    Zone: { href: '/zone/5' },
    StatusAccuracy: 'Good'
  }
}
2022-03-09T16:21:38.424Z leap:protocol got untagged, unsolicited response
2022-03-09T16:21:38.424Z leap:bridge bridge 01f1cdde got unsolicited message:
2022-03-09T16:21:38.424Z leap:bridge Response {
  Header: {
    MessageBodyType: 'OneZoneStatus',
    StatusCode: ResponseStatus { message: 'OK', code: 200 },
    Url: '/zone/5/status/level'
  },
  CommuniqueType: 'ReadResponse',
  Body: OneZoneStatus {
    ZoneStatus: {
      href: '/zone/5/status',
      Level: 0,
      SwitchedLevel: 'Off',
      Zone: [Object],
      StatusAccuracy: 'Good'
    }
  }
}

from homebridge-lutron-caseta-leap.

When I woke up this morning none of the Pico would respond. I've attached the full debug log. I'll hold off on rebooting homebridge in case there is anything you need me to test while in a broken state. Thanks for your help!

homebridge.log.txt

from homebridge-lutron-caseta-leap.

I too am having this same issue. Next time it happens I will pull logs and post.

from homebridge-lutron-caseta-leap.

Taking a look at the log, it looks like there’s a problem recovering from a lost connection. @Pottebaum, the log you posted starts after the problem manifests. Any chance you could post the full log from /var/lib/homebridge/homebridge.log ?

from homebridge-lutron-caseta-leap.

I'm not quite sure how to do that. The log I provided was from the HomeBridge UI, under logs, then the download button. The size seems to be the same as the file that lives at homebridge/homebridge.log, which might be the same as what you are looking for? If I traverse up to the root of /var/lib/ there is no homebridge folder.

That said, I'm running Homebridge on a Hyper-V VM and don't seem to have SSH access so I'm a bit stuck in trying to figure out how to actually copy the log file directly from the file system and not via HomeBridge. I'll keep looking but open to any suggestions.

from homebridge-lutron-caseta-leap.

Ah okay it looks like the log rolled over, then. Drat. At least I’ve got a direction to look. That code has always been a bit shit anyway.

from homebridge-lutron-caseta-leap.

Ok. I’ll restart and try to capture a new set of logs when it fails again. Maybe that will include the needed info.

I don’t recall having this issue with the previous version but I only had it running for a few days before the current version was released and I upgraded. Hard to say with any confidence that the problem was introduced with the current version or not.

Appreciate your help. This plug-in ads a ton of use for these remotes!

from homebridge-lutron-caseta-leap.

Updated log from today when it failed is attached.
homebridge.log (3).txt

from homebridge-lutron-caseta-leap.

Hm, I'm not sure what's happening. That log runs from 2022-03-11T18:09:20.919Z to 2022-03-11T19:48:24.468Z, so not much time, and looks like it's chopped off at the beginning. More than that, though, it doesn't appear to show the same symptom the older log did, with the repeated reconnection. My own log file looks similarly truncated, which is problematic. I'm not sure what's up.

from homebridge-lutron-caseta-leap.

I went ahead and fully removed the plugin and configs and then re-installed. We'll see if that makes any difference.

from homebridge-lutron-caseta-leap.

homebridge.log.txt

Here is my latest log. I have deleted all but the last few days, this morning around 8:00am was when I noticed my remote not working. Hope this helps.

If needed I can pull the log that goes back to March 3rd, but I don't know if that much data would be helpful.

from homebridge-lutron-caseta-leap.

@UNEXPhotography thanks for the update. Unfortunately, that log doesn't include debug info, so I'm still unsure what the underlying issue is. Something is causing the bridge to be re-detected and scanned, and I'm not sure what.

I spent some more time staring at the code, and noticed that the ping response timeout is 1s. On even lightly loaded Rpi hardware, that's proven to be far shorter than is typical. I just pushed out a new version that increases it to 10s. If my hunch is correct, this should at least reduce the symptom.

The client code is still busted somehow, but I'm not talented enough to see what I'm doing wrong.

from homebridge-lutron-caseta-leap.

There's definitely something weird going on with existing-bridge detection. There are situations in which a bridge will re-announce itself on the network (I don't know what they are). When this happens, the BridgeManager should look in its map and see that the bridge is known. For some reason, an already-known bridge is getting treated like it's being seen for the first time.

I have a sneaking suspicion it's capitalization of the bridge ID...

from homebridge-lutron-caseta-leap.

Okay, I think I also found a related bug that did indeed involve the bridge ID. I've pushed out 2.3.2. LMK how it goes.

from homebridge-lutron-caseta-leap.

I upgraded last night when you posted and will let you know how it goes.

from homebridge-lutron-caseta-leap.

Huzzah. I think I was just able to observe it in my home system.

from homebridge-lutron-caseta-leap.

Okay, I spent some time refactoring the LeapClient code, and published v2.3.3. I'm still not super confident in it, but it's simpler now, at least, and I don't forcibly remove listeners, which I think was a dumb idea.

from homebridge-lutron-caseta-leap.

Bah. Happened this morning. I'm still not sure what's going on, and my attempts to improve logging ended up accidentally removing log lines. The root symptom is a connection loop in the client, and when that happens, things get fucky.

from homebridge-lutron-caseta-leap.

Thanks for your work on this plugin, @thenewwazoo. I'm experiencing the same issue with 2.3.3. Every so often I see a log entry "Bridge ________ already known, closing." and the Pico remotes don't work until I restart the child bridge.

from homebridge-lutron-caseta-leap.

Thanks for confirming the issue still exists. It (completely unscientifically) seems to be rarer in 2.3.3, but I'm still pretty stumped on what the problem could be. :(

from homebridge-lutron-caseta-leap.

I concur it seems to be much less frequent in 2.3.3. Before I could count on it failing daily but now I go several days before it stops working.

from homebridge-lutron-caseta-leap.

Bug still persists for me

from homebridge-lutron-caseta-leap.

Well shit. What hardware are you running? How often is it happening?

from homebridge-lutron-caseta-leap.

I am running homebridge 1.3.4 and the most up to day version of the plugin.

from homebridge-lutron-caseta-leap.

Happening to me as well, all latest versions. Just stops working. All other homebridge and native Lutron work fine during this.

from homebridge-lutron-caseta-leap.

Frustrating that I can't reproduce it locallly, and log retention in homebridge is hard-coded at 1 MB, which is less than an hour of debug logs. 😠

from homebridge-lutron-caseta-leap.

I installed 1.3.4 when it was released and so far no issues. These last 2 versions have greatly reduced how often the plugin stops working for me. Went from pretty much every day prior to 1.3.3 to every few days. I can't explain why though.

Not sure if helps but I'm running HomeBridge on a HyperV VM and all my network gear is Ubiquity. No changes in my setup from the early version of the plugin to the current version that would explain why it fails less often for me now.

from homebridge-lutron-caseta-leap.

The two big changes were increasing timeouts and the latest fix that would prevent a crash. I think there's some ordering problem I can't nail down when the connection dies, though, and it (sometimes?) can't recover.

from homebridge-lutron-caseta-leap.

Just dropping in to say I'm seeing the same issue. I have a cron job to restart my HomeBridge docker container each night at 11pm and the pico remotes work for a short time after that, but by the morning they are back to not working at all.

from homebridge-lutron-caseta-leap.

I also notice when these disconnects happen it can actually affect all Luton switches it seems. Almost like there is a crash on the whole system. Anyone else notice that? I am on the latest versions.

from homebridge-lutron-caseta-leap.

That’s super strange. Can you enable debug logging and make a copy of the log file every hour or so?

from homebridge-lutron-caseta-leap.

@Zacklock if it’s that reliable and fast, can you please enable debug logging and send me the complete log from shortly after it stops working?

from homebridge-lutron-caseta-leap.

By setting the debug variable as described in the readme, it only enables debug output for my plug-in, so it’s limited in its effect and there’s nothing sensitive in the output from this code. I can come up with a regex to match against but it’ll be a few days before I’m in front of a computer

from homebridge-lutron-caseta-leap.

The timeout happens almost 1 second after the log saying that the ping has been sent.

So if I had to guess, occasionally it takes a really long time for ping to get sent. The promise timeout and the ping are expected to happen simultaneously, but apparently that's not the case here. So rather than waiting 10 seconds, it appears to have not waited long enough. That explains why increasing the timeout from 1 second to 10 seconds made the problem less consistent (but not impossible).

I wonder if that could be fixed by moving the ping so it completes before the race.

    private pingLoop(): void {
        const pingPromise = this.ping(); // wait till this happens outside of the promise.race
        const timeout = new Promise((resolve, reject): void => {
            setTimeout((): void => {
                reject('Ping timeout');
            }, PING_TIMEOUT_MS);
        });

        // now we have both promises and the ping has definitely been sent before we start the timeout.
        Promise.race([pingPromise, timeout])
            .then(() => {
                clearTimeout(this.pingLooper);
                this._setPingTimeout();
            })
            .catch((e) => {
                logDebug(e);
                this.client.close();
            });
    }

from homebridge-lutron-caseta-leap.

I believe I am running into this same issue with Lutron Caseta LEAP 2.3.4 and Homebridge 1.4.1 My occupancy sensors and pico remotes will go unresponsive after a period of 3-18 hours after a homebridge restart. In order to resolve, I restart homebridge again, and the LEAP accessories are responsive for another 3-18 hours.

I think @gautamvasudevan is right, this is related to the ping code. Each time the issue occurs, the last entries are similar to the following:

2022-05-06T16:51:33.049Z leap:protocol added promise to inFlightRequests with tag key d9e3fae3-6ace-49af-a4ea-fe75cdebc80b
2022-05-06T16:51:33.049Z leap:protocol request handler about to write: {"CommuniqueType":"ReadRequest","Header":{"ClientTag":"d9e3fae3-6ace-49af-a4ea-fe75cdebc80b","Url":"/server/1/status/ping"}}
2022-05-06T16:51:33.049Z leap:protocol sent request tag d9e3fae3-6ace-49af-a4ea-fe75cdebc80b  successfully
2022-05-06T16:51:33.052Z leap:protocol got data from socket: {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"d9e3fae3-6ace-49af-a4ea-fe75cdebc80b"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}

2022-05-06T16:51:33.052Z leap:responseparser handling data {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"d9e3fae3-6ace-49af-a4ea-fe75cdebc80b"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}

2022-05-06T16:51:33.052Z leap:responseparser buffer is 
2022-05-06T16:51:33.052Z leap:responseparser parsing line {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"d9e3fae3-6ace-49af-a4ea-fe75cdebc80b"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}
2022-05-06T16:51:33.052Z leap:message:bodytype parsing body type OnePingResponse with data: { PingResponse: { LEAPVersion: 1.114 } }
2022-05-06T16:51:33.052Z leap:protocol got response to tag d9e3fae3-6ace-49af-a4ea-fe75cdebc80b
2022-05-06T16:51:33.052Z leap:protocol tag d9e3fae3-6ace-49af-a4ea-fe75cdebc80b  recognized as in-flight
2022-05-06T16:52:33.053Z leap:protocol added promise to inFlightRequests with tag key 63fc43ef-8948-4363-afbe-2a2c093bcf06
2022-05-06T16:52:33.053Z leap:protocol request handler about to write: {"CommuniqueType":"ReadRequest","Header":{"ClientTag":"63fc43ef-8948-4363-afbe-2a2c093bcf06","Url":"/server/1/status/ping"}}
2022-05-06T16:52:33.053Z leap:protocol sent request tag 63fc43ef-8948-4363-afbe-2a2c093bcf06  successfully
2022-05-06T16:52:34.053Z leap:bridge Ping timeout
2022-05-06T16:52:34.054Z leap:protocol client socket has closed.

Another instance:

2022-05-03T22:48:48.982Z leap:protocol added promise to inFlightRequests with tag key bbac2621-de24-4d45-923f-9b07e80d4ad1
2022-05-03T22:48:48.982Z leap:protocol request handler about to write: {"CommuniqueType":"ReadRequest","Header":{"ClientTag":"bbac2621-de24-4d45-923f-9b07e80d4ad1","Url":"/server/1/status/ping"}}
2022-05-03T22:48:49.010Z leap:protocol sent request tag bbac2621-de24-4d45-923f-9b07e80d4ad1  successfully
2022-05-03T22:48:49.985Z leap:bridge Ping timeout
2022-05-03T22:48:50.001Z leap:protocol client socket has closed.

The plugin never recovers automatically, and requires a Homebridge restart.

I am fairly certain there is no network issue, the native Lutron functions are responsive even when this issue occurs, and the Lutron Bridge is connected directly via ethernet to the same switch as the server running homebridge.

from homebridge-lutron-caseta-leap.

Okay, I spent some time thinking and refactored how the whole ping loop stuff works. I think @gautamvasudevan was on to something - if it takes a long time to write to the socket, that can cause improper timeouts. See the commit message for a bit more on what changed.

I've published 2.3.5 that adopts this new version of the client lib and would greatly appreciate feedback. And, as always, thank you all for the reports and help.

from homebridge-lutron-caseta-leap.

I'm having this problem as well. It happens when one of my Apple TV Hubs is "offline" - the first Apple TV to be setup as a HomeKit hub works with the Pico remotes, another HomeKit hub doesn't work if the first hub configured goes offline.

from homebridge-lutron-caseta-leap.

Because that interaction isn't between the Homebridge plugin and the Smart Bridge 2, I strongly suspect that's a different, unrelated issue. If you can gather some more information, please file a new issue to track that problem.

from homebridge-lutron-caseta-leap.

2022-05-07T16:30:49.805Z leap:protocol:client request handler about to write: {"CommuniqueType":"ReadRequest","Header":{"ClientTag":"4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927","Url":"/server/1/status/ping"}}
2022-05-07T16:30:49.806Z leap:protocol:client added promise to inFlightRequests with tag key 4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927
2022-05-07T16:30:49.806Z leap:protocol:client sent request tag 4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927  successfully
2022-05-07T16:30:49.808Z leap:protocol:client got data from socket: {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}

2022-05-07T16:30:49.809Z leap:responseparser handling data {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}

2022-05-07T16:30:49.809Z leap:responseparser buffer is 
2022-05-07T16:30:49.809Z leap:responseparser parsing line {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}
2022-05-07T16:30:49.810Z leap:message:bodytype parsing body type OnePingResponse with data: { PingResponse: { LEAPVersion: 1.114 } }
2022-05-07T16:30:49.810Z leap:protocol:client got response to tag 4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927
2022-05-07T16:30:49.811Z leap:protocol:client tag 4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927  recognized as in-flight
2022-05-07T16:30:49.811Z leap:bridge Ping succeeded Response {
  Header: {
    MessageBodyType: 'OnePingResponse',
    StatusCode: ResponseStatus { message: 'OK', code: 200 },
    Url: '/server/1/status/ping',
    ClientTag: '4a3fbc7e-ef58-4b3c-8b0c-4f75f2c8a927'
  },
  CommuniqueType: 'ReadResponse',
  Body: OnePingResponse { PingResponse: { LEAPVersion: 1.114 } }
}
2022-05-07T16:31:04.107Z leap:protocol:client got data from socket: {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/107/status/event","ClientTag":"c59ba2f7-d4f3-4f55-ad95-88ea254cb374"},"Body":{"ButtonStatus":{"Button":{"href":"/button/107"},"ButtonEvent":{"EventType":"Press"}}}}

2022-05-07T16:31:04.107Z leap:responseparser handling data {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/107/status/event","ClientTag":"c59ba2f7-d4f3-4f55-ad95-88ea254cb374"},"Body":{"ButtonStatus":{"Button":{"href":"/button/107"},"ButtonEvent":{"EventType":"Press"}}}}

2022-05-07T16:31:04.107Z leap:responseparser buffer is 
2022-05-07T16:31:04.108Z leap:responseparser parsing line {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/107/status/event","ClientTag":"c59ba2f7-d4f3-4f55-ad95-88ea254cb374"},"Body":{"ButtonStatus":{"Button":{"href":"/button/107"},"ButtonEvent":{"EventType":"Press"}}}}
2022-05-07T16:31:04.109Z leap:message:bodytype parsing body type OneButtonStatusEvent with data: {
  ButtonStatus: {
    Button: { href: '/button/107' },
    ButtonEvent: { EventType: 'Press' }
  }
}
2022-05-07T16:31:04.109Z leap:protocol:client got response to tag c59ba2f7-d4f3-4f55-ad95-88ea254cb374
2022-05-07T16:31:04.109Z leap:protocol:client tag c59ba2f7-d4f3-4f55-ad95-88ea254cb374  not in flight
2022-05-07T16:31:04.109Z leap:protocol:client tag c59ba2f7-d4f3-4f55-ad95-88ea254cb374  has a subscription
[5/7/2022, 12:31:04 PM] [Lutron] handling event from button  /button/107
[5/7/2022, 12:31:04 PM] [Lutron] button  /button/107  was  Press
2022-05-07T16:31:04.337Z leap:protocol:client got data from socket: {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/107/status/event","ClientTag":"c59ba2f7-d4f3-4f55-ad95-88ea254cb374"},"Body":{"ButtonStatus":{"Button":{"href":"/button/107"},"ButtonEvent":{"EventType":"Release"}}}}

2022-05-07T16:31:04.337Z leap:responseparser handling data {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/107/status/event","ClientTag":"c59ba2f7-d4f3-4f55-ad95-88ea254cb374"},"Body":{"ButtonStatus":{"Button":{"href":"/button/107"},"ButtonEvent":{"EventType":"Release"}}}}

2022-05-07T16:31:04.337Z leap:responseparser buffer is 
2022-05-07T16:31:04.338Z leap:responseparser parsing line {"CommuniqueType":"UpdateResponse","Header":{"MessageBodyType":"OneButtonStatusEvent","StatusCode":"200 OK","Url":"/button/107/status/event","ClientTag":"c59ba2f7-d4f3-4f55-ad95-88ea254cb374"},"Body":{"ButtonStatus":{"Button":{"href":"/button/107"},"ButtonEvent":{"EventType":"Release"}}}}
2022-05-07T16:31:04.338Z leap:message:bodytype parsing body type OneButtonStatusEvent with data: {
  ButtonStatus: {
    Button: { href: '/button/107' },
    ButtonEvent: { EventType: 'Release' }
  }
}
2022-05-07T16:31:04.338Z leap:protocol:client got response to tag c59ba2f7-d4f3-4f55-ad95-88ea254cb374
2022-05-07T16:31:04.339Z leap:protocol:client tag c59ba2f7-d4f3-4f55-ad95-88ea254cb374  not in flight
2022-05-07T16:31:04.339Z leap:protocol:client tag c59ba2f7-d4f3-4f55-ad95-88ea254cb374  has a subscription
[5/7/2022, 12:31:04 PM] [Lutron] handling event from button  /button/107
[5/7/2022, 12:31:04 PM] [Lutron] Button  /button/107 on Pico remote Office Pico was released; notifying Homekit
[5/7/2022, 12:31:49 PM] [Bond] UDP message sent to 192.168.253.12:30007
[5/7/2022, 12:31:49 PM] [Bond] UDP Message received from 192.168.253.12:30007 - {"B":"ZZFB09578","d":2,"v":"v2.28.0"}
2022-05-07T16:31:49.805Z leap:protocol:client request handler about to write: {"CommuniqueType":"ReadRequest","Header":{"ClientTag":"27515cb7-cf55-481f-874d-2218e69e2d98","Url":"/server/1/status/ping"}}
2022-05-07T16:31:49.805Z leap:protocol:client added promise to inFlightRequests with tag key 27515cb7-cf55-481f-874d-2218e69e2d98
2022-05-07T16:31:49.806Z leap:protocol:client sent request tag 27515cb7-cf55-481f-874d-2218e69e2d98  successfully
2022-05-07T16:31:49.808Z leap:protocol:client got data from socket: {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"27515cb7-cf55-481f-874d-2218e69e2d98"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}

2022-05-07T16:31:49.808Z leap:responseparser handling data {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"27515cb7-cf55-481f-874d-2218e69e2d98"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}

2022-05-07T16:31:49.808Z leap:responseparser buffer is 
2022-05-07T16:31:49.808Z leap:responseparser parsing line {"CommuniqueType":"ReadResponse","Header":{"MessageBodyType":"OnePingResponse","StatusCode":"200 OK","Url":"/server/1/status/ping","ClientTag":"27515cb7-cf55-481f-874d-2218e69e2d98"},"Body":{"PingResponse":{"LEAPVersion":1.114}}}
2022-05-07T16:31:49.809Z leap:message:bodytype parsing body type OnePingResponse with data: { PingResponse: { LEAPVersion: 1.114 } }
2022-05-07T16:31:49.809Z leap:protocol:client got response to tag 27515cb7-cf55-481f-874d-2218e69e2d98
2022-05-07T16:31:49.809Z leap:protocol:client tag 27515cb7-cf55-481f-874d-2218e69e2d98  recognized as in-flight
2022-05-07T16:31:49.810Z leap:bridge Ping succeeded Response {
  Header: {
    MessageBodyType: 'OnePingResponse',
    StatusCode: ResponseStatus { message: 'OK', code: 200 },
    Url: '/server/1/status/ping',
    ClientTag: '27515cb7-cf55-481f-874d-2218e69e2d98'
  },
  CommuniqueType: 'ReadResponse',
  Body: OnePingResponse { PingResponse: { LEAPVersion: 1.114 } }
}

from homebridge-lutron-caseta-leap.

Nine hours and still no issues, all my remotes are responding as expected. They’d be non-responsive for certain by now on previous builds.

from homebridge-lutron-caseta-leap.

That’s fantastic news, thank you for the report. I’ll let it bake a bit longer before I close the issue but I’m optimistic!

You asked me to continue here from #42

I power cycled my Luton bridge and it is now working with no errors.

Thank you for all the hard work. If there was a donate button I'd hook you up.

from homebridge-lutron-caseta-leap.

@Pottebaum how is this build working for you? I have been running it since Saturday afternoon and my Pico remotes are still working perfectly.

from homebridge-lutron-caseta-leap.

It's now been roughly 40 hours since I updated to 2.3.6, and have not had a hang since. Usually I would've seen a ping timeout by now, so this is a really good sign the change has been effective. I'll post again in a few days with updates.

from homebridge-lutron-caseta-leap.

I just got the updated version installed a few minutes ago. Initially it is working as expected. I'll report back in a day or two with an update.

Appreciate everyone's help in troubleshooting this issue as this plugin has been a huge help in getting WAY more use out of my pico remotes :-).

from homebridge-lutron-caseta-leap.

I’ve been having the same issue. I’m running Lurton Caseta Leap 2.3.6 on a HOOBS box. Works as expected after restarting the bridge, but at some point there is an error and the pico remote no longer responds. I’m new to HOOBS/Homebridge, so I’m not very versed in troubleshooting. My log below.

5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORconnection failed:  Error: read ETIMEDOUT
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORat TLSWrap.onStreamRead (node:internal/stream_base_commons:217:20) {
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORerrno: -110,
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORcode: 'ETIMEDOUT',
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORsyscall: 'read'
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERROR}
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORsocket error: Error: read ETIMEDOUT
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORat TLSWrap.onStreamRead (node:internal/stream_base_commons:217:20) {
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORerrno: -110,
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORcode: 'ETIMEDOUT',
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORsyscall: 'read'
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERRORclient socket has closed.
5/10/2022, 7:27:07 AMLutron Caseta Leap BridgeERROR}
5/10/2022, 2:26:38 PMhub is running on port 80
5/10/2022, 2:26:40 PMDummy Bridge starting
5/10/2022, 2:26:41 PMLutron Caseta Leap Bridge starting
5/10/2022, 2:26:49 PMDummy BridgeLoaded plugin 'homebridge-dummy'
5/10/2022, 2:26:49 PMDummy BridgeLoading 1 accessories...
5/10/2022, 2:26:50 PMLutron Caseta Leap BridgeLoaded plugin 'homebridge-lutron-caseta-leap'
5/10/2022, 2:26:50 PMDummy BridgeBridge is running on port 51836.
5/10/2022, 2:26:50 PMLutron Caseta Leap BridgeLoading 1 platforms...
5/10/2022, 2:26:50 PMLutron Caseta Leap BridgeLutronCasetaLeapLutronCasetaLeap starting up...
5/10/2022, 2:26:50 PMLutron Caseta Leap BridgeLutronCasetaLeapLutronCasetaLeap plugin finished early initialization
5/10/2022, 2:26:50 PMLutron Caseta Leap BridgeLutronCasetaLeapRestoring cached Pico3ButtonRaiseLower 152b5a8e-79b5-4fb4-987a-48de93d14a07 on bridge 04cd09b1
5/10/2022, 2:26:50 PMLutron Caseta Leap BridgeLutronCasetaLeapRestoring Pico remote Master Bedroom Pico on bridge 04cd09b1
5/10/2022, 2:26:50 PMLutron Caseta Leap BridgeLutronCasetaLeapFinished launching; starting up automatic discovery
5/10/2022, 2:26:50 PMLutron Caseta Leap BridgeBridge is running on port 51826.
5/10/2022, 2:26:51 PMLutron Caseta Leap BridgeLutronCasetaLeapDevice type SmartBridge supported natively, skipping setup
5/10/2022, 2:26:51 PMLutron Caseta Leap BridgeLutronCasetaLeapDevice type WallDimmer supported natively, skipping setup
5/10/2022, 2:26:51 PMLutron Caseta Leap BridgeLutronCasetaLeapDevice type WallDimmer supported natively, skipping setup
5/10/2022, 2:26:51 PMLutron Caseta Leap BridgeLutronCasetaLeapDevice type CasetaFanSpeedController supported natively, skipping setup
5/10/2022, 2:26:51 PMLutron Caseta Leap BridgeLutronCasetaLeapAccessory Pico3ButtonRaiseLower 152b5a8e-79b5-4fb4-987a-48de93d14a07 Master Bedroom Pico already set up. Skipping.
5/10/2022, 2:26:51 PMLutron Caseta Leap BridgeLutronCasetaLeapFinished setting up Pico remote Master Bedroom Pico
5/10/2022, 6:44:22 PMLutron Caseta Leap BridgeLutronCasetaLeapButton  /button/106 on Pico remote Master Bedroom Pico was released; notifying Homekit
5/10/2022, 6:44:26 PMLutron Caseta Leap BridgeLutronCasetaLeapButton  /button/108 on Pico remote Master Bedroom Pico was released; notifying Homekit
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORconnection failed:  Error: read ETIMEDOUT
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORat TLSWrap.onStreamRead (node:internal/stream_base_commons:217:20) {
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORerrno: -110,
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORcode: 'ETIMEDOUT',
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORsyscall: 'read'
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERROR}
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORsocket error: Error: read ETIMEDOUT
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORat TLSWrap.onStreamRead (node:internal/stream_base_commons:217:20) {
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORerrno: -110,
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORcode: 'ETIMEDOUT',
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORsyscall: 'read'
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERROR}
5/10/2022, 7:27:50 PMLutron Caseta Leap BridgeERRORclient socket has closed.
5/11/2022, 2:32:49 AMLutron Caseta Leap BridgeLutronCasetaLeapBridge 04CD09B1 already known, closing.
5/11/2022, 2:32:55 AMLutron Caseta Leap BridgeLutronCasetaLeapBridge 04CD09B1 already known, closing.
5/11/2022, 2:32:58 AMLutron Caseta Leap BridgeLutronCasetaLeapBridge 04CD09B1 already known, closing.

from homebridge-lutron-caseta-leap.

I updated to v2.3.6 4-days ago, and all worked properly until this AM.
I'll apologize in advance for not turning on Debugging...it's now enabled...and I'll post logs if/when future issues arise.

Anyway. I was trying to think of things that could be contributing to the (infrequent) loss of Pico communication. The only thing that I can say specifically happened that is outside of 'normal' is that I used the Home App on iOS to control the Accessory that (one of) my Leap Picos is associated with last night.

The Accessory (it's a light) is normally controlled primarily by a Leap Pico, by Siri voice command...or by a Scene. Last night I activated the Accessory using the Tile in the iOS Home App (this is extremely rare for me to do) and turned it off using a Scene (as usual). Then when I got up in the middle of the night I tried to use the Pico and found it wasn't communicating/functioning.

I don't know if varied interaction method has an impact on how devices respond or communicate within HomeKit...or if this was simply an odd coincidence that I did something different than normal...and just happened to experience the Pico issue following. But. Either way. Thought I would mention it. Never know what may help solve a problem.

Also. Again. Sorry for not having Debugging enabled.

from homebridge-lutron-caseta-leap.

No worries at all - I don't usually recommend people leave debug logging enabled because it's so noisy.

The communications go like this:

[Smart Bridge 2] -- [plugin] -- [homebridge] -- [homekit devices]

The problem with this plugin is all the way on the left side; nothing you do with HomeKit can really affect that.

from homebridge-lutron-caseta-leap.

@primouomo81 that log looks confused, as it's not linear in time. can you please re-copy/paste it (just edit the existing comment), and enclose it in triple-backticks?

I don't use HOOBS, and don't really have any intention of supporting it, so I may not be able to help.

from homebridge-lutron-caseta-leap.

No worries at all - I don't usually recommend people leave debug logging enabled because it's so noisy.

The communications go like this:

[Smart Bridge 2] -- [plugin] -- [homebridge] -- [homekit devices]

The problem with this plugin is all the way on the left side; nothing you do with HomeKit can really affect that.

Just an FYI.

Seemingly random line showed-up in my HomeBridge UI log.
Nothing prompted it. Checked a couple of Leap Picos after seeing it...they seemed to be working.

[11/05/2022, 11:35:23] [Lutron] Bridge 01E12345 already known, closing.
Bridge number above is edited

from homebridge-lutron-caseta-leap.

Yeah, that line is okay. Bridges re-announce themselves, and we close the (duplicate) client once we know we're dealing with the same bridge.

from homebridge-lutron-caseta-leap.

I'm sad to report that my pico remotes stopped responding this morning. Worked for about 2 days since I updated to v2.3.7.

from homebridge-lutron-caseta-leap.

Yeah, same here - stopped responding last night. Will enable debug logs again.

from homebridge-lutron-caseta-leap.

[16/05/2022, 09:58:23] [Lutron] constructed bridges Map(0) {}
[16/05/2022, 09:58:23] [Lutron] Failed setting up Pico remote: Error: Timed out waiting for bridge to appear
    at Timeout._onTimeout (/usr/local/lib/node_modules/homebridge-lutron-caseta-leap/src/BridgeManager.ts:43:31)
    at listOnTimeout (node:internal/timers:559:17)
    at processTimers (node:internal/timers:502:7)
[16/05/2022, 09:58:23] [Lutron] pending map was Map(2) {
'<id>':     [
      [Function (anonymous)],
      Timeout {
        _idleTimeout: 15000,
        _idlePrev: null,
        _idleNext: null,
        _idleStart: 2437,
        _onTimeout: [Function (anonymous)],
        _timerArgs: undefined,
        _repeat: null,
        _destroyed: true,
        [Symbol(refed)]: true,
        [Symbol(kHasPrimitive)]: false,
        [Symbol(asyncId)]: 94,
        [Symbol(triggerId)]: 0
      }
    ],
    ... <repeat x 20>
  '<id2>':     [
      [Function (anonymous)],
      Timeout {
        _idleTimeout: 15000,
        _idlePrev: null,
        _idleNext: null,
        _idleStart: 2437,
        _onTimeout: [Function (anonymous)],
        _timerArgs: undefined,
        _repeat: null,
        _destroyed: true,
        [Symbol(refed)]: true,
        [Symbol(kHasPrimitive)]: false,
        [Symbol(asyncId)]: 94,
        [Symbol(triggerId)]: 0
      }
    ],
    ... <repeat x 20>

Both bridges are definitely online (and controllable), and the pi and the bridges are on the same unmanaged switch by ethernet.

from homebridge-lutron-caseta-leap.

apparently I'm having this issue as well, HomeBridge recognizes the Pico remote button events, but it doesn't seem to send it to HomeKit.

from homebridge-lutron-caseta-leap.

Here you can see that my Lutron bridge is communicating with HomeBridge, HomeBridge sees the button press, but I don't see in the debug logs where this plugin told HomeBridge to send notification to HomeKit of the button press.

[6/2/2022, 5:16:23 PM] [Lutron] bridge 02c1439f got unsolicited message Response {
Header: {
MessageBodyType: 'OneZoneStatus',
StatusCode: ResponseStatus { message: 'OK', code: 200 },
Url: '/zone/8/status/level'
},
CommuniqueType: 'ReadResponse',
Body: OneZoneStatus {
ZoneStatus: {
href: '/zone/8/status',
Level: 0,
SwitchedLevel: 'Off',
Zone: [Object],
StatusAccuracy: 'Good'
}
}
}
[6/2/2022, 5:16:23 PM] [Lutron] bridge 02c1439f got unsolicited message Response {
Header: {
MessageBodyType: 'OneZoneStatus',
StatusCode: ResponseStatus { message: 'OK', code: 200 },
Url: '/zone/8/status/level'
},
CommuniqueType: 'ReadResponse',
Body: OneZoneStatus {
ZoneStatus: {
href: '/zone/8/status',
Level: 0,
SwitchedLevel: 'Off',
Zone: [Object],
StatusAccuracy: 'Good'
}
}
}
[6/2/2022, 5:18:59 PM] [Lutron] handling event from button /button/109
[6/2/2022, 5:18:59 PM] [Lutron] button /button/109 was Press
[6/2/2022, 5:18:59 PM] [Lutron] handling event from button /button/109
[6/2/2022, 5:18:59 PM] [Lutron] Button /button/109 on Pico remote Office Pico was released; notifying Homekit

from homebridge-lutron-caseta-leap.

Pretty sure this is causing a crash on the Lutron hub as my Lutron lights have been very unstable while running this. Sometimes none of them will respond and I have to reboot the hub. Before this I never had any connection issues ever with my Lutron’s and I have had them for 4 years

from homebridge-lutron-caseta-leap.

Oof. That's... not great. Unfortunately, life has been pulling me away from investigating this any further, but I sincerely apologize :( I can't promise I'll have much time to dedicate, but I'll make another attempt as soon as I can.

from homebridge-lutron-caseta-leap.

I tried loading this pluggin in a child instance, I thought that seemed to help until I started testing. I found that if I press any button(s) too quickly, it seems to break the plugin. If I press a button, and wait 5-10 seconds before pressing another button, it seems to be a bit more stable. Resetting the child instance also seems to kick the buttons back into gear. I'll keep testing.

from homebridge-lutron-caseta-leap.

That’s a weird one. Since it’s reproducible, can you file a new ticket and attach debug logs?

from homebridge-lutron-caseta-leap.

I'm finding no correlation between button presses and time outs.

Seemingly random. On the same note on the boot of a plugin it takes awhile to register button presses too.

from homebridge-lutron-caseta-leap.

@thenewwazoo

Having the same problem.

Pico remotes stop sending triggers in HomeKit after a few hours.

If I reboot Homebridge they'll come back and work for awhile and then quit working after a bit again.

They still work fine inside of the Lutron system of course.

Caseta LEAP Version: 2.4.2
Homebridge Version: 1.5.0
Caseta Pro 2 Bridge

If it's helpful at all towards anything I can look at getting some debug logs of it working and not working.

As it is right now though I have reboot my Homebridge install every few hours to keep it working.

from homebridge-lutron-caseta-leap.

Frustrating.

I actually went as far as to write a little SmartBridge simulator and can't immediately reproduce the problem. I'm going to gradually increase the sophistication of the simulation, to include mDNS announcements, and I'll have to figure out what else to do.

from homebridge-lutron-caseta-leap.

This may or may not be helpful at all, but thought I'd throw out some variables I noticed in my testing.

I had previously had homebridge running on an old dell poweredge r720 with vmware ESXi 5.5 as a hypervisor, and Ubuntu focal as the host for homebridge. I was running into this scenario where Picos stopped responding every 24 hours or so. I noticed in the Caseta Leap debug logs that the commands from the button presses registered, but it appeared the signal was never passed through homebridge to homekit (assuming here, it doesn't look like this communication is logged).

I switched to installing Ubuntu Jammy bare metal on an old intel macbook, and the issue is virtually gone. I've had it occurr once in 2 and a half months since switching.

There seems to be a homebridge host variable involved, though I've changed so many variables it's hard to isolate from my situation.

from homebridge-lutron-caseta-leap.

Just wanted to add another datapoint. Having the same issue and need to restart Homebridge every few days otherwise the Picos are unresponsive. Running a on Pi with Portainer.

from homebridge-lutron-caseta-leap.

Just want to report something good!

Whatever changes you made under v2.4.3 (Final Release) has made the buttons much more reliable! Specifically, I use several button actions to trigger HomeKit SSH commands to control my WiZ bulbs built in special scenes. Until now if I hadn't used the buttons for a few hours I would often have to try 3 or 4 times before the buttons would finally work. Now, they seem to work on the first attempt every time!

Things are looking good!😁

from homebridge-lutron-caseta-leap.

Is anyone still experiencing this problem? I still haven't found a way to reproduce :(

from homebridge-lutron-caseta-leap.

Honestly, my Picos are pretty stable.
I have my Caseta bridge plugged into the ethernet port of my Xfinity xFi Pod. So the only issue is probably related to #82 because in my setup, if for any reason internet drops, then the xFi Pod drops, which causes the Caseta bridge to lose the link to Homebridge and it never restores until a Homebridge reboot. I'm not at option at the moment to change me network setup at the moment but if #82 gets a fix then I believe even that issue will go away.

from homebridge-lutron-caseta-leap.

My Picos have been much more stable over the last 6 months or so. I can’t say they have never disconnected but it is very infrequent.

from homebridge-lutron-caseta-leap.

The big problem I've got is that I can't reproduce the problem, and thus can't observe it, but a packet capture from a user is the next best thing. To that end, if anyone reading this is interested in providing me with a long-running capture of all network traffic between your plugin and the smart bridge, the newly-released version v2.4.4-beta0 will enable that.

Here's the thing - I have no idea how big such a packet capture will be. It could be several gigabytes. I mean, it probably won't be, but it might be. So please don't try it if there's a risk of crashing something or filling up an important disk.

Still interested?

First thing to do is to upgrade to this new version. That adds support for an undocumented configuration option logSSLKeyDangerous (it's not actually dangerous, I just don't want people setting it for no reason). You'll want to set it to true and then do not yet restart Homebridge, so your config will look something like:

            "platform": "LutronCasetaLeap",
            "options": {
                "filterPico": true,
                "filterBlinds": true,
                "clickSpeed": "medium",
                "clickSpeedLong": "default",
                "clickSpeedDouble": "default",
                "logSSLKeyDangerous": true
            }

Once that's done, log into your Homebridge server and grab the smart bridge's IP address. You'll need the dig command available:

pi@homebridge:~ $ sudo apt-get install dnsutils

Now get the IP address. You're looking for the line that says 10 IN A...

pi@homebridge:~ $ dig @224.0.0.251 -p 5353 -t ptr _lutron._tcp.local

; <<>> DiG 9.11.5-P4-5.1+deb10u8-Raspbian <<>> @224.0.0.251 -p 5353 -t ptr _lutron._tcp.local
; (1 server found)
;; global options: +cmd
;; Got answer:
;; WARNING: .local is reserved for Multicast DNS
;; You are currently testing what happens when an mDNS query is leaked to DNS
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 12098
;; flags: qr aa; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 4

;; QUESTION SECTION:
;_lutron._tcp.local.		IN	PTR

;; ANSWER SECTION:
_lutron._tcp.local.	10	IN	PTR	Lutron\032Status._lutron._tcp.local.

;; ADDITIONAL SECTION:
Lutron\032Status._lutron._tcp.local. 10	IN SRV	0 0 22 Lutron-032e7e88.local.
Lutron\032Status._lutron._tcp.local. 10	IN TXT	"MACADDR=90:70:65:e3:8f:25" "CODEVER=08.08.21f000" "DEVCLASS=08040100" "FW_STATUS=1:NoUpdate" "NW_STATUS=InternetWorking" "ST_STATUS=good" "SYSTYPE=SmartBridge"
Lutron-032e7e88.local.	10	IN	A	192.168.1.151
Lutron-032e7e88.local.	10	IN	AAAA	fe80::9270:65ff:fee3:8f25

;; Query time: 1 msec
;; SERVER: 192.168.1.151#5353(224.0.0.251)
;; WHEN: Tue Jan 03 22:55:26 PST 2023
;; MSG SIZE  rcvd: 303

In this example, the IP address is 192.168.1.151.

Now install the tcpdump program:

pi@homebridge:~ $ sudo apt-get install tcpdump
...

In a place where you can reasonably store a few GB of data (in case it comes to that), run the following tcpdump command:

# edit: first run this
sudo -l
password:
...

#okay now run this on linux:
sudo nohup tcpdump -i eth0 -nn -s0 -v -w homebridge-lutron.pcap host 192.168.1.151 &
#or this on a mac:
sudo nohup tcpdump -i en0 -nn -s0 -v -w homebridge-lutron.pcap host 192.168.1.151 &

except replace the IP address there with your Smart Bridge's IP address. Now restart Homebridge.

After however long it takes for the problem to occur, you'll need to send me the homebridge-lutron.pcap file, along with the key log file that's now in /tmp/, named something like "XXXXXXXX-tlskey.log".

from homebridge-lutron-caseta-leap.

this file: homebridge-lutron.pcap should be in the location that you run the tcpdump?

from homebridge-lutron-caseta-leap.

I edited the comment to add a step to "prime" sudo before running nohup.

Yes, homebridge-lutron.pcap (or whatever you name the file) will be in the current directory when you run tcpdump.

from homebridge-lutron-caseta-leap.

I think I figured it out. It's a stupid bug. As they always are.

from homebridge-lutron-caseta-leap.

Okay, I just released v2.4.5-beta0.

Basically, when the plugin starts up, it says to the bridge "yo dawg, let me know when shit happens". When the plugin loses its connection to the bridge, the bridge will stop sending updates. Obviously. Even if the plugin reconnects, because the bridge has no idea it's the "same" client, and the plugin never asks again.

So now, when the plugin loses its connection, it'll tell the bridge (again) to send updates.

from homebridge-lutron-caseta-leap.

Awesome, I really appreciate your continued work on this plugin, it adds so much value to the pico remotes! Donation heading your way.

from homebridge-lutron-caseta-leap.

Rock solid here so far for days. I’m bullish that this is resolved. No jinx. Sent a small donation. Appreciates the efforts. This is my fav plugin.

from homebridge-lutron-caseta-leap.

Yeah! No issues here!

from homebridge-lutron-caseta-leap.

from homebridge-lutron-caseta-leap.

No issues here for the last few days either!

from homebridge-lutron-caseta-leap.

Working great!
Trusting it to where I've hardwired a couple boxes for constant power to lamps and replaced the switches with new Pico's, giving me access to the great features of my WiZ bulbs💡

Thank you much!

from homebridge-lutron-caseta-leap.

from homebridge-lutron-caseta-leap.

@carbonappsx can you confirm that you're running 2.4.5-beta0?

from homebridge-lutron-caseta-leap.

Strange, but at least this morning, I had to reboot the child bridge before my Pico's would respond. I reboot only the child bridge running this plugin. 1/29 6:20am EST. Will log hear next time to keep track.

from homebridge-lutron-caseta-leap.

from homebridge-lutron-caseta-leap.

Still rock solid here. Child bridge.

from homebridge-lutron-caseta-leap.

I am having to reboot my child bridge for the remote to work and saw that this is an open issue. It seems to get disconnected after a couple days.

So I just mapped my Lutron hub to a static IP to see if that might help with anything. Will report back in a few days to update if the issue persists or if that might resolve.

Not sure how the communication is happening between the the plugin, homebridge (ie. Raspberry Pi network interface) and the Lutron hub, but I wonder if it's router/firewall related as they are on separate subnets.

from homebridge-lutron-caseta-leap.

from homebridge-lutron-caseta-leap.

@enz1ey and @arjunmehta can you both confirm you're running 2.4.5-beta0?

from homebridge-lutron-caseta-leap.

@thenewwazoo Yes can confirm running 2.4.5-beta0 on my end.

The issue did reoccur even though I fixed the IP on our Lutron hub and Homebridge.

from homebridge-lutron-caseta-leap.

So upsetting that this still goes randomly non-active. If only this great feature were directly implemented into the Caseta hub by Lutron. It would be so much better for everyone, including them! One 5-button Pico has so much more value that Five 1-button Flic buttons!

from homebridge-lutron-caseta-leap.