Plugin loads too slow about homebridge-hue HOT 13 CLOSED

Hi Daniel @DanielsCode

As far as I understand homebridge, the only way to overcome this structurally is by moving to the dynamic platform accessory model (see issue #4). Then, accessories can be added after homebridge has started, instead of only on startup time. With static platform accessories, homebridge waits a limited time (20 secs?) for platforms to issue the callback from the platform accessories() method, but then goes ahead anyway, ignoring late callbacks. Indeed, if the "found n accessories" message appears after the "homebridge is running on port nnnnn" message, the homebridge-hue callback came in too late.

The ECONNRESET indicates that the network connection between homebridge-hue and your Hue bridge broke. I've only seen this on a v1 bridge, when a homekit scene would cause more than 7 concurrent requests to the Hue bridge (see issue #15). We solved that by issuing a retry (as indicated in the log). This puzzles me though, since homebridge-hue would do fewer than 8 requests on startup. It could be a limitation on a RPi, where homebridge-hue and other plug-ins are competing for RPi network connections on startup. Did you get any ECONNRESETs when starting homebridge with only the homebrigde-hue plug-in? Are you starting homebridge manually or automatically when the RPi boots? I've had issues (on MacOS) that the network wasn't yet fully up when starting homebridge.

Troubleshooting these asynchronous issues is hard. Could you please start homebridge manually through homebridge -D > logfile and post the full logfile here? Could you also please post your full config.json? Are those 13 accessories all sensors, or lights, groups, ... as well? I assume your Hue bridge config isn't the issue, as homebridge-hue works fine when it's the only plug-in.

As a workaround, you could try running a separate instance of homebridge for the homebridge-hue plug-in, using the -U flag to indicate a different ~/.homebridge directory with a different config.json.

from homebridge-hue.

Hi Erik @ebaauw

thanks for your fast feedback. I did some more tests with log files. First, usually I start homebridge as a service like "/etc/init.d/homebridge start"

For debugging reason I started homebridge manually with different configs:

1. hue only:

{
   "bridge": {
       "name": "Homebridge",
       "username": "CC:88:3D:E3:CE:33",
       "port": 51826,
       "pin": "000-11-222"
    },

    "accessories": [
    ],

    "platforms": [
      {
          "platform": "Hue",
          "name": "Hue",
          "host": "192.168.1.35",
          "users": {
             "001788FFFE119783": "1yZPebdTrRut3Q2pi7STcBY53cwo73hECdXibR3t"
          },
          "heartrate": 5,
          "timeout": 5,
          "lights": true,
          "alllights": true,
          "groups": false,
          "sensors": true,
          "schedules": false,
          "rules": false
        }
    ]
}

Logfile: logfile_hue_only.txt

2. my usual config

{
    "bridge": {
        "name": "Homebridge",
        "username": "CC:88:3D:E3:CE:33",
        "port": 51826,
        "pin": "000-11-222"
    },

    "accessories": [
       {
           "accessory": "CMD",
           "name": "Radio",
           "on_cmd": "~/.homebridge/scripts/radio_on.sh",
           "off_cmd": "~/.homebridge/scripts/radio_off.sh"
       }
    ],

    "platforms": [
      {
          "platform": "Hue",
          "name": "Hue",
          "host": "192.168.1.35",
          "users": {
             "001788FFFE119783": "1yZPebdTrRut3Q2pi7STcBY53cwo73hECdXibR3t"
          },
          "heartrate": 5,
          "timeout": 5,
          "lights": true,
          "alllights": true,
          "groups": false,
          "sensors": true,
          "schedules": false,
          "rules": false
        },
        {
            "platform": "HomeMatic",
            "name": "HomeMatic CCU2",
            "ccu_ip": "192.168.1.31",
            "filter_device":[],
            "filter_channel":[],
            "outlets":[],
            "doors":[],
            "programs":[],
            "subsection":"Homekit"
        },
        {
           "platform": "HarmonyHub",
           "name": "Harmony Hub"
        }
    ]
}

Logfile: logfile_all.txt

The dynamic approach would be great.

Any other ideas as starting two homebridge services? Do you need further diagnostics?

from homebridge-hue.

Thanks, @DanielsCode

The standalone homebridge-hue log looks fine to me.

The all plug-in log does look troublesome, indeed. It looks like homebridge-hue actually found the bridge and is querying the bridge for the light and sensor states (at 11:42:39 and 11:42:40). The ECONNRESET (at 11:42:51) seems to be for querying the sensor states, which succeeds on retry, after which homebridge-hue reports its accessories to homebridge. However, homebridge is already running and no longer accepts the homebridge-hue accessories.

I think the conflict is with the HomeMatic plug-in. Looking at their source, they do a lot on startup, including a synchronous file read (index.js:179). The Harmony plug-in actually uses the dynamic platform accessory model, and the CMD plug-in doesn't seem to do any network requests on startup, so these plug-ins aren't impacted. I think your setup will run fine, if you remove only the HomeMatic plug-in.

The dynamic platform accessories approach is the structural solution, but this is a lot of work.

As a quick workaround, I could try and revert issue #3, doing a single GET / instead of separate GET /lights and GET /sensors. It would result in fewer network requests, but in more data per request. I'm still not sure which approach is the least resource intensive, on the Hue bridge as well as on the network. A single request will be more CPU intense on the RPi. As is takes 11 seconds to get the ECONNRESET, preventing that from happening would probably do the trick in your case.

from homebridge-hue.

Hi @ebaauw

What should I change to use single GET instead of separate ones? Of course, I will let you know if it fix the problem.

Disabling the homematic platform isn't a solution for me.

Thanks.

from homebridge-hue.

@DanielsCode
Install v0.0.19 ;-)

There was a 5 sec timeout in the homebridge-hue startup, that I forgot about. I removed that in v0.0.19 as well.

from homebridge-hue.

@ebaauw

Thanks a lot for this very fast update. I tried to update the package with

sudo npm -g update homebridge-hue

but if I check the version with npm list -g, I will see:

[email protected]

How can I perform this update?

from homebridge-hue.

@DanielsCode
Looking at sudo npm outdated -g, npm sees the latest homebridge-hue version but is happy with the currently installed version. For other packages (homebridge, npm itself), npm wants the latest version, so I guess I must have done something wrong. Unfortunately, I haven't got a clue what I should do to correct this. I tried deprecating the older versions, but npm is still happy keeping the old version.

Anyway, another sudo npm install -g homebridge-hue installs the latest version for me.

from homebridge-hue.

@DanielsCode
I published v0.1.0 and now sudo npm -g update seems to work. Apparently npm doesn't like 0.0.x versions.

from homebridge-hue.

@ebaauw

Hi,

sudo npm outdated -g showed me:

Package Current Wanted Latest Location
homebridge 0.4.11 0.4.11 0.4.12
homebridge-homematic 0.0.56 0.0.56 0.0.59
homebridge-hue 0.0.18 0.0.18 0.1.0
npm 3.10.8 4.0.5 4.0.3

I tried to update to v0.1.0 with sudo npm -g update homebridge-hue - but again it didn't work. Then I used sudo npm install -g to update homebrige, homebrighe-hue and homebridge-homematic.

Afterwards, I adjusted the config.json from alllights to philipslights and run homebridge manually. Unfortunately, I got an error ([2016-12-11 15:13:56] [Hue] Philips hue: hue bridge communication error ESOCKETTIMEDOUT) and only one accessories - see log file:
log_v0.1.0.txt

Did I miss something?

from homebridge-hue.

If you did miss something, @DanielsCode , then so do I...

Sorry, the correct command to capture the logfile is homebridge -D > logfile 2>&1, so that the error messages are captured as well. I understand that you only got one error message?

The one accessory is for the bridge itself. It's not doing anything, except dumping the full bridge state on Identify. Unfortunately, you need another app than iOS 10 Home to issue Identify. This one accessory is loading, however, so the homebridge-hue load time has definitely improved.

We do get a different error message now, ESOCKETTIMEDOUT instead of ECONNRESET. It looks like the get / at 15:13:45 is timing out and returning nothing, so homebridge-hue doesn't expose any bridge resources. Maybe it just needs a little more time. Could you change timeout in config.json to, say, 10 seconds and retry (now capturing the logfile with the 2>&1 bit). If that doesn't work, try increasing timeout, as long as the bridge accessory still loads. If the bridge accessory doesn't load, try decreasing timeout.

Note that it takes 4 seconds, before homebridge-hue gets to handle the response from the get /config at 15:13:41 -- it reports the bridge model and api version at 15:13:45. I my setup, these messages are issued within the same second. In your hue only logfile this only takes 1 second.
Also note that it takes 11 seconds, before homebridge-hue gets to handle the ESOCKETTIMEDOUT, of the get /, where the timeout occurs 5 seconds after the request (this is the timeout parameter). In your all logfile, homebridge-hue only gets to handle the ECONNRESET after 11 seconds as well.

With v0.1.0, homebridge-hue issues some more debug messages on startup and I'd like to see what it reports when it's working in your setup. Could you please capture a logfile with the HomeMatic plugin disabled, and post that logfile here. If that doesn't work either, could you please capture a logfile with only the homebridge-hue plugin enabled.

from homebridge-hue.

@ebaauw

yeah, I changed the timeout from 5 to 10 seconds and it works! Thanks a lot. Would you like to have the log files anyway?

from homebridge-hue.

That's good to hear, @DanielsCode !

Yes, please post the logfile with all plugins enabled and the homebridge-hue timeout to 10 seconds, so I have some documentation. Thanks.

from homebridge-hue.

@ebaauw

Sure. Here we go: logfile.txt

Thanks again for your work and your great support.

from homebridge-hue.