DevGroupSend causes device reboot

[dx136]

PROBLEM DESCRIPTION

A clear and concise description of what the problem is.

Executing the DevGroupSend command with a variable parameter (e.g. %var11%) causes a device reboot.

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): Sonoff POW
• Tasmota binary firmware version number used: 13.2.0
  • Pre-compiled
  • Self-compiled
• Flashing tools used: serial
• Provide the output of command: Backlog Template; Module; GPIO 255:

  Configuration output here:
15:52:17.708 CMD: Backlog Template; Module
15:52:17.711 SRC: WebConsole from 192.168.87.254
15:52:17.714 CMD: Grp 0, Cmd 'BACKLOG', Idx 1, Len 16, Pld -99, Data 'Template; Module'
15:52:17.744 SRC: Backlog
15:52:17.747 CMD: Grp 0, Cmd 'TEMPLATE', Idx 1, Len 0, Pld -99, Data ''
15:52:17.752 RSL: RESULT = {"NAME":"Generic","GPIO":[32,0,0,0,0,2592,0,0,224,2656,2688,288,0,0],"FLAG":0,"BASE":6}
15:52:17.757 WIF: Checking connection...
15:52:17.962 SRC: Backlog
15:52:17.965 CMD: Grp 0, Cmd 'MODULE', Idx 1, Len 0, Pld -99, Data ''
15:52:17.969 RSL: RESULT = {"Module":{"6":"Sonoff Pow"}}

• If using rules, provide the output of this command: Backlog Rule1; Rule2; Rule3:

  Rules output here:
15:53:28.763 CMD: Backlog Rule1; Rule2; Rule3
15:53:28.766 SRC: WebConsole from 192.168.87.254
15:53:28.769 CMD: Grp 0, Cmd 'BACKLOG', Idx 1, Len 19, Pld -99, Data 'Rule1; Rule2; Rule3'
15:53:28.782 SRC: Backlog
15:53:28.785 CMD: Grp 0, Cmd 'RULE', Idx 1, Len 0, Pld -99, Data ''
15:53:28.790 RSL: RESULT = {"Rule1":{"State":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""}}
15:53:29.009 SRC: Backlog
15:53:29.012 CMD: Grp 0, Cmd 'RULE', Idx 2, Len 0, Pld -99, Data ''
15:53:29.017 RSL: RESULT = {"Rule2":{"State":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""}}
15:53:29.259 SRC: Backlog
15:53:29.262 CMD: Grp 0, Cmd 'RULE', Idx 3, Len 0, Pld -99, Data ''
15:53:29.267 RSL: RESULT = {"Rule3":{"State":"ON","Once":"OFF","StopOnError":"ON","Length":54,"Free":457,"Rules":"ON var11#data DO devgroupsend1 193=var5\\ %var11% ENDON"}}

• Provide the output of this command: Status 0:

  STATUS 0 output here:
16:01:24.108 CMD: status 0
16:01:24.114 RSL: STATUS = {"Status":{"Module":6,"DeviceName":"AuxHeat6","FriendlyName":["AuxHeat6"],"Topic":"sonoff","ButtonTopic":"0","Power":0,"PowerOnState":0,"LedState":8,"LedMask":"FFFF","SaveData":1,"SaveState":0,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0,"InfoRetain":0,"StateRetain":0,"StatusRetain":0}}
16:01:24.147 RSL: STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"sonoffs","OtaUrl":"http://ota.tasmota.com/tasmota/release/tasmota.bin.gz","RestartReason":"Hardware Watchdog","Uptime":"0T00:00:45","StartupUTC":"2024-10-11T20:00:39","Sleep":50,"CfgHolder":4617,"BootCount":66,"BCResetTime":"2023-12-06T21:38:00","SaveCount":445,"SaveAddress":"F4000"}}
16:01:24.181 RSL: STATUS2 = {"StatusFWR":{"Version":"13.2.0(tasmota)","BuildDateTime":"2023-10-19T09:02:07","Boot":31,"Core":"2_7_4_9","SDK":"2.2.2-dev(38a443e)","CpuFrequency":80,"Hardware":"ESP8266EX","CR":"421/699"}}
16:01:24.198 RSL: STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["AuxNetIn",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["80008008","2805C80001000600003C5AFF002800000000","00000009","00006048","00004000","00000000"]}}
16:01:24.229 RSL: STATUS4 = {"StatusMEM":{"ProgramSize":635,"Free":368,"Heap":23,"ProgramFlashSize":1024,"FlashSize":4096,"FlashChipId":"1640E0","FlashFrequency":40,"FlashMode":"DOUT","Features":["00000809","8F9AC787","04368001","000000CF","010013C0","C000F981","00004004","00001000","54000020","00000080"],"Drivers":"1,2,3,4,5,6,7,8,9,10,12,16,18,19,20,21,22,24,26,27,29,30,35,37,45,62,68","Sensors":"1,2,3,4,5,6","I2CDriver":"7"}}
16:01:24.265 RSL: STATUS5 = {"StatusNET":{"Hostname":"SetupTemplate","IPAddress":"192.168.87.96","Gateway":"192.168.87.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.87.1","DNSServer2":"0.0.0.0","Mac":"EC:FA:BC:00:8D:06","Webserver":2,"HTTP_API":1,"WifiConfig":2,"WifiPower":17.0}}
16:01:24.288 RSL: STATUS6 = {"StatusMQT":{"MqttHost":"","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_008D06","MqttUser":"DVES_USER","MqttCount":0,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4}}
16:01:24.308 RSL: STATUS7 = {"StatusTIM":{"UTC":"2024-10-11T20:01:24","Local":"2024-10-11T16:01:24","StartDST":"2024-03-10T02:00:00","EndDST":"2024-11-03T02:00:00","Timezone":99,"Sunrise":"07:14","Sunset":"18:23"}}
16:01:24.325 RSL: STATUS9 = {"StatusPTH":{"PowerDelta":[0,0,0],"PowerLow":0,"PowerHigh":0,"VoltageLow":0,"VoltageHigh":0,"CurrentLow":0,"CurrentHigh":0}}
16:01:24.344 RSL: STATUS10 = {"StatusSNS":{"Time":"2024-10-11T16:01:24","ENERGY":{"TotalStartTime":"2019-10-03T02:27:29","Total":43.513,"Yesterday":0.000,"Today":0.011,"Power":0,"ApparentPower":0,"ReactivePower":0,"Factor":0.00,"Voltage":0,"Current":0.000}}}
16:01:24.364 RSL: STATUS11 = {"StatusSTS":{"Time":"2024-10-11T16:01:24","Uptime":"0T00:00:45","UptimeSec":45,"Heap":23,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":20,"MqttCount":0,"POWER":"OFF","Wifi":{"AP":1,"SSId":"AuxNetIn","BSSId":"4E:5E:0C:63:29:70","Channel":1,"Mode":"11n","RSSI":100,"Signal":-39,"LinkCount":1,"Downtime":"0T00:00:03"}}}

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

  Console output here:

(Nothing additional or useful from setting weblog to 4)

TO REPRODUCE

Steps to reproduce the behavior:

Enter the commands:
16:03:32.520 CMD: var5 1
16:03:32.522 SRC: WebConsole from 192.168.87.254
16:03:32.525 CMD: Grp 0, Cmd 'VAR', Idx 5, Len 1, Pld 1, Data '1'
16:03:32.529 RSL: RESULT = {"Var5":"1"}
... then issue: var11 2
... nothing is echoed or appears in the weblog, but after some moments, the device spontaneously reboots

EXPECTED BEHAVIOUR

A clear and concise description of what you expected to happen.

I expect the command: DevGroupSend1 193=var5\ 2
and for this command to be executed locally as part of the DevGroupSend processing

SCREENSHOTS

If applicable, add screenshots to help explain your problem.

After the spontaneous reboot, get a status line in one of the two following forms:
16:00:44.067 RSL: INFO3 = {"Info3":{"RestartReason":"Hardware Watchdog","BootCount":66}}

16:03:58.053 RSL: INFO3 = {"Info3":{"RestartReason":{"Exception":4,"Reason":"Software Watchdog","EPC":["40100b14","00000000","00000000"],"EXCVADDR":"00000000","DEPC":"00000000","CallChain":["40251470","4025147e","402445cf","4024465c","4022b7bc","40222d58","4022b7fe","4022b824","40244184","4022b897","40101c5b","4022ce1c","40222d58","402309e6","402234c7","402383e4","40222d58","40253020","40252fc2","40253020","401000e1","40222d90","4024f03d","4022ac1e","401012c2","4022ad37","402541a0","40253ce1","4022af0a","4022af5d","401012c2"]},"BootCount":67}}

ADDITIONAL CONTEXT

Add any other context about the problem here.

Variable substitution (%varX%) works just fine in other rules.

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

[dx136]

A clarification: the DevGroupSend command is contained in Rule3 (which gets triggered as a result of updating var11). For convenience, rule3 is:
rule3 ON var11#data DO devgroupsend1 193=var5\ %var11% ENDON

Var11 contains a temperature value read from a sensor; the intended application is distribute that temperature to all group members (kinda like an NTP server distributes a common, consistent time to all members).

[arendst]

Sorry, cannot test. It seems my Unifi AP's fail to send/receive multicast traffic.

Looking at the DevGroupSend code it might well be that it cannot work when executed form a rule. Are you able to send a simple DevGroupSend command from a rule like DevGroupSend 128=1?

[github-actions]

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.

[arendst]

Tickle

[dx136]

(My apologies for the delay Theo; away for work).
Direct reply to the question: Yes, DevGroupSend works reliably for other uses: I'm able to successfully send both simple commands (128=1) and Events.

More informative reply:
The problem is actually a little wider/more generic than I initially thought. The reboot occurs when using DevGroupSend type "193" in a rule, though the command works perfectly when issued directly from the console. Below is output captured from a Sender and Receiver device; the timestamps help correlate the timing between the two devices. There's more action and info on the Sender side.

Please let me know if there's other tests that would be helpful.

Thanks very much Theo. :-)

• Michael

DEVICE 1 - Sender

10:52:17.255 CMD: devgroupsend1 193=var7\ 3 <---- Sending command directly from console works
10:52:17.265 RSL: RESULT = {"Var7":"3"} <---- Processed locally
10:52:17.355 RSL: RESULT = {"DevGroupSend":"193=var7\ 3"} <---- Command executed/sent to other devices
10:53:06.576 CMD: rule3 ON var11#data DO devgroupsend1 193=var7\ 3 ENDON <---- Create identical rule, no var subs
10:53:06.582 RUL: Stored uncompressed, would compress from 48 to 41 (-15%)
10:53:06.585 RSL: RESULT = {"Rule3":{"State":"ON","Once":"OFF","StopOnError":"ON","Length":48,"Free":463,"Rules":"ON var11#data DO devgroupsend1 193=var7\ 3 ENDON"}}
---> var11 1 <---- Console command
[... Initially, command not echoed to main part of window; some moments later, device has rebooted ...]
[... Some regular bootup output omitted for ease of reading; rule2 with a System.Boot event is triggered as expected...]
10:55:21.309 RUL: SYSTEM#BOOT performs "backlog var1 0; var2 0; var3 0; var4 0; var5 0; var10 0; power 0; mem16; mem15; mem11; mem10; devgroupname; mem1"
10:55:21.406 CMD: var11 1 <---- Why is this command still hanging around; or is it just the output?
10:55:21.411 RSL: RESULT = {"Var11":"1"}
10:55:21.506 RUL: VAR11#DATA performs "devgroupsend1 193=var7\ 3"
10:55:21.509 RSL: RESULT = {"Command":"Error"} <---- From attempting a DevGroupSend type 193 from within a rule

[... Do some thinking about this, and then decide to check on actual status of var11 and var7...]
[... Delete rule3 to prevent re-triggering the reboot ...]
11:13:49.001 CMD: var7
11:13:49.007 RSL: RESULT = {"Var7":""}
11:14:12.559 CMD: rule3 "
11:14:12.565 RSL: RESULT = {"Rule3":{"State":"ON","Once":"OFF","StopOnError":"ON","Length":0,"Free":511,"Rules":""}}
11:14:17.001 CMD: var11
11:14:17.007 RSL: RESULT = {"Var11":""} <---- Despite the output from 10:55:21, var11 (and var7) are uninitialized

DEVICE 2 - Receiver

10:52:01.886 RSL: STATE = {"Time":"2024-11-21T10:52:01","Uptime":"0T00:05:08", [...snip...]
10:52:17.612 RSL: RESULT = {"Var7":"3"} <---- Console command, processed remotely about 50ms after sent
[... NO further output (other than periodic tele results) ...]

[dx136]

P.S. Additional testing reveals that the extra, unexpected lines of output on the Sender (10:55:21) do not always appear. I haven't figured out any pattern for when they do, or don't, appear.

[arendst]

Give latest dev a try and let me know if it solves your issue.

[dx136]

Awesome, thank you! I won't get a chance to test until later this week or on the weekend, but will report back here.

[dx136]

What the heck, other work can wait!! Flashed Tasmota 14.3.0.7 (71dfae2-tasmota). Tested successfully (see output below).
(Note to self: the mark-down used to post these comments treats "\\" as "\", thus the rule and results should actually appear as "var7\\ 3" throughout this thread)

Looks like you've crushed this bug Theo! The world is a happier, more energy-efficient place thanks to you. :-)

Device 1 - Sender (14.3.0.7)

(First test executing directly, then enable rule so that DevGroupSend is triggered by a rule)
14:18:22.196 CMD: devgroupsend1 193=var7\ 3 <------------- Execute directly from console; everything works
14:18:22.207 RSL: RESULT = {"Var7":"3"}
14:18:22.291 RSL: RESULT = {"DevGroupSend":"193=var7\ 3"}
14:19:57.389 CMD: rule3 1 <-------------- Enable rule to verify operation from within a rule
14:19:57.397 RSL: RESULT = {"Rule3":{"State":"ON","Once":"OFF","StopOnError":"ON","Length":48,"Free":463,"Rules":"ON var11#data DO devgroupsend1 193=var7\ 3 ENDON"}}
14:20:09.167 CMD: var11 1 <------------- Trigger the rule by updating a var; all works correctly
14:20:09.174 RSL: RESULT = {"Var11":"1"}
14:20:09.269 RUL: VAR11#DATA performs 'devgroupsend1 193=var7\ 3'
14:20:09.279 RSL: RESULT = {"Var7":"3"}
14:20:09.283 RSL: RESULT = {"DevGroupSend":"193=var7\ 3"}

Device 2 - Receiver (13.2.0)

14:18:22.131 RSL: RESULT = {"Var7":"3"} <------------- Result of direct execution on console of Sender
14:20:09.131 RSL: RESULT = {"Var7":"3"} <------------- Result of triggered execution on console of Sender

[arendst]

Thx for quick response. Closing issue.