[Ovmsdev] Poor wifi performance

[Stephen Casner]

I have finally given in and purchased a wifi extender to improve
coverage in my garage for the benefit of OVMS.  However, before I
install it, I'm trying to diagnose the problems in the wifi support
because I'm sure there will the other locations where OVMS will
encounter weak wifi connectivity.

The first section of log output below shows a typical situation.
(I've run a script over this log to replace the system's uptime values
with full date/timestamps.)  The system boots up and establishes both
WIFI and MODEM connectivity and gives priority to WIFI.  The server-v2
transmits two 10-minute updates successfully, but 23 minutes after
initially coming up it reports being disconnected.  Instead of
switching over to MODEM, it just tries every 20 seconds to connect
again through WIFI and fails.  This goes on for 25 minutes until the
condition worsens.  At that point mg_connect() begins reporting
"failed: cannot parse address" so the result continues to be failure
to connect.  The failed attempst continue every 20 seconds
indefinitely.  The "-1" after "cannot parse address" is from some
debugging code I added to determine which of several error returns
from the mg_parse_address() function was taken.  This tells me that
the actual failure was not in parsing, rather name lookup failed.  I
wonder if 25 minutes is timeout interval of the name cache.

The real question here is why wifi is still considered UP when
connections via wifi fail.  Perhaps a wifi disconnect event failed to
be sent or received, but I know I have seen instances where my router
indicated that the association to OVMS was inactive, yet OVMS wifi
status indicated UP.  I think it would make sense for the server to
signal netmanager when it has encountered N consecutive connection
failures and for netmanager to then try another interface if it has
one that is up.  I'm not sure how to transition back to wifi as the
preferred interface; perhaps netmanage could switch back after some
period of time (10 minutes?) and signal the server(s) to reconnect
(since I assume the established connection would not be affected when
netmanager switches priority).  Or perhaps netmanager can explore
connectivity using ping?

Here is this first section of the log:

I (2018-12-27 21:17:32.108) netmanager: MODEM up (with WIFI client up): staying with WIFI client priority
W (2018-12-27 21:18:14.538) websocket: WebSocketHandler[0x3f819994]: job queue overflow resolved, 2362 drops
W (2018-12-27 21:18:45.788) websocket: WebSocketHandler[0x3f819994]: job queue overflow detected
I (2018-12-27 21:19:14.428) housekeeping: 2018-12-27 21:19:14 GMT (RAM: 8b=113788-143140 32b=10448)
I (2018-12-27 21:22:08.428) ovms-server-v2: Send MP-0 S45.0,M,65535,127,stopped,standard,105,89,32,0,0,0,7,21,0,0,0,0,0.00,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,0.00,0
I (2018-12-27 21:22:08.488) ovms-server-v2: Send MP-0 D64,0,5,15,14,13,627,535490,0,64374,14,0,1,1,11.54,0,12.6,0,15,0,0
I (2018-12-27 21:22:08.548) ovms-server-v2: Send MP-0 L37.346279,-122.037292,67,48,1,1,0,0,0.0,0,0
I (2018-12-27 21:22:08.618) ovms-server-v2: Send MP-0 F3.1.011-90-g72ac9202-dirty/factory/main (build idf v3.1-dev-2835-g151269458-dirty Dec 22 2018 22:25:50),5YJRE11B181000033,14,1,TR1N,Revelstoke
I (2018-12-27 21:24:14.428) housekeeping: 2018-12-27 21:24:14 GMT (RAM: 8b=113788-143140 32b=10448)
I (2018-12-27 21:29:14.428) housekeeping: 2018-12-27 21:29:14 GMT (RAM: 8b=113788-143140 32b=10448)
I (2018-12-27 21:32:09.428) ovms-server-v2: Send MP-0 S45.0,M,65535,127,stopped,standard,105,89,32,0,0,0,7,21,0,0,0,0,0.00,0,0,0,0,-1,0,0,0,0,0,0,0,0.00,0.00,0
I (2018-12-27 21:32:09.498) ovms-server-v2: Send MP-0 D64,0,5,15,14,13,627,535490,0,64975,14,0,1,1,11.56,0,12.6,0,15,0,0
I (2018-12-27 21:32:09.558) ovms-server-v2: Send MP-0 L37.346260,-122.037315,67,56,1,1,0,0,0.0,0,0
I (2018-12-27 21:32:09.608) ovms-server-v2: Send MP-0 F3.1.011-90-g72ac9202-dirty/factory/main (build idf v3.1-dev-2835-g151269458-dirty Dec 22 2018 22:25:50),5YJRE11B181000033,13,1,TR1N,Revelstoke
I (2018-12-27 21:34:14.428) housekeeping: 2018-12-27 21:34:14 GMT (RAM: 8b=113788-143140 32b=10448)
I (2018-12-27 21:39:14.428) housekeeping: 2018-12-27 21:39:14 GMT (RAM: 8b=113788-143140 32b=10448)
I (2018-12-27 21:40:33.498) ovms-server-v2: Status: Disconnected
I (2018-12-27 21:40:53.428) ovms-server-v2: Connection is api.openvehicles.com:6867 US33
I (2018-12-27 21:40:53.478) ovms-server-v2: Status: Connecting...
W (2018-12-27 21:41:11.408) ovms-server-v2: Connection failed
E (2018-12-27 21:41:11.458) ovms-server-v2: Status: Error: Connection failed
I (2018-12-27 21:41:11.518) ovms-server-v2: Status: Disconnected
I (2018-12-27 21:41:31.428) ovms-server-v2: Connection is api.openvehicles.com:6867 US33
I (2018-12-27 21:41:31.478) ovms-server-v2: Status: Connecting...
W (2018-12-27 21:41:48.848) ovms-server-v2: Connection failed
E (2018-12-27 21:41:48.898) ovms-server-v2: Status: Error: Connection failed
I (2018-12-27 21:41:48.958) ovms-server-v2: Status: Disconnected
...
I (2018-12-27 22:05:44.428) ovms-server-v2: Connection is api.openvehicles.com:6867 US33
I (2018-12-27 22:05:44.498) ovms-server-v2: Status: Connecting...
E (2018-12-27 22:05:57.048) ovms-server-v2: mg_connect(api.openvehicles.com:6867) failed: cannot parse address -1
E (2018-12-27 22:05:57.098) ovms-server-v2: Status: Error: Connection failed
I (2018-12-27 22:06:04.428) ovms-server-v2: Connection is api.openvehicles.com:6867 US33
I (2018-12-27 22:06:04.478) ovms-server-v2: Status: Connecting...
E (2018-12-27 22:06:17.198) ovms-server-v2: mg_connect(api.openvehicles.com:6867) failed: cannot parse address -1
E (2018-12-27 22:06:17.268) ovms-server-v2: Status: Error: Connection failed
I (2018-12-27 22:06:24.428) ovms-server-v2: Connection is api.openvehicles.com:6867 US33
I (2018-12-27 22:06:24.478) ovms-server-v2: Status: Connecting...
E (2018-12-27 22:06:37.358) ovms-server-v2: mg_connect(api.openvehicles.com:6867) failed: cannot parse address -1
E (2018-12-27 22:06:37.408) ovms-server-v2: Status: Error: Connection failed

The second section of log is just to show a particular odd error in
the wifi driver: "wifi: ieee80211_output.c 853".  After this error
occurs, the wifi task is stuck in a loop resulting in a watchdog
timeout if enabled.  I did not find any mention of this in the github
issues for esp-idf.  On the forum there was one post with a similar
message but a different number, but there was no reply.

I (528) esp32wifi: Powering up WIFI driver
I (528) wifi: wifi driver task: 3ffcda80, prio:23, stack:3584, core=0
I (538) wifi: wifi firmware version: 771f1dc
I (538) wifi: config NVS flash: enabled
I (538) wifi: config nano formating: disabled
I (578) wifi: Init dynamic tx buffer num: 16
I (578) wifi: Init data frame dynamic rx buffer num: 16
I (578) wifi: Init management frame dynamic rx buffer num: 16
I (578) wifi: Init static rx buffer size: 2212
I (588) wifi: Init static rx buffer num: 4
I (588) wifi: Init dynamic rx buffer num: 16
I (648) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (658) wifi: mode : sta (30:ae:a4:43:9c:28)
I (3068) esp32wifi: STA disconnected with reason 201
I (12838) esp32wifi: STA disconnected with reason 201
I (22838) esp32wifi: STA disconnected with reason 201
I (32838) esp32wifi: STA disconnected with reason 201
I (42838) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (43598) wifi: state: init -> auth (b0)
I (44598) wifi: state: auth -> init (2)
I (44598) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (44598) esp32wifi: STA disconnected with reason 2
I (52838) esp32wifi: STA disconnected with reason 201
I (62838) esp32wifi: STA disconnected with reason 201
I (72838) esp32wifi: STA disconnected with reason 201
I (82858) esp32wifi: STA disconnected with reason 201
I (92838) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (92838) wifi: state: init -> auth (b0)
I (92848) wifi: state: auth -> assoc (0)
I (92858) wifi: state: assoc -> run (10)
I (92908) wifi: connected with Revelstoke, channel 1
I (92908) wifi: pm start, type: 1
I (128848) wifi: bcn_timout,ap_probe_send_start
E (133258) wifi: ieee80211_output.c 853
OVMS# Task watchdog got triggered. The following tasks did not reset the watchdog in time:
 - IDLE (CPU 0)
Tasks currently running:
CPU 0: wifi
CPU 1: IDLE
Aborting.
abort() was called at PC 0x400ddf43 on core 0

Backtrace: 0x40096068:0x3ffb05b0 0x4009622f:0x3ffb05d0 0x400ddf43:0x3ffb05f0 0x40085009:0x3ffb0610 0x401d351d:0x00000000

                                                        -- Steve