ioBroker / ioBroker.mqtt

Mqtt server and client for ioBroker.
MIT License
54 stars 29 forks source link

Incoming publish messages dropped somewhere #360

Open raintonr opened 1 year ago

raintonr commented 1 year ago

Version 4.0.7 in /opt/iobroker/node_modules/iobroker.mqtt, node: v16.19.1, js-controller: 4.0.24

Am using IoB MQTT with Frigate.

To test, have a JS script running with the following code:

on(new RegExp('^mqtt.0.frigate.*'), (obj) => {
    log(`Change: ${obj.id}`);
});

Somehow, some messages published by Frigate are not triggering this. Specifically binary snapshots. I verified this by running Wireshark on the IoB host capturing MQTT packets.

The script logged:

2023-04-25 13:17:44.782  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.cse.motion
2023-04-25 13:17:52.488  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.porch_intercom.motion
2023-04-25 13:17:53.088  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.events
2023-04-25 13:17:53.102  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.porch_intercom.person
2023-04-25 13:17:53.152  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.porch_intercom.all
2023-04-25 13:17:53.155  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.terrace_north.person
2023-04-25 13:17:53.159  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.terrace_north.all
2023-04-25 13:17:53.284  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.events
2023-04-25 13:17:58.301  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.events
2023-04-25 13:18:02.537  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.events
2023-04-25 13:18:02.713  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.porch_intercom.person
2023-04-25 13:18:02.718  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.porch_intercom.all
2023-04-25 13:18:02.719  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.terrace_north.person
2023-04-25 13:18:02.796  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.terrace_north.all

... but Wireshark saw...

image

As you can see, the highlighted snapshot publish was somehow lost.

As per the advice of #115 I have modified that state to be a file:

{
  "_id": "mqtt.0.frigate.porch_intercom.person.snapshot",
  "common": {
    "name": "frigate/porch_intercom/person/snapshot",
    "write": true,
    "read": true,
    "role": "variable",
    "desc": "mqtt server variable",
    "type": "file"
  },
  "native": {
    "topic": "frigate/porch_intercom/person/snapshot"
  },
  "type": "state",
  "acl": {
    "object": 1636,
    "state": 1636,
    "owner": "system.user.admin",
    "ownerGroup": "system.group.administrator"
  },
  "from": "system.adapter.admin.0",
  "user": "system.user.admin",
  "ts": 1682411812799,
  "binary": true
}

This is suspicious and seems something is still broken with binary handling.

raintonr commented 1 year ago

Digging deeper, I put some logging in front of this call to setForeignBinaryStateAsync: https://github.com/ioBroker/ioBroker.mqtt/blob/76cd5b7b2d8de5ca50db85392619a0037b75f579/lib/server.js#L414

The following was logged:

2023-04-25 14:05:44.424  - debug: mqtt.0 (27524) setForeignBinaryStateAsync: mqtt.0.frigate.porch_intercom.person.snapshot
2023-04-25 14:05:44.473  - info: javascript.0 (7755) script.js.cameras.frigateMqttTelegram: Change: mqtt.0.frigate.porch_intercom.person

What's going on here? Perhaps this is actually a bug with js-controller as setForeignBinaryStateAsync set ID mqtt.0.frigate.porch_intercom.person.snapshot but my JS script was triggered with a change on mqtt.0.frigate.porch_intercom.person.

Apollon77 commented 1 year ago

The reality is the following: Binary state changes are not subscribable right now, so this is the main reason. We can not fix this. Soon with js-controller 5 also Binary states will get deprecated and replaced by files and they can be subscribed in js-controller 5 then.

For now I can not provide a solution, but "soon"

raintonr commented 1 year ago

TBH, the Frigate doco is very unclear and turns out that the image it publishes in this binary topic are not actually what I want. Turns out one needs to just watch the other 'notification' topics then go fetch the image required manually when triggered.

So yeah, while something fishy is going on I do have another solution so for me at least this is not a high priority :wink: