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

Multiple Reboots when Mqqt log level set to "2 Info" #7547

Closed gjwo closed 4 years ago

gjwo commented 4 years ago

PROBLEM DESCRIPTION

A clear and concise description of what the problem is. If the Mqtt logging level is set to "2 Info" from the default "0 None" the device will reboot every few minutes with the the restart reason "Software Watchdog"

REQUESTED INFORMATION

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

- [N ] 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: 12:39:04 CMD: Status 0 12:39:04 MQT: stat/Plug4/STATUS = {"Status":{"Module":0,"FriendlyName":["Plug 4"],"Topic":"Plug4","ButtonTopic":"0","Power":1,"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}} 12:39:04 MQT: stat/Plug4/STATUS1 = {"StatusPRM":{"Baudrate":115200,"GroupTopic":"tasmotas","OtaUrl":"http://thehackbox.org/tasmota/release/tasmota.bin","RestartReason":"Software Watchdog","Uptime":"0T00:58:18","StartupUTC":"2020-01-18T10:40:46","Sleep":50,"CfgHolder":4617,"BootCount":931,"SaveCount":989,"SaveAddress":"F9000"}} 12:39:04 MQT: stat/Plug4/STATUS2 = {"StatusFWR":{"Version":"8.1.0(tasmota)","BuildDateTime":"2019-12-25T12:33:25","Boot":31,"Core":"2_61","SDK":"2.2.2-dev(38a443e)","Hardware":"ESP8266EX","CR":"349/699"}} 12:39:04 MQT: stat/Plug4/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["VM1916490",""],"TelePeriod":300,"Resolution":"55A180C0","SetOption":["00008009","2805C8000100060000005A00000000000000","00000000","00000000"]}} 12:39:04 MQT: stat/Plug4/STATUS4 = {"StatusMEM":{"ProgramSize":566,"Free":436,"Heap":25,"ProgramFlashSize":1024,"FlashSize":1024,"FlashChipId":"144068","FlashMode":3,"Features":["00000809","8FDAE397","043683A0","22B617CD","01001BC0","00007881"],"Drivers":"1,2,3,4,5,6,7,8,9,10,12,16,18,19,20,21,22,24,26,29","Sensors":"1,2,3,4,5,6,7,8,9,10,14,15,17,18,20,22,26,34"}} 12:39:04 MQT: stat/Plug4/STATUS5 = {"StatusNET":{"Hostname":"PLUG-FOUR","IPAddress":"10.0.129.4","Gateway":"10.0.128.1","Subnetmask":"255.255.252.0","DNSServer":"10.0.128.1","Mac":"A4:CF:12:C3:92:6B","Webserver":2,"WifiConfig":4}} 12:39:04 MQT: stat/Plug4/STATUS6 = {"StatusMQT":{"MqttHost":"10.0.128.2","MqttPort":1883,"MqttClientMask":"DVES%06X","MqttClient":"DVES_C3926B","MqttUser":"DVES_USER","MqttCount":1,"MAX_PACKET_SIZE":1000,"KEEPALIVE":30}} 12:39:04 MQT: stat/Plug4/STATUS7 = {"StatusTIM":{"UTC":"Sat Jan 18 11:39:04 2020","Local":"Sat Jan 18 12:39:04 2020","StartDST":"Sun Mar 29 02:00:00 2020","EndDST":"Sun Oct 25 03:00:00 2020","Timezone":"+01:00","Sunrise":"08:36","Sunset":"17:24"}} 12:39:05 MQT: stat/Plug4/STATUS9 = {"StatusPTH":{"PowerDelta":20,"PowerLow":2,"PowerHigh":0,"VoltageLow":0,"VoltageHigh":0,"CurrentLow":0,"CurrentHigh":0}} 12:39:05 MQT: stat/Plug4/STATUS10 = {"StatusSNS":{"Time":"2020-01-18T12:39:05","ENERGY":{"TotalStartTime":"2020-01-02T20:20:28","Total":4.872,"Yesterday":0.150,"Today":0.000,"Power":0,"ApparentPower":0,"ReactivePower":0,"Factor":0.00,"Voltage":239,"Current":0.000}}} 12:39:05 MQT: stat/Plug4/STATUS11 = {"StatusSTS":{"Time":"2020-01-18T12:39:05","Uptime":"0T00:58:19","UptimeSec":3499,"Heap":25,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"VM1916490","BSSId":"B0:4E:26:12:35:44","Channel":4,"RSSI":58,"Signal":-71,"LinkCount":1,"Downtime":"0T00:00:06"}}}

NB This is after reseting Mqtt log level to 0

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

Console output here:

Program Version 8.1.0(tasmota)
Build Date & Time 2019-12-25T12:33:25
Core/SDK Version 2_6_1/2.2.2-dev(38a443e)
Uptime 0T00:20:19
Flash write Count 989 at 0xF9000
Boot Count 931
Restart Reason Software Watchdog
Friendly Name 1 Plug 4

See High boot count!



### TO REPRODUCE
_Steps to reproduce the behavior:_
Change Mqtt logging to 2

### EXPECTED BEHAVIOUR
_A clear and concise description of what you expected to happen._
The device will reboot ever few minutes
Changing this back to the default value stops the problem 
### SCREENSHOTS
_If applicable, add screenshots to help explain your problem._

![image](https://user-images.githubusercontent.com/12109990/72663217-ea56b100-39e7-11ea-939f-2b5484312f24.png)

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

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

Please, do a reset 6 in the Tasmota console

gjwo commented 4 years ago

00:00:00 CFG: Loaded from flash at F9, Count 3 00:00:00 Project tasmota Tasmota Version 8.1.0(tasmota)-2_6_1 00:00:00 WIF: Connecting to AP1 VM1916490 in mode 11N as Plug4-4715... 00:00:05 WIF: Connected 00:00:05 HTP: Web server active on Plug4-4715 with IP address 10.0.129.4 00:00:06 MQT: Attempting connection... 00:00:06 MQT: Connected 00:00:06 MQT: tele/Plug4/LWT = Online (retained) 00:00:06 MQT: cmnd/Plug4/POWER = 00:00:06 MQT: tele/Plug4/INFO1 = {"Module":"Sonoff Basic","Version":"8.1.0(tasmota)","FallbackTopic":"cmnd/DVES_C3926B_fb/","GroupTopic":"cmnd/tasmotas/"} 00:00:06 MQT: tele/Plug4/INFO2 = {"WebServerMode":"Admin","Hostname":"Plug4-4715","IPAddress":"10.0.129.4"} 00:00:06 MQT: tele/Plug4/INFO3 = {"RestartReason":"Software/System restart"} 00:00:06 MQT: stat/Plug4/RESULT = {"POWER":"ON"} 00:00:06 MQT: stat/Plug4/POWER = ON 00:00:10 MQT: tele/Plug4/STATE = {"Time":"1970-01-01T00:00:10","Uptime":"0T00:00:12","UptimeSec":12,"Heap":28,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"VM1916490","BSSId":"B0:4E:26:12:35:44","Channel":4,"RSSI":60,"Signal":-70,"LinkCount":1,"Downtime":"0T00:00:06"}}

gjwo commented 4 years ago

I already stopped the rebooting by resetting the mqtt logging parameter to 0, I don't need the logging but thought it was worth reporting, because it causes power disruption when happening.

gjwo commented 4 years ago

The device is normally polled every second, I have suspended this temporarily as it makes collecting console output difficult. I am using the plugs for energy measurement not control

gjwo commented 4 years ago

The device is no longer responding on the original address, how do I get it back online? image


ascillato2 commented 4 years ago

If your router gave another IP to your device, you will need to search for the new IP in your router. Also try to de-energize your device and energize it again

gjwo commented 4 years ago

I don't think that is the reason, as the address is reserved at the router. Also the device is not responding to short button presses after de-energizing device and energizing it again. Do I need to put it in AP mode and reconfigure?

ascillato commented 4 years ago

Yes

gjwo commented 4 years ago

OK it's back, will need to re-calibrate.

gjwo commented 4 years ago

OK this isn't going well, the plug is online but not responding to on/off from the switch or the web interface, it was fine before the "Reset 6" command. Current info...

It says power is on but it isn't! image

arendst commented 4 years ago

It says Restart Reason: Power On. That has nothing to do with your outputs being either power on or off. All it says is that the last restart followed a power on of the device.

arendst commented 4 years ago

You also have a different module template which is the reason why your buttons and relays won't work

gjwo commented 4 years ago

Yes I just spotted and corrected the same thing, I have two types of plug this is the correct one... image

gjwo commented 4 years ago

All looks OK now, I guess the Reset 6 command cleared more than it should have done according to the Commands reference...

6 = erase all flash and reset parameters to firmware defaults but keep Wi-Fi and MQTT settings and restart

As the plug was definitely dead after that operation. Plus I made a mistake with the template when putting it back, now corrected. Plug calibrated OK & seems to work (as it did after I put the mqtt logging back to 0).

ascillato commented 4 years ago

You said seems ok. So, that means that you don't have any more restarts after setting mqtt log level to 2?

gjwo commented 4 years ago

That's not correct (set to 0 not 2), I have 3 plugs of the same type (Plug2, Plug3, Plug4) Before I raised the issue I noticed that Plug2 had a much lower boot count, the only difference was the mqqt logging setting which was "0 None", Plugs 3 & 4 had the setting "2 Info" I reset them both to "0 None" and the problem stopped. At the time I reset the parameters Plug3 had 1480 reboots, Plug4 had 931 reboots. Plug3 still has a boot count of 1480 and an up time of 0T02:51:50 The data is lost from Plug 4, but it had an uptime of an hour (see above) when I reported the problem. I reported it because this may be useful to others, I don't need to log data as I am now polling using Node-Red.

gjwo commented 4 years ago

Sorry setting level to 0 not 2

ascillato commented 4 years ago

Ok. But after you did reset 6, if you set mqtt log level to 2, you continue having restarts? If so, please, post the output of the console when your device restarts (please also set weblog to 4 for more debug information)

Jason2866 commented 4 years ago

Have you upgraded the devices from a older Tasmota version? SDK settings needs to be erased and wifi calibration has to be done -> reset 3 Do this on every device (reset 3) and when device is back a power cycle.

gjwo commented 4 years ago

No I didn't set mqtt log level to 2. No I haven't upgraded from an older version, I got the devices early January

Jason2866 commented 4 years ago

Tuya converted? If yes do reset 3

ascillato commented 4 years ago

Please, try mqtt to log level 2 in order to see if your issue is solved or not

gjwo commented 4 years ago

@ascillato given I lost communication after the Reset 6 I wouldn't be able to get a console log, also given the problem is to do with logging changing another logging parameter moves the goal posts. Have you tried to see if another device exhibits the same problem? To Reproduce

  1. Note boot count and up time
  2. Change mqqt log to "2 info" & Save
  3. Wait for 30 minutes to an hour
  4. If boot count has changed by more than 1 you have the problem
  5. Change mqqt log to "0 None" & Save
  6. Wait for 30 minutes to an hour
  7. If boot count has changed by 1 or less you have cleared the problem

@Jason2866 Yes I used Tuya convert, but this device has been reset (6) already with dire results

The device has been re-calibrated and is currently measuring something which it needs to finish before any more experimentation. It would be worth establishing if the problem is device specific or not, I suspect not!

ascillato commented 4 years ago

Please, try mqtt to log level 2 in order to see if your issue is solved or not

arendst commented 4 years ago

I cannot reproduce either.

gjwo commented 4 years ago

I will have a go again in an hour or so, once I have finished capturing the signature for the cycles of my fridge which I am an hour+ into. So when it is done, I will follow my "To Reproduce" script above and monitor the console (does changing this parameter normally cause a reboot? I will need to disable polling from Node-Red first to monitor the console effectively.

Jason2866 commented 4 years ago

Reset 6 has not the effect of reset 3 Completly different!!

gjwo commented 4 years ago

For the avoidance of doubt, the restarts happens once every 10-20 minutes, I had the plug attached to a light yesterday evening, and it flickered off and immediately on again at about that interval all evening. So unless you wait for that amount of time you may not see the problem.

gjwo commented 4 years ago

@Jason2866 our messages crossed

gjwo commented 4 years ago

@Jason2866 1 = reset device settings to firmware defaults and restart 2 = erase flash, reset device settings to firmware defaults and restart 3 = erase System Parameter Area in flash (Wi-Fi calibration and related data) and restart 4 = reset device settings to firmware defaults but retain Wi-Fi credentials and restart  »6.3.0 5 = erase all flash and reset parameters to firmware defaults but keep Wi-Fi settings and restart 6 = erase all flash and reset parameters to firmware defaults but keep Wi-Fi and MQTT settings and restart (Erase of flash can take a few seconds to complete and there is no output during the erase process on the serial or web console) 99 = reset device bootcount to zero  But it looks like reset 6 includes the effects of reset 3 unless I am reading this wrongly, so I have had the effect of a reset 3 since I flashed the device.

ascillato commented 4 years ago

Please, when you have time, do a reset 3 as Jason has stated (that will not erase any settings, just wifi signal recalibration) and then to allow the device to recalibrate you need to de-energize it, wait 2 seconds, and energize it again.

And then set mqtt log level to 2 in order to check if your issue is solved or not. There is no need to disable anything on your node red. Just check if the uptime or bootcount increases.

To troubleshoot your problem, we need you to do this test. I think that your issue is going to be solved with reset 3 and reset 6 but you need to test it.

Jason2866 commented 4 years ago

Reset 6 erases Tasmota settings and flash Reset 3 erases espressif SDK settings and ESP wifi calibration data

gjwo commented 4 years ago

isn't the espressif SDK settings and ESP wifi calibration data held in the flash which is erased by 6?

gjwo commented 4 years ago

@ascillato OK, but I should ensure the problem is back before doing that?

Jason2866 commented 4 years ago

No! (for the commands reset 3 and 6)

gjwo commented 4 years ago

@Jason2866 OK, I am just waiting for my fridge to complete a cycle. Let's be clear about the steps Reproduce the problem

  1. Note boot count and up time
  2. Change mqqt log to "2 info" & Save
  3. Wait for 30 minutes to an hour
  4. If boot count has changed by more than 1 you have the problem

The above steps reinstate the problem Try the fix

  1. Do a reset 3 as Jason has stated (that will not erase any settings, just wifi signal recalibration) and then to allow the device to recalibrate you need to
  2. de-energize it
  3. wait 2 seconds
  4. energize it again.
  5. Note boot count and up time
  6. Wait for 30 minutes to an hour
  7. If boot count has changed by 1 or less you have cleared the problem Tidy up
  8. Note boot count and up time
  9. Change mqqt log to "0 None" & Save
  10. Wait for 30 minutes to an hour
  11. Check the boot count etc.
gjwo commented 4 years ago

Ready to start, do you want any console information? If so when?

gjwo commented 4 years ago

image

gjwo commented 4 years ago

image

ascillato commented 4 years ago

We just need your confirmation that after at least one hour with mqtt log level 2 your device didn't restart anymore.

gjwo commented 4 years ago

OK, I am still trying to reproduce the issue (after the reset 6 earlier today) 12 minutes so far and no issue.

ascillato commented 4 years ago

Thanks

gjwo commented 4 years ago

If the problem on Plug4 was cleared by the Reset 6, in 40 minutes I can try with Plug3 which has not had a Reset 6 (Turn logging on, see issue, try Reset 3). I am going to turn Node-Red mqtt polling back on for Plug 4, in case that was part of the cause

gjwo commented 4 years ago

OK That did it, almost immediately, I managed to get some console output

image

00:00:00 CFG: Loaded from flash at FB, Count 33 00:00:00 Project tasmota Plug4 Version 8.1.0(tasmota)-2_6_1 00:00:00 WIF: Connecting to AP1 VM1916490 in mode 11N as plug_four... 00:00:05 WIF: Connected 00:00:05 HTP: Web server active on plug_four with IP address 10.0.129.4 00:00:05 UPP: Multicast (re)joined 17:45:48 MQT: Attempting connection... 17:45:48 MQT: Connected 17:45:48 MQT: tele/Plug4/LWT = Online (retained) 17:45:48 MQT: cmnd/Plug4/POWER = 17:45:48 MQT: tele/Plug4/INFO1 = {"Module":"Avatar UK 10A","Version":"8.1.0(tasmota)","FallbackTopic":"cmnd/DVES_C3926B_fb/","GroupTopic":"cmnd/tasmotas/"} 17:45:48 MQT: tele/Plug4/INFO2 = {"WebServerMode":"Admin","Hostname":"plug_four","IPAddress":"10.0.129.4"} 17:45:48 MQT: tele/Plug4/INFO3 = {"RestartReason":"Hardware Watchdog"} 17:45:48 MQT: stat/Plug4/RESULT = {"POWER":"ON"} 17:45:48 MQT: stat/Plug4/POWER = ON 17:45:48 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T17:45:48","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.067,"Yesterday":0.000,"Today":0.067,"Power":59,"ApparentPower":61,"ReactivePower":16,"Factor":0.97,"Voltage":237,"Current":0.258}}} 17:45:49 UPP: Multicast (re)joined 17:45:49 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T17:45:49","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.067,"Yesterday":0.000,"Today":0.067,"Power":60,"ApparentPower":61,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.258}}} 17:45:50 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T17:45:50","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.067,"Yesterday":0.000,"Today":0.067,"Power":60,"ApparentPower":61,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.258}}} 17:45:51 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T17:45:51","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.067,"Yesterday":0.000,"Today":0.067,"Power":59,"ApparentPower":61,"ReactivePower":15,"Factor":0.97,"Voltage":238,"Current":0.258}}} 17:45:52 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T17:45:52","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.067,"Yesterday":0.000,"Today":0.067,"Power":59,"ApparentPower":61,"ReactivePower":16,"Factor":0.97,"Voltage":238,"Current":0.258}}} 17:45:52 MQT: tele/Plug4/STATE = {"Time":"2020-01-18T17:45:52","Uptime":"0T00:00:12","UptimeSec":12,"Heap":26,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"VM1916490","BSSId":"B0:4E:26:12:35:44","Channel":4,"RSSI":74,"Signal":-63,"LinkCount":1,"Downtime":"0T00:00:06"}} 17:45:52 MQT: tele/Plug4/SENSOR = {"Time":"2020-01-18T17:45:52","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.067,"Yesterday":0.000,"Today":0.067,"Period":0,"Power":59,"ApparentPower":61,"ReactivePower":15,"Factor":0.97,"Voltage":237,"Current":0.258}} 17:45:53 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T17:45:53","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.067,"Yesterday":0.000,"Today":0.067,"Period":0,"Power":60,"ApparentPower":61,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.258}}} 17:45:54 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T17:45:54","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.067,"Yesterday":0.000,"Today":0.067,"Power":60,"ApparentPower":61,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.258}}}

gjwo commented 4 years ago

And another image

Jason2866 commented 4 years ago

Tried mqtt log 2 setting too. Running about an 1 hour. Still no Watchdog

gjwo commented 4 years ago

I have 1 second mqtt polls running "cmnd/Plug3/STATUS" I didn't get the issue until I restarted these, currently at 14 mins uptime after last restart

ascillato commented 4 years ago

Ok. Great. So the issue is solved with reset 3 and reset 6. Seems that some wrong settings was in the sdk area.

Please, close it. Thanks.

gjwo commented 4 years ago

Just saw telemetry, but still up 18:07:39 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:07:39","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.088,"Yesterday":0.000,"Today":0.088,"Power":60,"ApparentPower":62,"ReactivePower":15,"Factor":0.97,"Voltage":238,"Current":0.260}}} 18:07:39 MQT: tele/Plug4/STATE = {"Time":"2020-01-18T18:07:39","Uptime":"0T00:20:12","UptimeSec":1212,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"VM1916490","BSSId":"B0:4E:26:12:35:44","Channel":4,"RSSI":72,"Signal":-64,"LinkCount":1,"Downtime":"0T00:00:06"}} 18:07:39 MQT: tele/Plug4/SENSOR = {"Time":"2020-01-18T18:07:39","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.088,"Yesterday":0.000,"Today":0.088,"Period":5,"Power":60,"ApparentPower":62,"ReactivePower":16,"Factor":0.97,"Voltage":238,"Current":0.260}} 18:07:40 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:07:40","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.088,"Yesterday":0.000,"Today":0.088,"Period":0,"Power":60,"ApparentPower":62,"ReactivePower":15,"Factor":0.97,"Voltage":238,"Current":0.260}}}

Jason2866 commented 4 years ago

If it restarts with a watchdog please set serial log level to none