WiFi Connection Lost Repeatedly

[SillyHats]

Somewhere between every few hours to once per day the tilt bridge loses connection to the wifi (WPA2) for multiple hours. Other devices on the network do not seem to have the same issue. When I push the reboot button on the device it reconnects immediately upon reboot.

I have tried using the Arduio IDE serial port monitor, but it outputs gibberish characters. When I try to run the serial port monitor using Visual Studio Code with Platform IO installed I get the following error message.

Executing task: C:\Users\you.platformio\penv\Scripts\platformio.exe device monitor <

--- Available filters and text transformations: colorize, debug, default, direct, esp32_exception_decoder, hexlify, log2file, nocontrol, printable, send_on_enter, time --- More details at http://bit.ly/pio-monitor-filters --- forcing DTR active --- forcing RTS active Error: [WinError 2] The system cannot find the file specified The terminal process "C:\Users\you.platformio\penv\Scripts\platformio.exe 'device', 'monitor'" terminated with exit code: 1.

Is there a guide somewhere I can follow to get the serial port monitor in Visual Studio/Platform IO working or another, correct way to diagnose what is going on?

The Tilt Bridge has lost connection to your WiFi. Attempting to reconnect...

using TTGO USB-C with v1.0.2 from brewflasher (web interface about page says 1.0.1)

[lbussy]

The error you are receiving in PIO looks to be because of a missing driver. You might give a search for that. The baud rate is 115200, which may address your gibberish.

Other than that - all I can say is the antennas on these are not optimized. If you reset the wifi (the top button) and then pay attention to the signal strength when you re-set it, it may give you a clue.

[SillyHats]

Thanks for the tips. The baud rate fixed the gibberish. I'll update with the monitor log after it loses connection next.

[SillyHats]

Here we have it. Thanks for taking a look. tiltbridge-log_sheets.txt

I noticed that when the tiltbridge is running without a sheet name to log to the "Frag" paramater in the log stays much lower at 31% tiltbridge-log_nosheet.txt

[lbussy]

Yeah, the more you do the more memory it uses. That said, I am doing exactly the same thing without this issue.

Did you try resetting the WiFi credentials, going through the connection workflow, and seeing what the dB rating is for your access point?

[SillyHats]

I just tried resetting the wifi credentials while connected to the serial monitor. The tilt bridge is very close to the access point and this graphical representation of signal strength is shown for my network and a soft network I setup for testing before I choose one and connect.

I just found this part of the log showing ap signal strength for my network with duplicates shown for the mesh routers. 07:39:45.726 -> WM: [2] DUP AP: SSID 07:39:45.726 -> WM: [2] DUP AP: SSID 07:39:45.726 -> WM: [2] DUP AP: SSID 07:39:45.726 -> WM: [2] DUP AP: SSID 07:39:45.726 -> WM: [2] AP: -42 SSID 07:39:45.726 -> WM: [2] AP: -44 Soft_SSID

[lbussy]

Yes, that's it. -42 is very good.

Is it possible that something weird like cooling starting on the fridge is knocking it out?

[SillyHats]

During the test for the attached log above the tilt was in a bucket of water next to the bridge away from any fridge.

I thought it might be related to the my AP having spaces in the password, but testing with the soft AP with no spaces in the password had a similar result. Would the Dup AP due to mesh wifi system cause trouble for the bridge to pick one to reconnect to?

[SillyHats]

Here's another log from after clearing the wifi settings and reconnecting in the post above.

new-log.txt

[lbussy]

I am reasonably sure this is just more silliness between WiFi and Bluetooth - which use the same radio. Unfortunately, this is all either in 3rd party libs or (worse yet) in the core.

I had been looking at a little more aggressive reboots in the case of issues like this, along with a generic 24-hour reboot just for everything else. I'll look into that.

[lbussy]

The change which reboots if unable to rejoin the network, a well was a general-purpose 24-hour reboot has been pushed to devel. There are a few other changes pending in devel so this will get done when @thorrak gets around to it next.

[SillyHats]

Thanks for loading the dev branch into the alpha label in brewflasher. I loaded the TTGO alpha and the serial monitor log is much less verbose than the main branch was, but the reboot on disconnect seems to be functioning bandaid for now. It is now rebooting a lot rather than disconnecting a lot. Checking on the about page in the local web interface periodically I haven't seen uptime get over 15 minutes.

ttgoalphalog.txt

[lbussy]

Well that's a crapton more than I was getting. I think John is turning off the logging because I thought I left it on.

What targets/configuration are you using? Maybe there's a combination that works especially poorly.

[SillyHats]

After loading the beta build the only thing I did was connect to wifi, change offset to -4, and setup a link to a google sheet to see if the reboot solution enabled a continuous stream of data points in between reboots.

[lbussy]

Well, here's what I have:

The commit will not be the same but it should be the same code. That suggests your WiFi coverage there is really spotty, or there's something else interfering. Do you have the ability to capture any logs on your AP?

[SillyHats]

The TTGO board is still near the main router of a mesh network. Here's the relevant log entries from the router:

Apr 1 14:09:17 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-alpha-mac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0 Apr 1 14:09:18 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-alpha-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0 Apr 1 14:09:20 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-alpha-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0 Apr 1 15:37:43 syslog: wlceventd_proc_event(526): eth1: Auth tiltbridge-alpha-mac, status: Successful (0), rssi:0 Apr 1 15:37:43 syslog: wlceventd_proc_event(555): eth1: Assoc tiltbridge-alpha-mac, status: Successful (0), rssi:0 Apr 1 15:41:37 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-alpha-mac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0 Apr 1 15:42:01 syslog: wlceventd_proc_event(507): eth1: Disassoc tiltbridge-alpha-mac, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0

[lbussy]

That's weird ... you don't have someone firing off a deauther nearby do you? :P

How about the power supply. It's a longshot but have you tried a different one?

[SillyHats]

I don't have my deauther powered up. I'm not aware of anyone in the area who knows what that is. It also seems unlikely to only be deauthing these two TTGO boards and no other devices.

I've had the same result with a few different power supplies, including powering the board off a pc usb port in order to capture the logs.

[lbussy]

This is generally where I throw my hands up and page out my network engineers to run a sniffer. It's weird.

I can see about putting a debug version on BrewFlasher with more logging enabled. Maybe that will help diagnose the issue. I'd probably have to enable core logging and that would be VERY chatty.

[lbussy]

I put an Alpha out there with significantly increased logging:

There will be a metric crapton of BLE debug. Unfortunately, the lib does not respect its own logging levels and if I turn on core, it turns that on. Easy enough to filter out the ones that contain "NimBLEScan:" though.

You should see some correlation at the drops between your AP and the core WiFi lib debug. Hopefully. I've got it set for WARN level, hopefully that's enough.

[SillyHats]

I had a feeling the mesh nodes with overlapping signals with the same network names was confusing the esp32, even though I haven't seen any other device have such problems including a couple esp8266 running different bits of code and this same esp32 previously running tilt simulator. I created a test guest network that did not replicate across the nodes. The log below shows the output of the main branch serial monitor since the dev does not show as much. I now have one each connected to the test network on main and dev.

18:34:48.633 -> WM: [1] 10 networks found 18:34:48.633 -> WM: [2] DUP AP: main-network-node 18:34:48.633 -> WM: [2] DUP AP: main-network-node 18:34:48.633 -> WM: [2] DUP AP: main-network-node 18:34:48.633 -> WM: [2] DUP AP: main-network-node 18:34:48.633 -> WM: [2] AP: -45 main-network 18:34:48.633 -> *WM: [2] AP: -45 test-network-singular

It appears they are no longer getting disconnected as much/at all. This appears to be pointing towards a confusion between the nodes by the wifi library.

I'll give the extra logging alpha a go next.

[SillyHats]

There's a couple of reboots in there at lines 1254 & 1517. I removed all the log entries containing NimBLEScan using the regular expression search ^.\b(NimBLEScan)\b.$\r?\n in find and replace with replace blank. chatty-log.txt

[lbussy]

This one:

21:01:16.933 ->    4041978 V: Serving reset reason.
21:01:16.979 -> abort() was called at PC 0x400863b9 on core 0
21:01:16.979 -> 
21:01:16.979 -> ELF file SHA256: 0000000000000000
21:01:16.979 -> 
21:01:16.979 -> Backtrace: 0x4008f710:0x3ffbf620 0x4008f98d:0x3ffbf640 0x400863b9:0x3ffbf660 0x400864e5:0x3ffbf690 0x401132af:0x3ffbf6b0 0x4010b075:0x3ffbf970 0x4010afd1:0x3ffbf9c0 0x400e6f0f:0x3ffbf9f0 0x401c276a:0x3ffbfa20 0x401b3dde:0x3ffbfa40 0x4001791d:0x3ffbfa60 0x401b4585:0x3ffbfa80 0x401b4662:0x3ffbfac0 0x400188f5:0x3ffbfaf0 0x401b4017:0x3ffbfb30 0x400175ee:0x3ffbfb50 0x40017688:0x3ffbfb70 0x4008ee92:0x3ffbfba0 0x4008f067:0x3ffbfbc0 0x401b3d8b:0x3ffbfbe0 0x4008f084:0x3ffbfc00 0x40083759:0x3ffbfc20 0x400885b7:0x3ffb9d00 0x4008ee39:0x3ffb9d20 0x401c2909:0x3ffb9d40 0x401a46fc:0x3ffb9d60 0x400e6d05:0x3ffb9d80 0x40082283:0x3ffb9da0 0x4009098e:0x3ffb9dc0
21:01:16.979 -> 
21:01:16.979 -> Rebooting...

... is because you left it on the "About" screen. Yes, ironically enough, that screen highlights an issue with WiFi and BLE. The TTGO is better in this respect than the larger TFT, but it still happens.

This one:

21:07:57.419 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
21:07:57.419 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
21:08:02.839 -> E (406135) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
21:08:02.839 -> E (406135) task_wdt:  - IDLE0 (CPU 0)
21:08:02.839 -> E (406135) task_wdt: Tasks currently running:
21:08:02.839 -> E (406135) task_wdt: CPU 0: esp_timer
21:08:02.839 -> E (406135) task_wdt: CPU 1: loopTask
21:08:02.839 -> E (406135) task_wdt: Aborting.
21:08:02.839 -> abort() was called at PC 0x4011b53c on core 0
21:08:02.839 -> 
21:08:02.839 -> ELF file SHA256: 0000000000000000
21:08:02.839 -> 
21:08:02.839 -> Backtrace: 0x4008f710:0x3ffbfbc0 0x4008f98d:0x3ffbfbe0 0x4011b53c:0x3ffbfc00 0x40083759:0x3ffbfc20 0x40102746:0x3ffb77a0 0x4010328f:0x3ffb77c0 0x401c4dbd:0x3ffb77f0 0x400d2e98:0x3ffb7810 0x400d2fe1:0x3ffb7830 0x400d3021:0x3ffb7850 0x400dcc37:0x3ffb7870 0x4011d88e:0x3ffb7890 0x4011d903:0x3ffb78b0 0x4009098e:0x3ffb78d0
21:08:02.839 -> 
21:08:02.839 -> Rebooting...

Seems more like the de-auth issue. Does that correlate with what you see in your AP logs?

[SillyHats]

The AP log doesn't persist long enough to go back to that point. Here it is running again with both logs from the time STA_DISCONNECTED shows up in the tiltbridge log.

AP Log

Apr  2 11:02:59 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-mac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  2 11:03:00 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 11:03:00 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 11:03:00 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 11:03:00 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 11:03:00 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 11:03:00 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0

tiltbridge-chatty log

11:03:03.062 ->    6726455 V: Free Heap: 135728, Largest contiguous block: 51752, Frag: 62%
11:03:06.379 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
11:03:06.379 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
11:03:26.480 -> ....   6750219 E: Unable to reconnect WiFI, restarting.
11:03:27.817 -> ets Jul 29 2019 12:21:46
11:03:27.817 -> 
11:03:27.817 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
11:03:27.817 -> configsip: 0, SPIWP:0xee
11:03:27.817 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
11:03:27.817 -> mode:DIO, clock div:2
11:03:27.817 -> load:0x3fff0018,len:4
11:03:27.817 -> load:0x3fff001c,len:1044
11:03:27.817 -> load:0x40078000,len:10044
11:03:27.817 -> load:0x40080400,len:5872
11:03:27.817 -> entry 0x400806ac
11:03:28.423 -> 
11:03:28.423 ->         31 N: Serial logging started at 115200.
11:03:28.423 ->         33 V: Loading config.
11:03:28.518 -> [W][SPIFFS.cpp:71] begin(): SPIFFS Already Mounted!
11:03:28.618 ->        217 V: Initializing LCD.
11:03:29.173 ->        792 V: Initializing WiFi.
11:03:29.173 -> *wm:[2] Added Parameter: mdns
11:03:29.173 -> *wm:[1] AutoConnect 
11:03:29.312 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
11:03:29.312 -> *wm:[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
11:03:29.312 -> [2] WiFiSetCountry to US
11:03:29.312 -> *wm:[2] [OK] esp_wifi_set_country:  US
11:03:29.312 -> *wm:[2] ESP32 event handler enabled 
11:03:29.546 -> *wm:[2] Connecting as wifi client... 
11:03:29.546 -> *wm:[2] setSTAConfig static ip not set, skipping 
11:03:29.546 -> *wm:[1] Connecting to SAVED AP: MeshAP
11:03:30.015 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
11:03:31.418 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 4 - STA_CONNECTED
11:03:31.467 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 7 - STA_GOT_IP
11:03:31.467 -> [D][WiFiGeneric.cpp:419] _eventCallback(): STA IP: 000.000.000.000, MASK: 000.000.000.000, GW: 000.000.000.000
11:03:31.512 -> *wm:[2] Connection result: WL_CONNECTED
11:03:31.512 -> *wm:[1] AutoConnect: SUCCESS 
11:03:31.512 -> *wm:[1] STA IP Address: 000.000.000.000
11:03:31.558 ->       3189 V: Initializing scanner.
11:03:31.745 -> I NimBLEDevice: "BLE Host Task Started"
11:03:31.791 -> I NimBLEDevice: "NimBle host synced."
11:03:34.885 ->       6506 N: HTTP server started. Open: http://tiltbridge-chatty.local/ to view application.

Back to AP Log

Apr  2 11:03:30 syslog: wlceventd_proc_event(526): eth1: Auth tiltbridge-mac, status: Successful (0), rssi:0
Apr  2 11:03:33 syslog: wlceventd_proc_event(555): eth1: Assoc 3tiltbridge-mac, status: Successful (0), rssi:0

[lbussy]

11:03:06.379 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED

I'll have to see if I can get a callback on that one.

[SillyHats]

While that first set of logs in my last post shows the tiltbridge-chatty bouncing between AP nodes and not reauthenticating the other board on the last main branch release has been sitting on a non-mesh SSID for longer than I have seen before.

[SillyHats]

Here's another instance

Apr  2 12:17:49 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:17:49 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:17:49 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:17:49 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:18:09 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:18:09 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:18:09 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:18:09 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:18:09 syslog: wlceventd_proc_event(490): eth1: Deauth_ind tiltbridge-chatty-mac, status: 0, reason: Class 3 frame received from nonassociated station (7), rssi:0
Apr  2 12:24:16 syslog: wlceventd_proc_event(526): eth1: Auth tiltbridge-chatty-mac, status: Successful (0), rssi:0
Apr  2 12:24:16 syslog: wlceventd_proc_event(555): eth1: Assoc tiltbridge-chatty-mac, status: Successful (0), rssi:0

12:18:04.992 ->    4476509 V: Free Heap: 137060, Largest contiguous block: 52368, Frag: 62%
12:18:10.752 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
12:18:10.752 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
12:18:31.732 -> .   4503275 E: Unable to reconnect WiFI, restarting.
12:18:32.810 -> ets Jul 29 2019 12:21:46
12:18:32.810 -> 
12:18:32.810 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
12:18:32.810 -> configsip: 0, SPIWP:0xee
12:18:32.810 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
12:18:32.810 -> mode:DIO, clock div:2
12:18:32.810 -> load:0x3fff0018,len:4
12:18:32.810 -> load:0x3fff001c,len:1044
12:18:32.810 -> load:0x40078000,len:10044
12:18:32.810 -> load:0x40080400,len:5872
12:18:32.810 -> entry 0x400806ac
12:18:33.374 -> 
12:18:33.422 ->         31 N: Serial logging started at 115200.
12:18:33.422 ->         33 V: Loading config.
12:18:33.469 -> [W][SPIFFS.cpp:71] begin(): SPIFFS Already Mounted!
12:18:33.562 ->        217 V: Initializing LCD.
12:18:34.174 ->        792 V: Initializing WiFi.
12:18:34.174 -> *wm:[2] Added Parameter: mdns
12:18:34.174 -> *wm:[1] AutoConnect 
12:18:34.316 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
12:18:34.316 -> *wm:[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
12:18:34.316 -> [2] WiFiSetCountry to US
12:18:34.316 -> *wm:[2] [OK] esp_wifi_set_country:  US
12:18:34.316 -> *wm:[2] ESP32 event handler enabled 
12:18:34.504 -> *wm:[2] Connecting as wifi client... 
12:18:34.504 -> *wm:[2] setSTAConfig static ip not set, skipping 
12:18:34.504 -> *wm:[1] Connecting to SAVED AP: MeshAP
12:18:35.018 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
12:18:36.559 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 4 - STA_CONNECTED
12:18:36.559 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 7 - STA_GOT_IP
12:18:36.559 -> [D][WiFiGeneric.cpp:419] _eventCallback(): STA IP: 000.000.000.000, MASK: 000.000.000.000, GW: 000.000.000.000
12:18:36.605 -> *wm:[2] Connection result: WL_CONNECTED
12:18:36.605 -> *wm:[1] AutoConnect: SUCCESS 

12:23:39.980 ->     306615 V: Free Heap: 138420, Largest contiguous block: 97392, Frag: 30%
12:23:51.936 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
12:23:51.936 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
12:24:12.618 -> ..    339377 E: Unable to reconnect WiFI, restarting.
12:24:13.788 -> ets Jul 29 2019 12:21:46
12:24:13.788 -> 
12:24:13.788 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
12:24:13.788 -> configsip: 0, SPIWP:0xee
12:24:13.788 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
12:24:13.788 -> mode:DIO, clock div:2
12:24:13.788 -> load:0x3fff0018,len:4
12:24:13.788 -> load:0x3fff001c,len:1044
12:24:13.788 -> load:0x40078000,len:10044
12:24:13.788 -> load:0x40080400,len:5872
12:24:13.788 -> entry 0x400806ac
12:24:14.359 -> 
12:24:14.359 ->         31 N: Serial logging started at 115200.
12:24:14.359 ->         33 V: Loading config.
12:24:14.443 -> [W][SPIFFS.cpp:71] begin(): SPIFFS Already Mounted!
12:24:14.536 ->        217 V: Initializing LCD.
12:24:15.142 ->        792 V: Initializing WiFi.
12:24:15.142 -> *wm:[2] Added Parameter: mdns
12:24:15.142 -> *wm:[1] AutoConnect 
12:24:15.282 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
12:24:15.282 -> *wm:[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
12:24:15.282 -> [2] WiFiSetCountry to US
12:24:15.282 -> *wm:[2] [OK] esp_wifi_set_country:  US
12:24:15.282 -> *wm:[2] ESP32 event handler enabled 
12:24:15.470 -> *wm:[2] Connecting as wifi client... 
12:24:15.470 -> *wm:[2] setSTAConfig static ip not set, skipping 
12:24:15.470 -> *wm:[1] Connecting to SAVED AP: MeshAP
12:24:15.983 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
12:24:17.484 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 4 - STA_CONNECTED
12:24:17.577 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 7 - STA_GOT_IP
12:24:17.577 -> [D][WiFiGeneric.cpp:419] _eventCallback(): STA IP: 000.000.000.000, MASK: 000.000.000.000, GW: 000.000.000.000
12:24:17.577 -> *wm:[2] Connection result: WL_CONNECTED
12:24:17.577 -> *wm:[1] AutoConnect: SUCCESS 

[lbussy]

Just dropping notes here:

Can set up an event handler with WiFi.onEvent(WiFiEvent); Then, in the event handler I can scan for which WiFiEvent_t (which in WiFiType.h points to system_event_id_t in esp_event_legacy.h):

https://github.com/espressif/esp-idf/blob/1cb31e50943bb757966ca91ed7f4852692a5b0ed/components/esp_event/include/esp_event_legacy.h#L29-L62

There is no status for deauthed, the best we can do is SYSTEM_EVENT_STA_DISCONNECTED which is no better than what we are doing now checking for a disconnect via timer.

Long story short: Need to figure out why wifisetup.cpp::reconnectWiFi() is not working when we get deauthed.

[negativekelvin]

You are relying on arduino's autoreconnect which only is triggered in certain cases which does not include Reason: 7 - NOT_ASSOCED.

https://github.com/espressif/arduino-esp32/blob/5502879a5b25e5fff84a7058f448be481c0a1f73/libraries/WiFi/src/WiFiGeneric.cpp#L829-L835

You should request changes to arduino-esp32 or use a callback to handle the event separately

[SillyHats]

@lbussy @thorrak I am looking at the new issue form for the file linked by negativekelvin and want to make sure that I get the details right in requesting Reason: 7 - NOT_ASSOCED be added as a trigger for autoreconnect. What are the correct values for the categories below?

Board: ttgo_oled Core Installation version: ?1.0.0? ?1.0.1-rc4? ?1.0.1? ?1.0.1-git? ?1.0.2? ?1.0.3? IDE name: Platform.io Flash Frequency: ?40Mhz? PSRAM enabled: ?no? ?yes? Upload Speed: 115200 Computer OS: Windows 10

[lbussy]

@SillyHats I installed a callback that might work, but even if it does not there's a fair chance the additional debug should give me an idea which way to go. Sorry to keep experimenting on you but I am unaware of how to replicate this (unless I flash a deauther? That will kill my house though.)

Go ahead and flash the same named firmware and you should pick it up.

[SillyHats]

I appreciate all the help. I'm glad to test possible solutions. Speaking of deauthers, if you have an extra esp8266 around I think you can use the web interface to target a specific network device, in this case a testing tiltbridge.

I just reflashed the TTGO alpha from brewflasher and connected it back to the main mesh network with the serial port monitor running.

[lbussy]

I didn't know I could target a single device; good to know.

I might have 30-40 extra controllers lying about. Should be able to find one. 😃

[SillyHats]

Now with more logs! And an extra scoop of raisins! and a bonus squirt of mesquite!

tiltbridge

19:37:42.740 -> ets Jul 29 2019 12:21:46
19:37:42.740 -> 
19:37:42.740 -> rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
19:37:42.740 -> configsip: 0, SPIWP:0xee
19:37:42.740 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
19:37:42.740 -> mode:DIO, clock div:2
19:37:42.740 -> load:0x3fff0018,len:4
19:37:42.740 -> load:0x3fff001c,len:1044
19:37:42.740 -> load:0x40078000,len:10044
19:37:42.740 -> load:0x40080400,len:5872
19:37:42.740 -> entry 0x400806ac
19:37:43.345 -> 
19:37:43.345 ->         32 N: Serial logging started at 115200.
19:37:43.345 ->         33 V: Loading config.
19:37:43.439 -> [W][SPIFFS.cpp:71] begin(): SPIFFS Already Mounted!
19:37:43.486 ->        199 V: Initializing LCD.
19:37:44.091 ->        773 V: Initializing WiFi.
19:37:44.091 -> *wm:[2] Added Parameter: mdns
19:37:44.091 -> *wm:[1] AutoConnect 
19:37:44.231 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
19:37:44.231 -> *wm:[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
19:37:44.231 -> [2] WiFiSetCountry to US
19:37:44.231 -> *wm:[2] [OK] esp_wifi_set_country:  US
19:37:44.231 -> *wm:[2] ESP32 event handler enabled 
19:37:44.418 -> *wm:[2] Connecting as wifi client... 
19:37:44.418 -> *wm:[2] setSTAConfig static ip not set, skipping 
19:37:44.418 -> *wm:[1] Connecting to SAVED AP: MeshAP
19:37:44.935 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
19:37:47.317 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 4 - STA_CONNECTED
19:37:47.411 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 7 - STA_GOT_IP
19:37:47.411 -> [D][WiFiGeneric.cpp:419] _eventCallback(): STA IP: 000.000.000.000, MASK: 000.000.000.000, GW: 000.000.000.000
19:37:47.458 -> *wm:[2] Connection result: WL_CONNECTED
19:37:47.458 -> *wm:[1] AutoConnect: SUCCESS 
19:37:47.458 -> *wm:[1] STA IP Address: 000.000.000.000
19:37:47.504 ->       4178 V: Initializing scanner.
19:37:47.643 -> I NimBLEDevice: "BLE Host Task Started"
19:37:47.689 -> I NimBLEDevice: "NimBle host synced."
19:37:50.805 ->       7492 N: HTTP server started. Open: http://tiltbridge-chatty2.local/ to view application.
19:37:52.065 ->       8763 V: Serving Tilt JSON.
19:38:02.786 ->      19495 V: Serving Tilt JSON.
19:38:12.825 ->      29522 V: Serving Tilt JSON.
19:38:20.823 ->      37495 V: Free Heap: 138028, Largest contiguous block: 94636, Frag: 32%
19:38:22.787 ->      39467 V: Serving Tilt JSON.
19:38:32.819 ->      49498 V: Serving Tilt JSON.
19:38:44.314 ->      60983 V: Serving Tilt JSON.
19:38:49.167 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:38:50.805 ->      67495 V: Free Heap: 137576, Largest contiguous block: 94636, Frag: 32%
19:38:53.089 ->      69774 V: Serving Tilt JSON.
19:38:56.680 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:39:02.927 ->      79596 V: Serving Tilt JSON.
19:39:13.348 ->      90027 V: Serving Tilt JSON.
19:39:16.664 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:39:20.813 ->      97495 V: Free Heap: 136900, Largest contiguous block: 94636, Frag: 31%
19:39:22.865 ->      99572 V: Serving Tilt JSON.
19:39:32.891 ->     109603 V: Serving Tilt JSON.
19:39:43.256 ->     119937 V: Serving Tilt JSON.
19:39:46.717 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:39:50.822 ->     127495 V: Free Heap: 136496, Largest contiguous block: 94636, Frag: 31%
19:39:52.917 ->     129585 V: Serving Tilt JSON.
19:40:02.952 ->     139628 V: Serving Tilt JSON.
19:40:12.885 ->     149552 V: Serving Tilt JSON.
19:40:20.811 ->     157495 V: Free Heap: 136348, Largest contiguous block: 94636, Frag: 31%
19:40:22.868 ->     159562 V: Serving Tilt JSON.
19:40:32.911 ->     169613 V: Serving Tilt JSON.
19:40:42.976 ->     179651 V: Serving Tilt JSON.
19:40:50.825 ->     187495 V: Free Heap: 136404, Largest contiguous block: 94636, Frag: 31%
19:40:52.883 ->     189588 V: Serving Tilt JSON.
19:41:02.926 ->     199618 V: Serving Tilt JSON.
19:41:12.944 ->     209652 V: Serving Tilt JSON.
19:41:20.827 ->     217495 V: Free Heap: 136676, Largest contiguous block: 94636, Frag: 31%
19:41:23.016 ->     219696 V: Serving Tilt JSON.
19:41:32.940 ->     229619 V: Serving Tilt JSON.
19:41:42.972 ->     239660 V: Serving Tilt JSON.
19:41:50.808 ->     247495 V: Free Heap: 136764, Largest contiguous block: 94636, Frag: 31%
19:41:52.995 ->     249696 V: Serving Tilt JSON.
19:42:05.835 -> V: Serving Tilt JSON.
19:42:09.006 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:42:12.977 ->     269668 V: Serving Tilt JSON.
19:42:20.802 ->     277495 V: Free Heap: 136324, Largest contiguous block: 94176, Frag: 31%
19:42:23.044 ->     279704 V: Serving Tilt JSON.
19:42:33.075 ->     289741 V: Serving Tilt JSON.
19:42:43.677 ->     300378 V: Serving Tilt JSON.
19:42:46.579 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:42:48.722 ->     305407 V: Serving version.
19:42:49.236 ->     305937 V: Serving uptime.
19:42:49.745 ->     306423 V: Serving heap information.
19:42:50.259 ->     306933 V: Serving reset reason.
19:42:50.819 ->     307495 V: Free Heap: 135352, Largest contiguous block: 93260, Frag: 32%
19:43:08.907 ->     325575 V: Serving Tilt JSON.
19:43:12.086 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:43:12.086 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:43:12.789 ->     329449 V: Serving Tilt JSON.
19:43:15.593 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:43:20.811 ->     337495 V: Free Heap: 134540, Largest contiguous block: 92620, Frag: 32%
19:43:23.050 ->     339728 V: Serving Tilt JSON.
19:43:28.107 -> [W][AsyncTCP.cpp:1027] _poll(): ack timeout 4
19:43:30.495 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
19:43:30.495 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 16 - GROUP_KEY_UPDATE_TIMEOUT
19:43:30.495 ->     347144 V: WiFi event callback: reason code: 16.
19:43:30.495 ->     347156 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
19:43:50.805 ->     367495 V: Free Heap: 136012, Largest contiguous block: 92620, Frag: 32%
19:44:20.819 ->     397495 V: Free Heap: 136224, Largest contiguous block: 92620, Frag: 33%
19:44:50.832 ->     427495 V: Free Heap: 136440, Largest contiguous block: 92620, Frag: 33%
19:45:20.800 ->     457495 V: Free Heap: 136892, Largest contiguous block: 92620, Frag: 33%
19:45:30.453 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 8 - STA_LOST_IP
19:45:30.453 ->     467141 V: WiFi event callback: reason code: 0.
19:45:50.814 ->     487495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:46:20.807 ->     517495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:46:50.800 ->     547495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:47:20.815 ->     577495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:47:50.829 ->     607495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:48:20.835 ->     637495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:48:50.840 ->     667495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:49:20.843 ->     697495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:49:50.845 ->     727495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:50:20.804 ->     757495 V: Free Heap: 136920, Largest contiguous block: 92620, Frag: 33%
19:50:50.846 ->     787495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:51:20.838 ->     817495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:51:50.838 ->     847495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:52:20.808 ->     877495 V: Free Heap: 136920, Largest contiguous block: 92620, Frag: 33%
19:52:50.829 ->     907495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:53:20.839 ->     937495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:53:50.814 ->     967495 V: Free Heap: 136924, Largest contiguous block: 92620, Frag: 33%
19:54:20.814 ->     997495 V: Free Heap: 136920, Largest contiguous block: 92620, Frag: 33%

AP

Apr  8 19:00:59 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:01:25 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:01:25 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:20:53 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:21:18 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:21:18 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:25:22 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:25:22 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:25:22 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:25:28 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:25:28 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:25:28 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:28:24 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:28:24 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:28:24 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:29:16 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:32:35 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:32:35 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:32:38 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: 4-way handshake timeout (f), rssi:0
Apr  8 19:33:43 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:33:43 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:33:45 syslog: wlceventd_proc_event(508): wl0.3: Disassoc tiltbridgemac, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0
Apr  8 19:33:49 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:33:49 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:33:49 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:35:20 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:35:20 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:35:20 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:35:43 syslog: wlceventd_proc_event(508): wl0.3: Disassoc tiltbridgemac, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0
Apr  8 19:35:46 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:35:46 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:35:46 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:35:57 syslog: wlceventd_proc_event(508): wl0.3: Disassoc tiltbridgemac, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0
Apr  8 19:36:01 syslog: wlceventd_proc_event(491): wl0.3: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:36:01 syslog: wlceventd_proc_event(527): wl0.3: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:36:01 syslog: wlceventd_proc_event(556): wl0.3: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:36:18 syslog: wlceventd_proc_event(508): wl0.3: Disassoc tiltbridgemac, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0
Apr  8 19:37:28 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:37:28 syslog: wlceventd_proc_event(556): eth1: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:37:29 kernel: tiltbridgemac not mesh client, can't update it's ip
Apr  8 19:37:29 kernel: tiltbridgemac not mesh client, can't update it's ip
Apr  8 19:37:30 syslog: wlceventd_proc_event(508): eth1: Disassoc tiltbridgemac, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0
Apr  8 19:37:34 syslog: wlceventd_proc_event(491): eth1: Deauth_ind tiltbridgemac, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr  8 19:37:34 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:37:34 syslog: wlceventd_proc_event(556): eth1: Assoc tiltbridgemac, status: Successful (0), rssi:0
Apr  8 19:37:45 syslog: wlceventd_proc_event(508): eth1: Disassoc tiltbridgemac, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0
Apr  8 19:37:45 roamast: [EXAP]Deauth old sta in 0 0: tiltbridgemac
Apr  8 19:37:45 roamast: eth1: disconnect weak signal strength station [tiltbridgemac]
Apr  8 19:37:45 roamast: eth1: remove client [tiltbridgemac] from monitor list

After the above transpired, the display still appears normal but the board is no longer reachable via the web interface on the local ip address.

[lbussy]

Well, I mean it's not fixed but I'm poking the right scab. :)

I won't be able to look at this again till the morning. I have some ideas though.

[lbussy]

@negativekelvin unless I'm really dreaming you had a note about changing the default behavior from WIFI_FAST_SCAN to WIFI_ALL_CHANNEL_SCAN. Have I gone insane or did you post and then remove that? I was digging into that area without a ton of luck since it appears to be handled in the upstream lib (WiFiManager.)

It looks to me that in WiFiSTA.cpp that the default scan_method is WIFI_ALL_CHANNEL_SCAN and the default sort_method is WIFI_CONNECT_AP_BY_SIGNAL.

https://github.com/espressif/arduino-esp32/blob/371f382db7dd36c470bb2669b222adf0a497600d/libraries/WiFi/src/WiFiSTA.cpp#L71-L75

[lbussy]

Okay, @SillyHats go ahead and flash again if you would - the desired effect is that it will recognize the event and reconnect. The actual effect ... you tell me. :)

[SillyHats]

I'm having trouble using brewflasher to get the alpha flashed this time for some reason. I've tried now on a windows 10 computer and a mac. The v1.0.2 flashes as expected (albeit with a significantly longer time on the downloading firmware step), but the alpha just gets to this point and nothing else happens.

Downloading firmware...
Downloaded successfully!

Command: esptool.py --port...

[lbussy]

I probably screwed up the entry in brewflasher. If you want to pull that branch and install manually that will work, or I can fix it when I get home.

[negativekelvin]

@lbussy sorry the default method is WIFI_FAST_SCAN in esp-idf but WIFI_ALL_CHANNEL_SCAN in arduino so it was wrong and I deleted it

[lbussy]

@lbussy sorry the default method is WIFI_FAST_SCAN in esp-idf but WIFI_ALL_CHANNEL_SCAN in arduino so it was wrong and I deleted it

Hey no worries - I thought I had gone insane. :)

[SillyHats]

Is this how I would flash it manually using the bin files in the dev branch? Are the addresses for each bin file shown there correct for the tiltbridge files too?

http://esprtk.wap.sh/tt/t3/flash_bin_file_to_esp32.html

Type | File name | Address Bootloader | _a_0x1000.bin | 0x1000 Partition Table | _b_0x8000.bin | 0x8000 Main File | _c_0x10000.bin | 0x10000 SPIFFS | _d_0x225000.bin | 0x225000

[lbussy]

I think I know what’s wrong, I’m still not home but maybe I can get John to fix it real quick.

-- Lee Bussy

On Fri, Apr 9, 2021 at 6:01 PM, SillyHats @.***> wrote:

Is this how I would flash it manually using the bin files in the dev branch? Are the addresses for each bin file shown there correct for the tiltbridge files too?

http://esprtk.wap.sh/tt/t3/flash_bin_file_to_esp32.html

Type | File name | Address Bootloader | _a_0x1000.bin | 0x1000 Partition Table | _b_0x8000.bin | 0x8000 Main File | _c_0x10000.bin | 0x10000 SPIFFS | _d_0x225000.bin | 0x225000

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.

[lbussy]

Want to try again? He may have fixed it.

[SillyHats]

Thanks for trying, but brewflasher still stops at the esptool.py command line.

[lbussy]

Okay: Fresh version uploaded, tested flashing from Windows:

[SillyHats]

I got the new version running and logging. 🪵

[SillyHats]

tiltbridge

12:01:06.020 ->    4776489 V: Free Heap: 138528, Largest contiguous block: 96360, Frag: 31%
12:01:10.588 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
12:01:10.588 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
12:01:10.588 ->    4781009 V: WiFi event callback: reason code: 7.
12:01:10.588 ->    4781021 E: ERROR:  Lost Association   4781026 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
12:01:21.631 -> D N.imBLEScan: "erase device: 7b:92:c6:69:9d:b8"
12:01:30.655 ->    4801124 E: Unable to reconnect WiFI, restarting.
12:01:31.729 -> ets Jul 29 2019 12:21:46
12:01:31.729 -> 
12:01:31.729 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)

AP

Apr 10 12:01:38 syslog: wlceventd_proc_event(527): eth1: Auth 00:00:00:00:00:00, status: Successful (0), rssi:0
Apr 10 12:01:38 syslog: wlceventd_proc_event(556): eth1: Assoc 00:00:00:00:00:00, status: Successful (0), rssi:0

12:16:59.096 ->       6996 N: HTTP server started. Open: http://tiltbridge-gamma.local/ to view application.
12:17:24.499 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
12:17:24.499 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
12:17:24.499 ->      32386 V: WiFi event callback: reason code: 7.
12:17:24.499 ->      32398 E: ERROR:  Lost Association     32402 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
12:17:28.941 -> ..     36999 V: Free Heap: 139272, Largest contiguous block: 97392, Frag: 31%
12:17:44.617 -> D NimBLES can: "erase device: 4d:b2:2d:7c:cb:46"
12:17:44.617 -> E: Unable to reconnect WiFI, restarting.
12:17:45.929 -> ets Jul 29 2019 12:21:46
12:17:45.929 -> 
12:17:45.929 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)

Apr 10 12:16:28 syslog: wlceventd_proc_event(491): eth1: Deauth_ind 00:00:00:00:00:00, status: 0, reason: Deauthenticated because sending station is leaving (or has left) IBSS or ESS (3), rssi:0
Apr 10 12:16:31 syslog: wlceventd_proc_event(508): eth1: Disassoc 00:00:00:00:00:00, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0

The following instances have no correlated mention of the the tiltbridge mac address in the AP log

12:29:23.608 ->     697096 V: Free Heap: 139276, Largest contiguous block: 97392, Frag: 31%
12:29:47.526 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
12:29:47.526 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
12:29:47.526 ->     721006 V: WiFi event callback: reason code: 7.
12:29:47.526 ->     721019 E: ERROR:  Lost Association    721023 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
12:29:53.361 -> ...    727096 V: Free Heap: 139440, Largest contiguous block: 97392, Frag: 31%
12:30:07.286 -> ....    741120 E: Unable to reconnect WiFI, restarting.

12:37:47.405 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
12:37:47.405 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
12:37:47.405 ->     143897 V: WiFi event callback: reason code: 7.
12:37:47.405 ->     143909 E: ERROR:  Lost Association    143914 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
12:38:00.081 -> ....    156874 V: Free Heap: 139088, Largest contiguous block: 97392, Frag: 30%
12:38:07.484 -> .    164012 E: Unable to reconnect WiFI, restarting.
12:38:08.608 -> ets Jul 29 2019 12:21:46
12:38:08.608 -> 
12:38:08.608 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)

13:08:10.067 ->     367192 V: Free Heap: 139124, Largest contiguous block: 97392, Frag: 30%
13:08:10.769 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
13:08:10.769 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
13:08:10.769 ->     367843 V: WiFi event callback: reason code: 7.
13:08:10.769 ->     367855 E: ERROR:  Lost Association    367860 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
13:08:29.510 -> ..............    387960 E: Unable to reconnect WiFI, restarting.
13:08:31.897 -> ets Jul 29 2019 12:21:46
13:08:31.897 -> 
13:08:31.897 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)

13:08:39.436 ->       6994 N: HTTP server started. Open: http://tiltbridge-gamma.local/ to view application.
13:09:09.451 ->      36996 V: Free Heap: 139264, Largest contiguous block: 97392, Frag: 31%
13:09:26.288 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
13:09:26.288 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
13:09:26.288 ->      53831 V: WiFi event callback: reason code: 7.
13:09:26.288 ->      53844 E: ERROR:  Lost Association     53848 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
13:09:38.852 -> ......     66996 V: Free Heap: 139124, Largest contiguous block: 97392, Frag: 30%
13:09:46.218 -> ..     73947 E: Unable to reconnect WiFI, restarting.
13:09:47.812 -> ets Jul 29 2019 12:21:46
13:09:47.812 -> 
13:09:47.812 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)

14:08:56.250 ->       7449 N: HTTP server started. Open: http://tiltbridge-gamma.local/ to view application.
14:09:26.252 ->      37452 V: Free Heap: 139088, Largest contiguous block: 97392, Frag: 30%
14:09:53.322 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
14:09:53.322 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 7 - NOT_ASSOCED
14:09:53.322 ->      64501 V: WiFi event callback: reason code: 7.
14:09:53.322 ->      64513 E: ERROR:  Lost Association     64518 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
14:09:56.170 -> .     67452 V: Free Heap: 139260, Largest contiguous block: 97392, Frag: 31%
14:10:12.964 -> .....     84617 E: Unable to reconnect WiFI, restarting.
14:10:15.517 -> ets Jul 29 2019 12:21:46
14:10:15.517 -> 
14:10:15.517 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
14:10:15.517 -> configsip: 0, SPIWP:0xee
14:10:15.517 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
14:10:15.517 -> mode:DIO, clock div:2
14:10:15.517 -> load:0x3fff0018,len:4
14:10:15.517 -> load:0x3fff001c,len:1044
14:10:15.517 -> load:0x40078000,len:10044
14:10:15.517 -> load:0x40080400,len:5872
14:10:15.517 -> entry 0x400806ac
14:10:16.079 -> 
14:10:16.079 ->         31 N: Serial logging started at 115200.
14:10:16.079 ->         33 V: Loading config.
14:10:16.172 -> [W][SPIFFS.cpp:71] begin(): SPIFFS Already Mounted!
14:10:16.266 ->        198 V: Initializing LCD.
14:10:16.825 ->        772 V: Initializing WiFi.
14:10:16.825 -> *wm:[2] Added Parameter: mdns
14:10:16.825 -> *wm:[1] AutoConnect 
14:10:16.965 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
14:10:16.965 -> *wm:[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
14:10:16.965 -> [2] WiFiSetCountry to US
14:10:16.965 -> *wm:[2] [OK] esp_wifi_set_country:  US
14:10:16.965 -> *wm:[2] ESP32 event handler enabled 
14:10:17.199 -> *wm:[2] Connecting as wifi client... 
14:10:17.199 -> *wm:[2] setSTAConfig static ip not set, skipping 
14:10:17.199 -> *wm:[1] Connecting to SAVED AP: MeshAP
14:10:17.669 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
14:10:20.238 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 4 - STA_CONNECTED
14:10:27.688 -> *wm:[2] Connection result: WL_IDLE_STATUS
14:10:27.688 -> *wm:[1] AutoConnect: FAILED 
14:10:27.688 -> *wm:[2] Starting Config Portal 
14:10:27.688 -> *wm:[2] AccessPoint set password is VALID 
14:10:27.688 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 3 - STA_STOP
14:10:27.688 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 3 - STA_STOP
14:10:28.721 -> *wm:[2] Disabling STA 
14:10:28.721 -> *wm:[2] Enabling AP 
14:10:28.721 -> *wm:[1] StartAP with SSID:  TiltBridgeAP
14:10:28.721 -> *wm:[2] Starting AP on channel: 1
14:10:28.767 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
14:10:28.767 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 14 - AP_START
14:10:29.281 -> *wm:[1] AP IP address: 192.168.4.1
14:10:29.281 -> *wm:[2] setting softAP Hostname: tiltbridge-gamma
14:10:29.281 -> *wm:[2] WiFiSetCountry to US
14:10:29.281 -> *wm:[2] [OK] esp_wifi_set_country:  US
14:10:29.281 ->      13203 V: Entered config mode: SSID: TiltBridgeAP, IP: 192.168.4.1
14:10:29.328 -> *wm:[1] Starting Web Portal 
14:10:29.328 -> *wm:[2] HTTP server started 
14:10:29.328 -> *wm:[2] Config Portal Running, blocking, waiting for clients... 
14:10:29.328 -> *wm:[2] Portal Timeout In 300 seconds
14:10:46.048 -> *wm:[2] Portal Timeout In 282 seconds
14:11:16.033 -> *wm:[2] Portal Timeout In 252 seconds
14:12:46.041 -> *wm:[2] Portal Timeout In 162 seconds
14:13:16.039 -> *wm:[2] Portal Timeout In 132 seconds
14:13:46.078 -> *wm:[2] Portal Timeout In 102 seconds
14:14:16.062 -> *wm:[2] Portal Timeout In 72 seconds
14:14:46.054 -> *wm:[2] Portal Timeout In 42 seconds
14:15:16.086 -> *wm:[2] Portal Timeout In 12 seconds
14:15:28.748 -> *wm:[1] config portal has timed out 
14:15:28.748 -> *wm:[2] disconnect configportal 
14:15:28.748 -> *wm:[0] [ERROR] disconnect configportal - softAPdisconnect FAILED 
14:15:28.748 -> *wm:[2] restoring usermode STA
14:15:29.774 -> *wm:[2] wifi status: Unknown
14:15:29.774 -> *wm:[2] wifi mode: STA
14:15:29.774 -> *wm:[1] config portal exiting 
14:15:29.774 ->     313694 [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
14:15:29.774 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
14:15:29.774 -> W: Failed to connect and/or hit timeout. Restarting.
14:15:29.821 -> ets Jul 29 2019 12:21:46
14:15:29.821 -> 
14:15:29.821 -> rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
14:15:29.821 -> configsip: 0, SPIWP:0xee
14:15:29.821 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
14:15:29.821 -> mode:DIO, clock div:2
14:15:29.821 -> load:0x3fff0018,len:4
14:15:29.821 -> load:0x3fff001c,len:1044
14:15:29.821 -> load:0x40078000,len:10044
14:15:29.821 -> load:0x40080400,len:5872
14:15:29.821 -> entry 0x400806ac
14:15:30.381 -> 
14:15:30.381 ->         32 N: Serial logging started at 115200.
14:15:30.381 ->         33 V: Loading config.
14:15:30.475 -> [W][SPIFFS.cpp:71] begin(): SPIFFS Already Mounted!
14:15:30.569 ->        199 V: Initializing LCD.
14:15:31.130 ->        773 V: Initializing WiFi.
14:15:31.130 -> *wm:[2] Added Parameter: mdns
14:15:31.130 -> *wm:[1] AutoConnect 
14:15:31.272 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
14:15:31.272 -> *wm:[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
14:15:31.272 -> [2] WiFiSetCountry to US
14:15:31.272 -> *wm:[2] [OK] esp_wifi_set_country:  US
14:15:31.272 -> *wm:[2] ESP32 event handler enabled 
14:15:31.459 -> *wm:[2] Connecting as wifi client... 
14:15:31.459 -> *wm:[2] setSTAConfig static ip not set, skipping 
14:15:31.459 -> *wm:[1] Connecting to SAVED AP: MeshAP
14:15:31.972 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
14:15:34.496 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 4 - STA_CONNECTED
14:15:34.730 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 7 - STA_GOT_IP
14:15:34.730 -> [D][WiFiGeneric.cpp:419] _eventCallback(): STA IP: 000.000.000.000, MASK: 000.000.000.000, GW: 000.000.000.000
14:15:34.777 -> *wm:[2] Connection result: WL_CONNECTED
14:15:34.777 -> *wm:[1] AutoConnect: SUCCESS 
14:15:34.777 -> *wm:[1] STA IP Address: 000.000.000.000
14:15:34.824 ->       4475 V: Initializing scanner.
14:15:35.009 -> I NimBLEDevice: "BLE Host Task Started"
14:15:35.056 -> I NimBLEDevice: "NimBle host synced."
14:15:38.184 ->       7800 N: HTTP server started. Open: http://tiltbridge-gamma.local/ to view application.
14:16:08.148 ->      37802 V: Free Heap: 139416, Largest contiguous block: 97392, Frag: 31%

[lbussy]

Looks like I need to do some more dancing in order to (re)connect, since it's actually not reconnecting it's connecting.

[lbussy]

Okay, @SillyHats - you can test again at your leisure. With luck, this one will get it.

[SillyHats]

Apr 11 18:56:58 kernel: tiltbridgemac not mesh client, can't update it's ip
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0
Apr 11 19:32:01 syslog: wlceventd_proc_event(527): eth1: Auth tiltbridgemac, status: Successful (0), rssi:0

18:56:39.395 ->     930960 V: Serving Tilt JSON.
18:56:44.918 ->     936496 V: Free Heap: 131216, Largest contiguous block: 89544, Frag: 32%
18:56:53.450 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
18:56:53.450 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 16 - GROUP_KEY_UPDATE_TIMEOUT
18:56:53.450 ->     945025 V: WiFi event callback: reason code: 16.
18:56:53.450 ->     945037 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
18:56:53.450 ->     945041 V: Attempting rec onnect.
18:56:54.523 -> *wm:[1] AutoConnect 
18:56:54.523 -> *wm:[2] ESP32 event handler enabled 
18:56:54.523 -> *wm:[2] Connecting as wifi client... 
18:56:54.523 -> *wm:[2] setSTAConfig static ip not set, skipping 
18:56:54.523 -> *wm:[1] Connecting to SAVED AP: MeshAP
18:56:55.034 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
18:56:59.737 ->     951334 V: Serving Tilt JSON.
18:56:59.921 -> V: Serving Tilt JSON.
18:56:59.921 -> [W][AsyncTCP.cpp:1014] _poll(): pcb is NULL
18:57:05.022 -> *wm:[2] Connection result: WL_DISCONNECTED
18:57:05.022 -> *wm:[1] AutoConnect: FAILED 
18:57:05.022 -> *wm:[2] Starting Config Portal 
18:57:05.022 -> *wm:[2] AccessPoint set password is VALID 
18:57:05.162 -> *wm:[2] Disabling STA 
18:57:05.162 -> *wm:[2] Enabling AP 
18:57:05.162 -> *wm:[1] StartAP with SSID:  TiltBridgeAP
18:57:05.209 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
18:57:05.209 ->     956769 V: WiFi event callback: reason code: 0.
18:57:05.209 ->     956776 V: DEBUG: WiFiEvent() received unknown event: 0
18:57:05.718 -> *wm:[1] AP IP address: 192.168.4.1
18:57:05.718 -> *wm:[1] Starting Web Portal 
18:57:05.718 -> *wm:[2] HTTP server started 
18:57:05.718 -> *wm:[2] Config Portal Running, blocking, waiting for clients... 
18:57:05.718 -> *wm:[2] NUM CLIENTS:  0
18:57:14.930 ->     966496 V: Free Heap: 124608, Largest contiguous block: 85396, Frag: 32%
18:57:35.685 -> *wm:[2] NUM CLIENTS:  0
18:57:44.898 ->     996496 V: Free Heap: 124608, Largest contiguous block: 85396, Frag: 32%
18:58:05.688 -> *wm:[2] NUM CLIENTS:  0
18:58:14.905 ->    1026496 V: Free Heap: 124608, Largest contiguous block: 85396, Frag: 32%
18:58:35.700 -> *wm:[2] NUM CLIENTS:  0
18:58:44.936 ->    1056496 V: Free Heap: 124608, Largest contiguous block: 85396, Frag: 32%
18:59:05.727 -> *wm:[2] NUM CLIENTS:  0
18:59:14.929 ->    1086496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
18:59:35.716 -> *wm:[2] NUM CLIENTS:  0
18:59:44.934 ->    1116496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:00:05.721 -> *wm:[2] NUM CLIENTS:  0
19:00:14.926 ->    1146496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:00:35.700 -> *wm:[2] NUM CLIENTS:  0
19:00:44.924 ->    1176496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:01:05.725 -> *wm:[2] NUM CLIENTS:  0
19:01:14.916 ->    1206496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:01:35.713 -> *wm:[2] NUM CLIENTS:  0
19:01:44.933 ->    1236496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:02:05.724 -> *wm:[2] NUM CLIENTS:  0
19:02:14.939 ->    1266496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:02:35.738 -> *wm:[2] NUM CLIENTS:  0
19:02:44.952 ->    1296496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:03:05.739 -> *wm:[2] NUM CLIENTS:  0
19:03:14.912 ->    1326496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:03:35.746 -> *wm:[2] NUM CLIENTS:  0
19:03:44.950 ->    1356496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:04:05.734 -> *wm:[2] NUM CLIENTS:  0
19:04:14.920 ->    1386496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:04:35.737 -> *wm:[2] NUM CLIENTS:  0
19:04:44.944 ->    1416496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:05:05.738 -> *wm:[2] NUM CLIENTS:  0
19:05:14.948 ->    1446496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:05:35.757 -> *wm:[2] NUM CLIENTS:  0
19:05:44.944 ->    1476496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:06:05.715 -> *wm:[2] NUM CLIENTS:  0
19:06:14.923 ->    1506496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:06:35.742 -> *wm:[2] NUM CLIENTS:  0
19:06:44.932 ->    1536496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:07:05.763 -> *wm:[2] NUM CLIENTS:  0
19:07:14.925 ->    1566496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:07:35.745 -> *wm:[2] NUM CLIENTS:  0
19:07:44.932 ->    1596496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:08:05.761 -> *wm:[2] NUM CLIENTS:  0
19:08:14.918 ->    1626496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:08:35.733 -> *wm:[2] NUM CLIENTS:  0
19:08:44.932 ->    1656496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:09:05.756 -> *wm:[2] NUM CLIENTS:  0
19:09:14.947 ->    1686496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:09:35.734 -> *wm:[2] NUM CLIENTS:  0
19:09:44.925 ->    1716496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:10:05.773 -> *wm:[2] NUM CLIENTS:  0
19:10:14.930 ->    1746496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:10:35.749 -> *wm:[2] NUM CLIENTS:  0
19:10:44.957 ->    1776496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:11:05.744 -> *wm:[2] NUM CLIENTS:  0
19:11:14.933 ->    1806496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:11:35.744 -> *wm:[2] NUM CLIENTS:  0
19:11:44.945 ->    1836496 V: Free Heap: 124616, Largest contiguous block: 85396, Frag: 32%
19:12:05.743 -> *wm:[2] NUM CLIENTS:  0
19:12:35.770 -> *wm:[2] NUM CLIENTS:  0
19:13:05.758 -> *wm:[2] NUM CLIENTS:  0
19:13:35.768 -> *wm:[2] NUM CLIENTS:  0
19:14:05.763 -> *wm:[2] NUM CLIENTS:  0
19:14:35.777 -> *wm:[2] NUM CLIENTS:  0
19:15:05.780 -> *wm:[2] NUM CLIENTS:  0
19:15:35.788 -> *wm:[2] NUM CLIENTS:  0
19:16:05.770 -> *wm:[2] NUM CLIENTS:  0
19:16:35.788 -> *wm:[2] NUM CLIENTS:  0
19:16:48.894 ->    2140444 V: Serving 404 for request to /generate_204.
19:16:50.340 ->    2141889 V: Serving 404 for request to /generate_204.
19:16:51.787 ->    2143323 V: Serving 404 for request to /generate_204.
19:16:52.718 ->    2144280 V: Serving 404 for request to /generate_204.
19:16:59.110 ->    2150671 V: Serving 404 for request to /generate_204.
19:16:59.999 ->    2151539 V: Serving 404 for request to /generate_204.
19:17:01.766 ->    2153302 V: Serving 404 for request to /generate_204.
19:17:02.890 ->    2154456 V: Serving 404 for request to /generate_204.
19:17:03.868 ->    2155394 V: Serving 404 for request to /generate_204.
19:17:05.786 -> *wm:[2] NUM CLIENTS:  1
19:17:06.906 ->    2158462 V: Serving 404 for request to /gen_204.
19:17:08.074 ->    2159597 V: Serving 404 for request to /generate_204.
19:17:10.593 ->    2162121 V: Serving 404 for request to /generate_204.
19:17:15.960 ->    2167484 V: Serving 404 for request to /generate_204.
19:17:16.422 ->    2167946 V: Serving 404 for request to /generate_204.
19:17:23.414 ->    2174960 V: Serving 404 for request to /generate_204.
19:17:25.466 ->    2177010 V: Serving 404 for request to /generate_204.
19:17:29.425 ->    2180992 V: Serving 404 for request to /generate_204.
19:17:29.565 -> [W][AsyncTCP.cpp:1014] _poll(): pcb is NULL
19:17:29.565 -> [W][AsyncTCP.cpp:1014] _poll(): pcb is NULL
19:17:35.770 -> *wm:[2] NUM CLIENTS:  1
19:18:05.805 -> *wm:[2] NUM CLIENTS:  1
19:18:35.780 -> *wm:[2] NUM CLIENTS:  1
19:18:44.971 -> 
19:19:05.773 -> *wm:[2] NUM CLIENTS:  1
19:19:35.807 -> *wm:[2] NUM CLIENTS:  1
19:20:05.776 -> *wm:[2] NUM CLIENTS:  1
19:20:35.776 -> *wm:[2] NUM CLIENTS:  1
19:21:05.813 -> *wm:[2] NUM CLIENTS:  1
19:21:35.782 -> *wm:[2] NUM CLIENTS:  1
19:21:45.482 -> ets Jul 29 2019 12:21:46
19:21:45.482 -> 
19:21:45.482 -> rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
19:21:45.482 -> configsip: 0, SPIWP:0xee
19:21:45.482 -> clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
19:21:45.482 -> mode:DIO, clock div:2
19:21:45.482 -> load:0x3fff0018,len:4
19:21:45.482 -> load:0x3fff001c,len:1044
19:21:45.482 -> load:0x40078000,len:10044
19:21:45.482 -> load:0x40080400,len:5872
19:21:45.482 -> entry 0x400806ac
19:21:46.042 -> 
19:21:46.042 ->         32 N: Serial logging started at 115200.
19:21:46.042 ->         33 V: Loading config.
19:21:46.135 -> [W][SPIFFS.cpp:71] begin(): SPIFFS Already Mounted!
19:21:46.226 ->        197 V: Initializing LCD.
19:21:46.788 ->        771 V: Initializing WiFi.
19:21:46.788 -> *wm:[2] Added Parameter: mdns
19:21:46.788 -> *wm:[1] AutoConnect 
19:21:46.929 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
19:21:46.929 -> *wm:[D][WiFiGeneric.cpp:374] _eventCallback(): Event: 2 - STA_START
19:21:46.929 -> [2] WiFiSetCountry to US
19:21:46.929 -> *wm:[2] [OK] esp_wifi_set_country:  US
19:21:46.929 -> *wm:[2] ESP32 event handler enabled 
19:21:47.160 -> *wm:[2] Connecting as wifi client... 
19:21:47.160 -> *wm:[2] setSTAConfig static ip not set, skipping 
19:21:47.160 -> *wm:[1] Connecting to SAVED AP: MeshAP
19:21:47.628 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
19:21:49.119 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 4 - STA_CONNECTED
19:21:49.167 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 7 - STA_GOT_IP
19:21:49.167 -> [D][WiFiGeneric.cpp:419] _eventCallback(): STA IP: 000.000.000.000, MASK: 255.255.255.0, GW: 192.168.1.1
19:21:49.259 -> *wm:[2] Connection result: WL_CONNECTED
19:21:49.259 -> *wm:[1] AutoConnect: SUCCESS 
19:21:49.259 -> *wm:[1] STA IP Address: 000.000.000.000
19:21:49.305 ->       3269 V: Initializing scanner.
19:21:49.493 -> I NimBLEDevice: "BLE Host Task Started"
19:21:49.539 -> I NimBLEDevice: "NimBle host synced."
19:21:52.625 ->       6606 N: HTTP server started. Open: http://tiltbridge-epsilon.local/ to view application.
19:28:19.945 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:28:39.482 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:29:10.523 -> [W][AsyncTCP.cpp:1034] _poll(): rx timeout 4
19:31:49.640 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 5 - STA_DISCONNECTED
19:31:49.640 -> [W][WiFiGeneric.cpp:391] _eventCallback(): Reason: 16 - GROUP_KEY_UPDATE_TIMEOUT
19:31:49.640 ->     603553 V: WiFi event callback: reason code: 16.
19:31:49.640 ->     603566 V: DEBUG: WiFiEvent() received: SYSTEM_EVENT_STA_DISCONNECTED
19:31:49.640 ->     603570 V: Attempting rec onnect.
19:31:50.665 -> *wm:[1] AutoConnect 
19:31:50.665 -> *wm:[2] ESP32 event handler enabled 
19:31:50.665 -> *wm:[2] Connecting as wifi client... 
19:31:50.665 -> *wm:[2] setSTAConfig static ip not set, skipping 
19:31:50.665 -> *wm:[1] Connecting to SAVED AP: MeshAP
19:31:51.179 -> *wm:[1] connectTimeout not set, ESP waitForConnectResult... 
19:32:01.167 -> *wm:[2] Connection result: WL_DISCONNECTED
19:32:01.167 -> *wm:[1] AutoConnect: FAILED 
19:32:01.167 -> *wm:[2] Starting Config Portal 
19:32:01.167 -> *wm:[2] AccessPoint set password is VALID 
19:32:03.082 -> *wm:[2] Disabling STA 
19:32:03.082 -> *wm:[2] Enabling AP 
19:32:03.082 -> *wm:[1] StartAP with SSID:  TiltBridgeAP
19:32:03.128 -> [D][WiFiGeneric.cpp:374] _eventCallback(): Event: 0 - WIFI_READY
19:32:03.128 ->     617062 V: WiFi event callback: reason code: 0.
19:32:03.128 ->     617069 V: DEBUG: WiFiEvent() received unknown event: 0
19:32:03.638 -> *wm:[1] AP IP address: 192.168.4.1
19:32:03.638 -> *wm:[1] Starting Web Portal 
19:32:03.638 -> *wm:[2] HTTP server started 
19:32:03.638 -> *wm:[2] Config Portal Running, blocking, waiting for clients... 
19:32:03.638 -> *wm:[2] NUM CLIENTS:  0
19:32:33.643 -> *wm:[2] NUM CLIENTS:  0
19:33:03.647 -> *wm:[2] NUM CLIENTS:  0
19:33:33.627 -> *wm:[2] NUM CLIENTS:  0
19:34:03.652 -> *wm:[2] NUM CLIENTS:  0
19:34:33.618 -> *wm:[2] NUM CLIENTS:  0
19:35:03.655 -> *wm:[2] NUM CLIENTS:  0
19:35:33.650 -> *wm:[2] NUM CLIENTS:  0
19:36:03.638 -> *wm:[2] NUM CLIENTS:  0
19:36:33.622 -> *wm:[2] NUM CLIENTS:  0
19:37:03.658 -> *wm:[2] NUM CLIENTS:  0
19:37:33.624 -> *wm:[2] NUM CLIENTS:  0
19:38:03.632 -> *wm:[2] NUM CLIENTS:  0
19:38:33.635 -> *wm:[2] NUM CLIENTS:  0
19:39:03.650 -> *wm:[2] NUM CLIENTS:  0
19:39:33.647 -> *wm:[2] NUM CLIENTS:  0
19:40:03.637 -> *wm:[2] NUM CLIENTS:  0
19:40:33.638 -> *wm:[2] NUM CLIENTS:  0
19:41:03.678 -> *wm:[2] NUM CLIENTS:  0
19:41:33.678 -> *wm:[2] NUM CLIENTS:  0
19:42:03.686 -> *wm:[2] NUM CLIENTS:  0
19:42:33.657 -> *wm:[2] NUM CLIENTS:  0
19:43:03.658 -> *wm:[2] NUM CLIENTS:  0
19:43:33.673 -> *wm:[2] NUM CLIENTS:  0
19:44:03.665 -> *wm:[2] NUM CLIENTS:  0
19:44:33.674 -> *wm:[2] NUM CLIENTS:  0
19:45:03.661 -> *wm:[2] NUM CLIENTS:  0
19:45:33.695 -> *wm:[2] NUM CLIENTS:  0
19:46:03.682 -> *wm:[2] NUM CLIENTS:  0
19:46:33.671 -> *wm:[2] NUM CLIENTS:  0
19:47:03.704 -> *wm:[2] NUM CLIENTS:  0
19:47:33.676 -> *wm:[2] NUM CLIENTS:  0
19:48:03.682 -> *wm:[2] NUM CLIENTS:  0
19:48:33.712 -> *wm:[2] NUM CLIENTS:  0
19:49:03.694 -> *wm:[2] NUM CLIENTS:  0
19:49:33.693 -> *wm:[2] NUM CLIENTS:  0
19:50:03.698 -> *wm:[2] NUM CLIENTS:  0
19:50:33.680 -> *wm:[2] NUM CLIENTS:  0
19:51:03.716 -> *wm:[2] NUM CLIENTS:  0
19:51:33.679 -> *wm:[2] NUM CLIENTS:  0
19:52:03.717 -> *wm:[2] NUM CLIENTS:  0
19:52:33.726 -> *wm:[2] NUM CLIENTS:  0
19:53:03.682 -> *wm:[2] NUM CLIENTS:  0
19:53:33.717 -> *wm:[2] NUM CLIENTS:  0
19:54:03.717 -> *wm:[2] NUM CLIENTS:  0
19:54:33.701 -> *wm:[2] NUM CLIENTS:  0
19:55:03.708 -> *wm:[2] NUM CLIENTS:  0
19:55:33.715 -> *wm:[2] NUM CLIENTS:  0
19:56:03.735 -> *wm:[2] NUM CLIENTS:  0
19:56:33.709 -> *wm:[2] NUM CLIENTS:  0
19:57:03.729 -> *wm:[2] NUM CLIENTS:  0
19:57:33.698 -> *wm:[2] NUM CLIENTS:  0
19:58:03.719 -> *wm:[2] NUM CLIENTS:  0
19:58:33.746 -> *wm:[2] NUM CLIENTS:  0
19:59:03.705 -> *wm:[2] NUM CLIENTS:  0
19:59:33.738 -> *wm:[2] NUM CLIENTS:  0
20:00:03.735 -> *wm:[2] NUM CLIENTS:  0
20:00:33.734 -> *wm:[2] NUM CLIENTS:  0
20:01:03.750 -> *wm:[2] NUM CLIENTS:  0
20:01:15.071 ->    2368978 V: Serving 404 for request to /generate_204.
20:01:33.737 -> *wm:[2] NUM CLIENTS:  1
20:02:03.755 -> *wm:[2] NUM CLIENTS:  1
20:02:33.729 -> *wm:[2] NUM CLIENTS:  1
20:03:03.742 -> *wm:[2] NUM CLIENTS:  1
20:03:33.740 -> *wm:[2] NUM CLIENTS:  1
20:04:03.735 -> *wm:[2] NUM CLIENTS:  1
20:04:33.767 -> *wm:[2] NUM CLIENTS:  1
20:05:03.775 -> *wm:[2] NUM CLIENTS:  1
20:05:33.734 -> *wm:[2] NUM CLIENTS:  1
20:06:03.770 -> *wm:[2] NUM CLIENTS:  1
20:06:33.757 -> *wm:[2] NUM CLIENTS:  1
20:07:03.782 -> *wm:[2] NUM CLIENTS:  1
20:07:09.018 -> W (2723825) wifi:inactive timer: now=8bc8b0cb last_rx_time=79d94357 diff=49767, aid[1]fa:85:ac:57:c8:c8 leave
20:07:33.759 -> *wm:[2] NUM CLIENTS:  0
20:08:03.761 -> *wm:[2] NUM CLIENTS:  0
20:08:33.744 -> *wm:[2] NUM CLIENTS:  0
20:09:03.780 -> *wm:[2] NUM CLIENTS:  0
20:09:33.756 -> *wm:[2] NUM CLIENTS:  0
20:10:03.757 -> *wm:[2] NUM CLIENTS:  0
20:10:33.776 -> *wm:[2] NUM CLIENTS:  0
20:11:03.774 -> *wm:[2] NUM CLIENTS:  0
20:11:33.788 -> *wm:[2] NUM CLIENTS:  0
20:12:03.764 -> *wm:[2] NUM CLIENTS:  0
20:12:33.786 -> *wm:[2] NUM CLIENTS:  0
20:13:03.761 -> *wm:[2] NUM CLIENTS:  0
20:13:33.801 -> *wm:[2] NUM CLIENTS:  0
20:14:03.769 -> *wm:[2] NUM CLIENTS:  0
20:14:33.787 -> *wm:[2] NUM CLIENTS:  0
20:15:03.766 -> *wm:[2] NUM CLIENTS:  1
20:15:33.789 -> *wm:[2] NUM CLIENTS:  1
20:15:46.131 ->    3239987 V: Serving 404 for request to /generate_204.
20:16:03.799 -> *wm:[2] NUM CLIENTS:  1
20:16:33.777 -> *wm:[2] NUM CLIENTS:  1
20:17:03.787 -> *wm:[2] NUM CLIENTS:  1
20:17:33.803 -> *wm:[2] NUM CLIENTS:  1

At this point the TTGO display still shows Temp and Gravity, but is no longer accessible over the local network and has started the wifi config AP. Connecting to the TiltBridgeAP produces the following view where it would normally have the wifi config screens.