Speaker and Microphone Service Events not Working

[Brandawg93]

Describe The Bug:
I am the developer of homebridge-nest-cam. I am working on 2-way audio and need to be able to know when a user presses the microphone or speaker mute buttons. Currently, no events are triggered when the buttons are pressed.
To Reproduce:

1. Create camera object
2. Add twoWayAudio flag which should automatically add microphone and speaker services to camera controller.
3. Hook into microphone change event to get state of microphone
4. The above will never fire.

Expected behavior:
The above hook should fire whenever the buttons are pressed.

Environment:
Docker

[Supereg]

Will it never fire because HomeKit never write to the characteristics, or is the characteristic actually written to and the event is really not forwarded?
A DEBUG log would be helpful to verify the characteristic is actually written to.

[Brandawg93]

How can I generate a DEBUG log? This is the first issue I've really come across with homebridge so I haven't worked much with debugging it.

[Supereg]

Are you using a platform plugin? Just noticed a probability where it is possible that the speaker and the microphone service are not correctly recreated and set up when a cached accessory is restored from disk.

How can I generate a DEBUG log? This is the first issue I've really come across with homebridge so I haven't worked much with debugging it.

https://github.com/homebridge/HAP-NodeJS/wiki/FAQ#debug-mode. When using config-ui the DEBUG environment variable can also be set in the settings page.

But seems like I already identified the issue.

[Brandawg93]

I saw that too. That was the issue at first, but I've removed cache and set up the services again, both manually and by using the twoWayAudio flag. Neither way fires an event when pressing the buttons. I'll generate the DEBUG log shortly.

[Brandawg93]

2020-06-15T14:09:55.616Z HAP-NodeJS:Accessory [Homebridge] Getting value for Characteristic "Mute"
2020-06-15T14:09:55.617Z HAP-NodeJS:Accessory [Homebridge] Got Characteristic "Mute" value: false
2020-06-15T14:09:55.617Z HAP-NodeJS:Accessory [Homebridge] Getting value for Characteristic "Volume"
2020-06-15T14:09:55.617Z HAP-NodeJS:Accessory [Homebridge] Got Characteristic "Volume" value: 100

Yet the following does nothing:

this.controller.on(CameraControllerEvents.MICROPHONE_PROPERTIES_CHANGED, (mute, volume) => {
  console.log(mute as boolean);
});

[Supereg]

Well the mentioned log does not perform a write request, thus no value actually changed. What is the unexpected behavior for this exact log output?

[Brandawg93]

Ok. It looks like the MUTE characteristic is never being set in the logs. I assume that, in turn, this is never called?

[Brandawg93]

Here is the full output:

2020-06-15T17:25:14.614Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] New connection from client
2020-06-15T17:25:14.614Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server listening on port 45295
2020-06-15T17:25:14.617Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP request: /
2020-06-15T17:25:14.617Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] HAP Request: GET /
2020-06-15T17:25:14.617Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] WARNING: Handler for / not implemented
2020-06-15T17:25:14.618Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP Response is finished
2020-06-15T17:25:14.620Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP connection was closed
2020-06-15T17:25:14.620Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server was closed
2020-06-15T17:25:14.621Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] Client connection closed
2020-06-15T17:25:15.448Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.1.148] HTTP request: /characteristics?id=66.9,66.10
2020-06-15T17:25:15.448Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] HAP Request: GET /characteristics?id=66.9,66.10
2020-06-15T17:25:15.449Z HAP-NodeJS:Accessory [Homebridge] Getting value for Characteristic "Mute"
2020-06-15T17:25:15.450Z HAP-NodeJS:Accessory [Homebridge] Got Characteristic "Mute" value: false
2020-06-15T17:25:15.450Z HAP-NodeJS:Accessory [Homebridge] Getting value for Characteristic "Volume"
2020-06-15T17:25:15.451Z HAP-NodeJS:Accessory [Homebridge] Got Characteristic "Volume" value: 100
2020-06-15T17:25:15.453Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.1.148] HTTP Response is finished
2020-06-15T17:25:24.613Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] New connection from client
2020-06-15T17:25:24.613Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server listening on port 44939
2020-06-15T17:25:24.615Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP request: /
2020-06-15T17:25:24.615Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] HAP Request: GET /
2020-06-15T17:25:24.615Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] WARNING: Handler for / not implemented
2020-06-15T17:25:24.616Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP Response is finished
2020-06-15T17:25:24.617Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP connection was closed
2020-06-15T17:25:24.617Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server was closed
2020-06-15T17:25:24.618Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] Client connection closed
2020-06-15T17:25:25.168Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.1.148] HTTP request: /characteristics
2020-06-15T17:25:25.168Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] HAP Request: PUT /characteristics
2020-06-15T17:25:25.169Z HAP-NodeJS:Accessory [Homebridge] Processing characteristic set: [{"aid":66,"iid":26,"value":"ARUCAQQBEPp05Ml+M0O6nRxcM6W11RMCGQMLAQKAAgICaAEDAR4ECgMChAAEBAAAAAA="}]
2020-06-15T17:25:25.169Z HAP-NodeJS:Accessory [Homebridge] Setting Characteristic "Selected RTP Stream Configuration" to value ARUCAQQBEPp05Ml+M0O6nRxcM6W11RMCGQMLAQKAAgICaAEDAR4ECgMChAAEBAAAAAA=
2020-06-15T17:25:25.171Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.1.148] HTTP Response is finished
2020-06-15T17:25:34.615Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] New connection from client
2020-06-15T17:25:34.615Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server listening on port 37151
2020-06-15T17:25:34.618Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP request: /
2020-06-15T17:25:34.618Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] HAP Request: GET /
2020-06-15T17:25:34.618Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] WARNING: Handler for / not implemented
2020-06-15T17:25:34.619Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP Response is finished
2020-06-15T17:25:34.621Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP connection was closed
2020-06-15T17:25:34.622Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server was closed
2020-06-15T17:25:34.623Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] Client connection closed
2020-06-15T17:25:41.130Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.1.148] HTTP request: /characteristics?id=66.12,66.13
2020-06-15T17:25:41.130Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] HAP Request: GET /characteristics?id=66.12,66.13
2020-06-15T17:25:41.132Z HAP-NodeJS:Accessory [Homebridge] Getting value for Characteristic "Mute"
2020-06-15T17:25:41.132Z HAP-NodeJS:Accessory [Homebridge] Got Characteristic "Mute" value: false
2020-06-15T17:25:41.132Z HAP-NodeJS:Accessory [Homebridge] Getting value for Characteristic "Volume"
2020-06-15T17:25:41.132Z HAP-NodeJS:Accessory [Homebridge] Got Characteristic "Volume" value: 100
2020-06-15T17:25:41.133Z HAP-NodeJS:EventedHTTPServer [::ffff:192.168.1.148] HTTP Response is finished

//Mute button was pressed here

2020-06-15T17:25:44.614Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] New connection from client
2020-06-15T17:25:44.614Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server listening on port 39079
2020-06-15T17:25:44.616Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP request: /
2020-06-15T17:25:44.616Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] HAP Request: GET /
2020-06-15T17:25:44.616Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] WARNING: Handler for / not implemented
2020-06-15T17:25:44.617Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP Response is finished
2020-06-15T17:25:44.618Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP connection was closed
2020-06-15T17:25:44.619Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server was closed
2020-06-15T17:25:44.619Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] Client connection closed
2020-06-15T17:25:54.615Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] New connection from client
2020-06-15T17:25:54.626Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server listening on port 44997
2020-06-15T17:25:54.630Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP request: /
2020-06-15T17:25:54.631Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] HAP Request: GET /
2020-06-15T17:25:54.644Z HAP-NodeJS:HAPServer [CC:22:3D:E3:CE:30] WARNING: Handler for / not implemented
2020-06-15T17:25:54.645Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP Response is finished
2020-06-15T17:25:54.646Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP connection was closed
2020-06-15T17:25:54.647Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server was closed
2020-06-15T17:25:54.647Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] Client connection closed
2020-06-15T17:26:04.615Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] New connection from client
2020-06-15T17:26:04.615Z HAP-NodeJS:EventedHTTPServer [::ffff:127.0.0.1] HTTP server listening on port 4

[Supereg]

Ok. It looks like the MUTE characteristic is never being set in the logs. I assume that, in turn, this is never called?

The Mute characteristics defaults to false (I should have added a method to get the current mute state maybe 😅).

I observed that HomeKit won't really interact with the mute or volume characteristics. Only if mute ist set to true and the stream expects an microphone input, HomeKit will send a request to set it to unmute (but it won't mute it again).

[Supereg]

The mute buttons in the video view are all completely client side and have no effect on the camera accessory. Even the volume slider will not be changed. This happens all locally on the iDevice.

[Brandawg93]

Ok. Understandable. It looked connected in the code, but that makes sense. Is there another hook I can use the know when return audio is being enabled/disabled? Currently, when I see data, I'm assuming enabled and after a timeout period, I'm assuming disabled.

[Supereg]

Well, when the stream starts audio is enabled, when the stream stops, audio is disabled. You can't detect if the user decides to mute or unmute the audio stream on their device. And least that are my observations over the last few years.

[Brandawg93]

Ok. I'll continue with how I have it. Thanks for looking into this.

[Supereg]

reopned as there is actually still an issue with the service no being properly referenced when recreating the controller form disk 😅

[Supereg]

Fixed in v0.7.4, mic and speaker services are now properly referenced when recreating from disk. Should the options of the CameraController change, both services are removed/recreated if necessary.

I'm still undecided if methods like getMicrophoneMuted, getMicrophoneVolume, etc are necessary, as the CameraController is not the one deciding which value is the current one, rather the plugin dev should set the current value describing the current state of the Camera and react to set events accordingly. Nonetheless API changes would only be introduced with the future 0.8.0 minor release.