MQTT connection created while broker refused

[JanJaap]

Version: 4.11062
Platform: RPI 3b
Plugin/Hardware: Domoticz connection object in Python framework
Description:
I'm developing a Python plugin to connect to a Dyson pure cool tower. It has an MQTT broker, see github.com/JanJaapKo for more info. I use the Domoticz connection object (Domoticz.Connection) to setup the communication. This particular broker requires authentication with user name and password. Happy flow works well, but I'm now trying to improve the exception handling (in this case: supply wrong password). One thing I run into is that the Domoticz connection object seems to look only for the MQTT conack message, not it's payload. I used wireshark to check the traffic, see below screenshot.

What happens now is that the broker refuses the connection, but Domoticz (incorreclty) thinks we have a connection, so the plugin will start issueing commands, which will then result in an error:

Code: Select all

2019-08-06 22:18:38.320 Error: (Fan slaapkamer) No transport, write directive to '192.168.1.15' ignored.

So, would it be possible to take these returns codes into account?

Wireshark capture

Capture.PNG (31.25 KiB) Viewed 1783 times

possible returns codes:

Code: Select all

 0: 'Connection successful',
    1: 'Connection refused: incorrect protocol version',
    2: 'Connection refused: invalid client identifier',
    3: 'Connection refused: server unavailable',
    4: 'Connection refused: bad username or password',
    5: 'Connection refused: not authorised',
    99: 'Connection refused: timeout'

[Dnpwwo]

@JanJaap,

There is code in the Domoticz protocol to handle this (https://github.com/domoticz/domoticz/bl ... line 1212 if you are interested) but the MQTT Python class you are using seems to be where the assumption of a successful connection is being made on a CONNACK message.

I'm guessing the Dyson broker is dropping the connection after refusing to accept the credentials, the plugin framework should be informing the plugin of this.

Can you post the contents of verbose debug log when this happens? I will be able to tell you more from that

[JanJaap]

Hi,

I drew sort of the same conclusion: the connection object is created based on the CONACK message, but the content of the CONACK is not evaluated so it is always interpreted as positive ACK and never as negative ACK. Then the broker drops the connection and my plugin runs into an error when trying to publish to the broker.

I had a look into the C++ code (my C++ skills are a bit rusty though) but it looks like the Python Connection class is not getting this status of the CONACK message. In fact I would expect in C++ that the connection would not be created and a relevant return code be submitted to the python plugin. Therefor I printed the return parameters of the (like status and description) which are passed into the onConnect callback of the connection object. But it just returns 'Succes'.

Please see the verbose log (when I set my plugin to verbose logging, I hope that is what you mean) below. I could not find any useful hints, therefore I included the wireshark snapshot in the original post.

Verbose log:

Code: Select all

2019-08-09 15:51:20.766 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Night mode'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device nValue: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device sValue: 'OFF'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device: 3 - ID: 141, Name: 'Fan slaapkamer - Fan speed', nValue: 1, sValue: '110'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device ID: '141'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Fan speed'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device nValue: 1
2019-08-09 15:51:20.767 (Fan slaapkamer) Device sValue: '110'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device LastLevel: 110
2019-08-09 15:51:20.767 (Fan slaapkamer) Device: 4 - ID: 142, Name: 'Fan slaapkamer - Oscilation mode', nValue: 0, sValue: 'OFF'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device ID: '142'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Oscilation mode'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device nValue: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device sValue: 'OFF'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device: 5 - ID: 143, Name: 'Fan slaapkamer - Standby monitor', nValue: 0, sValue: ''
2019-08-09 15:51:20.767 (Fan slaapkamer) Device ID: '143'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Standby monitor'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device nValue: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device sValue: ''
2019-08-09 15:51:20.767 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device: 6 - ID: 144, Name: 'Fan slaapkamer - Remaining filter life', nValue: 0, sValue: '0'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device ID: '144'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Remaining filter life'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device nValue: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device sValue: '0'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device: 7 - ID: 145, Name: 'Fan slaapkamer - Air quality setpoint', nValue: 0, sValue: ''
2019-08-09 15:51:20.767 (Fan slaapkamer) Device ID: '145'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Air quality setpoint'
2019-08-09 15:51:20.767 (Fan slaapkamer) Device nValue: 0
2019-08-09 15:51:20.767 (Fan slaapkamer) Device sValue: ''
2019-08-09 15:51:20.767 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.768 (Fan slaapkamer) Device: 8 - ID: 146, Name: 'Temp en vocht slaapkamer', nValue: 1, sValue: '24.8;63;1'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device ID: '146'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device Name: 'Temp en vocht slaapkamer'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device nValue: 1
2019-08-09 15:51:20.768 (Fan slaapkamer) Device sValue: '24.8;63;1'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.768 (Fan slaapkamer) Device: 9 - ID: 147, Name: 'Fan slaapkamer - Volatile organic', nValue: 1, sValue: '1'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device ID: '147'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Volatile organic'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device nValue: 1
2019-08-09 15:51:20.768 (Fan slaapkamer) Device sValue: '1'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.768 (Fan slaapkamer) Device: 10 - ID: 148, Name: 'Fan slaapkamer - Dust', nValue: 3, sValue: '3'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device ID: '148'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Dust'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device nValue: 3
2019-08-09 15:51:20.768 (Fan slaapkamer) Device sValue: '3'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.768 (Fan slaapkamer) Device: 11 - ID: 149, Name: 'Fan slaapkamer - Sleep timer', nValue: 0, sValue: '0'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device ID: '149'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Sleep timer'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device nValue: 0
2019-08-09 15:51:20.768 (Fan slaapkamer) Device sValue: '0'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device LastLevel: 0
2019-08-09 15:51:20.768 (Fan slaapkamer) Device: 12 - ID: 139, Name: 'Fan slaapkamer - Fan state', nValue: 1, sValue: '20'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device ID: '139'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device Name: 'Fan slaapkamer - Fan state'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device nValue: 1
2019-08-09 15:51:20.768 (Fan slaapkamer) Device sValue: '20'
2019-08-09 15:51:20.768 (Fan slaapkamer) Device LastLevel: 20
2019-08-09 15:51:20.769 (Fan slaapkamer) MqttClient::__init__
2019-08-09 15:51:20.769 (Fan slaapkamer) MqttClient::Open
2019-08-09 15:51:20.769 (Fan slaapkamer) MqttClient::Open: setup Domoticz connection object with protocol: 'MQTT'
2019-08-09 15:51:20.769 (Fan slaapkamer) MqttClient::Open: open connection
2019-08-09 15:51:20.769 (Fan slaapkamer) Heartbeat interval set to: 10.
2019-08-09 15:51:20.769 (Fan slaapkamer) Protocol set to: 'MQTT'.
2019-08-09 15:51:20.769 (Fan slaapkamer) Transport set to: 'TCP/IP', 192.168.1.15:1883.
2019-08-09 15:51:20.769 (Fan slaapkamer) Connect directive received, action initiated successfully.
2019-08-09 15:51:20.819 (Fan slaapkamer) onConnect called
2019-08-09 15:51:20.819 (Fan slaapkamer) onConnect returns 1: Connection 'Name: '192.168.1.15', Transport: 'TCP/IP', Protocol: 'MQTT', Address: '192.168.1.15', Port: '1883', Baud: -1, Bytes: 0, Connected: True, Last Seen: 2019-08-09 15:51:20, Parent: 'None'', Status: '0', Description: 'Success'
2019-08-09 15:51:20.819 (Fan slaapkamer) MqttClient::MQTT connected successfully.
2019-08-09 15:51:20.820 (Fan slaapkamer) MqttClient::Connect
2019-08-09 15:51:20.820 (Fan slaapkamer) MqttClient::MQTT CONNECT ID: 'Domoticz_1565358680'
2019-08-09 15:51:20.820 (Fan slaapkamer) Sending 141 bytes of data
2019-08-09 15:51:20.820 (Fan slaapkamer) 10 8a 01 00 04 4d 51 54 54 04 c2 00 3c 00 13 44 6f 6d 6f 74 .�...MQTT.�.<..Domot
2019-08-09 15:51:20.820 (Fan slaapkamer) 69 63 7a 5f 31 35 36 35 33 35 38 36 38 30 00 0f 4e 4e 32 2d icz_1565358680..NN2-
2019-08-09 15:51:20.820 (Fan slaapkamer) 45 55 2d 4a 45 41 33 38 33 30 41 00 58 49 74 31 50 33 33 70 EU-JEA3830A.XIt1P33p
2019-08-09 15:51:20.820 (Fan slaapkamer) 45 6b 66 4c 36 4c 78 6b 30 69 61 71 71 74 5a 61 55 76 43 47 EkfL6Lxk0iaqqtZaUvCG
2019-08-09 15:51:20.820 (Fan slaapkamer) 70 6c 43 76 6c 68 6a 73 34 6c 58 39 76 2b 42 56 57 36 6f 41 plCvlhjs4lX9v+BVW6oA
2019-08-09 15:51:20.820 (Fan slaapkamer) 63 36 35 69 31 71 34 46 33 32 35 6f 4c 72 41 6d 55 54 73 65 c65i1q4F325oLrAmUTse
2019-08-09 15:51:20.820 (Fan slaapkamer) 42 54 6f 69 38 55 56 66 4d 76 32 63 72 6f 62 32 35 6e 51 3d BToi8UVfMv2crob25nQ=
2019-08-09 15:51:20.820 (Fan slaapkamer) 3d .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. =
2019-08-09 15:51:20.390 Status: (Fan slaapkamer) Stop directive received.
2019-08-09 15:51:20.391 Status: (Fan slaapkamer) Exiting work loop.
2019-08-09 15:51:20.591 Status: (Fan slaapkamer) Stopping threads.
2019-08-09 15:51:20.591 Status: (Fan slaapkamer) Stopped.
2019-08-09 15:51:20.591 Status: (Fan slaapkamer) Started.
2019-08-09 15:51:20.760 Status: (Fan slaapkamer) Entering work loop.
2019-08-09 15:51:20.761 Status: (Fan slaapkamer) Initialized version 1.0.3, author 'Jan-Jaap Kostelijk'
2019-08-09 15:51:21.491 (Fan slaapkamer) Queued asynchronous read aborted (192.168.1.15:1883), [2] End of file.
2019-08-09 15:51:21.521 (Fan slaapkamer) Received 4 bytes of data
2019-08-09 15:51:21.521 (Fan slaapkamer) 20 02 00 04 .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ....
2019-08-09 15:51:21.521 (Fan slaapkamer) Disconnect event received for '192.168.1.15:1883'.
2019-08-09 15:51:21.522 (Fan slaapkamer) MqttClient::onMessage called
2019-08-09 15:51:21.522 (Fan slaapkamer) MqttClient::onMessage Topic '', Data[Verb]: 'CONNACK'
2019-08-09 15:51:21.522 (Fan slaapkamer) MqttClient::Subscribe
2019-08-09 15:51:21.522 (Fan slaapkamer) dyson_pure_link_device: request_state called
2019-08-09 15:51:21.522 (Fan slaapkamer) request_state command built
2019-08-09 15:51:21.522 (Fan slaapkamer) MqttClient::Publish 475/NN2-EU-JEA3830A/command ({"msg": "REQUEST-CURRENT-STATE", "time": "2019-08-09T13:51:21Z"})
2019-08-09 15:51:21.522 (Fan slaapkamer) MqttClient::onDisonnect Disconnected from: 192.168.1.15:1883
2019-08-09 15:51:21.523 (Fan slaapkamer) MqttClient::Close
2019-08-09 15:51:21.523 (Fan slaapkamer) onMQTTDisconnected
2019-08-09 15:51:21.523 (Fan slaapkamer) Deallocating connection object '192.168.1.15' (192.168.1.15:1883).
2019-08-09 15:51:21.523 Error: (Fan slaapkamer) No transport, write directive to '192.168.1.15' ignored.
2019-08-09 15:51:21.523 Error: (Fan slaapkamer) No transport, write directive to '192.168.1.15' ignored.
2019-08-09 15:51:30.789 (Fan slaapkamer) MqttClient::Reconnecting
2019-08-09 15:51:30.789 (Fan slaapkamer) MqttClient::Open
2019-08-09 15:51:30.789 (Fan slaapkamer) MqttClient::Open: setup Domoticz connection object with protocol: 'MQTT'
2019-08-09 15:51:30.790 (Fan slaapkamer) MqttClient::Open: open connection
2019-08-09 15:51:30.790 (Fan slaapkamer) Polling unit in 5 heartbeats.
2019-08-09 15:51:30.790 (Fan slaapkamer) Protocol set to: 'MQTT'.
2019-08-09 15:51:30.790 (Fan slaapkamer) Transport set to: 'TCP/IP', 192.168.1.15:1883.
2019-08-09 15:51:30.790 (Fan slaapkamer) Connect directive received, action initiated successfully.
2019-08-09 15:51:30.840 (Fan slaapkamer) onConnect called
2019-08-09 15:51:30.841 (Fan slaapkamer) onConnect returns 1: Connection 'Name: '192.168.1.15', Transport: 'TCP/IP', Protocol: 'MQTT', Address: '192.168.1.15', Port: '1883', Baud: -1, Bytes: 0, Connected: True, Last Seen: 2019-08-09 15:51:30, Parent: 'None'', Status: '0', Description: 'Success'
2019-08-09 15:51:30.841 (Fan slaapkamer) MqttClient::MQTT connected successfully.
2019-08-09 15:51:30.841 (Fan slaapkamer) MqttClient::Connect
2019-08-09 15:51:30.841 (Fan slaapkamer) MqttClient::MQTT CONNECT ID: 'Domoticz_1565358680'
2019-08-09 15:51:30.841 (Fan slaapkamer) Sending 141 bytes of data
2019-08-09 15:51:30.841 (Fan slaapkamer) 10 8a 01 00 04 4d 51 54 54 04 c2 00 3c 00 13 44 6f 6d 6f 74 .�...MQTT.�.<..Domot
2019-08-09 15:51:30.841 (Fan slaapkamer) 69 63 7a 5f 31 35 36 35 33 35 38 36 38 30 00 0f 4e 4e 32 2d icz_1565358680..NN2-
2019-08-09 15:51:30.841 (Fan slaapkamer) 45 55 2d 4a 45 41 33 38 33 30 41 00 58 49 74 31 50 33 33 70 EU-JEA3830A.XIt1P33p
2019-08-09 15:51:30.841 (Fan slaapkamer) 45 6b 66 4c 36 4c 78 6b 30 69 61 71 71 74 5a 61 55 76 43 47 EkfL6Lxk0iaqqtZaUvCG
2019-08-09 15:51:30.841 (Fan slaapkamer) 70 6c 43 76 6c 68 6a 73 34 6c 58 39 76 2b 42 56 57 36 6f 41 plCvlhjs4lX9v+BVW6oA
2019-08-09 15:51:30.841 (Fan slaapkamer) 63 36 35 69 31 71 34 46 33 32 35 6f 4c 72 41 6d 55 54 73 65 c65i1q4F325oLrAmUTse
2019-08-09 15:51:30.841 (Fan slaapkamer) 42 54 6f 69 38 55 56 66 4d 76 32 63 72 6f 62 32 35 6e 51 3d BToi8UVfMv2crob25nQ=
2019-08-09 15:51:30.841 (Fan slaapkamer) 3d .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. =
2019-08-09 15:51:30.853 (Fan slaapkamer) Queued asynchronous read aborted (192.168.1.15:1883), [2] End of file.
2019-08-09 15:51:30.892 (Fan slaapkamer) Received 4 bytes of data
2019-08-09 15:51:30.892 (Fan slaapkamer) 20 02 00 04 .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ....
2019-08-09 15:51:30.892 (Fan slaapkamer) Disconnect event received for '192.168.1.15:1883'.
2019-08-09 15:51:30.892 (Fan slaapkamer) MqttClient::onMessage called
2019-08-09 15:51:30.892 (Fan slaapkamer) MqttClient::onMessage Topic '', Data[Verb]: 'CONNACK'
2019-08-09 15:51:30.892 (Fan slaapkamer) MqttClient::Subscribe
2019-08-09 15:51:30.892 (Fan slaapkamer) dyson_pure_link_device: request_state called
2019-08-09 15:51:30.893 (Fan slaapkamer) request_state command built
2019-08-09 15:51:30.893 (Fan slaapkamer) MqttClient::Publish 475/NN2-EU-JEA3830A/command ({"msg": "REQUEST-CURRENT-STATE", "time": "2019-08-09T13:51:30Z"})
2019-08-09 15:51:30.893 (Fan slaapkamer) MqttClient::onDisonnect Disconnected from: 192.168.1.15:1883
2019-08-09 15:51:30.893 (Fan slaapkamer) MqttClient::Close
2019-08-09 15:51:30.893 (Fan slaapkamer) onMQTTDisconnected
2019-08-09 15:51:30.893 (Fan slaapkamer) Deallocating connection object '192.168.1.15' (192.168.1.15:1883).
2019-08-09 15:51:30.893 Error: (Fan slaapkamer) No transport, write directive to '192.168.1.15' ignored.
2019-08-09 15:51:30.893 Error: (Fan slaapkamer) No transport, write dire