Tasmota: Multiple Reboots when Mqqt log level set to "2 Info"

[gjwo]

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!_

• [ ] Read the Contributing Guide and Policy and the Code of Conduct
• [ Y] Searched the problem in issues
• [ Y] Searched the problem in the docs
• [Y ] Searched the problem in the forum
• [Y ] Searched the problem in the chat
• [ Y] Device used (e.g., Sonoff Basic): Avatar UK 10A_____
• [ Y] Tasmota binary firmware version number used: _8.1.0____
  
  
  
  • [Y ] Pre-compiled
  
  
  • [N ] Self-compiled
  
  
  • [ N] IDE / Compiler used: _____
  
  
• [Y ] Flashing tools used: __tuya convert___
• [Y ] Provide the output of command: Backlog Template; Module; GPIO 255:

  Configuration output here:
12:35:08 CMD: Backlog Template; Module; GPIO 255
12:35:08 MQT: stat/Plug4/RESULT = {"NAME":"Avatar UK 10A","GPIO":[0,0,56,0,0,134,0,0,131,17,132,21,0],"FLAG":0,"BASE":45}
12:35:08 MQT: stat/Plug4/RESULT = {"Module":{"0":"Avatar UK 10A"}}
12:35:09 MQT: stat/Plug4/RESULT = {"GPIO0":{"0":"None"},"GPIO1":{"0":"None"},"GPIO2":{"56":"Led1i"},"GPIO3":{"0":"None"},"GPIO4":{"0":"None"},"GPIO5":{"134":"BL0937 CF"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO12":{"131":"HLWBL SELi"},"GPIO13":{"17":"Button1"},"GPIO14":{"132":"HLWBL CF1"},"GPIO15":{"21":"Relay1"},"GPIO16":{"0":"None"}}

• [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_6_1","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._

ADDITIONAL CONTEXT

_Add any other context about the problem here._

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

[ascillato2]

Please, do a reset 6 in the Tasmota console

[gjwo]

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]

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]

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]

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

---

[ascillato2]

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]

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]

Yes

[gjwo]

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

[gjwo]

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!

[arendst]

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]

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

[gjwo]

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

[gjwo]

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]

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

[gjwo]

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]

Sorry setting level to 0 not 2

[ascillato]

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]

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]

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]

Tuya converted? If yes do reset 3

[ascillato]

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

[gjwo]

@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]

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

[arendst]

I cannot reproduce either.

[gjwo]

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]

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

[gjwo]

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]

@Jason2866 our messages crossed

[gjwo]

@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]

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]

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

[gjwo]

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

[gjwo]

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

[Jason2866]

No! (for the commands reset 3 and 6)

[gjwo]

@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]

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

[gjwo]

[gjwo]

[ascillato]

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

[gjwo]

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

[ascillato]

Thanks

[gjwo]

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]

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

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]

And another

[Jason2866]

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

[gjwo]

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]

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]

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]

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

[gjwo]

@ascillato no I haven't done a reset 3 yet, I want to see it restart with no changes from me first

[gjwo]

Just gone again so reset 6 on it's own is not the cure

18:12:30 MQT: stat/Plug4/RESULT = {"POWER":"ON"}
18:12:30 MQT: stat/Plug4/POWER = ON
18:12:30 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:30","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":60,"ReactivePower":15,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:31 UPP: Multicast (re)joined
18:12:31 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:31","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":60,"ReactivePower":14,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:32 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:32","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":60,"ReactivePower":15,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:33 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:33","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":61,"ReactivePower":15,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:34 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:34","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":61,"ReactivePower":16,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:34 MQT: tele/Plug4/STATE = {"Time":"2020-01-18T18:12:34","Uptime":"0T00:00:12","UptimeSec":12,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":20,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"VM1916490","BSSId":"B0:4E:26:12:35:44","Channel":4,"RSSI":70,"Signal":-65,"LinkCount":1,"Downtime":"0T00:00:06"}}
18:12:34 MQT: tele/Plug4/SENSOR = {"Time":"2020-01-18T18:12:34","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Period":0,"Power":59,"ApparentPower":61,"ReactivePower":16,"Factor":0.97,"Voltage":239,"Current":0.253}}
18:12:35 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:35","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Period":0,"Power":59,"ApparentPower":61,"ReactivePower":15,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:36 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:36","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":60,"ReactivePower":15,"Factor":0.97,"Voltage":239,"Current":0.252}}}
18:12:37 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:37","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":60,"ReactivePower":13,"Factor":0.98,"Voltage":239,"Current":0.252}}}
18:12:38 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:38","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":60,"ReactivePower":15,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:39 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:39","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":61,"ReactivePower":15,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:40 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:40","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":61,"ReactivePower":15,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:41 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:41","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":61,"ReactivePower":13,"Factor":0.98,"Voltage":239,"Current":0.253}}}
18:12:42 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:42","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":61,"ReactivePower":14,"Factor":0.97,"Voltage":239,"Current":0.253}}}
18:12:43 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:12:43","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.093,"Yesterday":0.000,"Today":0.093,"Power":59,"ApparentPower":61,"ReactivePower":14,"Factor":0.97,"Voltage":239,"Current":0.253}}}

[gjwo]

OK I have reproduced the issue.
which step do you want me to take next? Reset 3? or something else?

[ascillato]

Yes please

[gjwo]

I just had another one, before I did anything else...

00:00:00 CFG: Loaded from flash at F8, Count 36
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
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":"Avatar UK 10A","Version":"8.1.0(tasmota)","FallbackTopic":"cmnd/DVES_C3926B_fb/","GroupTopic":"cmnd/tasmotas/"}
00:00:06 MQT: tele/Plug4/INFO2 = {"WebServerMode":"Admin","Hostname":"plug_four","IPAddress":"10.0.129.4"}
00:00:06 MQT: tele/Plug4/INFO3 = {"RestartReason":"Hardware Watchdog"}
00:00:06 MQT: stat/Plug4/RESULT = {"POWER":"ON"}
00:00:06 MQT: stat/Plug4/POWER = ON
00:00:06 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:06","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.098,"Yesterday":0.000,"Today":0.098,"Power":58,"ApparentPower":60,"ReactivePower":14,"Factor":0.97,"Voltage":235,"Current":0.254}}}
00:00:07 UPP: Multicast (re)joined
00:00:07 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:07","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.098,"Yesterday":0.000,"Today":0.098,"Power":58,"ApparentPower":60,"ReactivePower":14,"Factor":0.97,"Voltage":235,"Current":0.254}}}
00:00:08 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:08","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.098,"Yesterday":0.000,"Today":0.098,"Power":58,"ApparentPower":60,"ReactivePower":13,"Factor":0.97,"Voltage":235,"Current":0.254}}}
00:00:09 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:09","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.098,"Yesterday":0.000,"Today":0.098,"Power":58,"ApparentPower":60,"ReactivePower":14,"Factor":0.97,"Voltage":235,"Current":0.254}}}
00:00:10 MQT: tele/Plug4/STATE = {"Time":"1970-01-01T00:00:10","Uptime":"0T00:00:12","UptimeSec":12,"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":70,"Signal":-65,"LinkCount":1,"Downtime":"0T00:00:06"}}
00:00:10 MQT: tele/Plug4/SENSOR = {"Time":"1970-01-01T00:00:10","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.098,"Yesterday":0.000,"Today":0.098,"Period":0,"Power":58,"ApparentPower":60,"ReactivePower":14,"Factor":0.97,"Voltage":235,"Current":0.254}}
00:00:10 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:10","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.098,"Yesterday":0.000,"Today":0.098,"Period":0,"Power":58,"ApparentPower":60,"ReactivePower":14,"Factor":0.97,"Voltage":235,"Current":0.254}}}

[gjwo]

Sometimes H/W watchdog, sometimes S/W

[gjwo]

SO Reset3 + unplug for 2 seconds?

[ascillato]

Yes please

[gjwo]

@ascillato what about the serial log option from @Jason2866 ?
If it restarts with a watchdog please set serial log level to none**

[gjwo]

Gone again

Doing reset 3 now

[gjwo]

00:00:00 CFG: Loaded from flash at F5, Count 39
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
18:30:57 MQT: Attempting connection...
18:30:57 MQT: Connected
18:30:57 MQT: tele/Plug4/LWT = Online (retained)
18:30:57 MQT: cmnd/Plug4/POWER =
18:30:57 MQT: tele/Plug4/INFO1 = {"Module":"Avatar UK 10A","Version":"8.1.0(tasmota)","FallbackTopic":"cmnd/DVES_C3926B_fb/","GroupTopic":"cmnd/tasmotas/"}
18:30:57 MQT: tele/Plug4/INFO2 = {"WebServerMode":"Admin","Hostname":"plug_four","IPAddress":"10.0.129.4"}
18:30:57 MQT: tele/Plug4/INFO3 = {"RestartReason":"Software/System restart"}
18:30:57 MQT: stat/Plug4/RESULT = {"POWER":"ON"}
18:30:57 MQT: stat/Plug4/POWER = ON
18:30:58 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:30:58","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":1,"ApparentPower":2,"ReactivePower":2,"Factor":0.26,"Voltage":236,"Current":0.008}}}

18:30:58 UPP: Multicast (re)joined
18:30:59 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:30:59","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":0,"ApparentPower":2,"ReactivePower":2,"Factor":0.21,"Voltage":236,"Current":0.008}}}
18:31:00 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:31:00","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":0,"ApparentPower":2,"ReactivePower":2,"Factor":0.21,"Voltage":236,"Current":0.008}}}
18:31:01 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:31:01","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":0,"ApparentPower":2,"ReactivePower":2,"Factor":0.19,"Voltage":236,"Current":0.009}}}
18:31:01 MQT: tele/Plug4/STATE = {"Time":"2020-01-18T18:31:01","Uptime":"0T00:00:12","UptimeSec":12,"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":76,"Signal":-62,"LinkCount":1,"Downtime":"0T00:00:06"}}
18:31:01 MQT: tele/Plug4/SENSOR = {"Time":"2020-01-18T18:31:01","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Period":0,"Power":0,"ApparentPower":2,"ReactivePower":2,"Factor":0.19,"Voltage":238,"Current":0.009}}
18:31:02 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:31:02","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Period":0,"Power":0,"ApparentPower":2,"ReactivePower":2,"Factor":0.19,"Voltage":238,"Current":0.009}}}
18:31:03 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:31:03","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":0,"ApparentPower":2,"ReactivePower":2,"Factor":0.21,"Voltage":238,"Current":0.008}}}

[gjwo]

OK done Reset 3 and power off/on

[Jason2866]

serial log should be disabled by Tasmota by default when configured as power monitoring device.
But who knows. If this is not working strange stuff could happen.

Info: Test device after a restart up for 30 minutes.

[gjwo]

@Jason2866 These are the current log settings

[gjwo]

@Jason2866 I have never changed the serial log setting so Tasmota didn't clear it when I set up the template.

[gjwo]

If this device stays up, @ascillato has provided an effective remedial work around, but the issue isn't eliminated for other users. This could be something to disable serial logging for monitoring plugs (if that is the root cause ... not proven)

But sadly, it's just crashed again!

:52:38 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:52:38","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":2,"ApparentPower":5,"ReactivePower":5,"Factor":0.43,"Voltage":235,"Current":0.022}}}
18:52:38 MQT: tele/Plug4/STATE = {"Time":"2020-01-18T18:52:38","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":70,"Signal":-65,"LinkCount":1,"Downtime":"0T00:00:06"}}
18:52:38 MQT: tele/Plug4/SENSOR = {"Time":"2020-01-18T18:52:38","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Period":0,"Power":2,"ApparentPower":5,"ReactivePower":5,"Factor":0.45,"Voltage":235,"Current":0.022}}
18:52:39 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:52:39","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Period":0,"Power":2,"ApparentPower":5,"ReactivePower":5,"Factor":0.43,"Voltage":235,"Current":0.022}}}
18:52:40 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:52:40","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":2,"ApparentPower":5,"ReactivePower":5,"Factor":0.43,"Voltage":235,"Current":0.022}}}
18:52:41 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:52:41","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":2,"ApparentPower":5,"ReactivePower":5,"Factor":0.43,"Voltage":235,"Current":0.022}}}
18:52:42 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:52:42","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":2,"ApparentPower":5,"ReactivePower":5,"Factor":0.43,"Voltage":235,"Current":0.022}}}
18:52:43 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T18:52:43","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.100,"Yesterday":0.000,"Today":0.100,"Power":2,"ApparentPower":5,"ReactivePower":5,"Factor":0.43,"Voltage":235,"Current":0.022}}}
18:52:44 MQT: stat/Plug4/STATUS8

[gjwo]

@Jason2866 shall I try disabling the serial logging now?

[gjwo]

Done

[gjwo]

That didn't work either, so the only thing that stops it so far is tuning off mqtt logging
Crashed again... and again a short while afterwards...

I have also noticed it takes a few seconds to get the time right.

00:00:00 CFG: Loaded from flash at F9, Count 43
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
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":"Avatar UK 10A","Version":"8.1.0(tasmota)","FallbackTopic":"cmnd/DVES_C3926B_fb/","GroupTopic":"cmnd/tasmotas/"}
00:00:06 MQT: tele/Plug4/INFO2 = {"WebServerMode":"Admin","Hostname":"plug_four","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:06 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:06","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.114,"Yesterday":0.000,"Today":0.114,"Power":57,"ApparentPower":59,"ReactivePower":16,"Factor":0.96,"Voltage":237,"Current":0.250}}}
00:00:07 UPP: Multicast (re)joined
00:00:07 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:07","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.114,"Yesterday":0.000,"Today":0.114,"Power":58,"ApparentPower":59,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.250}}}
00:00:08 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:08","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.114,"Yesterday":0.000,"Today":0.114,"Power":57,"ApparentPower":59,"ReactivePower":15,"Factor":0.97,"Voltage":237,"Current":0.250}}}
00:00:09 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:09","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.114,"Yesterday":0.000,"Today":0.114,"Power":57,"ApparentPower":59,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.250}}}
00:00:10 MQT: tele/Plug4/STATE = {"Time":"1970-01-01T00:00:10","Uptime":"0T00:00:12","UptimeSec":12,"Heap":27,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":23,"MqttCount":1,"POWER":"ON","Wifi":{"AP":1,"SSId":"VM1916490","BSSId":"B0:4E:26:12:35:44","Channel":4,"RSSI":66,"Signal":-67,"LinkCount":1,"Downtime":"0T00:00:06"}}
00:00:10 MQT: tele/Plug4/SENSOR = {"Time":"1970-01-01T00:00:10","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.114,"Yesterday":0.000,"Today":0.114,"Period":0,"Power":58,"ApparentPower":59,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.250}}
00:00:10 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:10","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.114,"Yesterday":0.000,"Today":0.114,"Period":0,"Power":58,"ApparentPower":59,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.250}}}
00:00:11 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:11","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.114,"Yesterday":0.000,"Today":0.114,"Power":57,"ApparentPower":59,"ReactivePower":14,"Factor":0.97,"Voltage":237,"Current":0.250}}}
00:00:12 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"1970-01-01T00:00:12","ENERGY":
Second crash

[gjwo]

And again

00:00:00 CFG: Loaded from flash at F7, Count 45
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
19:19:13 MQT: Attempting connection...
19:19:13 MQT: Connected
19:19:13 MQT: tele/Plug4/LWT = Online (retained)
19:19:13 MQT: cmnd/Plug4/POWER =
19:19:13 MQT: tele/Plug4/INFO1 = {"Module":"Avatar UK 10A","Version":"8.1.0(tasmota)","FallbackTopic":"cmnd/DVES_C3926B_fb/","GroupTopic":"cmnd/tasmotas/"}
19:19:13 MQT: tele/Plug4/INFO2 = {"WebServerMode":"Admin","Hostname":"plug_four","IPAddress":"10.0.129.4"}
19:19:13 MQT: tele/Plug4/INFO3 = {"RestartReason":"Hardware Watchdog"}
19:19:13 MQT: stat/Plug4/RESULT = {"POWER":"ON"}
19:19:13 MQT: stat/Plug4/POWER = ON
19:19:13 MQT: stat/Plug4/STATUS8 = {"StatusSNS":{"Time":"2020-01-18T19:19:13","ENERGY":{"TotalStartTime":"2020-01-18T13:33:30","Total":0.116,"Yesterday":0.000,"Today":0.116,"Power":2,"ApparentPower":5,"ReactivePower":5,"Factor":0.42,"Voltage":237,"Current":0.022}}}
19:19:14 UPP: Multicast (re)joined

[gjwo]

3 Different restart reasons!

[ascillato]

Ok. As this thread has become very long. Let's summarize. You did a reset 6, a reset 3 and a power cycle and that didn't solve your issue right? As long as you have mqtt log level set to 2, you have restarts, right? And if you set mqtt log level to 0 you don't have any restart and everything works fine right?

[gjwo]

@ascillato Yes, I also tried setting the serial log to 0.
I will now set mqtt log to 0 to see if it stabilises again

[gjwo]

done

[ascillato]

Ok. Please, restart your device in order to start clean for testing. Thanks.

[gjwo]

It's been up for 40 minutes, do you want to wait another 20 for the full hour or restart now?

[Jason2866]

My test device is running without a issue. So if there is a problem, it is "just" your decvice or this type of device.

[gjwo]

Possibly the type of device, as I have had two of them do it.

[gjwo]

OK that's a solid hour, I will restart it

[gjwo]

Restarted

[gjwo]

Possibly a memory leak?

[nagyrobi]

Possibly a shitty model like Obi Socket 2.

[sentiment-bot[bot]]

Please be sure to review the code of conduct and be respectful of other users.
Keep in mind, this repository uses the Contributor Covenant.

[gjwo]

I don't think the status of this should be awaiting feedback. I also don't see how a software functionality parameter related symptom can be related to the quality of the hardware build, unless there is faulty memory or a processor with failing op codes or some residual code remains from the oem. I could understand that analysis if the fault related to peripheral hardware.

[arendst]

Well, this issue is not as simple as it looks.

Watchdogs are "normally" caused by endless loops. In this case, where we can assume the code is stable enough, the loops are probably caused by networking wait states in UDP (your Wemo emulation using uPnP too) and TCP (mqtt with additional mqttlogging). As you request mqtt data every second there is a lot going on within the tiny box.

In addition to your mqtt requests, uPnP data has to be services at irregular intervals. Depending on your network this can be heavy considering that routers, Sonos and Chromecasts tend to request tens of them per second. The Ardiuno core tries to save UDP requests in core and waits for Tasmota to service them. Tasmota on the other hand contains code to drop requests as they flood in to keep buffering at a minimum.

It would be nice to know if your device still watchdog restarts if you disable emulation while keeping mqtt logging enabled.

On a side note I've tried to emulate your situation with a similar device, wemo emulation and mqttlogging enabled and hammering mqtt requests every 0.6 second to it but until now no watchdog experienced. Find below the simple bash script:

#!/bin/bash
SLEEP=0.6
TOPIC=digoo
MAXCNT=1000

for (( c=1; c<=$MAXCNT; c++ ))
do
  mosquitto_pub -t cmnd/$TOPIC/status -m 8
  sleep $SLEEP
done

[arendst]

You may also want to upgrade your version from 8.1.0 release to development version 8.1.0.4 which contains some fixes in both uPnP and mqqt logging.

[gjwo]

Theo,
it's nice to talk to a grown up who understands in depth how things work and offers rational fact based hypotheses. I didn't know what the WeMo emulation was, but I have just read up on it.
In terms of the environment in my house, I do have an Echo dot, but I didn't issue any commands to it during yesterday, and I don't have a Sonos. I do have two Chromo cast devices, one for video, the other for audio, neither were used yesterday. I have Node-Red polling 5 plugs, InfluxDB, recording the data and Grafana plotting graphs.
Plug4 is currently plugged into my fridge to collect energy data, I am happy to do experiments that don't involve powering it off, or losing the network connection for any length of time as I want to get a full day's view of its consumption, restarts don't have a significant effect. Re-flashing at this stage would probably lose some data.
What effect will turning off the Wemo emulation have (apart from making it inaccessible to Alexa (which I don't care about)?

[meingraham]

@gjwo

it's nice to talk to a grown up who understands in depth how things work and offers rational fact based hypotheses.

If you are looking for a better way to alienate anybody trying to help you, you will not find it.

[arendst]

I do have two Chromo cast devices, one for video, the other for audio, neither were used yesterday.

If you mean by not using they are NOT connected to the network then they won't "pollute" your network. If you meant you're not using the devices but they are still connected to your network then they "pollute" your network with uPnP messages looking for devices they may want to control.

Disabling Wemo (or any emulation) stops Tasmota from listen for these messages and frees resources.

To see what's going on enable weblog 4 and enjoy all kinds of uPnP packet information:

13:24:20 UDP: Packet (199)
13:24:20 UDP: Packet (199)
13:24:20 UDP: Packet (199)
13:24:20 UDP: Packet (199)
13:24:20 UDP: Packet (199)
13:24:20 UDP: Packet (199)
13:24:20 UDP: Packet (199)
13:24:20 UDP: Packet (199)
13:24:20 UDP: Packet (199)

[gjwo]

OK I need to go out for a couple of hours, but I will disable wemo and enable mqtt logging now before I go and post the evidence

[gjwo]

No resets overnight

[gjwo]

[gjwo]

All parameters changed before the restart caused by changing the emulation

[gjwo]

[ascillato2]

Great to know that now it is working for you. Closing issue.

[gjwo]

Looks like that hasn't helped, many restarts

[gjwo]

@ascillato2 it hasn't helped please reopen the issue, overnight mqtt logging was disabled.

[arendst]

Let's call it a day. In your case do not use mqttlog on these devices.

Mine ran for hours just fine.

[gjwo]

OK I will keep an eye out for the next release as it is easy for me to reproduce the issue, at least we have eliminated some potential causes on this thread.