search

arendst / Tasmota

Alternative firmware for ESP8266 and ESP32 based devices with easy configuration using webUI, OTA updates, automation using timers or rules, expandability and entirely local control over MQTT, HTTP, Serial or KNX. Full documentation at
https://tasmota.github.io/docs
GNU General Public License v3.0
21.97k stars 4.77k forks source link

MqttLog 4 on ESP32 results in garbled Data when receiving mqtt command #9571

Closed arovak closed 3 years ago

arovak commented 3 years ago

PROBLEM DESCRIPTION

A clear and concise description of what the problem is.

REQUESTED INFORMATION

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

- [x] Provide the output of this command: `Status 0`:

21:20:00 MQT: stat/ESP32Cam/STATUS = {"Status":{"Module":0,"DeviceName":"ESP32Cam","FriendlyName":["ESP32Cam"],"Topic":"ESP32Cam","ButtonTopic":"0","Power":0,"PowerOnState":3,"LedState":1,"LedMask":"FFFF","SaveData":1,"SaveState":1,"SwitchTopic":"0","SwitchMode":[0,0,0,0,0,0,0,0],"ButtonRetain":0,"SwitchRetain":0,"SensorRetain":0,"PowerRetain":0}} 21:20:00 MQT: stat/ESP32Cam/STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://10.4.0.5/esp8266/tasmota/tasmota.bin.gz","RestartReason":"Software reset CPU","Uptime":"0T01:57:45","StartupUTC":"2020-10-18T17:22:15","Sleep":50,"CfgHolder":4617,"BootCount":6,"BCResetTime":"2020-10-18T19:15:48","SaveCount":20}} 21:20:00 MQT: stat/ESP32Cam/STATUS2 = {"StatusFWR":{"Version":"9.0.0.2(webcam)","BuildDateTime":"2020-10-14T00:40:05","Core":"1_04","SDK":"v3.2.3-14-gd3e562907","CpuFrequency":240,"Hardware":"ESP32","CR":"390/699"}} 21:20:00 MQT: stat/ESP32Cam/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":4,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["***",""],"TelePeriod":300,"Resolution":"558180C0","SetOption":["00008009","2805C8000100060000005A00000000000000","00000000","00006000","00000000"]}} 21:20:00 MQT: stat/ESP32Cam/STATUS4 = {"StatusMEM":{"ProgramSize":1153,"Free":1984,"Heap":111,"PsrMax":4095,"PsrFree":4095,"ProgramFlashSize":4096,"FlashSize":4096,"FlashFrequency":40,"FlashMode":3,"Features":["00000809","8F8A8587","00040001","020004CF","010013F1","40000880","80004000","00000000"],"Drivers":"1,2,3,4,5,8,9,10,29,81","Sensors":"1,2,3,5,6,9,22,29,92"}} 21:20:00 MQT: stat/ESP32Cam/STATUS5 = {"StatusNET":{"Hostname":"ESP32Cam-3596","IPAddress":"10.4.0.159","Gateway":"10.4.0.1","Subnetmask":"255.255.255.0","DNSServer":"10.4.0.7","Mac":"24:62:AB:D8:6E:0C","Webserver":2,"WifiConfig":4,"WifiPower":17.0}} 21:20:00 MQT: stat/ESP32Cam/STATUS6 = {"StatusMQT":{"MqttHost":"10.4.0.5","MqttPort":1883,"MqttClientMask":"DVES%06X","MqttClient":"DVES_D86E0C","MqttUser":"DVES_USER","MqttCount":4,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30}} 21:20:00 MQT: stat/ESP32Cam/STATUS7 = {"StatusTIM":{"UTC":"2020-10-18T19:20:00","Local":"2020-10-18T21:20:00","StartDST":"2020-03-29T02:00:00","EndDST":"2020-10-25T03:00:00","Timezone":99,"Sunrise":"08:16","Sunset":"18:54"}} 21:20:00 MQT: stat/ESP32Cam/STATUS10 = {"StatusSNS":{"Time":"2020-10-18T21:20:00"}} 21:20:00 MQT: stat/ESP32Cam/STATUS11 = {"StatusSTS":{"Time":"2020-10-18T21:20:00","Uptime":"0T01:57:45","UptimeSec":7065,"Heap":111,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":4,"POWER":"OFF","Dimmer":10,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"*","BSSId":"**","Channel":11,"RSSI":86,"Signal":-57,"LinkCount":1,"Downtime":"0T00:00:03"}}}

- [x] Provide the output of the Console log output when you experience your issue; if applicable:
  _(Please use_ `weblog 4` _for more debug information)_

21:22:32 CMD: weblog 4 21:22:32 SRC: WebConsole from 10.4.0.187 21:22:32 CMD: Group 0, Index 1, Command "WEBLOG", Data "4" 21:22:32 MQT: stat/ESP32Cam/RESULT = {"WebLog":4} 21:22:41 WIF: Checking connection... 21:22:41 MQT: Data Size 1, "cmnd/ESP32Cam/mqttlog 0" 21:22:41 SRC: MQTT 21:22:41 CMD: Group 0, Index 1, Command "MQTTLOG", Data "IN�?" 21:22:41 MQT: stat/ESP32Cam/RESULT = {"MqttLog":4}



### TO REPRODUCE
Set `mqttlog 4` either via webconsole or mqtt
After that all commands send via mqtt result in garbage data received.

### EXPECTED BEHAVIOUR
Data received via mqtt commands should be handled correct when `mqttlog 4` is set.

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

### ADDITIONAL CONTEXT
I can reproduce the same error also on a ESP32-Wroom 

**(Please, remember to close the issue when the problem has been addressed)**
sfromis commented 3 years ago

Did not happen when I tested, neither on 8.5.1 nor on 9.0.0.2 sensors build.

sfromis commented 3 years ago

Not on the webcam build either. Maybe try on most recent dev binary, instead of a 4 days old one?

arovak commented 3 years ago

quite bizarre, I just did a new pull, erased flash and compiled again and see the same garbled data.

23:15:03 MQT: stat/tasmota_962088/STATUS2 = {"StatusFWR":{"Version":"9.0.0.2(netwize)","BuildDateTime":"2020-10-18T23:09:46","Core":"1_0_4","SDK":"v3.2.3-14-gd3e562907","CpuFrequency":80,"Hardware":"ESP32","CR":"359/699"}}

23:12:05 CFG: Saved, Count 5, Bytes 4096
23:12:21 WIF: Checking connection...
23:12:30 MQT: Data Size 1, "cmnd/tasmota_962088/mqttlog 4"
23:12:30 SRC: MQTT
23:12:30 CMD: Group 0, Index 1, Command "MQTTLOG", Data "4"
23:12:30 MQT: stat/tasmota_962088/RESULT = {"MqttLog":4}
23:12:31 CFG: Saved, Count 6, Bytes 4096
23:12:41 WIF: Checking connection...
23:12:44 MQT: Data Size 1, "cmnd/tasmota_962088/status 1"
23:12:44 SRC: MQTT
23:12:44 CMD: Group 0, Index 1, Command "STATUS", Data "GI"
23:12:44 MQT: stat/tasmota_962088/RESULT = {"Command":"Error"}
23:19:40 MQT: Data Size 1, "cmnd/tasmota_962088/syslog 0"
23:19:40 SRC: MQTT
23:19:40 CMD: Group 0, Index 1, Command "SYSLOG", Data "GI?�"
23:19:40 MQT: stat/tasmota_962088/RESULT = {"SysLog":{"0":{"Active":"0"}}}
23:20:15 MQT: Data Size 1, "cmnd/tasmota_962088/power1 0"
23:20:15 SRC: MQTT
23:20:15 CMD: Group 0, Index 1, Command "POWER", Data "GI��dd@�'"
23:20:15 MQT: stat/tasmota_962088/RESULT = {"Command":"Error"}

setting mqttlog 0in webconsole stops the garbled data from occuring

23:20:40` CMD: mqttlog 0
23:20:40 SRC: WebConsole from 10.4.0.187
23:20:40 CMD: Group 0, Index 1, Command "MQTTLOG", Data "0"
23:20:40 MQT: stat/tasmota_962088/RESULT = {"MqttLog":0}
23:20:41 CFG: Saved, Count 10, Bytes 4096
23:20:41 WIF: Checking connection...
23:20:43 MQT: Data Size 1, "cmnd/tasmota_962088/power1 0"
23:20:43 SRC: MQTT
23:20:43 CMD: Group 0, Index 1, Command "POWER", Data "0"
23:20:43 MQT: stat/tasmota_962088/RESULT = {"Command":"Error"}
sfromis commented 3 years ago

Testing again when already having MqttLog 4 allowed me to replicate the issue.

arendst commented 3 years ago

I need to dive in but I think the latest change I made will contribute to the error observed.

As you compile yourselves pls try to comment lines 248 and 249 in file xdrv_02_mqtt.ino like this:

  char data[data_len +1];

//  memcpy(data, mqtt_data, sizeof(data));
//  AddLog_P2(LOG_LEVEL_DEBUG_MORE, PSTR(D_LOG_MQTT D_DATA_SIZE " %d, \"%s %s\""), data_len, topic, RemoveControlCharacter(data));
//  if (LOG_LEVEL_DEBUG_MORE <= seriallog_level) { Serial.println(data); }

  memcpy(data, mqtt_data, sizeof(data));
arendst commented 3 years ago

Verified the issue on both ESP32 and ESP8266. Also that it is fixed with the change above.

I'll need to dive further to get the logging back while not to corrupt the data....

arendst commented 3 years ago

Now a small log issue. Working on it...

arovak commented 3 years ago

A new build with the latest development branch fixed the issue. Thanks for the quick response and fix!