ESP32 with enabled BLE resets when Wifi (AP) is turned off

Micha70 commented 2 years ago

PROBLEM DESCRIPTION

During night at 1am I'm switching off my WLAN router until 6pm. Between 3:42am and 3:46am each night the ESP32 with Tasmota gets an reset (Software Reset CPU). If I keep the router active there is no reset.

REQUESTED INFORMATION

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

[x] Read the Contributing Guide and Policy and the Code of Conduct
[x] Searched the problem in issues
[x] Searched the problem in discussions
[x] Searched the problem in the docs
[x] Searched the problem in the chat
[x] Device used (e.g., Sonoff Basic): ESP32
[x] Tasmota binary firmware version number used: 12.2.0.1(bluetooth)
- [x] Pre-compiled
- [ ] Self-compiled
[x] Flashing tools used: OTA

[x] Provide the output of command: Backlog Template; Module; GPIO 255:


Configuration output here:
18:31:13.494 MQT: stat/LED-Hausflur/RESULT = {"NAME":"ESP32-DevKit","GPIO":[1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,1,0,1,1,1,0,1,1,1,0,0,0,0,1,1,1,1,1,0,0,1],"FLAG":0,"BASE":1}
18:31:13.691 MQT: stat/LED-Hausflur/RESULT = {"Module":{"0":"ESP32-DevKit"}}
18:31:13.915 MQT: stat/LED-Hausflur/RESULT = {"GPIO0":{"0":"None"},"GPIO1":{"0":"None"},"GPIO2":{"0":"None"},"GPIO3":{"0":"None"},"GPIO4":{"0":"None"},"GPIO5":{"0":"None"},"GPIO6":{"0":"None"},"GPIO7":{"0":"None"},"GPIO8":{"0":"None"},"GPIO9":{"0":"None"},"GPIO10":{"0":"None"},"GPIO11":{"0":"None"},"GPIO12":{"0":"None"},"GPIO13":{"0":"None"},"GPIO14":{"0":"None"},"GPIO15":{"0":"None"},"GPIO16":{"416":"PWM1"},"GPIO17":{"0":"None"},"GPIO18":{"0":"None"},"GPIO19":{"0":"None"},"GPIO20":{"0":"None"},"GPIO21":{"0":"None"},"GPIO22":{"0":"None"},"GPIO23":{"0":"None"},"GPIO24":{"0":"None"},"GPIO25":{"0":"None"},"GPIO26":{"0":"None"},"GPIO27":{"0":"None"},"GPIO32":{"0":"None"},"GPIO33":{"0":"None"},"GPIO34":{"0":"None"},"GPIO35":{"0":"None"},"GPIO36":{"0":"None"},"GPIO37":{"0":"None"},"GPIO38":{"0":"None"},"GPIO39":{"0":"None"}}

- [x] If using rules, provide the output of this command: `Backlog Rule1; Rule2; Rule3`:
```lua
  Rules output here:
18:32:20.618 MQT: stat/LED-Hausflur/RESULT = {"Rule1":{"State":"OFF","Once":"ON","StopOnError":"OFF","Length":35,"Free":476,"Rules":"on Clock#Timer=6 do Restart 1 endon"}}
18:32:20.829 MQT: stat/LED-Hausflur/RESULT = {"Rule2":{"State":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""}}
18:32:21.038 MQT: stat/LED-Hausflur/RESULT = {"Rule3":{"State":"OFF","Once":"OFF","StopOnError":"OFF","Length":0,"Free":511,"Rules":""}}

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


STATUS 0 output here:
18:33:10.629 MQT: stat/LED-Hausflur/STATUS = {"Status":{"Module":0,"DeviceName":"LED-Neu","FriendlyName":["LED-Hausflur-Neu"],"Topic":"LED-Hausflur","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,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":1,"PowerRetain":0,"InfoRetain":0,"StateRetain":0,"StatusRetain":0}}
18:33:10.643 MQT: stat/LED-Hausflur/STATUS1 = {"StatusPRM":{"Baudrate":115200,"SerialConfig":"8N1","GroupTopic":"tasmotas","OtaUrl":"http://ota.tasmota.com/tasmota32/tasmota32-bluetooth.bin","RestartReason":"Software reset CPU","Uptime":"0T14:50:37","StartupUTC":"2022-10-31T02:42:33","Sleep":100,"CfgHolder":4617,"BootCount":110,"BCResetTime":"2022-04-09T12:07:39","SaveCount":159784}}
18:33:10.653 MQT: stat/LED-Hausflur/STATUS2 = {"StatusFWR":{"Version":"12.2.0.1(bluetooth)","BuildDateTime":"2022-10-23T18:09:44","Core":"2_0_5","SDK":"v4.4.3.4","CpuFrequency":80,"Hardware":"ESP32-D0WD-V3 rev.3","CR":"427/699"}}
18:33:10.662 MQT: stat/LED-Hausflur/STATUS3 = {"StatusLOG":{"SerialLog":2,"WebLog":2,"MqttLog":0,"SysLog":0,"LogHost":"","LogPort":514,"SSId":["ollahMuz","ollahMuz_K"],"TelePeriod":300,"Resolution":"558180C0","SetOption":["00008209","2805C80001000600003C5A0A002800000000","00000280","00006000","00004002","00000000"]}}
18:33:10.683 MQT: stat/LED-Hausflur/STATUS4 = {"StatusMEM":{"ProgramSize":1585,"Free":1294,"Heap":70,"StackLowMark":3,"PsrMax":0,"PsrFree":0,"ProgramFlashSize":4096,"FlashSize":4096,"FlashChipId":"16405E","FlashFrequency":40,"FlashMode":"DOUT","Features":["00000809","8F9AC7C7","00148001","000000CF","010013C0","C0000981","00004080","00200000","5400082C","00000000"],"Drivers":"1,2,3,4,5,7,8,9,10,12,16,20,21,24,26,27,29,35,38,50,52,59,62,79,85","Sensors":"1,2,3,5,6,52,62,127"}}
18:33:10.702 MQT: stat/LED-Hausflur/STATUS5 = {"StatusNET":{"Hostname":"LED-Hausflur-7916","IPAddress":"192.168.178.80","Gateway":"192.168.178.1","Subnetmask":"255.255.255.0","DNSServer1":"192.168.178.50","DNSServer2":"0.0.0.0","Mac":"24:D7:EB:0D:FE:EC","Webserver":2,"HTTP_API":1,"WifiConfig":4,"WifiPower":17.0}}
18:33:10.718 MQT: stat/LED-Hausflur/STATUS6 = {"StatusMQT":{"MqttHost":"192.168.178.50","MqttPort":1883,"MqttClientMask":"DVES_%06X","MqttClient":"DVES_0DFEEC","MqttUser":"Micha","MqttCount":1,"MAX_PACKET_SIZE":1200,"KEEPALIVE":30,"SOCKET_TIMEOUT":4}}
18:33:10.733 MQT: stat/LED-Hausflur/STATUS7 = {"StatusTIM":{"UTC":"2022-10-31T17:33:10","Local":"2022-10-31T18:33:10","StartDST":"2022-03-27T02:00:00","EndDST":"2022-10-30T03:00:00","Timezone":99,"Sunrise":"06:57","Sunset":"16:51"}}
18:33:10.751 MQT: stat/LED-Hausflur/STATUS10 = {"StatusSNS":{"Time":"2022-10-31T18:33:10"}}
18:33:10.764 MQT: stat/LED-Hausflur/STATUS11 = {"StatusSTS":{"Time":"2022-10-31T18:33:10","Uptime":"0T14:50:37","UptimeSec":53437,"Heap":69,"SleepMode":"Dynamic","Sleep":10,"LoadAvg":99,"MqttCount":1,"Berry":{"HeapUsed":3,"Objects":40},"POWER":"ON","Dimmer":63,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"ollahMuz","BSSId":"2C:91:AB:9A:FD:8E","Channel":4,"Mode":"11n","RSSI":100,"Signal":-47,"LinkCount":1,"Downtime":"0T02:17:56"}}}

- [ ] Set `weblog` to 4 and then, when you experience your issue, provide the output of the Console log:
```lua
  Console output here:
Impossible, because during problem Wifi is off.

TO REPRODUCE

Keep Tasmota on ESP32 running, stopp Wifi router and wait at least three hours. Outputs will flash shortly, afterwards the boot counter is increased.

EXPECTED BEHAVIOUR

No flashing of outputs, no boot counter increase.

SCREENSHOTS

ADDITIONAL CONTEXT

Device is used to control a light stripe and as BLE-MQTT gateway.

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

Jason2866 commented 2 years ago

Please post result of cmd wificonfig

Micha70 commented 2 years ago

19 20 10.281 MQT: stat/LED-Hausflur/RESULT = {"WifiConfig" {"4" "Retry"}}

barbudor commented 2 years ago

4 = retry other AP without rebooting (default)
5 = wait until selected AP is available again without rebooting

Unless you have a 2nd SSID configured, the later (5) seems to be more what you need

Micha70 commented 2 years ago

Ok, I will give it a try.

Micha70 commented 2 years ago

Today in the morning it was not accessible at all. I had to disconnect and reconnect the device, then it was working again ....

Interesting, seems over nicht it did not got a reset, because the bootcount was yesterday at 110, now after hard reset is 111. How ever it seems it got totally stuck ....

barbudor commented 2 years ago

You are specifically pointing ESP32? What about esp8266? What device is that? Do you have serial access so see what happens actually when the problem occurs?

So far we are totally blind and just guessed some possibilities. You need to provide more details including details on your wifi infrastructure (brand/model of AP(s))

Micha70 commented 2 years ago

I have several Tasmota devices with ESP8266 without problems. However only the one with ESP32 has this problem... Is an ESP32-DevKit. Unfortunately is not very good accessible.... I will setup a second one. If problem is reproducible I will be able to connect a serial monitor. Maybe I need some help then... About WiFi infrastructure I'm using AVM FRITZ!Box 7590 with a second AP FRITZ!Repeater 2400. Nothing really special....

barbudor commented 2 years ago

Fritzbox and repeaters seems to be "special" indeed https://github.com/arendst/Tasmota/discussions/14986

Jason2866 commented 2 years ago

Oh, again the AVM Fritzbox stuff. Check your setup if the repeater is using 5Ghz to connect to the Router. Does your ESP32 connect without troubles? Please check the serial console. Probably it is the same known issue as #14986

Micha70 commented 2 years ago

The repeater is used as AP, connected via LAN cable to router. What is issue #14986? I don't find it ..

barbudor commented 2 years ago

You don't need to find it, just click on the link

Micha70 commented 2 years ago

I don't believe this is my problem. Messages like this I don't see in console. I did a restart now by web server interface. In my opinion there are no connection problems ...


00:00:00.004 HDW: FoundPSRAM=0 CanUsePSRAM=0
00:00:00.069 UFS: FlashFS mounted with 296 kB free
00:00:00.115 CFG: Loaded from File, Count 159800
00:00:00.131 QPC: Count 1
00:00:00.133 CFG: CR 427/699, Busy 0
00:00:00.139 ROT: Mode 1
00:00:00.154 BRY: GC from 3819 to 3049 bytes, objects freed 5/20 (in 0 ms) - slots from 35/61 to 23/61
00:00:00.155 BRY: GC timing (us) 1:175 2:151 3:127 4:6 5:28 total:487
00:00:00.155 BRY: GC by type string:6 class:0 proto:3 instance:0 map:3 list:1 closure:1 ntvclos:0 module:0 comobj:0
00:00:00.263 CFG: No '*.autoconf' file found
00:00:00.268 BRY: GC from 4751 to 4041 bytes, objects freed 5/42 (in 1 ms) - slots from 61/91 to 41/91
00:00:00.269 BRY: GC timing (us) 1:211 2:281 3:581 4:6 5:29 total:1108
00:00:00.270 BRY: GC by type string:6 class:0 proto:3 instance:18 map:4 list:1 closure:4 ntvclos:0 module:0 comobj:0
00:00:00.271 BRY: Berry initialized, RAM used=4041 bytes
00:00:00.287 BRY: No 'preinit.be'
00:00:00.290 SRC: Restart
00:00:00.297 Project tasmota - LED-Neu Version 12.2.0.1(bluetooth)-2_0_5(2022-10-23T18:09:44)
00:00:00.298 iBeacon register for advert callbacks
00:00:00.299 MI32Option0: 1
00:00:00.310 MI32Option1: 0
00:00:00.311 MI32Option2: 0
00:00:00.312 MI32Option4: 1
00:00:00.313 MI32Option5: 0
00:00:00.313 MI32Option6: 0
00:00:00.324 M32: init: request callbacks
00:00:00.407 BRY: No 'autoexec.be'
00:00:00.530 WIF: Checking connection...
00:00:00.531 WIF: Attempting connection...
00:00:00.017 WIF: Connecting to AP1 ollahMuz Channel 4 BSSId 2C:91:AB:9A:FD:8E in mode 11n as LED-Hausflur-7916...
00:00:00.081 WIF: Checking connection...
00:00:00.082 WIF: Attempting connection...
00:00:01.297 WIF: Checking connection...
00:00:01.298 WIF: Attempting connection...
00:00:01.299 WIF: Checking connection...
00:00:01.300 WIF: Attempting connection...
00:00:03.300 WIF: Checking connection...
00:00:03.301 WIF: Connected
00:00:03.500 NTP: Sync time...
00:00:03.725 RTC: UTC 2022-11-01T13:38:25, DST 2022-03-27T02:00:00, STD 2022-10-30T03:00:00
14:38:25.001 RTC: Synced by NTP
14:38:25.006 BLE: MasterEnable->1
14:38:25.025 BLE: BLETask:Starting NimBLE
14:38:25.027 HTP: Web server active on LED-Hausflur-7916 with IP address 192.168.178.80
14:38:26.254 QPC: Reset
14:38:26.366 MQT: Attempting connection...
14:38:26.584 M32: MI32: new ATC at slot: 0
14:38:27.845 MQT: Connected
14:38:27.853 MQT: tele/LED-Hausflur/LWT = Online (retained)
14:38:27.858 MQT: cmnd/LED-Hausflur/POWER = 
14:38:27.861 MQT: Subscribe to cmnd/LED-Hausflur/#
14:38:27.868 MQT: Subscribe to cmnd/tasmotas/#
14:38:27.875 MQT: Subscribe to cmnd/DVES_0DFEEC_fb/#
14:38:27.891 MQT: tele/LED-Hausflur/INFO1 = {"Info1":{"Module":"ESP32-DevKit","Version":"12.2.0.1(bluetooth)","FallbackTopic":"cmnd/DVES_0DFEEC_fb/","GroupTopic":"cmnd/tasmotas/"}}
14:38:27.908 MQT: tele/LED-Hausflur/INFO2 = {"Info2":{"WebServerMode":"Admin","Hostname":"LED-Hausflur-7916","IPAddress":"192.168.178.80"}}
14:38:27.925 MQT: tele/LED-Hausflur/INFO3 = {"Info3":{"RestartReason":"Software reset CPU","BootCount":116}}
14:38:27.940 MQT: stat/LED-Hausflur/RESULT = {"POWER":"OFF"}
14:38:27.944 MQT: stat/LED-Hausflur/POWER = OFF
14:38:27.982 MQT: tele/LED-Hausflur/SENSOR = {"Time":"2022-11-01T14:38:27","ATC7bc767":{"mac":"a4c1387bc767","Temperature":19.9,"Humidity":65.1,"DewPoint":13.1,"Btn":1,"Battery":35,"RSSI":-84},"TempUnit":"C"} (retained)
14:38:28.030 SRC: File
14:38:28.034 CMD: Grp 0, Cmd 'BLEALIAS', Idx 1, Len 21, Pld 1, Data '001A220BBF0A=EQ3Fabio'
14:38:28.043 BLE: Add Alias mac 001A220BBF0A = name EQ3Fabio
14:38:28.058 MQT: stat/LED-Hausflur/RESULT = {"BLEAlias":{"001A220BBF0A":"EQ3Fabio"}}
14:38:28.131 SRC: File
14:38:28.134 CMD: Grp 0, Cmd 'BLEALIAS', Idx 1, Len 22, Pld -99, Data 'A4C1386B40E8=ATC_Simon'
14:38:28.142 BLE: Add Alias mac A4C1386B40E8 = name ATC_Simon
14:38:28.153 MQT: stat/LED-Hausflur/RESULT = {"BLEAlias":{"001A220BBF0A":"EQ3Fabio","A4C1386B40E8":"ATC_Simon"}}
14:38:28.230 SRC: File
14:38:28.233 CMD: Grp 0, Cmd 'BLEALIAS', Idx 1, Len 18, Pld 4, Data '04EE03B8AA49=OralB'
14:38:28.241 BLE: Add Alias mac 04EE03B8AA49 = name OralB
14:38:28.252 MQT: stat/LED-Hausflur/RESULT = {"BLEAlias":{"001A220BBF0A":"EQ3Fabio","A4C1386B40E8":"ATC_Simon","04EE03B8AA49":"OralB"}}
14:38:28.331 SRC: File
14:38:28.334 CMD: Grp 0, Cmd 'BLEADDRFILTER', Idx 1, Len 1, Pld 0, Data '0'
14:38:28.352 MQT: stat/LED-Hausflur/RESULT = {"BLEAddrFilter1":0}
14:38:28.430 SRC: File
14:38:28.433 CMD: Grp 0, Cmd 'MI32OPTION', Idx 6, Len 1, Pld 1, Data '1'
14:38:28.457 MQT: stat/LED-Hausflur/RESULT = {"MI32Option6":1}
14:38:28.467 APP: Boot Count 116
14:38:28.483 MQT: tele/tasmota_ble/ATC7bc767 = {"Time":"2022-11-01T14:38:28","mac":"a4c1387bc767","Temperature":19.9,"Humidity":65.1,"DewPoint":13.1,"Btn":1,"Battery":35,"RSSI":-84,"TempUnit":"C"} (retained)
14:38:28.530 SRC: File
14:38:28.533 CMD: Grp 0, Cmd 'BLEENABLEUNSAVED', Idx 1, Len 1, Pld 1, Data '1'
14:38:28.558 MQT: stat/LED-Hausflur/RESULT = {"BLEEnableUnsaved":1}
14:38:28.630 SRC: File
14:38:28.634 CMD: Grp 0, Cmd 'TRVHIDEFAILEDPOLL', Idx 1, Len 1, Pld 1, Data '1'
14:38:28.659 MQT: stat/LED-Hausflur/RESULT = {"trvHideFailedPoll":1}
14:38:28.730 SRC: File
14:38:28.733 CMD: Grp 0, Cmd 'TRVMINRSSI', Idx 1, Len 3, Pld -90, Data '-90'
14:38:28.745 MQT: stat/LED-Hausflur/RESULT = {"trvMinRSSI":-90}
14:38:29.092 EQ3 mqtt: cmnd/LED-Hausflur/STATE:
14:38:29.095 SRC: MQTT
14:38:29.099 CMD: Grp 0, Cmd 'STATE', Idx 1, Len 0, Pld -99, Data ''
14:38:29.108 BRY: GC from 7807 to 3734 bytes, objects freed 55/40 (in 1 ms) - slots from 145/167 to 41/137
14:38:29.113 BRY: GC timing (us) 1:237 2:358 3:1222 4:5 5:57 total:1879
14:38:29.118 BRY: GC by type string:5 class:0 proto:2 instance:18 map:4 list:1 closure:5 ntvclos:1 module:0 comobj:0
14:38:29.130 MQT: tele/LED-Hausflur/STATE = {"Time":"2022-11-01T14:38:29","Uptime":"0T00:00:11","UptimeSec":11,"Heap":77,"SleepMode":"Dynamic","Sleep":100,"LoadAvg":111,"MqttCount":1,"Berry":{"HeapUsed":3,"Objects":40},"POWER":"OFF","Dimmer":63,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"ollahMuz","BSSId":"2C:91:AB:9A:FD:8E","Channel":4,"Mode":"11n","RSSI":100,"Signal":-46,"LinkCount":1,"Downtime":"0T00:00:06"}}
14:38:29.181 MQT: stat/LED-Hausflur/RESULT = {"Time":"2022-11-01T14:38:29","Uptime":"0T00:00:11","UptimeSec":11,"Heap":77,"SleepMode":"Dynamic","Sleep":100,"LoadAvg":111,"MqttCount":1,"Berry":{"HeapUsed":3,"Objects":40},"POWER":"OFF","Dimmer":63,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"ollahMuz","BSSId":"2C:91:AB:9A:FD:8E","Channel":4,"Mode":"11n","RSSI":100,"Signal":-46,"LinkCount":1,"Downtime":"0T00:00:06"}}
14:38:29.237 EQ3 mqtt: cmnd/LED-Hausflur/STATUS:11
14:38:29.242 SRC: MQTT
14:38:29.245 CMD: Grp 0, Cmd 'STATUS', Idx 1, Len 2, Pld 11, Data '11'
14:38:29.253 BRY: GC from 4253 to 3734 bytes, objects freed 2/40 (in 1 ms) - slots from 44/137 to 41/137
14:38:29.260 BRY: GC timing (us) 1:212 2:350 3:510 4:1 5:30 total:1103
14:38:29.263 BRY: GC by type string:5 class:0 proto:2 instance:18 map:4 list:1 closure:5 ntvclos:1 module:0 comobj:0
14:38:29.280 MQT: stat/LED-Hausflur/STATUS11 = {"StatusSTS":{"Time":"2022-11-01T14:38:29","Uptime":"0T00:00:11","UptimeSec":11,"Heap":80,"SleepMode":"Dynamic","Sleep":100,"LoadAvg":114,"MqttCount":1,"Berry":{"HeapUsed":3,"Objects":40},"POWER":"OFF","Dimmer":63,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"ollahMuz","BSSId":"2C:91:AB:9A:FD:8E","Channel":4,"Mode":"11n","RSSI":100,"Signal":-46,"LinkCount":1,"Downtime":"0T00:00:06"}}}
14:38:30.030 CFG: Saved, Count 159801, Bytes 4096
14:38:30.075 M32: MI32: new ATC at slot: 1
14:38:30.364 MQT: tele/tasmota_ble/ATC_Simon = {"Time":"2022-11-01T14:38:30","alias":"ATC_Simon","mac":"a4c1386b40e8","Temperature":20.8,"Humidity":74.1,"DewPoint":16.0,"Btn":1,"Battery":51,"RSSI":-85,"TempUnit":"C"} (retained)
14:38:31.410 BRY: GC from 4194 to 3734 bytes, objects freed 1/40 (in 1 ms) - slots from 43/137 to 41/137
14:38:31.415 BRY: GC timing (us) 1:251 2:350 3:185 4:6 5:34 total:826
14:38:31.419 BRY: GC by type string:5 class:0 proto:2 instance:18 map:4 list:1 closure:5 ntvclos:1 module:0 comobj:0
14:38:31.442 MQT: tele/LED-Hausflur/STATE = {"Time":"2022-11-01T14:38:31","Uptime":"0T00:00:13","UptimeSec":13,"Heap":80,"SleepMode":"Dynamic","Sleep":100,"LoadAvg":42,"MqttCount":1,"Berry":{"HeapUsed":3,"Objects":40},"POWER":"OFF","Dimmer":63,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"ollahMuz","BSSId":"2C:91:AB:9A:FD:8E","Channel":4,"Mode":"11n","RSSI":100,"Signal":-46,"LinkCount":1,"Downtime":"0T00:00:06"}}
14:38:31.494 MQT: tele/LED-Hausflur/BLE = {"Time":"2022-11-01T14:38:31","BLEDevices":{"total":3,"A4C1387BC767":{"i":0,"r":-84},"A4C1386B40E8":{"i":1,"r":-85,"a":"ATC_Simon"},"001A220BBF0A":{"i":2,"r":-86,"a":"EQ3Fabio"}}}
14:38:31.524 MQT: tele/LED-Hausflur/BLE = {"Time":"2022-11-01T14:38:31","BLE":{"scans":0,"adverts":27,"devices":3,"resets":0}}
14:38:36.473 MQT: tasmota/discovery/24D7EB0DFEEC/config = {"ip":"192.168.178.80","dn":"LED-Neu","fn":["LED-Hausflur-Neu",null,null,null,null,null,null,null],"hn":"LED-Hausflur-7916","mac":"24D7EB0DFEEC","md":"ESP32-DevKit","ty":0,"if":0,"ofln":"Offline","onln":"Online","state":["OFF","ON","TOGGLE","HOLD"],"sw":"12.2.0.1","t":"LED-Hausflur","ft":"%prefix%/%topic%/","tp":["cmnd","stat","tele"],"rl":[2,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],"swc":[-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1,-1],"swn":[null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null,null],"btn":[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],"so":{"4":0,"11":0,"13":0,"17":0,"20":0,"30":0,"68":0,"73":0,"82":0,"114":0,"117":0},"lk":1,"lt_st":1,"sho":[0,0,0,0],"sht":[[0,0,0],[0,0,0],[0,0,0],[0,0,0]],"ver":1} (retained)
14:38:36.498 MQT: tasmota/discovery/24D7EB0DFEEC/sensors = {"sn":{"Time":"2022-11-01T14:38:36"},"ver":1} (retained)
14:38:38.439 EQ3 poll cycle starting
14:38:38.443 EQ3 EQ3Fabio: Op queued len now 1
14:38:38.446 EQ3 EQ3Fabio:Op dequeued len now 0
14:38:41.459 MQT: stat/EQ3/EQ3Fabio = {"cmd":"poll","result":"ok","MAC":"001A220BBF0A","tas":"LED-Hausflur-7916","RSSI":-88,"stattime":1667309921,"temp":17.0,"posn":0,"mode":"auto","hassmode":"auto","boost":"inactive","dst":"set","window":"closed","state":"unlocked","battery":"GOOD","holidayend":"00-00-00 00:00","windowtemp":12.0,"windowdur":15,"day":20.0,"night":17.5,"offset":0.0}
14:38:41.509 MQT: tele/LED-Hausflur/BLE = {"BLEOperation":{"opid":"0","stat":"7","state":"DONENOTIFIED","MAC":"001A220BBF0A","u":"128","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03160B010E2626000000000000000000","notify":"020108000422000000001803282307"}} (retained)
14:38:47.161 WIF: Checking connection...
14:38:57.908 M32: MI32: new ATC at slot: 2
14:38:58.476 MQT: tele/tasmota_ble/ATCa7b47e = {"Time":"2022-11-01T14:38:58","mac":"a4c138a7b47e","Temperature":23.3,"Humidity":64.5,"DewPoint":16.2,"Btn":1,"Battery":74,"RSSI":-94,"TempUnit":"C"} (retained)
14:39:07.164 WIF: Checking connection...
14:39:27.167 WIF: Checking connection...
14:39:47.100 WIF: Checking connection...
15:03:31.514 MQT: tele/LED-Hausflur/BLE = {"Time":"2022-11-01T15:03:31","BLEDevices":{"total":4,"A4C1387BC767":{"i":0,"r":-85},"A4C1386B40E8":{"i":1,"r":-89,"a":"ATC_Simon"},"001A220BBF0A":{"i":2,"r":-90,"a":"EQ3Fabio"},"A4C138A7B47E":{"i":3,"r":-100}}}
15:03:31.559 MQT: tele/LED-Hausflur/BLE = {"Time":"2022-11-01T15:03:31","BLE":{"scans":76,"adverts":11451,"devices":4,"resets":0}}
15:03:38.484 EQ3 poll cycle starting
15:03:38.487 EQ3 EQ3Fabio: Op queued len now 1
15:03:38.492 EQ3 EQ3Fabio:Op dequeued len now 0
15:03:43.534 BLE: failed to connect to device
15:03:44.486 EQ3 001A220BBF0A: trv operation failed - retrying -11
15:03:44.505 MQT: tele/LED-Hausflur/BLE = {"BLEOperation":{"opid":"5","stat":"-11","state":"FAILCONNECT","MAC":"001A220BBF0A","u":"128","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03160B010F0326000000000000000000"}} (retained)
15:03:47.084 WIF: Checking connection...
15:03:48.498 MQT: stat/EQ3/EQ3Fabio = {"cmd":"poll","result":"ok","MAC":"001A220BBF0A","tas":"LED-Hausflur-7916","RSSI":-89,"stattime":1667311428,"temp":17.0,"posn":0,"mode":"auto","hassmode":"auto","boost":"inactive","dst":"set","window":"closed","state":"unlocked","battery":"GOOD","holidayend":"00-00-00 00:00","windowtemp":12.0,"windowdur":15,"day":20.0,"night":17.5,"offset":0.0}
15:03:48.557 MQT: tele/LED-Hausflur/BLE = {"BLEOperation":{"opid":"6","stat":"7","state":"DONENOTIFIED","MAC":"001A220BBF0A","u":"128","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03160B010F0326000000000000000000","notify":"020108000422000000001803282307"}} (retained)
15:04:07.105 WIF: Checking connection...
15:04:27.106 WIF: Checking connection...
15:04:47.108 WIF: Checking connection...
15:05:07.110 WIF: Checking connection...
15:05:27.113 WIF: Checking connection...
15:05:47.115 WIF: Checking connection...
15:06:07.116 WIF: Checking connection...
15:06:27.119 WIF: Checking connection...
15:06:47.120 WIF: Checking connection...
15:07:07.122 WIF: Checking connection...
15:07:27.122 WIF: Checking connection...
15:07:47.123 WIF: Checking connection...
15:08:07.125 WIF: Checking connection...
15:08:19.430 M32: Kick off readOneSensor
15:08:19.432 M32: Hit tele time, restarted but not finished last - lost from slot 1073562288
15:08:20.445 MQT: tele/tasmota_ble/ATC7bc767 = {"Time":"2022-11-01T15:08:20","mac":"a4c1387bc767","Temperature":17.8,"Humidity":66.8,"DewPoint":11.5,"Btn":1,"Battery":31,"RSSI":-86,"TempUnit":"C"} (retained)
15:08:21.439 MQT: tele/tasmota_ble/ATC_Simon = {"Time":"2022-11-01T15:08:21","alias":"ATC_Simon","mac":"a4c1386b40e8","Temperature":20.9,"Humidity":74.2,"DewPoint":16.1,"Btn":1,"Battery":51,"RSSI":-85,"TempUnit":"C"} (retained)
15:08:22.439 MQT: tele/tasmota_ble/ATCa7b47e = {"Time":"2022-11-01T15:08:22","mac":"a4c138a7b47e","Temperature":23.3,"Humidity":65.8,"DewPoint":16.5,"Btn":1,"Battery":74,"RSSI":-100,"TempUnit":"C"} (retained)
15:08:27.126 WIF: Checking connection...
15:08:31.444 BRY: GC from 5266 to 3734 bytes, objects freed 5/40 (in 1 ms) - slots from 47/137 to 41/137
15:08:31.446 BRY: GC timing (us) 1:222 2:372 3:204 4:6 5:34 total:838
15:08:31.450 BRY: GC by type string:5 class:0 proto:2 instance:18 map:4 list:1 closure:5 ntvclos:1 module:0 comobj:0
15:08:31.464 MQT: tele/LED-Hausflur/STATE = {"Time":"2022-11-01T15:08:31","Uptime":"0T00:30:13","UptimeSec":1813,"Heap":77,"SleepMode":"Dynamic","Sleep":100,"LoadAvg":11,"MqttCount":1,"Berry":{"HeapUsed":3,"Objects":40},"POWER":"OFF","Dimmer":63,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"ollahMuz","BSSId":"2C:91:AB:9A:FD:8E","Channel":4,"Mode":"11n","RSSI":100,"Signal":-46,"LinkCount":1,"Downtime":"0T00:00:06"}}
15:08:31.526 MQT: tele/LED-Hausflur/BLE = {"Time":"2022-11-01T15:08:31","BLEDevices":{"total":4,"A4C1387BC767":{"i":0,"r":-85},"A4C1386B40E8":{"i":1,"r":-85,"a":"ATC_Simon"},"001A220BBF0A":{"i":2,"r":-90,"a":"EQ3Fabio"},"A4C138A7B47E":{"i":3,"r":-100}}}
15:08:31.559 MQT: tele/LED-Hausflur/BLE = {"Time":"2022-11-01T15:08:31","BLE":{"scans":92,"adverts":13338,"devices":4,"resets":0}}
15:08:38.488 EQ3 poll cycle starting
15:08:38.493 EQ3 EQ3Fabio: Op queued len now 1
15:08:38.497 EQ3 EQ3Fabio:Op dequeued len now 0
15:08:41.501 MQT: stat/EQ3/EQ3Fabio = {"cmd":"poll","result":"ok","MAC":"001A220BBF0A","tas":"LED-Hausflur-7916","RSSI":-89,"stattime":1667311721,"temp":17.0,"posn":0,"mode":"auto","hassmode":"auto","boost":"inactive","dst":"set","window":"closed","state":"unlocked","battery":"GOOD","holidayend":"00-00-00 00:00","windowtemp":12.0,"windowdur":15,"day":20.0,"night":17.5,"offset":0.0}
15:08:41.550 MQT: tele/LED-Hausflur/BLE = {"BLEOperation":{"opid":"7","stat":"7","state":"DONENOTIFIED","MAC":"001A220BBF0A","u":"128","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03160B010F0826000000000000000000","notify":"020108000422000000001803282307"}} (retained)
15:08:47.096 WIF: Checking connection...
15:09:07.097 WIF: Checking connection...
15:09:27.097 WIF: Checking connection...
15:09:47.097 WIF: Checking connection...
15:09:48.500 M32: Dev no longer present MAC: a4c138a7b47e
15:10:07.097 WIF: Checking connection...
15:10:27.101 WIF: Checking connection...
15:10:47.102 WIF: Checking connection...
15:11:07.103 WIF: Checking connection...
15:11:27.103 WIF: Checking connection...
15:11:47.104 WIF: Checking connection...
15:12:07.109 WIF: Checking connection...
15:12:27.111 WIF: Checking connection...
15:12:47.409 WIF: Checking connection...
15:13:07.409 WIF: Checking connection...
15:13:19.416 M32: Kick off readOneSensor
15:13:19.419 M32: Hit tele time, restarted but not finished last - lost from slot 1073562288
15:13:20.427 MQT: tele/tasmota_ble/ATC7bc767 = {"Time":"2022-11-01T15:13:20","mac":"a4c1387bc767","Temperature":17.5,"Humidity":68.4,"DewPoint":11.7,"Btn":1,"Battery":14,"RSSI":-84,"TempUnit":"C"} (retained)
15:13:21.429 MQT: tele/tasmota_ble/ATC_Simon = {"Time":"2022-11-01T15:13:21","alias":"ATC_Simon","mac":"a4c1386b40e8","Temperature":20.8,"Humidity":74.2,"DewPoint":16.1,"Btn":1,"Battery":52,"RSSI":-87,"TempUnit":"C"} (retained)
15:13:27.411 WIF: Checking connection...
15:13:31.416 BRY: GC from 4972 to 3734 bytes, objects freed 4/40 (in 1 ms) - slots from 47/137 to 41/137
15:13:31.421 BRY: GC timing (us) 1:221 2:364 3:190 4:6 5:34 total:815
15:13:31.425 BRY: GC by type string:5 class:0 proto:2 instance:18 map:4 list:1 closure:5 ntvclos:1 module:0 comobj:0
15:13:31.448 MQT: tele/LED-Hausflur/STATE = {"Time":"2022-11-01T15:13:31","Uptime":"0T00:35:13","UptimeSec":2113,"Heap":76,"SleepMode":"Dynamic","Sleep":100,"LoadAvg":10,"MqttCount":1,"Berry":{"HeapUsed":3,"Objects":40},"POWER":"OFF","Dimmer":63,"Fade":"OFF","Speed":1,"LedTable":"ON","Wifi":{"AP":1,"SSId":"ollahMuz","BSSId":"2C:91:AB:9A:FD:8E","Channel":4,"Mode":"11n","RSSI":100,"Signal":-46,"LinkCount":1,"Downtime":"0T00:00:06"}}
15:13:31.501 MQT: tele/LED-Hausflur/BLE = {"Time":"2022-11-01T15:13:31","BLEDevices":{"total":3,"A4C1387BC767":{"i":0,"r":-84},"A4C1386B40E8":{"i":1,"r":-87,"a":"ATC_Simon"},"001A220BBF0A":{"i":2,"r":-89,"a":"EQ3Fabio"}}}
15:13:31.519 MQT: tele/LED-Hausflur/BLE = {"Time":"2022-11-01T15:13:31","BLE":{"scans":107,"adverts":15416,"devices":3,"resets":0}}
15:13:38.445 EQ3 poll cycle starting
15:13:38.448 EQ3 EQ3Fabio: Op queued len now 1
15:13:38.451 EQ3 EQ3Fabio:Op dequeued len now 0
15:13:41.457 MQT: stat/EQ3/EQ3Fabio = {"cmd":"poll","result":"ok","MAC":"001A220BBF0A","tas":"LED-Hausflur-7916","RSSI":-89,"stattime":1667312021,"temp":17.0,"posn":0,"mode":"auto","hassmode":"auto","boost":"inactive","dst":"set","window":"closed","state":"unlocked","battery":"GOOD","holidayend":"00-00-00 00:00","windowtemp":12.0,"windowdur":15,"day":20.0,"night":17.5,"offset":0.0}
15:13:41.507 MQT: tele/LED-Hausflur/BLE = {"BLEOperation":{"opid":"8","stat":"7","state":"DONENOTIFIED","MAC":"001A220BBF0A","u":"128","svc":"3e135142-654f-9090-134a-a6ff5bb77046","char":"3fa4585a-ce4a-3bad-db4b-b8df8179ea09","notifychar":"d0e8434d-cd29-0996-af41-6c90f4e0eb2a","write":"03160B010F0D26000000000000000000","notify":"020108000422000000001803282307"}} (retained)
15:13:47.360 WIF: Checking connection...
15:14:07.362 WIF: Checking connection... ```

And why this shall lead to a reset .... ?

Jason2866 commented 2 years ago

Good, and now switch off the AP, and post the log where the esp32 resets.

Micha70 commented 2 years ago

Ok, and how I get the log, if AP is off? I don't have any connection... :confused:

barbudor commented 2 years ago

Over serial as it is a devkit

Micha70 commented 2 years ago

logging is working now, but after some time I get

00:09:56.906 WIF: Connecting to AP2 ollahMuz_K in mode 11n as LED-Hausflur-test-6584...
00:09:57.810 WIF: Checking connection...
00:09:57.814 WIF: Attempting connection...
00:09:58.810 WIF: Checking connection...
00:09:58.814 WIF: Attempting connection...
00:09:58.818 APP: Serial logging disabled

I found in documentation: "SerialLog will be disabled automatically 10 minutes after the device reboots." Is there any way to prevent this?

barbudor commented 2 years ago

There might be different ways The one I'm using is a rule such as On time#minute|5 do SerialLog 3 endon

Micha70 commented 2 years ago

ahhh, figured out that logging disabled appeared due to a restart. So seem I have catched the unintendet restart:

11:59:53.054 WIF: Checking connection...
11:59:53.058 WIF: Attempting connection...
11:59:53.372 WIF: Retry set Mode...
11:59:53.486 WIF: Retry set Mode...
11:59:53.640 WIF: Connecting to AP2 ollahMuz_K in mode 11  as LED-Hausflur-test-6584...
11:59:54.551 APP: Restarting
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:184
load:0x40078000,len:12588
ho 0 tail 12 room 4
load:0x40080400,len:2916
entry 0x400805c4

00:00:00.003 HDW: ESP32-D0WDQ6 
00:00:00.089 UFS: FlashFS mounted with 304 kB free
00:00:00.191 CFG: Loaded from File, Count 86
00:00:00.206 QPC: Count 1
00:00:00.208 CFG: CR 439/699, Busy 0

00:00:00.214 ROT: Mode 1
00:00:00.228 BRY: GC from 3819 to 3049 bytes, objects freed 5/20 (in 1 ms) - slots from 35/61 to 23/61
00:00:00.229 BRY: GC timing (us) 1:163 2:143 3:124 4:5 5:30 total:465
00:00:00.240 BRY: GC by type string:6 class:0 proto:3 instance:0 map:3 list:1 closure:1 ntvclos:0 module:0 comobj:0
00:00:00.472 CFG: No '*.autoconf' file found
00:00:00.477 BRY: GC from 4751 to 4041 bytes, objects freed 5/42 (in 1 ms) - slots from 61/91 to 41/91
00:00:00.478 BRY: GC timing (us) 1:190 2:286 3:477 4:5 5:31 total:989
00:00:00.490 BRY: GC by type string:6 class:0 proto:3 instance:18 map:4 list:1 closure:4 ntvclos:0 module:0 comobj:0
00:00:00.501 BRY: Berry initialized, RAM used=4041 bytes
00:00:00.522 BRY: No 'preinit.be'
00:00:00.525 SRC: Restart
00:00:00.530 Project tasmota - LED-Neu-test Version 12.2.0.2(bluetooth)-2_0_5_2(2022-10-31T16:56:52)
00:00:00.532 iBeacon register for advert callbacks
00:00:00.543 MI32Option0: 1
00:00:00.544 MI32Option1: 0
00:00:00.545 MI32Option2: 0
00:00:00.546 MI32Option4: 1
00:00:00.546 MI32Option5: 0
00:00:00.547 MI32Option6: 0
00:00:00.558 M32: init: request callbacks
00:00:00.743 BRY: No 'autoexec.be'
00:00:00.058 WIF: Checking connection...
00:00:00.059 WIF: Attempting connection...
00:00:01.335 WIF: Connecting to AP2 ollahMuz_K in mode 11n as LED-Hausflur-test-6584...
00:00:02.393 WIF: Checking connection...
00:00:02.394 WIF: Attempting connection...
00:00:03.393 WIF: Checking connection...

barbudor commented 2 years ago

Interresting, that seems to be tasmota deciding to restart Are you sure you are in WifiConfig 5?

When did the AP was shutdown? Just before the restart or long before?

Jason2866 commented 2 years ago

This Connecting to AP2 ollahMuz_K in mode 11 as does mean AP could not be reached and there is no wifi mode set. Dunno why this results in a restart. Normally this should result in a retry when wificonfig 4 or 5 is set.

Next question why Tasmota tries to connect to AP2? Please configure your device with ONLY one AP set in configuration and use wificonfig 5

Micha70 commented 2 years ago

Yes sure , wificonfig 5. The AP was shutdown almost 2:45h before the reset.

Micha70 commented 2 years ago

And during the shutdown phase each few seconds appears a retry. If needed I can upload complete trace of these about 3h...

barbudor commented 2 years ago

Those are normal when wifi is down:

00:00:02.394 WIF: Attempting connection...
00:00:03.393 WIF: Checking connection...

What I'm curious is those:

11:59:53.372 WIF: Retry set Mode...
11:59:53.486 WIF: Retry set Mode...

Do they occur as soon as the AP is down ? or only after some time ? or just before the restart ? You can attach the whole file if you want

Micha70 commented 2 years ago

Ok just short explanation. Logfile starts during disconnected AP. At 09:41:07.549 AP is again available. You see also at 09:41:54.836 WifiConfig is 5. At 09:42 AP was finally disconnected and at 11:59:54.551 gots the reset....

20221102_logfile_ESP32reset.txt

barbudor commented 2 years ago

Since the AP goes off, hep is continuously decreasing from 72 to 16 (pretty low) at 11:31:21.882 Then next teleperiod at 11:36:21.926, heap is back at 35 and stay there until it restarts Any idea what happened between 11:31 and 11:36 that explain why the heap get back to 35

Does Tasmota reconnects to Wifi when it gets on again ?

As you have a lot of stuff going on (bluetooth, EQ3, Berry), I would suggest to try to disable some and see if the problem can be narrowed to one of them because for now I see no real clue

Micha70 commented 2 years ago

Does Tasmota reconnects to Wifi when it gets on again ?

You see at the beginning of the log, AP was off for some minutes. Was switched on again and connected...

I will do today another try with bluetooth off, to see if still reproducible... Btw. can it be an issue, if BT message still received, no connection to MQTT server, that some buffers overflow after some hours.... Just an idea....

Micha70 commented 2 years ago

just a short update ... started again the test with switching off bluetooth (Configure BLE -> Disable Bluetooth + BLEMode0) after more than 3h is still working and heap is at 118

10:55:24.857 WIF: Connecting to AP2 ollahMuz_K in mode 11n as LED-Hausflur-test-6584...
10:55:24.867 BRY: GC from 4276 to 3734 bytes, objects freed 2/40 (in 1 ms) - slots from 47/137 to 41/137
10:55:24.871 BRY: GC timing (us) 1:232 2:324 3:163 4:6 5:31 total:756
10:55:24.887 BRY: GC by type string:5 class:0 proto:2 instance:18 map:4 list:1 closure:5 ntvclos:1 module:0 comobj:0
10:55:24.893 RSL: STATE = {"Time":"2022-11-03T10:55:24","Uptime":"0T03:05:10","UptimeSec":11110,"Heap":118,"SleepMode":"Dynamic","Sleep":100,"LoadAvg":9,"MqttCount":1,"Berry":{"HeapUsed":3,"Objects":40},"POWER":"OFF"}
10:55:24.929 RSL: BLE = {"Time":"2022-11-03T10:55:24","BLEDevices":{"total":0}}
10:55:24.937 RSL: BLE = {"Time":"2022-11-03T10:55:24","BLE":{"scans":7,"adverts":919,"devices":0,"resets":0}}

I will keep it running for further two hours ....

Micha70 commented 2 years ago

After 5h no reset seen... Seems has something to do with Bluetooth/BLE...

Micha70 commented 2 years ago

I'm using now this rule as temporary solution. Switches off BLE during periode if no WiFi connection is available and on again after reconnection.

Rule1 ON Wifi#Disconnected DO BLEMode0 ENDON ON Wifi#Connected DO BLEMode2 ENDON
Rule1 1
Rule 4

Until now no reset anymore detected and no stuck.

Jason2866 commented 1 year ago

@Micha70 Closed since Tasmota is not designed to be used without working wifi. You found a workaround solution. The probably responsible BT code part is not in Tasmota.

arendst / Tasmota