Python Plugin: MqttMapper

[FlyingDomotic]

When reading the log, I saw an incoming "Pool/cmd" message without a Domoticz click on "Pool Camera Switch" button. You probably send the change using Mqtt-Explorer. We're now sure that this way of changing state lead to a protocol violation.

Would it be possible to try to delete "Pool/cmd" topic, then restart Domoticz, and click on "Pool Camera Switch" button, to see if this way on changing topic better works?

Idea behind this is to try to locate where problem is (broker, Mqtt-Explorer, Domoticz) to try to fix it.

[peterchef]

The incoming cmd was generated when I clicked on the domoticz switch. I did not publish a message using mqtt explorer.
The sequence of actions was exactly as described in my message. Before I clicked on the domoticz switch the topic was cleared as shown in the image (before click).

[FlyingDomotic]

The strange thing is that I don't see in the log the trace of button press, nor sending the "Pool/cmd" message, while I see incoming "Pool/cmd" subscribed message. How do you set "debug" field on plugin page?

[peterchef]

Hi
Logging is set to verbose. I also was surprised that there was no message for the switch being pressed.

[FlyingDomotic]

Are you sure there's no two (or more) devices with same name in devices tab?

Could you also check if there's no multiple MqttMapper instances in hardware tab? You may use "search" field to give (part of) field name.

[peterchef]

There was a device with th same name and different ID on other hardware. I deleted the device and disabled the hardware.
There is no duplicate mqttmapper.

I reran the test with the switch . This shows the outbound and inbound MQTT cmd messages.

2024-10-08 08:16:38.851 mymqtt: Worker thread started.
2024-10-08 08:16:38.851 Status: mymqtt: Entering work loop.
2024-10-08 08:16:38.851 Status: mymqtt: Started.
2024-10-08 08:16:39.017 Status: mymqtt: Initialized version 1.0.48, author 'Flying Domotic'
2024-10-08 08:16:39.018 mymqtt: 'HardwareID':'19'
2024-10-08 08:16:39.018 mymqtt: 'HomeFolder':'C:\Program Files (x86)\Domoticz\plugins\domoticz-mqttmapper-plugin-main\'
2024-10-08 08:16:39.018 mymqtt: 'StartupFolder':'C:\Program Files (x86)\Domoticz\'
2024-10-08 08:16:39.018 mymqtt: 'UserDataFolder':'C:\Program Files (x86)\Domoticz\'
2024-10-08 08:16:39.018 mymqtt: 'Database':'C:\Program Files (x86)\Domoticz\domoticz.db'
2024-10-08 08:16:39.018 mymqtt: 'Language':'en'
2024-10-08 08:16:39.019 mymqtt: 'Version':'1.0.48'
2024-10-08 08:16:39.019 mymqtt: 'Author':'Flying Domotic'
2024-10-08 08:16:39.019 mymqtt: 'Name':'mymqtt'
2024-10-08 08:16:39.019 mymqtt: 'Address':'192.168.1.143'
2024-10-08 08:16:39.019 mymqtt: 'Port':'1883'
2024-10-08 08:16:39.019 mymqtt: 'Key':'MqttMapper'
2024-10-08 08:16:39.019 mymqtt: 'Mode1':'mydevices.json'
2024-10-08 08:16:39.019 mymqtt: 'Mode6':'Verbose'
2024-10-08 08:16:39.019 mymqtt: 'DomoticzVersion':'2024.7 (build 16268)'
2024-10-08 08:16:39.019 mymqtt: 'DomoticzHash':'3bff20de4'
2024-10-08 08:16:39.019 mymqtt: 'DomoticzBuildTime':'2024-10-01 14:38:10'
2024-10-08 08:16:39.019 mymqtt: Device count: 0
2024-10-08 08:16:39.019 mymqtt: Debug logging mask set to: PYTHON PLUGIN DEVICE CONNECTION MESSAGE
2024-10-08 08:16:39.020 mymqtt: Creating device Pool Camera Switch
2024-10-08 08:16:39.020 mymqtt: Creating device 'Pool Camera Switch'.
2024-10-08 08:16:39.021 mymqtt: MqttClient::__init__
2024-10-08 08:16:39.021 mymqtt: MqttClient::Open
2024-10-08 08:16:39.021 mymqtt: Protocol set to: 'MQTT'.
2024-10-08 08:16:39.021 mymqtt: Transport set to: 'TCP/IP', 192.168.1.143:1883.
2024-10-08 08:16:39.022 mymqtt: Connect directive received, action initiated successfully.
2024-10-08 08:16:39.022 mymqtt: Heartbeat interval set to: 60.
2024-10-08 08:16:39.075 mymqtt: MqttClient::onConnect
2024-10-08 08:16:39.076 mymqtt: Successful connect to: 192.168.1.143:1883
2024-10-08 08:16:39.076 mymqtt: MqttClient::Connect
2024-10-08 08:16:39.077 mymqtt: MQTT CONNECT ID: 'Domoticz_MqttMapper_19_1728368199'
2024-10-08 08:16:39.077 mymqtt: Sending 47 bytes of data
2024-10-08 08:16:39.078 mymqtt: 10 2d 00 04 4d 51 54 54 04 02 00 3c 00 21 44 6f 6d 6f 74 69 .-..MQTT...<.!Domoti
2024-10-08 08:16:39.079 mymqtt: 63 7a 5f 4d 71 74 74 4d 61 70 70 65 72 5f 31 39 5f 31 37 32 cz_MqttMapper_19_172
2024-10-08 08:16:39.079 mymqtt: 38 33 36 38 31 39 39 .. .. .. .. .. .. .. .. .. .. .. .. .. 8368199
2024-10-08 08:16:39.142 mymqtt: Received 4 bytes of data
2024-10-08 08:16:39.144 mymqtt: 20 02 00 00 .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. ....
2024-10-08 08:16:39.148 mymqtt: onMQTTConnected
2024-10-08 08:16:39.149 mymqtt: getTopics: '{'Pool/cmd'}'
2024-10-08 08:16:39.150 mymqtt: MqttClient::Subscribe
2024-10-08 08:16:39.150 mymqtt: Sending 15 bytes of data
2024-10-08 08:16:39.151 mymqtt: 82 0d 00 01 00 08 50 6f 6f 6c 2f 63 6d 64 00 .. .. .. .. .. ®....Pool/cmd.
2024-10-08 08:16:39.213 mymqtt: Received 5 bytes of data
2024-10-08 08:16:39.213 mymqtt: 90 03 00 01 00 .. .. .. .. .. .. .. .. .. .. .. .. .. .. .. Ю...
2024-10-08 08:16:39.214 mymqtt: onMQTTSubscribed
2024-10-08 08:17:02.698 Status: User: admin (IP: 127.0.0.1) initiated a switch command (320/mymqtt - Pool Camera Switch/On)
2024-10-08 08:17:02.746 mymqtt: 001/mymqtt - Pool Camera Switch, Pool/cmd: Command: 'On', Level: 0, Color:
2024-10-08 08:17:02.747 mymqtt: Setting Pool/cmd to >{"command": "ON"}<
2024-10-08 08:17:02.750 mymqtt: MqttClient::Publish Pool/cmd ({"command": "ON"})
2024-10-08 08:17:02.751 mymqtt: Sending 29 bytes of data
2024-10-08 08:17:02.752 mymqtt: 31 1b 00 08 50 6f 6f 6c 2f 63 6d 64 7b 22 63 6f 6d 6d 61 6e 1...Pool/cmd{"comman
2024-10-08 08:17:02.752 mymqtt: 64 22 3a 20 22 4f 4e 22 7d .. .. .. .. .. .. .. .. .. .. .. d":."ON"}
2024-10-08 08:17:02.808 mymqtt: Received 29 bytes of data
2024-10-08 08:17:02.809 mymqtt: 30 1b 00 08 50 6f 6f 6c 2f 63 6d 64 7b 22 63 6f 6d 6d 61 6e 0...Pool/cmd{"comman
2024-10-08 08:17:02.810 mymqtt: 64 22 3a 20 22 4f 4e 22 7d .. .. .. .. .. .. .. .. .. .. .. d":."ON"}
2024-10-08 08:17:02.811 Error: (ProcessInbound) MQTT protocol violation: Invalid message length 27 for packet type '3' (iQoS:0, topicLen:2048)
2024-10-08 08:17:02.811 Error: (ProcessInbound) MQTT protocol violation, sending DisconnectedEvent to Connection.
2024-10-08 08:17:02.812 mymqtt: Disconnect event received for '192.168.1.143:1883'.
2024-10-08 08:17:02.813 mymqtt: MqttClient::onDisonnect Disconnected from: 192.168.1.143:1883
2024-10-08 08:17:02.819 mymqtt: MqttClient::Close
2024-10-08 08:17:02.820 mymqtt: onMQTTDisconnected
2024-10-08 08:17:02.820 mymqtt: Deallocating connection object '192.168.1.143' (192.168.1.143:1883).

[peterchef]

It seems to me that the mqttmapper is calculating the 'topic len' by joining bytes 4 (value 08) and value 00 of the incoming message giving a length of 0800 (2048 decimal). This matches up with a previous test for a status message where byte 4 =12hex and the topic len was calculated as 1200hex 4608 decimal. The topic len in byte 4 is the correct length.

[waltervl]

Looking at the error it is the Domoticz plugin framework and not the plugin itself that is giving the error: https://github.com/search?q=repo%3Adomo ... &type=code
And now my contribution stops as my knowledge ends here....

Edit this is the specific error: (there could be more ) https://github.com/domoticz/domoticz/bl ... .cpp#L1602

[FlyingDomotic]

Trying to analyze packet format, I have a doubt: what's MQTT version of your broker? 3.1.1 or 5.0 ?

I suspect a version 5.0, for with an additional byte is added into packet, which may lead to this error.

Could you confirm?

@waltervl: Is MQTT V5.0 supported in Domoticz? If yes, how to make difference between 3.1.1 and 5.0? I don't saw anything in MQTT Connect message about this in PluginProtocls?cpp.

[waltervl]

@waltervl: Is MQTT V5.0 supported in Domoticz? If yes, how to make difference between 3.1.1 and 5.0? I don't saw anything in MQTT Connect message about this in PluginProtocls?cpp.

As said before, I do not know much about this subject.... Perhaps check the source code I referred to.

[FlyingDomotic]

As said before, I do not know much about this subject.... Perhaps check the source code I referred to.

I'm not an expert too... It seems there's a possibility to ask broker for a specific protocol version (3.1.1 or 5.0), but this seems not to be used by Domoticz code. In addition, the way code seems to be written (remember, I'm still not expert in MQTT), managing other thing than 3.1.1 may not be possible.

I'll try to board Paho MQTT (which has a good MQTT support) in a plugin, but I'm not so sure it won't block plugin loop, leading to a timeout.

Stay tuned!

[waltervl]

Perhaps easier to have peterchef send MQTT V3 instead of V5 for debug purposes. If that works perhaps Domoticz plugin framework can be updated to also support MQTT v5

[peterchef]

Hi
My understanding is that the eclipse mqqt broker supports both v3 and v5. But I think that is the client that chooses on connection which protocol version it wishes to use. In the case of Domoticz I assume it connects requesting V3.1.
Also in the test that I did with the switch my app is not involved at all - it is only the domoticz plugin framework that is communicating.

[FlyingDomotic]

Hi
My understanding is that the eclipse mqqt broker supports both v3 and v5. But I think that is the client that chooses on connection which protocol version it wishes to use. In the case of Domoticz I assume it connects requesting V3.1.
Also in the test that I did with the switch my app is not involved at all - it is only the domoticz plugin framework that is communicating.

I share the same understanding. But, the problematic instance is under Windows, and I don't known anything about client code, nor about Windows broker.
This could also be a default protocol value set to 5.0 into either client or broker settings.
Small remark: it seems that MQTT version is not specified into PluginProtocols.cpp, letting default value being used. I may perhaps be good to "force" 3.1, to be sure that nothing will default to 5.0, with amazing side effects (like not working at all

[peterchef]

I have looked at the mqtt broker documentation and I can see no way to force the protocol version used by the client.
I am wondering if there is something in the windows version of the plugin framework that is "casting" (i am not a C programmer) the 8 bit topic len value into a 16 bit value by mistake.

[FlyingDomotic]

I have looked at the mqtt broker documentation and I can see no way to force the protocol version used by the client.
I am wondering if there is something in the windows version of the plugin framework that is "casting" (i am not a C programmer) the 8 bit topic len value into a 16 bit value by mistake.

Giving MQTT documentation (http://docs.oasis-open.org/mqtt/mqtt/v3 ... .1-os.html and https://docs.oasis-open.org/mqtt/mqtt/v ... -v5.0.html), in 3.1.2.2, client should send 4 (for 3.1.1) and 5 (for 5) in connect message.

Concerning remark about 8 versus 16 bits, it seems is that there's an additional byte in 5.0 message before length. So length bit size don't change, but is slipped 8 bits later due to this additional byte

[peterchef]

Finally found some verbose logging in the eclipse broker. Domoticz is connecting as a v3.1.1 client.

2024-10-09T11:44:49: New client connected from 192.168.1.140:3308 as Domoticz_MqttMapper_19_1728467088 (p2, c1, k60)

The 'p2' indicates the mqtt protocol version,c1=clean session,k60 = keep alive

[FlyingDomotic]

Finally found some verbose logging in the eclipse broker. Domoticz is connecting as a v3.1.1 client.

2024-10-09T11:44:49: New client connected from 192.168.1.140:3308 as Domoticz_MqttMapper_19_1728467088 (p2, c1, k60)

The 'p2' indicates the mqtt protocol version,c1=clean session,k60 = keep alive

I may be wrong, but it seems to me that 2 means MQTT V2 (3 is V3, 4 is V3.1, 5 is V5).

[peterchef]

That is true for the client protocol version request. But Eclipse internally uses:

enum mosquitto__protocol {
mosq_p_invalid = 0,
mosq_p_mqtt31 = 1,
mosq_p_mqtt311 = 2,
mosq_p_mqtts = 3,
mosq_p_mqtt5 = 5,
};

[FlyingDomotic]

I learned something today. Thanks!

We can eliminate the V5 protocol version idea, as we now know that 3.1.1 was used.

Getting back to log, we can isolate:

Code: Select all

2024-10-08 08:17:02.747 mymqtt: Setting Pool/cmd to >{"command": "ON"}<
2024-10-08 08:17:02.750 mymqtt: MqttClient::Publish Pool/cmd ({"command": "ON"})
2024-10-08 08:17:02.751 mymqtt: Sending 29 bytes of data
2024-10-08 08:17:02.752 mymqtt: 31 1b 00 08 50 6f 6f 6c 2f 63 6d 64 7b 22 63 6f 6d 6d 61 6e 1...Pool/cmd{"comman
2024-10-08 08:17:02.752 mymqtt: 64 22 3a 20 22 4f 4e 22 7d .. .. .. .. .. .. .. .. .. .. .. d":."ON"}
2024-10-08 08:17:02.808 mymqtt: Received 29 bytes of data
2024-10-08 08:17:02.809 mymqtt: 30 1b 00 08 50 6f 6f 6c 2f 63 6d 64 7b 22 63 6f 6d 6d 61 6e 0...Pool/cmd{"comman
2024-10-08 08:17:02.810 mymqtt: 64 22 3a 20 22 4f 4e 22 7d .. .. .. .. .. .. .. .. .. .. .. d":."ON"}
2024-10-08 08:17:02.811 Error: (ProcessInbound) MQTT protocol violation: Invalid message length 27 for packet type '3' (iQoS:0, topicLen:2048)
2024-10-08 08:17:02.811 Error: (ProcessInbound) MQTT protocol violation, sending DisconnectedEvent to Connection

Looking in detail, send and received messages dump are exactly the same except first byte (31 when sending and 30 when receiving).

Mainly, for sent packed, we have "31" for publish, qos = 0, retain = 1, "1b" for total length, "00 08" for topic length, 8 bytes of topic followed by payload. To me, sent packed is in line with http://docs.oasis-open.org/mqtt/mqtt/v3 ... .1-os.html

For received packed, we have exactly the same thing, except "30", meaning retain= 0, which is in line with definition, as packet is sent just when received, and not from MQTT data store.

Again, for me, packet is ok.

Going deeper on PluginProtocol.cpp code, MQTTDecodeVariableByte seems to work, as it returned 27, which is ok. Looking at error message, it seems that code incorrectly evaluates topic length as 0x"0800" instead of 0x"0008", giving the error. This is strange as loading code is "int topicLen = (*it++ << 8) + *it++;", which seems correct. In addition, the pointer (it) has not been increased by one, as this would have been 0x8050 (2128).

Honestly, I don"t see something incorrect in this.

I then tried on a test machine, RPi4 with 2024.7, and a copy/paste of configuration given here. Here's copy of log:

Code: Select all

2024-10-09 17:41:47.330  Tests: Sending 29 bytes of data
2024-10-09 17:41:47.330  Tests:      31 1b 00 08 50 6f 6f 6c 2f 63 6d 64 7b 22 63 6f 6d 6d 61 6e     1...Pool/cmd{"comman
2024-10-09 17:41:47.331  Tests:      64 22 3a 20 22 4f 4e 22 7d .. .. .. .. .. .. .. .. .. .. ..     d":."ON"}
2024-10-09 17:41:47.332  Tests: Pushing 'ReadEvent' on to queue
2024-10-09 17:41:47.381  Tests: Processing 'ReadEvent' message
2024-10-09 17:41:47.382  Tests: Received 29 bytes of data
2024-10-09 17:41:47.382  Tests:      30 1b 00 08 50 6f 6f 6c 2f 63 6d 64 7b 22 63 6f 6d 6d 61 6e     0...Pool/cmd{"comman
2024-10-09 17:41:47.383  Tests:      64 22 3a 20 22 4f 4e 22 7d .. .. .. .. .. .. .. .. .. .. ..     d":."ON"}

This is exactly the same log (except date) in both cases.

What are exact versions of hardware, OS, Domoticz, Python and MqttMapper?