search

indigodomo / HomeKit-Bridge

Enabled HomeKit integration via Homebridge for Indigo Home Automation
The Unlicense
46 stars 13 forks source link

SecuritySpy race condition on restart #96

Open webdeck opened 6 years ago

webdeck commented 6 years ago

I restarted my Mac and the Indigo server started up before SecuritySpy. The result was that all of my cameras in HomeKit showed as unavailable until I restarted the HomeKit Bridge devices.

I suppose I can add triggers to restart the bridge when the cameras change state to active, but if that could be dealt with automatically, that would be cleaner.

webdeck commented 6 years ago

From the logs (excerpted):

2018-04-05 14:37:14.713 Application     Starting Indigo Server version 7.1.1 (Mac OS X 10.12.6)
2018-04-05 14:37:21.914 Application     Loading plugin "Cynical SecuritySpy 2.2.2"
2018-04-05 14:37:21.935 Application     Starting plugin "Cynical SecuritySpy 2.2.2" (pid 5850)
2018-04-05 14:37:21.936 Application     Loading plugin "HomeKit Bridge 0.22.1"
2018-04-05 14:37:21.943 Application     Starting plugin "HomeKit Bridge 0.22.1" (pid 5851)
2018-04-05 14:37:25.636 Cynical SecuritySpy     API version 2.0
2018-04-05 14:37:25.637 Cynical SecuritySpy     Python version 2.7.10.final.0
2018-04-05 14:37:25.996 Cynical SecuritySpy Error       SecuritySpy unavailable: [Errno 61] Connection refused
2018-04-05 14:37:25.999 Cynical SecuritySpy Error       Front Door Camera unavailable: host device SecuritySpy is unavailable
2018-04-05 14:37:26.000 Cynical SecuritySpy Error       Rear Door Camera unavailable: host device SecuritySpy is unavailable
2018-04-05 14:37:26.336 HomeKit Bridge Debug    Indigo JSON Stuffer 1.0.0 loaded
2018-04-05 14:37:26.336 HomeKit Bridge Debug    Indigo Plugin Redirector 1.0.0 loaded
2018-04-05 14:37:26.336 HomeKit Bridge Debug    Indigo Plugin User Interface 1.0.0 loaded
2018-04-05 14:37:26.336 HomeKit Bridge Debug    Indigo Plugin Factory 1.0.0 loaded
2018-04-05 14:37:26.336 HomeKit Bridge Debug    HomeKit Data Conversion 1.0.0 loaded
2018-04-05 14:37:26.337 HomeKit Bridge Debug    HomeKit Payload Processor 1.0.0 loaded
2018-04-05 14:37:26.337 HomeKit Bridge Debug    HomeKit Integration Factory for Indigo 1.0.0 loaded
2018-04-05 14:37:26.337 HomeKit Bridge  Caching all HomeKit Bridge devices...
2018-04-05 14:37:29.003 HomeKit Bridge Debug    Front Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:29.007 HomeKit Bridge Debug    Homebridge-Indigo2 Device Payload 1.0.0 loaded
2018-04-05 14:37:29.032 HomeKit Bridge Debug    Converting  keyword for HomeKit type or firmware on 'Front Door Camera'
2018-04-05 14:37:29.048 HomeKit Bridge Debug    Converting indigoVersion keyword for HomeKit type or firmware on 'Front Door Camera'
2018-04-05 14:37:29.052 HomeKit Bridge Debug    Homebridge-Indigo2 Payload Data 1.0.0 loaded
2018-04-05 14:37:29.053 HomeKit Bridge Debug    Homebridge-Indigo2 Payload Data 1.0.0 loaded
2018-04-05 14:37:29.053 HomeKit Bridge Debug    Homebridge-Indigo2 Payload Data 1.0.0 loaded
2018-04-05 14:37:32.530 HomeKit Bridge Debug    Rear Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:32.534 HomeKit Bridge Debug    Homebridge-Indigo2 Device Payload 1.0.0 loaded
2018-04-05 14:37:32.544 HomeKit Bridge Debug    Converting  keyword for HomeKit type or firmware on 'Rear Door Camera'
2018-04-05 14:37:32.553 HomeKit Bridge Debug    Converting indigoVersion keyword for HomeKit type or firmware on 'Rear Door Camera'
2018-04-05 14:37:32.556 HomeKit Bridge Debug    Homebridge-Indigo2 Payload Data 1.0.0 loaded
2018-04-05 14:37:32.556 HomeKit Bridge Debug    Homebridge-Indigo2 Payload Data 1.0.0 loaded
2018-04-05 14:37:32.556 HomeKit Bridge Debug    Homebridge-Indigo2 Payload Data 1.0.0 loaded
2018-04-05 14:37:57.937 HomeKit Bridge Debug    Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
2018-04-05 14:37:57.973 HomeKit Bridge Debug    Front Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:57.978 HomeKit Bridge Debug    Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
2018-04-05 14:37:58.010 HomeKit Bridge Debug    Front Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:58.014 HomeKit Bridge Debug    Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
2018-04-05 14:37:58.053 HomeKit Bridge Debug    Front Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:58.057 HomeKit Bridge Debug    Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
2018-04-05 14:37:58.110 HomeKit Bridge Debug    Front Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:58.114 HomeKit Bridge Debug    Indigo device Rear Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
2018-04-05 14:37:58.141 HomeKit Bridge Debug    Rear Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:58.145 HomeKit Bridge Debug    Indigo device Rear Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
2018-04-05 14:37:58.172 HomeKit Bridge Debug    Rear Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:58.177 HomeKit Bridge Debug    Indigo device Rear Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
2018-04-05 14:37:58.205 HomeKit Bridge Debug    Rear Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
2018-04-05 14:37:58.210 HomeKit Bridge Debug    Indigo device Rear Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
2018-04-05 14:37:58.240 HomeKit Bridge Debug    Rear Door Camera started as a HomeKit Camera RTP Stream Management (Experimental)
[2018-4-5 14:37:40] Loaded plugin: homebridge-camera-ffmpeg
[2018-4-5 14:37:41] Registering platform 'homebridge-camera-ffmpeg.Camera-ffmpeg'
[2018-4-5 14:37:41] ---
[2018-4-5 14:37:41] Loaded plugin: homebridge-indigo2
[2018-4-5 14:37:41] Registering platform 'homebridge-indigo2.Indigo2'
[2018-4-5 14:37:41] ---
[2018-4-5 14:37:41] Loaded config.json with 0 accessories and 1 platforms.
[2018-4-5 14:37:41] ---
[2018-4-5 14:37:41] Loading 1 platforms...
[2018-4-5 14:37:41] [HomeKit Bridge Server] Initializing Indigo2 platform...
[2018-4-5 14:37:41] [HomeKit Bridge Server] HomeKit Bridge base URL is http://127.0.0.1:8558
[2018-4-5 14:37:41] [HomeKit Bridge Server] HomeKit Bridge serverId is 764107208
[2018-4-5 14:37:41] Loading 0 accessories...
Load homebridge-camera-ffmpeg.Camera-ffmpeg
[2018-4-5 14:37:41] [HomeKit Bridge Server] HomeKit Bridge request: http://127.0.0.1:8558/HomeKit?cmd=deviceList&serverId=764107208
[2018-4-5 14:37:41] [HomeKit Bridge Server] Listening on port 8449

Oddly, there were no other camera references in the rest of the homebridge.log. After restart, then I saw camera references:

[2018-4-5 20:12:51] Loaded plugin: homebridge-camera-ffmpeg
[2018-4-5 20:12:51] Registering platform 'homebridge-camera-ffmpeg.Camera-ffmpeg'
[2018-4-5 20:12:51] [Camera-ffmpeg] Initializing Camera-ffmpeg platform...
[2018-4-5 20:13:00] [Camera-ffmpeg] Snapshot from Rear Door Camera at 480x270
[2018-4-5 20:13:00] [Camera-ffmpeg] Snapshot from Front Door Camera at 480x270
[2018-4-5 20:15:20] [Camera-ffmpeg] Snapshot from Rear Door Camera at 480x270
[2018-4-5 20:15:20] [Camera-ffmpeg] Snapshot from Front Door Camera at 480x270
[2018-4-5 20:17:24] [Camera-ffmpeg] Snapshot from Rear Door Camera at 480x270
[2018-4-5 20:17:24] [Camera-ffmpeg] Snapshot from Front Door Camera at 480x270
[2018-4-5 20:17:36] [Camera-ffmpeg] Snapshot from Rear Door Camera at 480x270
[2018-4-5 20:17:36] [Camera-ffmpeg] Snapshot from Front Door Camera at 480x270
Colorado4Wheeler commented 6 years ago

I'll have to look into that. Having Indigo start before SS could certainly cause an error that I could fix because I don't do a ton of trapping there, but why it races is odd. I'll shut down my SS server and see what happens.

webdeck commented 6 years ago

On my system, I intentionally delay the startup of SecuritySpy because it needs to wait for an external storage array to mount.

Colorado4Wheeler commented 6 years ago

You mentioned a 'race' condition, when I turned off my SS server and reloaded HKB I only got errors consistent with the number of cameras that I got and then it was fine. 

   HomeKit Bridge                  Attempting to start 'HomeKit Basement'
   HomeKit Bridge Error            Exception in plugin.buildServerConfigurationDict line 4650: HTTPConnectionPool(host='x.x.x.x, port=xxxx): Max retries exceeded with url: /++systemInfo (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x110286d90>: Failed to establish a new connection: [Errno 61] Connection refused',))
                             CODE: data = requests.get(ssSystem).content# Pull XML data

You didn't get these errors? In your log it shows:

Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit

Which should only fire when we get a request from Homebridge to do something with the cameras. Did it race when you tried to view the stream or use HomeKit and not when the plugin started?

Colorado4Wheeler commented 6 years ago

I don't think it will make a difference but try updating to the latest release, I see you are a version old and there were a few minor changes to cameras in the latest - mostly for error trapping but still.

webdeck commented 6 years ago

Steps to reproduce:

  1. Stop HomeKit Bridge device with cameras
  2. Quit SecuritySpy application - Cynical SecuritySpy plugin reports camera devices as "Unavailable"
   Cynical SecuritySpy Error       SecuritySpy unavailable: [Errno 61] Connection refused
   Cynical SecuritySpy Error       Front Door Camera unavailable: host device SecuritySpy is unavailable
   Cynical SecuritySpy Error       Rear Door Camera unavailable: host device SecuritySpy is unavailable
  1. Start HomeKit Bridge device with cameras
   HomeKit Bridge Debug            Rebuilding configuration for 'HomeKit Bridge'
   HomeKit Bridge Debug            Saving 'HomeKit Bridge' configuration to /Library/Application Support/Perceptive Automation/Indigo 7/Preferences/Plugins/com.eps.indigoplugin.homekit-bridge/764107208
   HomeKit Bridge Error            Exception in plugin.buildServerConfigurationDict line 4650: HTTPConnectionPool(host='home.webdeck.com', port=8001): Max retries exceeded with url: /++systemInfo (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x11360ae90>: Failed to establish a new connection: [Errno 61] Connection refused',))
                             CODE: data = requests.get(ssSystem).content# Pull XML data

   HomeKit Bridge Warning          Configuration will be built despite the error
   HomeKit Bridge Error            Exception in plugin.buildServerConfigurationDict line 4650: HTTPConnectionPool(host='home.webdeck.com', port=8001): Max retries exceeded with url: /++systemInfo (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x11373cb10>: Failed to establish a new connection: [Errno 61] Connection refused',))
                             CODE: data = requests.get(ssSystem).content# Pull XML data

   HomeKit Bridge Warning          Configuration will be built despite the error
   HomeKit Bridge                  Attempting to start 'HomeKit Bridge'
  1. Start SecuritySpy application - Cynical SecuritySpy plugin changes camera devices to "active"
   HomeKit Bridge Debug            Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
   HomeKit Bridge Debug            Front Door Camera started as a HomeKit Camera RTP Stream
   HomeKit Bridge Debug            Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
   HomeKit Bridge Debug            Front Door Camera started as a HomeKit Camera RTP Stream
   HomeKit Bridge Debug            Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
   HomeKit Bridge Debug            Front Door Camera started as a HomeKit Camera RTP Stream
   HomeKit Bridge Debug            Indigo device Front Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
   HomeKit Bridge Debug            Front Door Camera started as a HomeKit Camera RTP Stream
   HomeKit Bridge Debug            Indigo device Rear Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
   HomeKit Bridge Debug            Rear Door Camera started as a HomeKit Camera RTP Stream
   HomeKit Bridge Debug            Indigo device Rear Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
   HomeKit Bridge Debug            Rear Door Camera started as a HomeKit Camera RTP Stream
   HomeKit Bridge Debug            Indigo device Rear Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
   HomeKit Bridge Debug            Rear Door Camera started as a HomeKit Camera RTP Stream
   HomeKit Bridge Debug            Indigo device Rear Door Camera changed and is linked to HomeKit, checking if that change impacts HomeKit
   HomeKit Bridge Debug            Rear Door Camera started as a HomeKit Camera RTP Stream
  1. Try to view cameras in HomeKit Home app - "No Response This camera is not responding"

Reason is, they are missing in config.json:

{
        "platforms": [
                {
                        "protocol": "http", 
                        "name": "HomeKit Bridge Server", 
                        "listenPort": "8449", 
                        "platform": "Indigo2", 
                        "host": "127.0.0.1", 
                        "serverId": 764107208, 
                        "port": "8558"
                }
        ], 
        "bridge": {
                "username": "CC:22:3D:E3:CE:10", 
                "name": "HomeKit Bridge", 
                "pin": "031-45-154", 
                "port": "51827"
        }, 
        "accessories": [], 
        "description": "HomeKit configuration generated by HomeKit Bridge on 2018-04-07 12:35:24.034000 for device HomeKit Bridge"
}

So, the bug is, if HomeKit Bridge device starts when camera devices are "Unavailable", then they are omitted from config.json. When camera devices change to "active", they are not added back to config.json and server doesn't restart.

Colorado4Wheeler commented 6 years ago

Very helpful, thank you. I’ll do some further testing.

FlyingDiver commented 6 years ago

Got this multiple times after installing 7.1.2 Beta 1c. Went away after I rebooted the mini.

2018-04-21 10:34:05.100 Sonos Error plugin runConcurrentThread function returned or failed (will attempt again in 10 seconds)
2018-04-21 10:34:06.717 Application Started plugin "HomeKit Bridge 0.23.0"
2018-04-21 10:34:06.880 SQL Logger  updating all variable tables
2018-04-21 10:34:07.000 HomeKit Bridge  Attempting to start 'HomeKit Bridge'
2018-04-21 10:34:07.240 SQL Logger  update complete
2018-04-21 10:34:12.011 HomeKit Bridge Error    Exception in plugin.buildServerConfigurationDict line 4399: HTTPConnectionPool(host='proserver.local', port=8123): Max retries exceeded with url: /++systemInfo (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x10fcea590>: Failed to establish a new connection: [Errno 64] Host is down',))
                             CODE: data = requests.get(ssSystem).content# Pull XML data

2018-04-21 10:34:12.011 HomeKit Bridge Warning  Configuration will be built despite the error
Colorado4Wheeler commented 6 years ago

Ok, so that one is a bit different but it's Homebridge not responding to a web request. I get those sometimes, but its good to have it documented. I've had some problems getting that trapped in a logical way. Thank you Joe.

FlyingDiver commented 6 years ago

I doubt I could reproduce it, as it immediately stopped happening with the reboot.

Colorado4Wheeler commented 6 years ago

It should have reset if you restarted the plugin too.

FlyingDiver commented 6 years ago

I was more concerned with getting Little Snitch working, and I figure the reboot was what it needed. ;)

Colorado4Wheeler commented 6 years ago

;)