search

thenewwazoo / homebridge-lutron-caseta-leap

Homebridge support for Lutron Caseta Smart Bridge 2
Apache License 2.0
80 stars 28 forks source link

Pico Remotes not responding #31

Closed Pottebaum closed 1 year ago

Pottebaum commented 2 years ago

Describe The Bug: Multiple times over the last couple days Pico remotes that I have exposed via HomeKit will not respond. Other HomeBridge devices function during this time so it does not appear to be a HomeBridge wide issue. Other Lutron devices connected directly to HomeKit function as well.

When I restart Homebridge the problem is resolved for a period of time and the below expected behaviors function as expected.

To Reproduce: When experiencing the problem I can hit any Pico button that I have programmed in Home app and no trigger is fired.

Expected behavior: When you press a button on the Pico remote I expect:

  1. Log entry in HomeBridge
  2. Simulated button press in Home app
  3. Action defined in Home app to trigger

Logs:

I'm not sure what logs to include as no logs get added during the time the button presses don't trigger.  When it triggers as expected I get this log entry. 
[3/9/2022, 7:44:00 AM] [Lutron] Button  /button/126 on Pico remote Office Pico was released; notifying Homekit

I do get these entries in the log about every hour, unsure if that's related or not.  

[3/9/2022, 6:46:42 AM] [Lutron] Device type SmartBridge supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallDimmer supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower eca30f8b-b097-4978-adb0-34866f5b58c7 Living Room Pico already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallDimmer supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower 2f1f977e-2211-403f-a695-d714d20599d0 Upstairs Hallway Hallway South already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower ec9b1893-194e-4e16-9b62-d3eb0e0a4aed Upstairs Hallway Hallway North already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower 4468130e-861a-4929-986e-7d0814c733d4 Master Bedroom Door already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallDimmer supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Device type PlugInDimmer not recognized, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower 82e151bf-0b96-4cc6-bd61-b733ea13c9dc Game Room Game Room Kitchen already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallSwitch supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallDimmer supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower 26c272ad-4e4a-4d16-85f8-3c7f993d699a Office Pico already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Device type PlugInDimmer not recognized, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower fa015385-c890-4235-bedb-e21f6f35dcc5 Floor Lamp Remote 1 already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallSwitch supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallSwitch supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallDimmer supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallDimmer supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallDimmer supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Device type WallDimmer supported natively, skipping setup
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower 36f74796-23f0-42e5-9ea7-24d92466e0f0 Basement Pico already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower 758fa10e-3e6b-4711-8553-dccb5f51feec Basement Stairs Pico already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower 9e1eebd3-c28e-4801-9a62-daa6fefa801c Master Bedroom Bed already set up. Skipping.
[3/9/2022, 6:46:42 AM] [Lutron] Accessory Pico3ButtonRaiseLower 1b2062de-68d4-4871-b4c6-eea3ce52e5cd Upstairs Office Pico already set up. Skipping.

Plugin Config:

Show your Homebridge config.json here, remove any sensitive information.

Screenshots:

Environment:

thenewwazoo commented 2 years ago

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

Pottebaum commented 2 years ago

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'
    }
  }
}
thenewwazoo commented 2 years ago

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.

Pottebaum commented 2 years ago

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

UNEXPhotography commented 2 years ago

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

thenewwazoo commented 2 years ago

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 ?

Pottebaum commented 2 years ago

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.

thenewwazoo commented 2 years ago

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.

Pottebaum commented 2 years ago

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!

Pottebaum commented 2 years ago

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

thenewwazoo commented 2 years ago

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.

Pottebaum commented 2 years ago

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

UNEXPhotography commented 2 years ago

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.

thenewwazoo commented 2 years ago

@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.

thenewwazoo commented 2 years ago

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...

thenewwazoo commented 2 years ago

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.

Pottebaum commented 2 years ago

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

thenewwazoo commented 2 years ago

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

thenewwazoo commented 2 years ago

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.

Pottebaum commented 2 years ago

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.

thenewwazoo commented 2 years ago

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.

allizo commented 2 years ago

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.

thenewwazoo commented 2 years ago

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. :(

Pottebaum commented 2 years ago

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.

gray8211 commented 2 years ago

@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.

thenewwazoo commented 2 years ago

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.

gray8211 commented 2 years ago

Bug still persists for me

thenewwazoo commented 2 years ago

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

gray8211 commented 2 years ago

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

reboot-digital commented 2 years ago

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

thenewwazoo commented 2 years ago

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. 😠

Pottebaum commented 2 years ago

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.

thenewwazoo commented 2 years ago

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.

enz1ey commented 2 years ago

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.

reboot-digital commented 2 years ago

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.

thenewwazoo commented 2 years ago

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

thenewwazoo commented 2 years ago

@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?

thenewwazoo commented 2 years ago

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

gautamvasudevan commented 2 years ago

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();
            });
    }
gavinar1 commented 2 years ago

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.

thenewwazoo commented 2 years ago

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.

pknaz commented 2 years ago

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.

thenewwazoo commented 2 years ago

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.

pknaz commented 2 years ago 
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 } }
}
enz1ey commented 2 years ago

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.

enz1ey commented 2 years ago

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.

enz1ey commented 2 years ago

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.

enz1ey commented 2 years ago

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.

thenewwazoo commented 2 years ago

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!

wsmeyer90277 commented 2 years ago

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.