TV accessory events not firing since update of homebridge-broadlink-rm plugin

[thiete]

The homebridge-broadlink-rm plugin (this fork: https://github.com/kiwi-cam/homebridge-broadlink-rm) recently changed how TV accessories are handled due to changes in iOS 14. They are now exposed as a standalone accessory, not part of the homebridge bridge, if I understand correctly. The accessory shares the same PIN as the homebridge instance but must be added to homekit separately. Since this change it seems that hb-events no longer trigger for the accessory. If triggered externally, the hb-status and hb-control nodes for the TV accessory still work. The accessory is working fine on iOS devices and updates are logged inside homebridge.

My config: Homebridge v1.3.0-beta.14 Node.js v12.19.0 Host Ubuntu 18.04.5 LTS Nodered 1.2.2 node-red-contrib-automation 0.0.72

The following minimal flow is sufficient to reproduce the issue with my configuration: https://pastebin.com/1rLHRLBV

Here is a node-red message from the TV accessory captured by triggering a hb-status node https://pastebin.com/DjgpvwPv

The output of avahi-browse showing the Homebridge instance and the Amplifier (TV) accessory: https://pastebin.com/2HHKDXWx

I have seen error messages pop up in node-red sporadically from the TV accessory node, but the problem is present whether these messages appear or not: hbEvent _status: error and 192.168.0.10:37477 -> Error: connect ECONNREFUSED 192.168.0.10:37477 -> undefined

Here is a node-red log from service startup. I have switched the accessory on and off several times during this time: https://pastebin.com/Ty06RXUL I have enabled node-red debug logging but the log does not seem very verbose - am I missing something?

[NorthernMan54]

There is a known issue ( by me ) with changing IP address or port numbers of Homebridge instances causing issues. This issue is evident in camera and TV accessories or in homebridge configurations without a declared port number. The workaround for this is to start or restart node-red after Homebridge is started.

Under the covers I'm caching the host and port number of each homebridge instance and if they change the only way to refresh the cache is to restart node-red.

Is this the issue your seeing or is it something deeper ?

[thiete]

Nope, restarting node-red doesn’t fix it and I’m fairly sure the port is consistent, the IP definitely is.

In the meantime I have a set up a node to monitor the homebridge log and hit a hub-status node when it sees activity on the tv accessory, but it’s not exactly an elegant solution.

Edit: correction: the port of the TV accessory does change, but restarting node-red does not help.

[NorthernMan54]

In the logs you shared I see a couple of errors are they related ?

Oct 30 13:58:34 MikeServer Node-RED[4689]: 30 Oct 13:58:34 - [error] [function:Amplifier power state] TypeError: Cannot use 'in' operator to search for 'Amplifier' in undefined

Oct 30 13:58:35 MikeServer Node-RED[4689]: 30 Oct 13:58:35 - [error] [castv2-sender:AudioSuf] Error: Not connected
Oct 30 13:58:35 MikeServer Node-RED[4689]:     at CastV2ConnectionNode.sendPlatformCommandAsync (/home/mike/.node-red/node_modules/node-red-contrib-castv2/castv2-sender.js:308:23)

Appears to be an issue with the castv2 node

[thiete]

The castv2 node seems to throw that error when first initialising, before it establishes a connection. The other error is one of my function nodes trying to query a context which has not been initialised yet. Think they are red herrings in this case.

If I disable my big home automation flow and just have a single hb-event from the TV (I.e. “Amplifier”) connected to a debug node, I don’t see any events firing.

I suspected it may be some difference in between how the homebridge hub instance and the TV accessory get advertised on ciao/avahi, but I can’t find any evidence of this. From the host machine (all services are running directly on one host, no dockers or anything) I am able to connect to both the homebridge port and the TV accessory port via: wget --server-response http://192.168.0.10:xxx so it doesn’t appear to be a routing problem.

[NorthernMan54]

Give me a day to wire up my TV accessory to node-red and see if I can recreate the issue ( I'm using Homebridge-apple-tv-remote ).

[NorthernMan54]

This is from my setup when running node-red in debug mode ( very verbose )

Command line was this

DEBUG=*,-puppeteer:*,-express:*,-body-parser:*,-send npm/bin/node-red

The last bit with npm/bin/node-red you may need to change to match your setup

This is after node-red has started and homebridge instance discovery is completed. This is critical as this is the event message registration, which drives the hb-event node. It is registering for events, and also requesting current status.

What does your setup show ?

  hapNodeRed Discovered 87 new ctDevices +4ms
  hapNodeRed hb-event registered: Play (TV) - Switch -> 192.168.1.11:51828 null +21ms
  hapNodeRed hbEvent.register Play (TV) - Switch +1ms
  hapNodeRed _status request: Play (TV) - Switch -> 192.168.1.11:51828 -> ?id=49.13 +5ms
  hapNodeRed hbEvent received: Play (TV) - Switch = [{"aid":49,"iid":13,"value":false}] { On: false } +19ms

I then hit pause on my TV ( not sure why the Apple TV sends a couple of messages ) these are the event messages.

  hapNodeJSClient Events [{"host":"192.168.1.11","port":51828,"aid":49,"iid":13,"value":true,"status":true}] +27s
  hapNodeRed hbEvent Play (TV) {
  host: '192.168.1.11',
  port: 51828,
  deviceID: undefined,
  aid: 49,
  iid: 13,
  value: true,
  status: true
} { On: false } +27s
  hapNodeJSClient Events [{"host":"192.168.1.11","port":51828,"aid":49,"iid":13,"value":false,"status":false}] +847ms
  hapNodeRed hbEvent Play (TV) {
  host: '192.168.1.11',
  port: 51828,
  deviceID: undefined,
  aid: 49,
  iid: 13,
  value: false,
  status: false
} { On: true } +846ms
  hapNodeJSClient Events [{"host":"192.168.1.11","port":51828,"aid":49,"iid":13,"value":true,"status":true}] +14ms
  hapNodeRed hbEvent Play (TV) {
  host: '192.168.1.11',
  port: 51828,
  deviceID: undefined,
  aid: 49,
  iid: 13,
  value: true,
  status: true
} { On: false } +14ms
  hapNodeJSClient Events [{"host":"192.168.1.11","port":51828,"aid":49,"iid":13,"value":false,"status":false}] +56ms
  hapNodeRed hbEvent Play (TV) {
  host: '192.168.1.11',
  port: 51828,
  deviceID: undefined,
  aid: 49,
  iid: 13,
  value: false,
  status: false
} { On: true } +56ms
  hapNodeJSClient Events [{"host":"192.168.1.11","port":51828,"aid":49,"iid":13,"value":true,"status":true}] +24ms
  hapNodeRed hbEvent Play (TV) {
  host: '192.168.1.11',
  port: 51828,
  deviceID: undefined,
  aid: 49,
  iid: 13,
  value: true,
  status: true
} { On: false } +24ms
  hapNodeJSClient Events [{"host":"192.168.1.11","port":51828,"aid":49,"iid":13,"value":false,"status":false}] +11s
  hapNodeRed hbEvent Play (TV) {
  host: '192.168.1.11',
  port: 51828,
  deviceID: undefined,
  aid: 49,
  iid: 13,
  value: false,
  status: false
} { On: true } +11s

[thiete]

Well this is curious.

It turns out if I disable my relatively big homebridge automation flow and restart node-red with just a minimal flow containing a TV hb-event > debug node, then things work absolutely fine. Here is a log of this: bigflow0.log

If I enable my bigger flow, then the TV hb-events do not fire. Any events from the TV you see in the log below are due to polling of hb-status nodes: bigflow1.log

I have tried disabling various nodes inside my big flow, such as my custom function nodes and the chromecast automation nodes, but I have not yet located a culprit. Finally, if I start node-red with just the minimal flow but then enable my big flow and re-deploy, then things continue to work fine - so it would seem the issue is somewhere in the initialization.

[NorthernMan54]

Looking at the detail at the differences between the two logs, I see two things

First the error message is only in the second log

Second, the event registration message fails due to a bad message format error.

I'm wondering if the error message is triggering it ? It fails due to undefined, and that may be part of the bad message format error. Do you know what node is triggering the error ?

flow 0

Oct 30 23:02:21 MikeServer Node-RED[27439]: 2020-10-30T22:02:21.940Z hapNodeRed hb-event registered: Amplifier - Television -> 192.168.0.10:44667 {"characteristics":[{"aid":1,"iid":13,"status":-70406},{"aid":1,"iid":16,"status":-70406},{"aid":1,"iid":14,"ev":true,"status":0},{"aid":1,"iid":15,"ev":true,"status":0},{"aid":1,"iid":10,"ev":true,"status":0},{"aid":1,"iid":11,"ev":true,"status":0}]}

flow 1

Oct 30 22:59:55 MikeServer Node-RED[25641]: 30 Oct 22:59:55 - [error] [function:Amplifier power state] TypeError: Cannot use 'in' operator to search for 'Amplifier' in undefined
Oct 30 22:59:55 MikeServer Node-RED[25641]:     at Function node setup:5540d3c0.28d7bc [Amplifier power state]:19:19
Oct 30 22:59:55 MikeServer Node-RED[25641]:     at Function node setup:5540d3c0.28d7bc [Amplifier power state]:22:23

Oct 30 23:00:15 MikeServer Node-RED[25641]: 2020-10-30T22:00:15.923Z hapNodeRed hb-event registered: Amplifier - Television -> 192.168.0.10:44667 {"characteristics":[{"aid":1,"iid":13,"status":-70406},{"aid":1,"iid":16,"status":-70410},{"aid":1,"iid":14,"status":-70410},{"aid":1,"iid":15,"status":-70410},{"aid":1,"iid":10,"status":-70410},{"aid":1,"iid":11,"status":-70410}]}

Error "status":-70410

For the HAP Spec section 6.7.1.4

[thiete]

First of all, thank you for your help with this! There is a bug in my function node, but it's not the cause of this. I have been trying to isolate the problem.

This flow consistently registers the hb-events:

While I'm getting inconsistent results with this: Sometimes it starts up and then from that point works fine and sometimes it doesn't. Can't pin it down. I have tried deleting each of the other accessories in turn and it's not due to a specific one - almost like seems to be related to having multiple accessories trying to register at the same time?

Edit: Just for completeness, the Projector is operated by the homebridge-epson-projector v0.0.2 plugin, while the other two are a Chromecast and Chromecast Audio connected via homebridge-control-chromecast v1.3.1

[NorthernMan54]

I don't think its the number of devices registering at the same time as my main node-red instance is running with about 15+ different nodes.

I quickly built this in the my test environment, and had no issues. Each generated its own registration event ( Including 6 times for my TV play button )

I'm going to try and setup a device in my environment which mimics your Amplifier, as the -70406 worries me. Will take a day or so as its back in the city

Would it be possible to collect a homebridge accessory dump for the amplifier ? Want to look at what is being shared to node-red from that device. Details are here

https://github.com/NorthernMan54/homebridge-alexa#homebridge-accessory-dump

[thiete]

Sure: hbdump.log

EDIT: I just noticed you mention your TV play button. I used to have my node-red setup capture the iOS control centre remote control events and route them to the appropriate devices. This stopped working some months ago, way before the current issue. It appears that homebridge is stil generating the button press events but hb-event nodes were no longer being fired. It's not a huge problem for me, just though I would mention since it seems to be working for you.

[NorthernMan54]

Okay, I think I have nailed this, I was able to recreate your issue and believe this resolves it.

If you update to the latest version, 0.0.75 it should now be working.

[thiete]

That indeed seems to have done it! Thank you for the fantastic support! Marking as closed.

[NorthernMan54]

Awesome