Adapter needs 15 Mins to detect MQTT outage

[padman74]

Hello,
I'm using a Dyson Purifier Cool and the adapter works good.
When i unplug the fan and plug it in again, the adapter is not able to reconnect.
The debug log only says "Updating device [K1Y-EU-PEA2526A] (polling API scheduled)." but nothing else.

Did i miss anything?

Regards
Volker

[Grizzelbee]

Hi Volker,
The adapter is not able to react to chaning IP-adresses during runtime.
I assume that due to the un- and replug of the fan it gets a new IP.
So if you use a FritzBox or a lokal DNS use the host name of the fan instead of it's IP.
If not - assign a fixed IP to your fan in your router.

If none of this works, please drop me a notice and a debug-Log.

[padman74]

Hi Grippelbee,
i have a static IP with my Dyson.

Log snippet here - it does not contain much information, to be honest.

2023-12-11 13:57:39.713 - debug: dysonairpurifier.0 (37246) Updating device [K1Y-EU-PEA2526A] (polling API scheduled).
2023-12-11 13:57:39.892 - debug: dysonairpurifier.0 (37246) MessageType: CURRENT-STATE
2023-12-11 13:57:39.906 - debug: dysonairpurifier.0 (37246) K1Y-EU-PEA2526A - MQTT message received: {"msg":"CURRENT-STATE","time":"2023-12-11T12:57:40.000Z","mode-reason":"NONE","state-reason":"MODE","rssi":"-35","channel":"11","fqhp":"104336","fghp":"72808","product-state":{"fpwr":"OFF","auto":"OFF","oscs":"OFF","oson":"OFF","nmod":"OFF","rhtm":"OFF","fnst":"OFF","ercd":"NONE","wacd":"NONE","nmdv":"0004","fnsp":"0001","bril":"0002","corf":"ON","cflr":"INV","hflr":"0100","cflt":"NONE","hflt":"GCOM","sltm":"OFF","osal":"0135","osau":"0225","ancp":"CUST","fdir":"ON"},"scheduler":{"srsc":"0000000000000000","dstv":"0000","tzid":"0001"}}
2023-12-11 13:57:39.944 - debug: dysonairpurifier.0 (37246) MessageType: ENVIRONMENTAL-CURRENT-SENSOR-DATA
2023-12-11 13:57:39.949 - debug: dysonairpurifier.0 (37246) K1Y-EU-PEA2526A - MQTT message received: {"msg":"ENVIRONMENTAL-CURRENT-SENSOR-DATA","time":"2023-12-11T12:57:40.000Z","data":{"tact":"OFF","hact":"OFF","pm25":"OFF","pm10":"OFF","va10":"OFF","noxl":"OFF","p25r":"OFF","p10r":"OFF","hcho":"NONE","hchr":"NONE","sltm":"OFF"}}
2023-12-11 13:57:39.992 - debug: dysonairpurifier.0 (37246) MessageType: CURRENT-FAULTS
2023-12-11 13:57:40.007 - debug: dysonairpurifier.0 (37246) K1Y-EU-PEA2526A - MQTT message received: {"msg":"CURRENT-FAULTS","time":"2023-12-11T12:57:40.000Z","product-errors":{"amf1":"OK","amf2":"OK","amf3":"OK","amf4":"OK","amf5":"OK","amf6":"OK","amf7":"OK","amf8":"OK","amf9":"OK","com4":"OK","com1":"OK","ste1":"OK","iuh0":"OK","iup0":"OK","iuw0":"OK","iuh1":"OK","iuu1":"OK","iuc1":"OK","iuw1":"OK","iua1":"OK","iuh2":"OK","iuu2":"OK","iuc2":"OK","iuw2":"OK","iua2":"OK","ui01":"OK","ui02":"OK","ui03":"OK","uid1":"OK","uid2":"OK","fs01":"OK","fs02":"OK","fs03":"OK","fs04":"OK","fs05":"OK","fs06":"OK","fs07":"OK","fs08":"OK","fs09":"OK","fs0a":"OK","fs0b":"OK","fs0c":"OK","psu1":"OK","psu2":"OK","sen1":"OK","sen2":"OK","sen3":"OK","sen4":"OK","sen7":"OK","com5":"OK","com2":"OK"},"product-warnings":{"fltr":"OK"},"module-errors":{"szme":"OK","szmw":"OK","szps":"OK","szpe":"OK","szpw":"OK","szed":"OK","lspd":"OK","szpi":"OK","szpp":"OK","szhv":"OK","szbv":"OK","szav":"OK"},"module-warnings":{"srnk":"OK","stac":"OK","strs":"OK","srmi":"OK","srmu":"OK","nwcs":"OK","nwts":"OK","nwps":"OK","nwss":"OK"}}
2023-12-11 13:58:09.715 - debug: dysonairpurifier.0 (37246) Updating device [K1Y-EU-PEA2526A] (polling API scheduled).
2023-12-11 13:58:39.718 - debug: dysonairpurifier.0 (37246) Updating device [K1Y-EU-PEA2526A] (polling API scheduled).

---

[Grizzelbee]

Okay. Let's try to clarify and sort things out:

a usual log should look like ths:
I have 2 dysons running and disconnected/reconnected one of them:

2023-12-11 12:33:09.542  - info: dysonairpurifier.0 (1247) starting. Version 2.5.9 in /opt/iobroker/node_modules/iobroker.dysonairpurifier, node: v18.13.0, js-controller: 5.0.16
2023-12-11 12:33:09.570  - info: dysonairpurifier.0 (1247) Querying devices from dyson API.
2023-12-11 12:33:09.924  - info: dysonairpurifier.0 (1247) No host address given. Trying to connect to the device with it's default hostname [C4H-EU-NHC1007A]. This should work if you haven't changed it and if you're running a DNS.
2023-12-11 12:33:09.926  - info: dysonairpurifier.0 (1247) Trying to connect to device [C4H-EU-NHC1007A] via MQTT on host address [C4H-EU-NHC1007A].
2023-12-11 12:33:09.953  - info: dysonairpurifier.0 (1247) C4H-EU-NHC1007A - MQTT connection requested for [C4H-EU-NHC1007A].
2023-12-11 12:33:09.976  - info: dysonairpurifier.0 (1247) No host address given. Trying to connect to the device with it's default hostname [VS9-EU-NAB0887A]. This should work if you haven't changed it and if you're running a DNS.
2023-12-11 12:33:09.976  - info: dysonairpurifier.0 (1247) Trying to connect to device [VS9-EU-NAB0887A] via MQTT on host address [VS9-EU-NAB0887A].
2023-12-11 12:33:09.981  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT connection requested for [VS9-EU-NAB0887A].
2023-12-11 12:33:13.273  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT connection established.
2023-12-11 12:33:13.275  - info: dysonairpurifier.0 (1247) Starting Polltimer with a 30 seconds interval.
2023-12-11 12:33:13.290  - info: dysonairpurifier.0 (1247) C4H-EU-NHC1007A - MQTT connection established.
2023-12-11 12:33:13.291  - info: dysonairpurifier.0 (1247) Starting Polltimer with a 30 seconds interval.
2023-12-11 14:04:45.331  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT offline.
[ connection is broken for some reason ]
2023-12-11 14:04:45.335  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT disconnected.
2023-12-11 14:04:46.337  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT reconnecting.
2023-12-11 14:04:51.933  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT connection established.
2023-12-11 14:04:51.933  - info: dysonairpurifier.0 (1247) Starting Polltimer with a 30 seconds interval.
[ dyson reconnected automatically ]
2023-12-11 17:54:56.784  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT offline.
[ dyson got disconnected intentionally ]
2023-12-11 17:54:56.788  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT disconnected.
2023-12-11 17:54:57.790  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT reconnecting.
2023-12-11 17:55:05.870  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT disconnected.
2023-12-11 17:55:06.870  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT reconnecting.
2023-12-11 17:55:12.875  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT disconnected.
2023-12-11 17:55:13.875  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT reconnecting.
[...]
2023-12-11 18:14:18.570  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT disconnected.
2023-12-11 18:14:19.572  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT reconnecting.
2023-12-11 18:14:25.546  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT disconnected.
2023-12-11 18:14:26.547  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT reconnecting.
2023-12-11 18:14:34.634  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT disconnected.
[ dyson got pluged in back again and reconnected automatically] 
2023-12-11 18:14:35.634  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT reconnecting.
2023-12-11 18:14:42.451  - info: dysonairpurifier.0 (1247) VS9-EU-NAB0887A - MQTT connection established.
2023-12-11 18:14:42.452  - info: dysonairpurifier.0 (1247) Starting Polltimer with a 30 seconds interval.

This is the usual behavior of the adapter. Sorry that I didn't come up with this earlier - I've been blind and stupid for some reason.

As you may see: The adapter is pretty silent as long as it works as intended - and it needs some time (until the next poll happens) to detect that the fan has disconnected. If the interrupt is shorter - the adapter won't recognise it.

Conclusion: As long as you don't see these MQTT messages in your log, you shouldn't have any connection issues.

That brings me to the following question:
You mentioned in the beginning that the adapter doesn't reconnect - what happend exactly that let you think that you might have a connection issue?

[padman74]

Well, indeed, i do not see any MQTT messages in the log and what’s interesting: Although the power got lost, the data node still says that the fan is online. Seems that the adapter does not poll the right status from the physical fan. But when i then (re)plug in the fan and set the data node for main power to on, the fan doesn’t turn on. I need to restart the adapter so that everything is cleared.

[Grizzelbee]

Although the power got lost, the data node still says that the fan is online.

Hmmm. Things are geting stranger with every post.

My assumption: The power interrupt wasn't long enough so that the adapter wasn't able to recognize that the connection to the fan got lost - that's pretty obvious.

In my case it takes up to 30 seconds (= 1 poll intervall) for the adapter to recognize that the connection got lost. In your case it depends on what time you have set for a poll interval.

As soon as the poll happens the adapter throws these MQTT messages and sets the ONLINE datapoint for the device to FALSE and vice versa when the device reconnects.

By the way: What adapter version are you on and have you maybe disabled the reconnection logging? In that case you won't see the MQTT disconnected/reconnecting messages in the log. But you'll still see some other MQTT messages and the correct online/offline state of the device in the device tree.

So please test: Unplug the fan from power and wait at least up to the poll interval you set (plus a few seconds) and look for MQTT messages in the log and the online state of the fan to change. Does it happen as I expect - showing the right states?

[padman74]

I use version 2.5.9, i use default values, 30sec and disabled "Deaktivieren Sie die Wiederverbindungsprotokollierung".

Now I found out that MQTT failure is only identified after 15 minutes. Connection is being reestablished successfully then.

Although this is not the expected behavior, I can live with it.

Kind Regards
Volker

[Grizzelbee]

Hi Volker,

Now I found out that MQTT failure is only identified after 15 minutes. Connection is being reestablished successfully then.
Although this is not the expected behavior, I can live with it.

I'm happy that you have identified this issue/behaviour - since it's not intended to work that way and even you can live with it I'm going to try to find the root cause and fix it.

Thank you so far.

[Grizzelbee]

Checked this issue again with V3.1.1 - and the outage is detected immediately with next poll.
Would you please re-check this with v3.1.1 and drop me a note whether the issue is still active for you, or whether it has been fixed by accident?

[padman74]

Not sure. It still needs 15 min to detect the disconnection. And then it throws every sec the log messages "disconnected" and "reconnecting" so that I have stopped the adapter. In winter it's out of order.

[Grizzelbee]

Hmm. Really strange. But for now I don't have any point to start searching from - since I can't reproduce that behavior.
I'm open to start a new round of investigation if get new information on this.

Maybe write another debug log with V3.1.1 and post the full log (filtered to dysonairpurifier) this time - when you have time and the mood to do so.
To filter the log on Linux command line use: cat iobroker.current.log | grep dysonairpurifier when in directory /opt/iobroker/log/.