Openpilot: Fix system lags related to cellular connection -- $1000 bounty

[pd0wm]

Very rarely we have seen complete system lockup of about 0.2 to 1 second. See for example the time between packets in this plot:

Usually this causes a CAN error out of nowhere and a disengagement. One user reported that it always happens at the same point in his commute when he loses cellular connection.

My theory is that it is related to cell signal dropping or switching between towers, this is doing something in the kernel that locks up the whole system until it's done.

• $200 for a reliable way to reproduce
• $800 for a description of the root cause and merged pull request that fixes this issue.

[cmarshall108]

@pd0wm May or may not be the issue, however this call to subprocess.check_output will block until the result is returned, this determines what type cellular connection currently exists (2G, 3G, 4G). Furthermore, see the comment above the line highlighted below:

https://github.com/commaai/openpilot/blob/2716e37b28c987eed5ce3209e596b2400adb54db/selfdrive/thermald.py#L200

I suppose an easy way to test this theory would be to simulate a delay of a few milliseconds within get_network_type. This would suffice for such: time.sleep(0.001)

[pd0wm]

The issue is at a much lower level than just an individual service. Just thermald lagging for a little bit wouldn't cause all the other packets in the system to be delayed too.

[AskAlice]

I had this happen with tmux open once. I was driving on i70 near 39.712522, -105.304391, which is a major geographic transition, from mountains to metro area.
unfortunately I was unable to scroll up past this, as I had to find a place to safely pull over to extract this data.

https://discordapp.com/channels/469524606043160576/524611978208215070/670887377132060672

{"event": "alert_add", "alert_type": "canError", "enabled": true, "ctx": {"dongle_id": "6b53237138b1b2c5", "version": "0.7-release", "dirty$
: true, "is_eon": true}}                                                                                                                    
selfdrive/boardd/boardd.cc: missed cycle                                                                                                    
selfdrive/ui/ui.cc: slow frame(221959) time: 238.58  

thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
Result: Parcel(00000000    '....')                                                                                                          
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter                                                                                               
thermald logmessaged logcatd tombstoned uploader ui updated pandad controlsd plannerd loggerd sensord radard calibrationd paramsd camerad mo
deld monitoringd proclogd ubloxd gpsd deleter 


{"event": "upload_failed", "stat": null, "exc": ["ConnectionError(MaxRetryError(\"HTTPSConnectionPool(host='api.commadotai.com', port=443): 
Max retries exceeded with url: /v1.3/6b53237138b1b2c5/upload_url/?path=2020-01-25--21-26-50--73%2Fqlog.bz2 (Caused by NewConnectionError('<$
rllib3.connection.VerifiedHTTPSConnection object at 0x7f91615e10>: Failed to establish a new connection: [Errno 101] Network is unreachable$
))\"))", "Traceback (most recent call last):\n  File \"/data/data/com.termux/files/usr/lib/python3.7/site-packages/urllib3/connection.py\", 
line 157, in _new_conn\n    (self._dns_host, self.port), self.timeout, **extra_kw\n  File \"/data/data/com.termux/files/usr/lib/python3.7/s$
te-packages/urllib3/util/connection.py\", line 84, in create_connection\n    raise err\n  File \"/data/data/com.termux/files/usr/lib/python$
.7/site-packages/urllib3/util/connection.py\", line 74, in create_connection\n    sock.connect(sa)\nOSError: [Errno 101] Network is unreach$
ble\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n  File \"/data/data/com.t$
rmux/files/usr/lib/python3.7/site-packages/urllib3/connectionpool.py\", line 672, in urlopen\n    chunked=chunked,\n  File \"/data/data/com$
termux/files/usr/lib/python3.7/site-packages/urllib3/connectionpool.py\", line 376, in _make_request\n    self._validate_conn(conn)\n  File 
\"/data/data/com.termux/files/usr/lib/python3.7/site-packages/urllib3/connectionpool.py\", line 994, in _validate_conn\n    conn.connect()\$
  File \"/data/data/com.termux/files/usr/lib/python3.7/site-packages/urllib3/connection.py\", line 334, in connect\n    conn = self._new_co$
n()\n  File \"/data/data/com.termux/files/usr/lib/python3.7/site-packages/urllib3/connection.py\", line 169, in _new_conn\n    self, \"Fail$
d to establish a new connection: %s\" % e\nurllib3.exceptions.NewConnectionError: <urllib3.connection.VerifiedHTTPSConnection object at 0x7$
91615e10>: Failed to establish a new connection: [Errno 101] Network is unreachable\n\nDuring handling of the above exception, another exce$
tion occurred:\n\nTraceback (most recent call last):\n  File \"/data/data/com.termux/files/usr/lib/python3.7/site-packages/requests/adapter$
.py\", line 449, in send\n    timeout=timeout\n  File \"/data/data/com.termux/files/usr/lib/python3.7/site-packages/urllib3/connectionpool.$
y\", line 720, in urlopen\n    method, url, error=e, _pool=self, _stacktrace=sys.exc_info()[2]\n  File \"/data/data/com.termux/files/usr/li$
/python3.7/site-packages/urllib3/util/retry.py\", line 436, in increment\n    raise MaxRetryError(_pool, url, error or ResponseError(cause)$
\nurllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='api.commadotai.com', port=443): Max retries exceeded with url: /v1.3/6b532371$
8b1b2c5/upload_url/?path=2020-01-25--21-26-50--73%2Fqlog.bz2 (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection obj$
ct at 0x7f91615e10>: Failed to establish a new connection: [Errno 101] Network is unreachable'))\n\nDuring handling of the above exception, 
another exception occurred:\n\nTraceback (most recent call last):\n  File \"/data/openpilot/selfdrive/loggerd/uploader.py\", line 159, in d$
_upload\n    url_resp = self.api.get(\"v1.3/\"+self.dongle_id+\"/upload_url/\", timeout=10, path=key, access_token=self.api.get_token())\n  
File \"/data/openpilot/common/api/__init__.py\", line 14, in get\n    return self.request('GET', *args, **kwargs)\n  File \"/data/openpilot$
common/api/__init__.py\", line 20, in request\n    return api_get(endpoint, method=method, timeout=timeout, access_token=access_token, **pa$
ams)\n  File \"/data/openpilot/common/api/__init__.py\", line 41, in api_get\n    return requests.request(method, backend+endpoint, timeout$
timeout, headers = headers, params=params)\n  File \"/data/data/com.termux/files/usr/lib/python3.7/site-packages/requests/api.py\", line 60$
 in request\n    return session.request(method=method, url=url, **kwargs)\n  File \"/data/data/com.termux/files/usr/lib/python3.7/site-pack$
ges/requests/sessions.py\", line 533, in request\n    resp = self.send(prep, **send_kwargs)\n  File \"/data/data/com.termux/files/usr/lib/p$
thon3.7/site-packages/raven/breadcrumbs.py\", line 341, in send\n    resp = real_send(self, request, *args, **kwargs)\n  File \"/data/data/$
om.termux/files/usr/lib/python3.7/site-packages/requests/sessions.py\", line 646, in send\n    r = adapter.send(request, **kwargs)\n  File $
"/data/data/com.termux/files/usr/lib/python3.7/site-packages/requests/adapters.py\", line 516, in send\n    raise ConnectionError(e, reques$

[pd0wm]

That's a traceback from the uploader, probably because the network got interrupted. That's not what's causing the lags, just a symptom.

I grabbed a couple of kernel/android logs around the time of the lag from some of our users.

lag1.txt
lag @ t=90809

lag2.txt
lag @ t=20133

lag3.txt
lag @ 191751

[pd0wm]

I might have found a way to reproduce the problem. I noticed that a usleep sleeps for way longer when you put it the sim card or take it out. Simple c++ program to reproduce:

#include <iostream>
#include <chrono>
#include <unistd.h>


int main(void){

  while (true){
    long sleep = 1000; // 1ms

    auto t_start = std::chrono::high_resolution_clock::now();
    usleep(sleep);
    auto t_end = std::chrono::high_resolution_clock::now();
    double elapsed_time_ms = std::chrono::duration<double, std::milli>(t_end-t_start).count();
    if (elapsed_time_ms > 5.0) {
      std::cout << "Sleep too long: " << elapsed_time_ms << std::endl;
    }
  }

  return 0;
}

Do something with the sim card and you see a sleep of over 10ms. I'm not sure what this means somehow. Is something locking up the scheduler?

[LoganxDev]

They all seem to be doing something with the "WifiConfigStore" at the time of the lag.

lag1.txt
[90805.780590] MAIN 1154 WifiConfigStore - Retrieve network priorities after PNO.

lag2.txt
[20127.346106] MAIN 1159 WifiConfigStore - rewrite network history for "DIRECT-Lq-Car_ffab"-WPA_PSK

lag3.txt
[191732.893202] MAIN 1131 WifiConfigStore - Retrieve network priorities after PNO.

Possibly a blocking read on the wpa_supplicant file.

Info on PNO:
https://source.android.com/devices/tech/connect/wifi-scan

It can probably be reproduced if wifi is on but not in range of any saved networks. I'll have to test it though.

[pd0wm]

Should be fixed by https://github.com/commaai/openpilot/commit/03a9b546362a5a085ad6261c7901d19f80cfbeb1. Thanks @jyoung8607

Incoming data from 0.7.5 will confirm this. Will reopen the issue if it's not fixed.

[adam-nelson]

Could mapping cellular / mobile dead spot help openpilot mitigate and prevent this?

Eg IF in known dead spot temporary enable 'airplane' mode as workaround

[adam-nelson]

In my own experience I can't pinpoint this to a geographical spot or dead spot because to mobile coverage area is good / excellent at all time

[nabeelr]

I can fairly predictably reproduce this error if that matters to anyone. I also have a screen record of it happening with tmux running on my iPhone, that I can pair up to the drive video.

Basically there are a ton of missed cycle messages, then a Receive Buffer full message.

I know a screenshot/video is kind of sacrilege, but this is the best I can do right now.

I'm willing to do any testing that anyone wants to do considering I can fairly reliably reproduce it, just let me know. That being said, it might take some time, because on this drive after removing the Sim card it fell somewhere, God knows where, in the centre console, in my car. I might need to buy a replacement.

[ShaneSmiskol]

I've gotten a CAN error out of no where on a road trip I took last month, didn't think anything of it since there was no reason it would disengage after driving hundreds of miles engaged. However, it only occurred twice when I was in the middle of nowhere, back to back after restarting the car. Never happened again, the trip was about 700 miles with no issues except those two CAN errors. I don't have a SIM connected, nor comma prime so I'm not sure if this issue would have affected me or not

[adeebshihadeh]

Fixed by #2194 until a kernel fix is shipped in the next NEOS update.