[Ovmsdev] Poor wifi performance

Mon Dec 31 06:52:12 HKT 2018

Steve,

we've got an open issue on the connection failure detection: https://github.com/openvehicles/Open-Vehicle-Monitoring-System-3/issues/112

Mark also planned to do a rework of our Wifi integration to better handle some event situations IIRC. But do you see a wifi system event on connection loss,
that should be handled? The situations I checked did not show any events we should have handled better, it just lost the connection.

Can you try the current idf version? There are quite some Wifi related entries in the change history, I'm still hoping the update will solve some of these problems.

If you hesitate because of the config partition problem: that's just a one time event when doing the upgrade, you can restore your config afterwards.

Regards,
Michael

Am 30.12.18 um 04:17 schrieb 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
> _______________________________________________
> OvmsDev mailing list
> OvmsDev at lists.openvehicles.com
> http://lists.openvehicles.com/mailman/listinfo/ovmsdev

-- 
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26