search

lukasroegner / homebridge-apple-tv-remote

Plugin for controlling Apple TVs in homebridge.
MIT License
131 stars 13 forks source link

Enabling Switches kills Homebridge #37

Closed mwilgar closed 4 years ago

mwilgar commented 4 years ago

I have 2 AppleTVs defined, with credentials all set. Everything is fine if I don't enable any switches. But if I enable either the On/Off or Play/Pause switch (one, both, one AppleTV or both, doesn't make a difference) an error is thrown, and Homebridge is restarted.

[5/6/2020, 18:11:09] Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:452:14) at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:152:29 at new Promise (<anonymous>) at Connection.sendProtocolMessage (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:134:16) at Connection.send (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:130:21) at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/appletv.js:182:22 [5/6/2020, 18:11:09] Got SIGTERM, shutting down Homebridge... [5/6/2020, 18:11:09] [Apple TVs] Shutting down Apple TV clients...

Here's my config:

{ "name": "Apple TVs", "devices": [ { "name": "Family Room", "credentials": "blah", "isOnOffSwitchEnabled": true, "onOffSwitchName": "Family Room OnOff", "isPlayPauseSwitchEnabled": false, "playPauseSwitchName": "Family Room PlayPause" }, { "name": "Bedroom", "credentials": "blah", "isOnOffSwitchEnabled": false, "onOffSwitchName": "Bedroom OnOff", "isPlayPauseSwitchEnabled": false, "playPauseSwitchName": "Bedroom PlayPause" } ], "platform": "AppleTvPlatform" }

lukasroegner commented 4 years ago

@mwilgar Looks like an issue within the network. Do you have a special configuration, firewalls, etc. on your network? Is the Homebridge host in the same subnet as the Apple TVs?

mwilgar commented 4 years ago

My network is about as basic and “out of the box” as possible. I don’t have any odd firewalls, or anything like that. The router is even an Eero, which is HomeKit certified. I don’t have this problem with any other plugins - if the others (like Ring for example) have trouble communicating, they report an error, but they don’t crash, and certainly don’t crash the homebridge. And, yes, the AppleTVs and homebridge are all on the same subnet.

alexargo commented 4 years ago

Hmm... I also have an Eero router am having issues. Its' not crashing home bridge for me, but it does stop working after a certain after a certain point.

mwilgar commented 4 years ago

I my case it happens immediately after enabling a switch, predictably and repeatedly.

lukasroegner commented 4 years ago

@mwilgar Can you please start Homebridge in debug mode (parameter -D) and post the logs that are printed out when you enable the switch?

lukasroegner commented 4 years ago

@mwilgar Does the appletv command line tool work on the Homebridge host? Or did you use another PC for retrieving the credentials?

mwilgar commented 4 years ago

I used the appletv command line tool, it worked perfectly.

Here's the part of my log, this is a few seconds after changing the plugin setting to enable the On/Of switch on one of my two AppleTVs (the one called "Family Room"):

[5/9/2020, 07:40:41] [Apple TVs] [Family Room] Sending heartbeat...
[5/9/2020, 07:40:41] [Apple TVs] [Family Room] Connecting...
[5/9/2020, 07:40:41] [Apple TVs] [Family Room] Force reconnect: false
[5/9/2020, 07:40:41] [Apple TVs] [Family Room] Retry count: 10
[5/9/2020, 07:40:41] [Apple TVs] [Family Room] Already connected
[5/9/2020, 07:40:41] Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:452:14)
    at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:152:29
    at new Promise (<anonymous>)
    at Connection.sendProtocolMessage (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:134:16)
    at Connection.send (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:130:21)
    at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/appletv.js:182:22
[5/9/2020, 07:40:41] Got SIGTERM, shutting down Homebridge...
[5/9/2020, 07:40:41] [Apple TVs] Shutting down Apple TV clients...
[5/9/2020, 07:40:41] [Apple TVs] [Family Room] Disconnecting...

If I just leave it like this Homebridge will just continuously restart, until I change the setting to disable the switch. If the all the switches are disabled, I see this...

[5/9/2020, 07:47:28] [Apple TVs] Initialing platform...
[5/9/2020, 07:47:28] [Apple TVs] [Family Room] Device not used.
[5/9/2020, 07:47:28] [Apple TVs] [Bedroom] Device not used.

... which of course is not much fun ;)

lukasroegner commented 4 years ago

Can you provide the logs starting with the entry "[Family Room] On/off switch changed to ..."?

mwilgar commented 4 years ago

It actually says [Family Room] On/off switch updated to false, I assume that's what you meant...

Shortly after reboot...

[5/10/2020, 11:28:11] [Apple TVs] [Family Room] Message received: logicalDeviceCount - 0 | isProxyGroupPlayer - false | isAirplayActive - false
[5/10/2020, 11:28:11] [Apple TVs] [Family Room] On/off switch updated to false
[5/10/2020, 11:28:12] [Apple TVs] [Family Room] Connected
[5/10/2020, 11:28:12] [Apple TVs] [Family Room] Message received: logicalDeviceCount - 0 | isProxyGroupPlayer - false | isAirplayActive - false
[5/10/2020, 11:28:12] [Apple TVs] [Family Room] On/off switch updated to false

... then after a short bit of time ...

[5/10/2020, 11:31:47] [Apple TVs] [Family Room] Connecting...
[5/10/2020, 11:31:47] [Apple TVs] [Family Room] Force reconnect: false
[5/10/2020, 11:31:47] [Apple TVs] [Family Room] Retry count: 10
[5/10/2020, 11:31:47] [Apple TVs] [Family Room] Already connected
[5/10/2020, 11:31:47] Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:452:14)
    at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:152:29
    at new Promise (<anonymous>)
    at Connection.sendProtocolMessage (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:134:16)
    at Connection.send (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:130:21)
    at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/appletv.js:182:22
[5/10/2020, 11:31:47] Got SIGTERM, shutting down Homebridge...
[5/10/2020, 11:31:47] [Apple TVs] Shutting down Apple TV clients...
[5/10/2020, 11:31:47] [Apple TVs] [Family Room] Disconnecting...
lukasroegner commented 4 years ago

It actually says [Family Room] On/off switch updated to false, I assume that's what you meant...

I was searching for "On/off switch changed to", which is the log entry that occurs when you toggle the on/off switch. But that is missing in your logs. Does it mean that the error also occurs if you don't toggle the switch?

mwilgar commented 4 years ago

No, the error only occurs if the switch is enabled. But the reason the “changed” logs aren’t in the logs is because I can’t ever get to the point of trying to toggle the switch - the error occurs as soon as Homebridge tries to poll the state of the switch.

lukasroegner commented 4 years ago

OK, now I understand your problem. After digging through the library that I use to communicate with the Apple TV, it seems that there is an unhandled exception. I created a PR here: https://github.com/stickpin/node-appletv-x/pull/1

When the PR has been accepted, I can publish a new version, which should not through unhandled exception anymore. This does not solve the issue that there are communication issues with your Apple TV, however, the plugin should reconnect instead of killing Homebridge.

lukasroegner commented 4 years ago

@mwilgar New version 0.8.5 published. This should solve the issue with the unhandled exception.

mwilgar commented 4 years ago

I’m afraid I spoke too soon:

It took me doing a power-down reset after installing 0.8.5 (just restarting the Homebridge service didn’t work), but now it’s working as expected! Thanks so much!

Unfortunately, after updating to 0.8.5 I'm getting the same result. The logs are reporting the same events, and the Homebridge is still getting killed and restarting, continuously.

Here's the latest log without debug turned on...

[5/10/2020, 15:45:25] [Apple TVs] Initializing AppleTvPlatform platform...
[5/10/2020, 15:45:26] [Apple TVs] Initialing platform...
[5/10/2020, 15:45:26] [Apple TVs] [Family Room] Initializing...
[5

> /10/2020, 15:45:26] [Apple TVs] [Family Room] Adding on/off switch
> [5/10/2020, 15:45:26] [Apple TVs] [Bedroom] Device not used.
> [5/10/2020, 15:45:30] [Apple TVs] [Family Room] Connected
> Enter this code with your HomeKit app on your iOS device to pair with Homebridge:
>                        
>     ┌────────────┐     
>     │ XXX-XX-XXX │     
>     └────────────┘     
>                        
> [5/10/2020, 15:45:31] Homebridge is running on port 51724.
> [5/10/2020, 15:46:26] Error: This socket has been ended by the other party
>     at Socket.writeAfterFIN [as write] (net.js:452:14)
>     at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:153:33
>     at new Promise (<anonymous>)
>     at Connection.sendProtocolMessage (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:134:16)
>     at Connection.send (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:130:21)
>     at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/appletv.js:182:22
> [5/10/2020, 15:46:26] Got SIGTERM, shutting down Homebridge...
> [5/10/2020, 15:46:26] [Apple TVs] Shutting down Apple TV clients...
lukasroegner commented 4 years ago

@mwilgar I dived deeper into the base lib of nodejs, it seems that the error handling of the problematic Socket.write method has been changed between version 10 and 12.

Can you check which node version you are running?

mwilgar commented 4 years ago

Node.js Version v12.16.3 - This is a very basic install of Homebridge, I used the image found at https://github.com/homebridge/homebridge-raspbian-image

lukasroegner commented 4 years ago

OK, before I create another PR for node-appletv-x that doesn't fix your issue, we should check it on your Homebridge host (as I cannot replicate it).

  1. Stop homebridge

  2. Navigate to your global node_modules folder (can be found via npm list -g --depth=0) E.g. cd /usr/local/lib

  3. Open the file homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js and jump to line 153 E.g. nano +153 homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js

  4. Replace the line

    that.socket.write(bytes);

    with

    if (that.isOpen) { that.socket.write(bytes); } else { reject(); return; }

  5. Replace the same thing on line 165

  6. Save and close the editor E.g. [CTRL]+[X], [Y], [ENTER]

  7. Restart homebridge

If the plugin then runs without issues, I'll create the PR and you can update the plugin via NPM.

mwilgar commented 4 years ago

Well, after a few hours of trying to follow those instructions and googling to get around the errors (I'm not a developer) I got to the end and got a "permission denied" error trying to save the file. Isn't there a better way to do this?

lukasroegner commented 4 years ago

@mwilgar This can be solved. In step 3 (opening the file), use sudo when starting the editor, e.g.

sudo nano +153 homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js
mwilgar commented 4 years ago

Well, it's an improvement, the crash isn't happening, but I get this every minute now:

[5/13/2020, 14:04:51] [Apple TVs] [Family Room] Error while sending heartbeat: undefined

I'm actually able to see the switch in the Home app now, and toggling it results in this:

(from OFF to ON)

[5/13/2020, 14:08:01] [Apple TVs] [Family Room] On/off switch changed to true
[5/13/2020, 14:08:01] [Apple TVs] [Family Room] Getting power state...
[5/13/2020, 14:08:01] [Apple TVs] [Family Room] Returning cached value false for power state
[5/13/2020, 14:08:02] [Apple TVs] [Family Room] Pressing key topmenu...
[5/13/2020, 14:08:02] [Apple TVs] [Family Room] Error while pressing key topmenu: undefined
[5/13/2020, 14:08:02] [Apple TVs] [Family Room] Pressing key topmenu...
[5/13/2020, 14:08:02] [Apple TVs] [Family Room] Error while pressing key topmenu: undefined
[5/13/2020, 14:08:02] [Apple TVs] [Family Room] Giving up. Error while switching on

(From ON to OFF)


[5/13/2020, 14:08:13] [Apple TVs] [Family Room] On/off switch changed to false
[5/13/2020, 14:08:13] [Apple TVs] [Family Room] Getting power state...
[5/13/2020, 14:08:13] [Apple TVs] [Family Room] Returning cached value false for power state
lukasroegner commented 4 years ago

This is indeed an improvement as homebridge doesn't crash. I'll create a PR to integrate this fix and publish a new version.

DJay-X commented 4 years ago

At the moment I'm not deep in using the plugin. Installed it just recently. Worked well the last two days. However today homebridge crashed out of the blue. Using one Apple TV 4K. I will have an eye on this. Or maybe it is just fixed with your next release anyway. :)

homebridge@1.1.0 | node@12.16.3 | npm 6.14.5

[2020-5-18 20:22:19] Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:452:14)
    at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:153:33
    at new Promise (<anonymous>)
    at Connection.sendProtocolMessage (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:134:16)
    at Connection.send (/usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/connection.js:130:21)
    at /usr/local/lib/node_modules/homebridge-apple-tv-remote/node_modules/node-appletv-x/dist/lib/appletv.js:182:22
[2020-5-18 20:22:19] Got SIGTERM, shutting down Homebridge...
{
            "platform": "AppleTvPlatform",
            "devices": [
                {
                    "name": "Apple TV",
                    "credentials": "DExxxxx-xxxx-xxxx-...",
                    "isOnOffSwitchEnabled": false,
                    "isPlayPauseSwitchEnabled": true,
                    "playPauseSwitchName": "Play Pause",
                    "commandSwitches": [
                        {
                            "name": "Bildschirmschoner",
                            "commands": [
                                {
                                    "key": "menu",
                                    "longPress": true
                                },
                                {
                                    "wait": 2000
                                },
                                {
                                    "key": "menu",
                                    "longPress": false
                                }
                            ]
                        },
                        {
                            "name": "Home",
                            "commands": [
                                {
                                    "key": "menu",
                                    "longPress": true
                                }
                            ]
                        }
                    ]
                }
            ],
            "isApiEnabled": true,
            "apiPort": 40304,
            "apiToken": "123abc"
        },
mwilgar commented 4 years ago

At the moment I'm not deep in using the plugin. Installed it just recently. Worked well the last two days. However today homebridge crashed out of the blue. Using one Apple TV 4K. I will have an eye on this. Or maybe it is just fixed with your next release anyway. :)

This looks like the same problem I'm having. Until there is an update published, making the changes above will prevent Homebridge from crashing, but it doesn't fix the plugin. The switches still don't work properly.

lukasroegner commented 4 years ago

@DJay-X I've already created a pull request (https://github.com/stickpin/node-appletv-x/pull/3) that fixes the issue, as soon as it is merged, I can release a new version.

d3bing commented 4 years ago

Plus 1 here. It started happening today and homebridge is down for me. I just commented on an older closed issue but it looks like my issue is the same as the other two folks here. @lukasroegner was the new version released? Any updates?

d3bing commented 4 years ago

@lukasroegner I actually edited connection.js according to your pull request to stickpin, and while it doesn't crash HB anymore, the tv plugin still doesn't work (same error message Error while connecting: Error: Apple TV not found while scanning.). At least my HB is back up.

If it helps, I didn't change any configuration in my network or anything. I just wake up this morning and everything went haywire. Until last night all was good.

lukasroegner commented 4 years ago

I've created an issue that merges several other issues. This new issue will be used to track the instability issues: #46