[Ovmsdev] That nagging wifi won't reconnect problem

[Mark Webb-Johnson]

I managed to recreate this (it is very rare for me), with logging enabled to SD CARD. Here is what I saw:

2019-07-07 21:37:13 HKT I (66811669) events: Signal(location.enter.honghay)
2019-07-07 21:37:14 HKT I (66813039) events: Signal(system.event)
2019-07-07 21:37:14 HKT I (66813099) events: Signal(system.wifi.scan.done)
2019-07-07 21:37:54 HKT I (66853039) events: Signal(system.event)
2019-07-07 21:37:54 HKT I (66853099) events: Signal(system.wifi.scan.done)
2019-07-07 21:37:54 HKT I (66853159) esp32wifi: Found SSID <REDACTED> - trying to connect
2019-07-07 21:37:57 HKT I (66855679) wifi: n:13 0, o:13 0, ap:255 255, sta:13 0, prof:1
2019-07-07 21:37:58 HKT I (66856619) wifi: state: init -> auth (b0)
2019-07-07 21:37:58 HKT I (66856679) wifi: state: auth -> assoc (0)
2019-07-07 21:37:58 HKT I (66856749) wifi: state: assoc -> run (10)
2019-07-07 21:37:58 HKT I (66856809) wifi: connected with <REDACTED>, channel 13
2019-07-07 21:37:58 HKT I (66856859) wifi: pm start, type: 1
2019-07-07 21:37:58 HKT I (66856919) events: Signal(system.event)
2019-07-07 21:37:58 HKT I (66856989) events: Signal(system.wifi.sta.connected)
...
2019-07-07 21:37:59 HKT I (66858139) events: Signal(system.event)
2019-07-07 21:37:59 HKT I (66858199) events: Signal(network.interface.up)
2019-07-07 21:37:59 HKT I (66858269) events: Signal(system.wifi.sta.gotip)

So, I drive home, it does a wifi.scan, finds my home AP, connects, and all is ok.

Then, in the middle of the night:

2019-07-08 03:03:53 HKT I (86400639) housekeeping: 2019-07-08 03:03:53 HKT (RAM: 8b=113788-132640 32b=22276)
2019-07-08 03:03:53 HKT I (86401049) ota: AutoFlash: Update ota_0 to 3.2.002-111-gac15fe8 (api.openvehicles.com/firmware/ota/v3.1/edge/ovms3.bin)
2019-07-08 03:03:53 HKT I (86401109) events: Signal(notify.info.ota.update)
2019-07-08 03:03:53 HKT I (86401109) ovms-server-v2: Send MP-0 PINew OTA firmware 3.2.002-111-gac15fe8 is available for download
2019-07-08 03:03:54 HKT I (86401269) ota: AutoFlash: Preparing flash partition...
2019-07-08 03:04:08 HKT I (86403399) wifi: bcn_timout,ap_probe_send_start
2019-07-08 03:04:11 HKT I (86405949) wifi: ap_probe_send over, resett wifi status to disassoc
2019-07-08 03:04:11 HKT I (86406009) wifi: state: run -> init (1)
2019-07-08 03:04:11 HKT I (86406049) wifi: pm stop, total sleep time: 18482424110 us / 19572759396 us
2019-07-08 03:04:11 HKT I (86406109) wifi: n:13 0, o:13 0, ap:255 255, sta:13 0, prof:1
2019-07-08 03:04:11 HKT I (86406159) events: Signal(system.event)
2019-07-08 03:04:11 HKT V (86406159) ovms-server-v2: OvmsServerV2MongooseCallback(MG_EV_CLOSE)
2019-07-08 03:04:11 HKT I (86406159) ota: AutoFlash:: Download complete (at 5385 bytes)
2019-07-08 03:04:11 HKT I (86406219) events: Signal(system.wifi.sta.disconnected)
2019-07-08 03:04:11 HKT I (86406319) ovms-server-v2: Status: Disconnected
2019-07-08 03:04:11 HKT E (86406369) ota: AutoFlash: Download file size (5385) does not match expected (2537376)
2019-07-08 03:04:11 HKT I (86406419) netmanager: WIFI client down (with MODEM down): network connectivity has been lost
2019-07-08 03:04:11 HKT I (86406519) esp_image: segment 0: paddr=0x00410020 vaddr=0x3f400020 size=0xc9c98 (826520) map
2019-07-08 03:04:12 HKT I (86406579) esp32wifi: STA disconnected with reason 200
2019-07-08 03:04:12 HKT I (86406739) events: Signal(network.wifi.down)
2019-07-08 03:04:12 HKT I (86406829) events: Signal(server.v2.waitreconnect)
2019-07-08 03:04:12 HKT I (86406919) events: Signal(network.down)
...
2019-07-08 03:04:12 HKT I (86407379) events: Signal(server.v2.waitnetwork)
2019-07-08 03:04:48 HKT I (86443029) events: Signal(system.event)
2019-07-08 03:04:48 HKT I (86443099) events: Signal(system.wifi.scan.done)
2019-07-08 03:05:11 HKT I (86466139) event: station ip lost
2019-07-08 03:05:11 HKT I (86466189) events: Signal(system.event)
2019-07-08 03:05:28 HKT I (86483029) events: Signal(system.event)
2019-07-08 03:05:28 HKT I (86483089) events: Signal(system.wifi.scan.done)
2019-07-08 03:06:08 HKT I (86523029) events: Signal(system.event)
2019-07-08 03:06:08 HKT I (86523089) events: Signal(system.wifi.scan.done)
2019-07-08 03:06:48 HKT I (86563029) events: Signal(system.event)
2019-07-08 03:06:48 HKT I (86563089) events: Signal(system.wifi.scan.done)
2019-07-08 03:07:28 HKT I (86603029) events: Signal(system.event)
2019-07-08 03:07:28 HKT I (86603089) events: Signal(system.wifi.scan.done)
2019-07-08 03:08:08 HKT I (86643029) events: Signal(system.event)
2019-07-08 03:08:08 HKT I (86643089) events: Signal(system.wifi.scan.done)
2019-07-08 03:08:48 HKT I (86683029) events: Signal(system.event)
2019-07-08 03:08:48 HKT I (86683089) events: Signal(system.wifi.scan.done)
2019-07-08 03:09:06 HKT I (86700639) housekeeping: 2019-07-08 03:09:06 HKT (RAM: 8b=113788-144368 32b=22276)

And from then on, the wifi scan cannot see the AP.

It is not a solution, but a clue as to at least one cause of these problems. From what I can see, the wifi got starved of CPU during that horribly long flash erase process, then wifi connection went down, OTA update failed, and it wasn’t recoverable from there.

Perhaps if the STA gets disconnected (always, or just with reason 200?) we should reset the wifi stack? The root cause of that esp_ota_begin() starving the wifi during erase of the 4MB partition would also be good to address.

Regards, Mark.


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20190711/39bb6ef5/attachment.html>