Node-red-contrib-homekit-bridged: Error: This callback function has already been called by someone else...

[djiwondee]

Hello guys,

thank you very much for the large progress you have made with version 0.6.0. I'm really exited how linked services work now. Right now the only issue I have with that is I got a lot of this message in my node-red-log:

18 Mar 14:35:26 - [error] [homekit-service:XXXXX-XXXX-temp] Error: This callback function has already been called by someone else; it can only be called one time.

It looks like this is cause by re-deploying modified flows on node-red but I haven't figured out right now if this is based on changes on _node-red-contrib-homekit-bridged-nodes_ or on changes of any other nodes as well.

Any ideas?

[Fearraiser]

Same issue, showing this error, but works normally.

[djiwondee]

As more as I play with that I would say it happens only if (re-)deploy a flow /part of a flow with changes on the HomeKit node (e. g. adding a new accessories to an existing config node, changing service characteristics, properties etc.)

[Shaquu]

Thanks for reporting.
Maybe this is called twice onIdentify.

_{Sent with GitHawk}

[Shaquu]

@djiwondee @Fearraiser
Can you retest it on dev branch?
start node-red in debug mode:

DEBUG=NRCHKB node-red

Then try to make this error appear again and paste log here.

[Fearraiser]

My log after redeploy node:

19 Mar 02:12:55 - [info] Starting modified flows
19 Mar 02:12:55 - [info] Started modified flows
19 Mar 02:13:07 - [red] Uncaught Exception:
19 Mar 02:13:07 - Error: This callback function has already been called by someone else; it can only be called one time.
    at /home/pi/.node-red/node_modules/hap-nodejs/lib/util/once.js:12:13
    at Characteristic.TargetPosition.<anonymous> (/home/pi/.node-red/node_modules/node-red-contrib-homekit-bridged/lib/utils/CharacteristicUtils.js:47:25)
    at emitThree (events.js:141:20)
    at Characteristic.TargetPosition.emit (events.js:217:7)
    at Characteristic.TargetPosition.Characteristic.getValue (/home/pi/.node-red/node_modules/hap-nodejs/lib/Characteristic.js:164:10)
    at Bridge.<anonymous> (/home/pi/.node-red/node_modules/hap-nodejs/lib/Accessory.js:762:20)
    at Array.forEach (<anonymous>)
    at Bridge.Accessory._handleGetCharacteristics (/home/pi/.node-red/node_modules/hap-nodejs/lib/Accessory.js:726:8)
    at emitMany (events.js:147:13)
    at HAPServer.emit (events.js:224:7)
    at HAPServer._handleCharacteristics (/home/pi/.node-red/node_modules/hap-nodejs/lib/HAPServer.js:926:10)
    at HAPServer.<anonymous> (/home/pi/.node-red/node_modules/hap-nodejs/lib/HAPServer.js:209:39)
    at emitNone (events.js:106:13)
    at IncomingMessage.emit (events.js:208:7)
    at endReadableNT (_stream_readable.js:1064:12)
    at _combinedTickCallback (internal/process/next_tick.js:138:11)

and then node-red stops

My flow is:

[{"id":"9c3a35ec.e9439","type":"tab","label":"Flow 3","disabled":false,"info":""},{"id":"41f12712.256b7","type":"homekit-service","z":"9c3a35ec.e9439","isParent":true,"bridge":"34d1ed3.82cca12","parentService":"","name":"Калитка","serviceName":"Door","topic":"","filter":false,"manufacturer":"Default Manufacturer","model":"Default Model","serialNo":"Default Serial Number","characteristicProperties":"","x":580,"y":60,"wires":[["aab31409.9545f"]]},{"id":"52097f82.de13e","type":"inject","z":"9c3a35ec.e9439","name":"Открыто","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":120,"y":60,"wires":[["eeea4e5d.2383d"]]},{"id":"3bcb3f2e.2120d8","type":"inject","z":"9c3a35ec.e9439","name":"Закрыто","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":true,"onceDelay":0.1,"x":120,"y":120,"wires":[["1c3f73da.3823a4"]]},{"id":"eeea4e5d.2383d","type":"template","z":"9c3a35ec.e9439","name":"Convert to JSON","field":"payload","fieldType":"msg","format":"handlebars","syntax":"mustache","template":"{\n\"CurrentPosition\": \"100\"\n}","output":"json","x":330,"y":60,"wires":[["41f12712.256b7"]]},{"id":"1c3f73da.3823a4","type":"template","z":"9c3a35ec.e9439","name":"Convert to JSON","field":"payload","fieldType":"msg","format":"handlebars","syntax":"mustache","template":"{\n\"CurrentPosition\": \"0\"\n}","output":"json","x":330,"y":120,"wires":[["41f12712.256b7"]]},{"id":"aab31409.9545f","type":"debug","z":"9c3a35ec.e9439","name":"2","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","x":770,"y":60,"wires":[]},{"id":"34d1ed3.82cca12","type":"homekit-bridge","z":"","bridgeName":"Virtual Homebridge","pinCode":"111-11-111","port":"","allowInsecureRequest":false,"manufacturer":"Fer","model":"Virtual Homebridge","serialNo":"SN 111-11-111"}]

[Shaquu]

@Fearraiser thanks, very helpful.
@radionoise would you like to take care about this as I think it’s related to your change (NO_RESPONSE).

_{Sent with GitHawk}

[radionoise]

I’ll look at it

[Shaquu]

One more thing. Maybe we can just remove callback if accessory is reachable?

if (node.accessory.reachable === true) {
    callback(null, characteristic.value);
} else {
    callback("no response", null);
}

=>

if (node.accessory.reachable !== true) {
    callback("no response", null);
}

[djiwondee]

@Shaquu
may be I'm doing something wrong but my log is not showing something more than already metioned

19 Mar 10:21:58 - [trace] [flow:755d7c8e.995f8c]  3ccbca9e.00895e  | inject       |
19 Mar 10:21:58 - [trace] [flow:755d7c8e.995f8c] ------------------|--------------|-----------------
19 Mar 10:21:58 - [trace] runtime event: {"id":"runtime-state","retain":true}
19 Mar 10:21:58 - [info] Gestartete geänderte Flows
19 Mar 10:21:58 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"4e8aeb141c05cbf1035ea449222cb5fd"},"retain":true}
19 Mar 10:22:15 - [error] [homekit-service:Temperature Outdoor] Error: This callback function has already been called by someone else; it can only be called one time.
19 Mar 10:22:15 - [error] [homekit-service:Humidity Outdoor] Error: This callback function has already been called by someone else; it can only be called one time.
19 Mar 10:22:15 - [error] [homekit-service:Temperature Outdoor Battery Service] Error: This callback function has already been called by someone else; it can only be called one time.
19 Mar 10:22:15 - [error] [homekit-service:Humi Outdoor Battery Service] Error: This callback function has already been called by someone else; it can only be called one time.
Stopping Node-RED graphical event wiring tool...

My flow ist this:

and I can replicate this if I change something in the node e. g. the node name and click on redeploy.

May be it it is caused by the "double linked" battery level. The humidity and the temperature sensor sharing the same battery. But since both are different accessories in home.app I would like to see the battery level in both home.app accessories properties.

As I wrote before, the message never appears again if i just restart node-red. Also with the error both sensor in home.app working well:

[Shaquu]

@djiwondee thanks for additional info. I think additional Battery Service should not cause this but you know...
I will live this to @radionoise for now

[djiwondee]

Back to the initial problem: found some more log info but dealing with Switch instead of Battery Service:

19 Mar 16:39:14 - [error] [homekit-service:Guest WIFI] Error: This callback function has already been called by someone else; it can only be called one time.
19 Mar 16:39:25 - [error] [homekit-service:Guest WIFI] Error: This callback function has already been called by someone else; it can only be called one time.
19 Mar 16:40:09 - [red] Uncaught Exception:
19 Mar 16:40:09 - Error: This callback function has already been called by someone else; it can only be called one time.
    at /home/pi/.node-red/node_modules/hap-nodejs/lib/util/once.js:12:13
    at Characteristic.On.<anonymous> (/home/pi/.node-red/node_modules/node-red-contrib-homekit-bridged/lib/utils/CharacteristicUtils.js:63:21)
    at emitMany (events.js:152:20)
    at Characteristic.On.emit (events.js:224:7)
    at Characteristic.On.Characteristic.setValue (/home/pi/.node-red/node_modules/hap-nodejs/lib/Characteristic.js:321:10)
nodered.service: Main process exited, code=exited, status=1/FAILURE

[bakman2]

Same issue here, it crashes node-red regularly.

[Shaquu]

Please update to new version 0.6.1 using node-red.
Then please retest this bug if it's still occurs.

[djiwondee]

Hello @Shaquu

problem seems to have gone. Have just checked it wit 0.6.1

• Changing bridge
• Changing characteristics properties
• Changing name

Works quite well!

Btw.: in addition to the behavior as describe as the issue in my last test with 0.6.0node red gots crashed with that message:

20 Mar 17:08:18 - [info] Gestartete geänderte Flows 20 Mar 17:08:20 - [red] Uncaught Exception: 20 Mar 17:08:20 - Error: This callback function has already been called by someone else; it can only be called one time. at /home/pi/.node-red/node_modules/hap-nodejs/lib/util/once.js:12:13 at Characteristic.On.<anonymous> (/home/pi/.node-red/node_modules/node-red-contrib-homekit-bridged/lib/utils/CharacteristicUtils.js:47:25) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Unit entered failed state. nodered.service: Failed with result 'exit-code'. nodered.service: Service hold-off time over, scheduling restart. Stopped Node-RED graphical event wiring tool. Started Node-RED graphical event wiring tool.

This also disappeared with 0.6.1 as expected. Thanks for resolving that issue!

[Shaquu]

Thanks to @radionoise
And thanks to all here who reported bug and provided explanation.

Closing.

[bakman2]

Thanks for fixing this.

In the mean time I was checking out homebridge-mqtt. What surprised to me compared to homekit-bridged is that accessories are removed and added instantly. I have never seen this, always had issues with homekit behaviour when adding accessories and quite slow detecting new items or removing. Is this just me ?

[Shaquu]

Different architecture @bakman2
So yes, it can be slower here. If you have issues running our module then please report in as a new Issue.

[subzero79]

I am getting this error using the latest 0.6.2

Jul 11 10:47:40 ha nodered[9482]: 11 Jul 10:47:40 - [error] [homekit-service:3fd86e93.d19ba2] Error: This callback function has already been called by someone else; it can only be called one time.
Jul 11 10:47:40 ha nodered[9482]:     at /srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/node_modules/hap-nodejs/lib/util/once.js:12:13
Jul 11 10:47:40 ha nodered[9482]:     at Accessory.onIdentify (/srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/lib/utils/AccessoryUtils.js:94:9)
Jul 11 10:47:40 ha nodered[9482]:     at Accessory.emit (events.js:203:15)
Jul 11 10:47:40 ha nodered[9482]:     at Accessory.EventEmitter.emit (domain.js:448:20)
Jul 11 10:47:40 ha nodered[9482]:     at Accessory._identificationRequest (/srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/node_modules/hap-nodejs/lib/Accessory.js:132:10)
Jul 11 10:47:40 ha nodered[9482]:     at Accessory.<anonymous> (/srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/node_modules/hap-nodejs/lib/Accessory.js:82:14)
Jul 11 10:47:40 ha nodered[9482]:     at Characteristic.Identify.emit (events.js:198:13)
Jul 11 10:47:40 ha nodered[9482]:     at Characteristic.Identify.EventEmitter.emit (domain.js:448:20)
Jul 11 10:47:40 ha nodered[9482]:     at Characteristic.Identify.Characteristic.setValue (/srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/node_modules/hap-nodejs/lib/Characteristic.js:323:10)
Jul 11 10:47:40 ha nodered[9482]:     at Service.AccessoryInformation.Service.setCharacteristic (/srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/node_modules/hap-nodejs/lib/Service.js:183:32)
Jul 11 10:47:40 ha nodered[9482]:     at Object.getOrCreate (/srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/lib/utils/AccessoryUtils.js:60:14)
Jul 11 10:47:40 ha nodered[9482]:     at configure (/srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/lib/HAPServiceNode.js:109:40)
Jul 11 10:47:40 ha nodered[9482]:     at new init (/srv/hass_storage/home/.node-red/node_modules/node-red-contrib-homekit-bridged/lib/HAPServiceNode.js:17:13)
Jul 11 10:47:40 ha nodered[9482]:     at Object.createNode (/srv/hass_storage/apps/virtualenvs/nodered_nodeenv/lib/node_modules/node-red/node_modules/@node-red/runtime/lib/nodes/flows/util.js:483:31)
Jul 11 10:47:40 ha nodered[9482]:     at Flow.start (/srv/hass_storage/apps/virtualenvs/nodered_nodeenv/lib/node_modules/node-red/node_modules/@node-red/runtime/lib/nodes/flows/Flow.js:176:44)
Jul 11 10:47:40 ha nodered[9482]:     at start (/srv/hass_storage/apps/virtualenvs/nodered_nodeenv/lib/node_modules/node-red/node_modules/@node-red/runtime/lib/nodes/flows/index.js:329:33)
Jul 11 10:47:40 ha nodered[9482]:     at stop.then.then (/srv/hass_storage/apps/virtualenvs/nodered_nodeenv/lib/node_modules/node-red/node_modules/@node-red/runtime/lib/nodes/flows/index.js:196:21)
Jul 11 10:47:40 ha nodered[9482]: 11 Jul 10:47:40 - [info] Started modified nodes

Let me know if you need more logs, this happens every time i deploy.

nodejs version 10.16.0
OS: Debian 9

[mullischlumpf]

I am also getting this error using the latest 0.6.2 Version.

[mgx0]

me too, happening on version 0.8.0 as well