| brennen | |
| Sep 20 2023, 6:36 PM |
| F55289448: 2024-06-13-09:36:42.png | |
| Jun 13 2024, 3:37 PM |
| F41434769: Screenshot 2023-11-02 at 22.39.40.png | |
| Nov 2 2023, 11:36 PM |
| F41434768: Screenshot 2023-11-02 at 22.39.29.png | |
| Nov 2 2023, 11:36 PM |
Uncaught ConfigException: Failed to load configuration from etcd: in /srv/mediawiki/php-1.41.0-wmf.27/includes/config/EtcdConfig.php:229
(REDACTED)
~13 in last hour. I'm seeing this for .26 as well, so presumably not train-related.
Untagging MediaWiki-Platform-Team since MediaWiki-Configuration does not have an owner today (mw:Maintainers).
Tagging MW-on-K8s and ServiceOps new because in Logstash: mediawiki dashboard, results for "Failed to load configuration from etcd" over the past 7 days are exclusively from kubernetes nodes. Baremetal seems to be fine.
I apologize in advance for speculating on something I know very little about, but it's starting to smell like Kubernetes just doesn't know how to do networking. See also T342201#9151176 about MW-on-K8s failing to reach Memcached. We also have an as-of-yet-unknown issue with reaching Shellbox, AQS, and EventBus in K8s from services outside it (T292663, T341634, T249700)
Given this is K8s-specific and likely to get worse as traffic increases, also pinging T346422: Move 10% of mediawiki external requests to mw on k8s and T290536: Serve production traffic via Kubernetes.
The error condition is reached when there is no value in apc and a response can't be fetched from etcd in time.
I kind of suspect one of the two following conditions are causing this:
I'll take a better look tomorrow.
As per your speculations: it seems improbable that we fail http requests often enough because of network failures that we end up in this code path. Also suspicious is the fact that $error is empty which I wouldn't expect to happen if the problem is with fetching data from etcd.
Maybe a DNS resolution issue would explain this behaviour: DnsSrvDiscoverer::getServers throwing an exception that gets silently caught by the try/finally block; I would totally consider possible that dns resolution inside of k8s might have some issues. The code, as written, doesn't really help debug this problem.
Change 959801 had a related patch set uploaded (by Krinkle; author: Krinkle):
[mediawiki/core@master] config: replace unused Logger in EtcdConfig with native trigger_error
I've checked the logs from September (https://logstash.wikimedia.org/goto/37581ef39fe3ed2251e9cf0e13d12445) where this happened 132 times as of now, usually in batches of around 13 messages coming from one single pod. Cross referencing with k8s events showed that this "sometimes" happens during the startup of a new mediawiki pod. I would assume there is some kind of race condition at play.
Change 959801 merged by jenkins-bot:
[mediawiki/core@master] config: replace unused Logger in EtcdConfig with native trigger_error
With the instrumentation in place to fix the empty string reason, we now know the reason recorded. All entries have the same reason: lost lock
Uncaught MediaWiki\Config\ConfigException: Failed to load configuration from etcd: lost lock
There are about ~100 per day. They are exclusively from MW-on-k8s.
Correlation with the new non-fatal diagnostic warnings added by the above patch is hard, since they happen before Monolog is initialised during the MW web request. This means those warnigns to to the php7.2-fpm (baremetal) or php-fpm-error (k8s) syslog, where there is no reqId, HTTP host name, or request URL logged.
The best I know to do, is to use the View surrounding documents button in Logstash, and limit surrounding documents to the same logsource host.
What I'm seeing consistently is that the Kubernetes pods are encountering this within the first minute of booting up. This makes logical sense since the data is stored indefinitely in php-apcu once it is succesfully loaded and allowed to be used in a stale way as long as needed. The EtcdConfig class treats cache data as fresh for 10s and after that it lets the first request get a lock to renew the data, and uses the cached data until new data is available, waiting either for that request to succeed or to let another request try it after it times out after 2s.
For example:
| timestamp | Nov 1, 2023 @ 20:17:18.458 |
| host | mw-api-ext.codfw.main-78dc85dd44-f5zvw |
| type | mediawiki |
| caught_by | php-wmerrors |
| message | Uncaught MediaWiki\Config\ConfigException: Failed to load configuration from etcd: lost lock in /srv/mediawiki/php-1.42.0-wmf.2/includes/config/EtcdConfig.php:231 |
The "View surrounding documents" button, and then pressing the positive filter for the host name, yields a warning saying that only 7 earlier documents exist in the Logstash index. This is without any type or channel filter, meaning it would include any messages from syslog/php-fpm, but there is nothing earlier.
Querying the same from the Discover page, shows the same, there exist only 7 earlier messages:
The 1 selected message and 7 earlier messages are all the same uncaught exception. So where's what I think is happening:
| Time | Event |
|---|---|
| ? | K8s pod boots up. |
| ? | MW request 1 starts, tries cache (empty), acquires lock (expires after 9s if not released), starts Etcd fetch (HTTP connect timeout: 2s, HTTP req timeout: 2s). The etcd fetch takes over 2 seconds to complete, but does eventually succeed. |
| ? | MW request 2 starts, tries cache (empty), loses lock, enters a poll loop for upto 2 seconds with brief sleeps in between. |
| Nov 1, 2023 @ 20:17:16.139 | MW request 2 fails with HTTP 500, after 2 seconds of waiting, got Uncaught MediaWiki\Config\ConfigException: Failed to load configuration from etcd: lost lock. |
| Nov 1, 2023 @ 20:17:16.426 | MW request 3 fails, idem. |
| Nov 1, 2023 @ 20:17:16.448 | MW request 4 fails, idem. |
| Nov 1, 2023 @ 20:17:17.181 | MW request 5 fails, idem. |
| Nov 1, 2023 @ 20:17:17.704 | MW request 6 fails, idem. |
| Nov 1, 2023 @ 20:17:18.050 | MW request 7 fails, idem. |
| Nov 1, 2023 @ 20:17:18.338 | MW request 8 fails, idem. |
| Nov 1, 2023 @ 20:17:18.458 | MW request 9 fails, idem. |
| Nov 1, 2023 @ 20:17:18.859 | MW request 10, second successful request. It either saw cache data on the first try if it started after MW req 1 ended, or maybe it also entered a poll loop for a short time and then saw the cache data appear. |
MW request 2-9 represent the 8 uncaught exceptions in the logs.
The only messages we see during the first minute of the pod's existence are Failed to load configuration from etcd: lost lock. By definition this means the first request, which acquired the lock, must not have gotten any HTTP error or HTTP timeout for the Etcd fetch, as that would have resulted in a different or extra log message.
Main questions:
Action item: Can we avoid this? I think so.
In the long-term, I hope a warmup can be implemented which would benefit lots of things and absorb many different kinds of bootstrapping scenarios through a single mechanism. As I understand it, Kubernetes has a built-in health check probe that it requires to finish succesfully before pooling the pod. However, I'm guessing we've either disabled this for MW right now, or it points to a generic virtualhost that isn't served by MediaWiki.
In the short-term, I suppose we could re-align the timeouts better so that we don't rely on servers starting in a way where the first request must succeed in under 2s or else all incoming requests during that window fail with HTTP 500.
Current timeouts:
We could lower the Etcd fetch timeouts (currently 4s = 2s connect, 2s req) to be less than the poll-wait timeout (currently 2s). Given the Etcd SLO of 32ms at https://wikitech.wikimedia.org/wiki/SLO/etcd_main_cluster, we could for example set this to 0.5s and 0.5s. That way, if a fetch would have taken 2+ seconds to complete, it will timeout before that and have time left to retry under the same acquired lock, succeed, and then feed it to the other queued requests instead of letting those all fail.
Another way could be to lower the lock expiry significantly. For example, if we set the lock expiry to 0.5s, that would mean if the lock-holding thread takes more than 0.5s to renew the value, one of the other queued threads is given a chance to make a succesful renew. The Etcd rate should be similar, but rather than happening serially from a single thread, it would be in parallel from one other thread that succesfully gets the lock on its next wait-loop iteration.
Still seen in 1.43.0-wmf.9.
Recent versions:
Uncaught MediaWiki\Config\ConfigException: Failed to load configuration from etcd: lost lock in /srv/mediawiki/php-1.43.0-wmf.8/includes/config/EtcdConfig.php:231
(REDACTED)
Still appearing in reasonable numbers
Uncaught MediaWiki\Config\ConfigException: Failed to load configuration from etcd: lost lock in /srv/mediawiki/php-1.44.0-wmf.19/includes/config/EtcdConfig.php:231
(REDACTED)
Change #1183614 had a related patch set uploaded (by Lucas Werkmeister (WMDE); author: Lucas Werkmeister (WMDE)):
[mediawiki/core@master] maintenance: Try to keep going after ConfigException
Change #1183614 merged by jenkins-bot:
[mediawiki/core@master] maintenance: Try to keep going after ConfigException
There's some solid discussion here around how to potentially increase the likelihood of (eventual) success in the ConfigException case if fetch fails or is slow (T346971#9303816).
Zooming out a bit, there seems to be a general background issue involving surprisingly slow config fetch - e.g., EtcdConfig using stale data: (curl error: 28) Timeout was reached - the vast majority of it happening in the (happier) stale-cached-data case rather than the fatal no-cached-data case (leading to ConfigException).
In the cases with explicit errors, what we get out of MultiHttpClient is just the curl_strerror description, which if I understand correctly only gives us a general description of the error code, rather than session-level details of what specifically we were waiting on at the time (i.e., vs. what we could get from curl_error).
What concerns me is that 28 is inclusive of DNS resolution, and in a recent issue we encountered during other work (ICU 72 upgrade), we saw that the tail of DNS resolution duration can be surprisingly long (multiple seconds; certainly longer than the 2s connTimeout) (note: this would have to be after we successfully resolved the SRV record to constituent cluster members; i.e., it would be a timeout resolving one of the latter).
Apologies if this is an angle we've looked at previously and ruled out - given the fact that it rhymes with something else we encountered recently, I wanted to draw the potential connection.
More thoughts
If this sounds like something worth pursuing, I wonder whether it might be useful to run an experiment where we use explicit IPs from a narrow set of clients - e.g., in canaries - to side-step DNS resolution.
That would require some tweaks in a couple of places (in EtcdConfig itself, some overrides in mediawiki-config, and updates to the SAN list in the conftool etcd TLS-proxy cert). While that's clearly not a solution, and it's not exactly trivial, the result would likely be quite informative.
Alternatively, if there's some other way to passively assess the health of DNS within the k8s cluster (e.g., load / latency on core DNS), I think that might be another way to get at this.
Edit 1: Just to note explicitly, this could of course be a symptom of a network issue (and possibly one that will tend to have an outsized impact on UDP in particular).
Edit 2: While 1.0 is not a useful quantile to look at in general, I'm now curious about the 40 day trend in per-instance max coredns resolution duration in eqiad (and see complementary view in codfw which clearly shows the effect of the switchover, though that does not explain the entire trend).