Tasmota icon indicating copy to clipboard operation
Tasmota copied to clipboard

Published 20 hours ago • verified publisher icon arendst

SUBSCRIBE and SUBSCRIBE2 commands do not work for multi level JSON contained in MQTT messages.

Open jkwim opened this issue 1 year ago • 1 comments

PROBLEM DESCRIPTION

SUBSCRIBE and SUBSCRIBE2 commands do not work for multi level JSON contained in MQTT messages.

Always a following error is reported: MQT: stat/tasmotaNW2-211/RESULT = {"Command":"Error"}

REQUESTED INFORMATION

Make sure your have performed every step and checked the applicable boxes before submitting your issue. Thank you!

  • [ ] Read the Contributing Guide and Policy and the Code of Conduct
  • [ ] Searched the problem in issues
  • [ ] Searched the problem in discussions
  • [ ] Searched the problem in the docs
  • [ ] Searched the problem in the chat
  • [ ] Device used (e.g., Sonoff Basic): _____
  • [ ] Tasmota binary firmware version number used: Version 12.1.1.2(displ)-2_7_4_9(2022-09-21T10:47:59)
    • [ ] Pre-compiled
    • [ X] Self-compiled
  • [ ] Flashing tools used: tasmotizer
  • [ ] Provide the output of command: Backlog Template; Module; GPIO 255:
  Configuration output here:
  • [ ] If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:
  Rules output here:
  • [ ] Provide the output of this command: Status 0:
  STATUS 0 output here:

image
  • [ ] Set weblog to 4 and then, when you experience your issue, provide the output of the Console log:
  Console output here:

Case 1: SUBSCRIBE
02:52:58.067 CMD: SUBSCRIBE ACTIVEPOWER, tele/TasmotaNW1-210/SENSOR, SAKO.ActPw
02:52:58.069 SRC: WebConsole from 192.168.1.201
02:52:58.071 CMD: Grp 0, Cmd 'SUBSCRIBE', Idx 1, Len 51, Pld -99, Data 'ACTIVEPOWER, tele/TasmotaNW1-210/SENSOR, SAKO.ActPw'
02:52:58.075 MQT: Subscribe to tele/TasmotaNW1-210/SENSOR/#
02:52:58.082 MQT: stat/tasmotaNW2-211/RESULT = {"Subscribe":"ACTIVEPOWER,tele/TasmotaNW1-210/SENSOR/#,SAKO.ActPw"}
02:52:59.781 SRC: MQTT
02:52:59.784 CMD: Grp 0, Cmd 'SENSOR', Idx 1, Len 264, Pld -99, Data '{"Time":"2022-09-22T02:52:59","SAKO":{"GridV":"243.2","ActPw":"0406","OutV":"243.2","BatV":"54.10","BatVSCC":"00.00","BatCap":"100","BatChargCur":"000","BatDischCur":"00000","PVPower":"00000","PVVoltage":"036.5","PVCurrent":"00.0","BUSV":"430","InverterT":"0037"}}'
02:52:59.791 MQT: stat/tasmotaNW2-211/RESULT = {"Command":"Error"}


Case 2: SUBSCRIBE2
02:52:58.067 CMD: SUBSCRIBE ACTIVEPOWER, tele/TasmotaNW1-210/SENSOR, SAKO.ActPw
02:52:58.069 SRC: WebConsole from 192.168.1.201
02:52:58.071 CMD: Grp 0, Cmd 'SUBSCRIBE', Idx 1, Len 51, Pld -99, Data 'ACTIVEPOWER, tele/TasmotaNW1-210/SENSOR, SAKO.ActPw'
02:52:58.075 MQT: Subscribe to tele/TasmotaNW1-210/SENSOR/#
02:52:58.082 MQT: stat/tasmotaNW2-211/RESULT = {"Subscribe":"ACTIVEPOWER,tele/TasmotaNW1-210/SENSOR/#,SAKO.ActPw"}
02:52:59.781 SRC: MQTT
02:52:59.784 CMD: Grp 0, Cmd 'SENSOR', Idx 1, Len 264, Pld -99, Data '{"Time":"2022-09-22T02:52:59","SAKO":{"GridV":"243.2","ActPw":"0406","OutV":"243.2","BatV":"54.10","BatVSCC":"00.00","BatCap":"100","BatChargCur":"000","BatDischCur":"00000","PVPower":"00000","PVVoltage":"036.5","PVCurrent":"00.0","BUSV":"430","InverterT":"0037"}}'
02:52:59.791 MQT: stat/tasmotaNW2-211/RESULT = {"Command":"Error"}



### TO REPRODUCE
_Steps to reproduce the behavior:_

SUBSCRIBE ACTIVEPOWER, tele/TasmotaNW1-210/SENSOR, SAKO.ActPw SUBSCRIBE2 ACTIVEPOWER, tele/TasmotaNW1-210/SENSOR, SAKO.ActPw



### EXPECTED BEHAVIOUR
_A clear and concise description of what you expected to happen._

02:48:59.099 CMD: Grp 0, Cmd 'SENSOR', Idx 1, Len 264, Pld -99, Data '{"Time":"2022-09-22T02:48:59","SAKO":{"GridV":"242.3","ActPw":"0403","OutV":"242.3","BatV":"54.00","BatVSCC":"00.00","BatCap":"100","BatChargCur":"000","BatDischCur":"00000","PVPower":"00000","PVVoltage":"035.5","PVCurrent":"00.0","BUSV":"430","InverterT":"0037"}}' 02:48:59.107 MQT: stat/tasmotaNW2-211/RESULT = {"Command":"Error"}




### SCREENSHOTS
_If applicable, add screenshots to help explain your problem._


### ADDITIONAL CONTEXT
_Add any other context about the problem here._


**(Please, remember to close the issue when the problem has been addressed)**

jkwim avatar Sep 21 '22 21:09 jkwim

Same issue using this subscribe example copied from the docs. Subscribe DnTemp, stat/other-device-topic/SENSOR, DS18B20.Temperature Obviously with a topic matching a device having a DS18B20.

Event not fired, but getting the message indicating that the topic/payload was processed as a command.

sfromis avatar Sep 21 '22 23:09 sfromis

I tested with a 9.5.0.2 custom bin file that I had also and the issue is present in that version also.

So this may be an issue which had not been caught before.

jkwim avatar Sep 22 '22 05:09 jkwim

Error gets hit here Tasmota/tasmota/tasmota_support/support_command.ino

image

image

Can somebody have a look further please?

jkwim avatar Sep 22 '22 05:09 jkwim

I can't reproduce

21:10:41.783 CMD: rule1
21:10:41.791 MQT: stat/dev-4119/RULE = {"Rule1":{"State":"ON","Once":"OFF","StopOnError":"OFF","Length":34,"Free":477,"Rules":"on event#pow do var1 %value% endon"}}
21:10:42.171 MQT: stat/dev-4119/SENSOR = {"Command":"Error"}
21:10:43.172 MQT: stat/dev-4119/SENSOR = {"Command":"Error"}
21:10:50.238 CMD: subscribe2 pow, tele/skt-barbuxps/SENSOR, Energy.Power
21:10:50.247 MQT: stat/dev-4119/SUBSCRIBE = {"Subscribe":"POW,tele/skt-barbuxps/SENSOR,Energy.Power"}
21:10:50.390 RUL: EVENT#POW performs "var1 57.4"
21:10:50.399 MQT: stat/dev-4119/VAR = {"Var1":"57.4"}
21:10:52.191 RUL: EVENT#POW performs "var1 53.1"
21:10:52.198 MQT: stat/dev-4119/VAR = {"Var1":"53.1"}
21:10:54.179 RUL: EVENT#POW performs "var1 46.7"
21:10:54.186 MQT: stat/dev-4119/VAR = {"Var1":"46.7"}

Event gets fired as expected

barbudor avatar Sep 22 '22 19:09 barbudor

Hum, indeed there are 2 "Command Error" before it started to work correctly...

barbudor avatar Sep 22 '22 19:09 barbudor

Done it again after a restart and t's ok:

00:00:00.002 HDW: ESP8266EX
00:00:00.050 CFG: Loaded from flash at F9, Count 30
00:00:00.062 Project tasmota - dev-4119 Version 12.1.1.2(bhome)-2_7_4_9(2022-09-21T00:01:19)
00:00:03.447 WIF: Connecting to AP1 XXXXXXXXX Channel 1 BSSId XXXXXXXXXXX in mode 11n as dev-4119...
00:00:04.753 WIF: Connected
00:00:05.006 HTP: Web server active on dev-4119 with IP address 192.168.168.199
21:16:45.046 MQT: Attempting connection...
21:16:45.083 MQT: Connected
21:16:45.086 MQT: tele/dev-4119/LWT = Online (retained)
21:16:45.088 MQT: cmnd/dev-4119/POWER = 
21:16:45.094 MQT: tele/dev-4119/INFO1 = {"Info1":{"Module":"Generic","Version":"12.1.1.2(bhome)","FallbackTopic":"cmnd/3C71BF2AD017_fb/","GroupTopic":"cmnd/alldevices/"}}
21:16:45.106 MQT: tele/dev-4119/INFO2 = {"Info2":{"WebServerMode":"Admin","Hostname":"dev-4119","IPAddress":"192.168.168.199"}}
21:16:45.116 MQT: tele/dev-4119/INFO3 = {"Info3":{"RestartReason":"Software/System restart","BootCount":12}}
21:16:49.497 MQT: tele/dev-4119/STATE = {"Time":"2022-09-22T21:16:49+02:00","Uptime":"0T00:00:12","UptimeSec":12,"Heap":28,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"Wifi":{"AP":1,"SSId":"BNETWLAN","BSSId":"88:C3:97:F2:25:EC","Channel":1,"Mode":"11n","RSSI":100,"Signal":-48,"LinkCount":1,"Downtime":"0T00:00:06"}}
21:16:53.189 CMD: subscribe
21:16:53.195 MQT: stat/dev-4119/SUBSCRIBE = {"Subscribe":""}
21:16:57.761 CMD: rule1 1
21:16:57.767 MQT: stat/dev-4119/RULE = {"Rule1":{"State":"ON","Once":"OFF","StopOnError":"OFF","Length":34,"Free":477,"Rules":"on event#pow do var1 %value% endon"}}
21:17:09.853 CMD: subscribe2 pow, tele/skt-barbuxps/SENSOR, Energy.Power
21:17:09.863 MQT: stat/dev-4119/SUBSCRIBE = {"Subscribe":"POW,tele/skt-barbuxps/SENSOR,Energy.Power"}
21:17:09.003 RUL: EVENT#POW performs "var1 61.6"
21:17:10.000 MQT: stat/dev-4119/VAR = {"Var1":"61.6"}
21:17:10.743 RUL: EVENT#POW performs "var1 43.4"
21:17:10.750 MQT: stat/dev-4119/VAR = {"Var1":"43.4"}
21:17:14.737 RUL: EVENT#POW performs "var1 63.5"
21:17:14.743 MQT: stat/dev-4119/VAR = {"Var1":"63.5"}
21:17:16.763 RUL: EVENT#POW performs "var1 49.6"
21:17:16.769 MQT: stat/dev-4119/VAR = {"Var1":"49.6"}

barbudor avatar Sep 22 '22 19:09 barbudor

Hmm.. Interesting!

Could it be that my JSON string is too lengthy?

jkwim avatar Sep 22 '22 19:09 jkwim

Problem starts to occur when trying to unsubscribe:

21:18:59.749 RUL: EVENT#POW performs "var1 41.8"
21:18:59.757 MQT: stat/dev-4119/VAR = {"Var1":"41.8"}
21:19:00.192 CMD: unsubscribe pow
21:19:00.204 MQT: stat/dev-4119/UNSUBSCRIBE = {"Unsubscribe":"POW"}
21:19:05.687 MQT: stat/dev-4119/SENSOR = {"Command":"Error"}
21:19:07.713 MQT: stat/dev-4119/SENSOR = {"Command":"Error"}
21:19:08.728 MQT: stat/dev-4119/SENSOR = {"Command":"Error"}

It looks like the Unsubscribe command remove the link between topic and event but do not actually unsubscribe from the broker

barbudor avatar Sep 22 '22 19:09 barbudor

Problem starts to occur when trying to unsubscribe:

21:18:59.749 RUL: EVENT#POW performs "var1 41.8"
21:18:59.757 MQT: stat/dev-4119/VAR = {"Var1":"41.8"}
21:19:00.192 CMD: unsubscribe pow
21:19:00.204 MQT: stat/dev-4119/UNSUBSCRIBE = {"Unsubscribe":"POW"}
21:19:05.687 MQT: stat/dev-4119/SENSOR = {"Command":"Error"}
21:19:07.713 MQT: stat/dev-4119/SENSOR = {"Command":"Error"}
21:19:08.728 MQT: stat/dev-4119/SENSOR = {"Command":"Error"}

It looks like the Unsubscribe command remove the link between topic and event but do not actually unsubscribe from the broker

Yes, I noticed this behavior also (after creating this post). Only way out was to restart.

jkwim avatar Sep 22 '22 19:09 jkwim

Tried rebooting between different executions, but same result.

jkwim avatar Sep 22 '22 19:09 jkwim

Are you using Rules or Scripting ? Are you on ESP8266 or ESP32 ? Please post more details as I can't reproduce (except the unsubscribe stuff)

@sfromis Did you tested on ESP32/ESP8266 ? Rules ?

barbudor avatar Sep 22 '22 19:09 barbudor

Hmm.. Interesting!

Could it be that my JSON string is too lengthy?

Indeed there is a limit to JSON size for Subscribe less than 100 chars

See my comment in the PR here : https://github.com/arendst/Tasmota/pull/12496

EDIT: However my test is receiving a JSON of 232 chars. So may be some buffers have been improved since the original PR

barbudor avatar Sep 22 '22 19:09 barbudor

@jkwim Are you using SetOption140 1 to have persistent MQTT sessions ? That would explain why after a restart you are getting the Command Error as the subscription is still active at the broker level However, I soon as I run the Subscribe2 command again in the console, the rule gets fired as expect and no more Command Error

There's deifnitively something wrong with the Unsubscribe but I can't see anything wrong with Tasmota code for now. Could be in the MqttClient library. Need to dig further

barbudor avatar Sep 22 '22 19:09 barbudor

I can confirm that my recreation of the issue also was trying to pick a sensor value from a long payload, the JSON text being approx 360 chars.

ESP8266 build "Version":"12.1.1.2(fullrules)","BuildDateTime":"2022-09-19T20:56:28"

sfromis avatar Sep 22 '22 20:09 sfromis

I feel there is something wrong with Mosqitto too. Setting up a test platform wiht Mosquitto 2.0.15, totally inpendant from my prod setup. Only a Tasmota test device + using linux command tool to simulate another Tasmota publishing

Tasmota start:

2022-09-22 22:03:52: New connection from 192.168.168.199:50024 on port 1883.
2022-09-22 22:03:52: New client connected from 192.168.168.199:50024 as 3C71BF2AD017 (p2, c0, k30, u'dev-4119').
2022-09-22 22:03:52: Will message specified (7 bytes) (r1, q1).
2022-09-22 22:03:52:    tele/dev-4119/LWT
2022-09-22 22:03:52: Sending CONNACK to 3C71BF2AD017 (1, 0)
2022-09-22 22:03:52: Received PUBLISH from 3C71BF2AD017 (d0, q0, r1, m0, 'tele/dev-4119/LWT', ... (6 bytes))
2022-09-22 22:03:52: Received PUBLISH from 3C71BF2AD017 (d0, q0, r0, m0, 'cmnd/dev-4119/POWER', ... (0 bytes))
2022-09-22 22:03:52: Sending PUBLISH to 3C71BF2AD017 (d0, q0, r0, m0, 'cmnd/dev-4119/POWER', ... (0 bytes))
2022-09-22 22:03:52: Received SUBSCRIBE from 3C71BF2AD017
2022-09-22 22:03:52:    cmnd/dev-4119/# (QoS 0)
2022-09-22 22:03:52: 3C71BF2AD017 0 cmnd/dev-4119/#
2022-09-22 22:03:52: Sending SUBACK to 3C71BF2AD017
2022-09-22 22:03:52: Received SUBSCRIBE from 3C71BF2AD017
2022-09-22 22:03:52:    cmnd/alldevices/# (QoS 0)
2022-09-22 22:03:52: 3C71BF2AD017 0 cmnd/alldevices/#
2022-09-22 22:03:52: Sending SUBACK to 3C71BF2AD017
2022-09-22 22:03:52: Received SUBSCRIBE from 3C71BF2AD017
2022-09-22 22:03:52:    cmnd/3C71BF2AD017_fb/# (QoS 0)
2022-09-22 22:03:52: 3C71BF2AD017 0 cmnd/3C71BF2AD017_fb/#
2022-09-22 22:03:52: Sending SUBACK to 3C71BF2AD017
2022-09-22 22:03:52: Received PUBLISH from 3C71BF2AD017 (d0, q0, r0, m0, 'stat/dev-4119/POWER', ... (19 bytes))
2022-09-22 22:03:52: Received PUBLISH from 3C71BF2AD017 (d0, q0, r1, m0, 'tasmota/discovery/3C71BF2AD017/config', ... (606 bytes))
2022-09-22 22:03:52: Received PUBLISH from 3C71BF2AD017 (d0, q0, r1, m0, 'tasmota/discovery/3C71BF2AD017/sensors', ... (51 bytes))

Now Subscribe command in console

2022-09-22 22:04:20: Received SUBSCRIBE from 3C71BF2AD017
2022-09-22 22:04:20:    tele/skt-barbuxps/SENSOR/# (QoS 0)
2022-09-22 22:04:20: 3C71BF2AD017 0 tele/skt-barbuxps/SENSOR/#
2022-09-22 22:04:20: Sending SUBACK to 3C71BF2AD017
2022-09-22 22:04:20: Received PUBLISH from 3C71BF2AD017 (d0, q0, r0, m0, 'stat/dev-4119/SUBSCRIBE', ... (59 bytes))

Using a command line tool to simulate another tasmota publishing on tele/skt-barbuxps/SENSOR:

2022-09-22 22:04:27: New connection from 192.168.168.8:45077 on port 1883.
2022-09-22 22:04:27: New client connected from 192.168.168.8:45077 as auto-4D5A59AF-AEE1-2F3D-F191-635C933552C0 (p2, c1, k60, u'superuser').
2022-09-22 22:04:27: No will message specified.
2022-09-22 22:04:27: Sending CONNACK to auto-4D5A59AF-AEE1-2F3D-F191-635C933552C0 (0, 0)
2022-09-22 22:04:27: Received PUBLISH from auto-4D5A59AF-AEE1-2F3D-F191-635C933552C0 (d0, q0, r0, m0, 'tele/skt-barbuxps/SENSOR', ... (231 bytes))

message received and forwarded to test Tasmota:

2022-09-22 22:04:27: Sending PUBLISH to 3C71BF2AD017 (d0, q0, r0, m0, 'tele/skt-barbuxps/SENSOR', ... (231 bytes))

Confim execution of rule:

2022-09-22 22:04:27: Received PUBLISH from 3C71BF2AD017 (d0, q0, r0, m0, 'stat/dev-4119/VAR', ... (15 bytes))
2022-09-22 22:04:28: Received DISCONNECT from auto-4D5A59AF-AEE1-2F3D-F191-635C933552C0
2022-09-22 22:04:28: Client auto-4D5A59AF-AEE1-2F3D-F191-635C933552C0 disconnected.

Now Unsubscribe command

2022-09-22 22:04:38: Received UNSUBSCRIBE from 3C71BF2AD017
2022-09-22 22:04:38:    tele/skt-barbuxps/SENSOR/#
2022-09-22 22:04:38: 3C71BF2AD017 tele/skt-barbuxps/SENSOR/#
2022-09-22 22:04:38: Sending UNSUBACK to 3C71BF2AD017
2022-09-22 22:04:38: Received PUBLISH from 3C71BF2AD017 (d0, q0, r0, m0, 'stat/dev-4119/UNSUBSCRIBE', ... (23 bytes))

PC command line to send exact same SENSOR message:

2022-09-22 22:05:00: New connection from 192.168.168.8:40065 on port 1883.
2022-09-22 22:05:00: New client connected from 192.168.168.8:40065 as auto-29AFAB3F-9C7B-43F7-AE8C-27BA859593F3 (p2, c1, k60, u'superuser').
2022-09-22 22:05:00: No will message specified.
2022-09-22 22:05:00: Sending CONNACK to auto-29AFAB3F-9C7B-43F7-AE8C-27BA859593F3 (0, 0)
2022-09-22 22:05:00: Received PUBLISH from auto-29AFAB3F-9C7B-43F7-AE8C-27BA859593F3 (d0, q0, r0, m0, 'tele/skt-barbuxps/SENSOR', ... (231 bytes))

WTF!!! Mosquitto still forward the message to Tasmota despite the unsubscribe:

2022-09-22 22:05:00: Sending PUBLISH to 3C71BF2AD017 (d0, q0, r0, m0, 'tele/skt-barbuxps/SENSOR', ... (231 bytes))
2022-09-22 22:05:00: Received PUBLISH from 3C71BF2AD017 (d0, q0, r0, m0, 'stat/dev-4119/SENSOR', ... (19 bytes))
2022-09-22 22:05:01: Received DISCONNECT from auto-29AFAB3F-9C7B-43F7-AE8C-27BA859593F3
2022-09-22 22:05:01: Client auto-29AFAB3F-9C7B-43F7-AE8C-27BA859593F3 disconnected.

barbudor avatar Sep 22 '22 20:09 barbudor

@jkwim Are you using SetOption140 1 to have persistent MQTT sessions ? That would explain why after a restart you are getting the Command Error as the subscription is still active at the broker level However, I soon as I run the Subscribe2 command again in the console, the rule gets fired as expect and no more Command Error

There's deifnitively something wrong with the Unsubscribe but I can't see anything wrong with Tasmota code for now. Could be in the MqttClient library. Need to dig further

No I am not using persistent MQTT session from client device. I had one persistent message from mobile phone client which is directed towards this client device which I could see being received when booting.

jkwim avatar Sep 23 '22 06:09 jkwim

This issue has been automatically marked as stale because it hasn't any activity in last few weeks. It will be closed if no further activity occurs. Thank you for your contributions.

github-actions[bot] avatar Oct 21 '22 06:10 github-actions[bot]

This issue was automatically closed because of being stale. Feel free to open a new one if you still experience this problem.

github-actions[bot] avatar Oct 26 '22 07:10 github-actions[bot]