Page MenuHomePhabricator

Frequent Kask read errors
Closed, ResolvedPublic

Assigned To
Authored By
Tgr
Mar 10 2025, 7:50 PM
Referenced Files
F58808583: image.png
Mar 12 2025, 4:32 PM
F58808567: image.png
Mar 12 2025, 4:32 PM
F58808521: image.png
Mar 12 2025, 4:32 PM
F58808037: image.png
Mar 12 2025, 4:32 PM

Description

Logstash has 2000 Failed to fetch {cacheKey} : ({code}) {error} errors for the last 24 hours. Not all of them are Kask (unfortunately the logging code doesn't make it easy to figure out what cache is used) but just by skimming, most seem to be. Also, I get these errors on mwdebug basically any time I test something session-related (though I never see any breakage, even though I'd expect a session read failure to be quite visible - maybe there is an automatic retry?).

Some random examples:
Failed to fetch global:session:centralauth:XXX : (0) (curl error: 7) Couldn't connect to server
Failed to fetch enwiki:MWSession:XXX : (0) (curl error: 56) Failure when receiving data from the peer
Failed to fetch mediawikiwiki:MWSession:XXX : (503)

I'm not sure what's the expected rate of error with Kask, so feel free to close if this is within expectations.

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald Transcript

Interesting. I guess these errors are actually coming from Envoy (even if they're being propagated from Kask). Does someone know off the top of their head the logstash-fu to see what these endpoints are logging?

I'm not sure what's the expected rate of error with Kask, so feel free to close if this is within expectations.

TBH, I'm not sure what the expected error rate is either. This is where an SLO would come in, and unfortunately we don't have one. That said: If I'm doing the math right, an error rate of 2000(ish)/day is 4 or 5 9s?

Again, an SLO would be authoritative for this, but I'm inclined to think that if we had one, we'd be within bounds.

That doesn't mean that I'm not curious as to what's happening here though...


Looking at the 1987 log messages for the last 24 hours, they break down like this:

no. errorsstatus codereason
12220curl error 7: Couldn't connect to server
5430curl error 56: Failure when receiving data from the peer
1020curl error 52: Server returned nothing (no headers, no data)
120503Unavailable

We have an envoy sidecar that sits between mediawiki and the sessionstore service that does TLS termination and connection pooling. My guess is that whatever these errors are, they're happening mediawiki <--> envoy; I can't correlate any of this with the sessionstore logs.

image.png (1,918×962 px, 88 KB)

I can't find logs for envoy, but there is a telemetry dashboard, and the "destroyed connections with active requests" seems like it may correlate (timeline-wise)?

image.png (1,918×1,045 px, 105 KB)
image.png (1,918×613 px, 130 KB)

The "destroyed connections" panel is the result of upstream_cx_destroy_remote_with_active_rq which the docs describe as: Total connections destroyed remotely with 1+ active request, and this Github task says:

If there is an active request and a connection is terminated abnormally either by upstream or downstream, this stat is incremented.


TL;DR I think these errors are happening between mediawiki and envoy, and I think they are within acceptable bounds, but let's see if we can get serviceops to weigh in

[ ... ]

TL;DR I think these errors are happening between mediawiki and envoy, and I think they are within acceptable bounds, but let's see if we can get serviceops to weigh in

And we need an SLO!

#wikimedia-serviceops
4:21 PM <swfrench-wmf> so, these look like deployments
4:22 PM <swfrench-wmf> e.g., mediawiki is still attempting to issue sessionstore requests after the grace period before envoy shutdown expires
4:35 PM <swfrench-wmf> arbitrary 3h time window yesterday has 4 blips of errors: https://logstash.wikimedia.org/goto/7cef358f4205aaa218bddacf51de7d6c
4:38 PM <swfrench-wmf> correlating with the SAL, those appear to be the prod phases of https://sal.toolforge.org/log/_zBzhpUB8tZ8Ohr09E5n, https://sal.toolforge.org/log/FQSshpUBvg159pQr-UFu, https://sal.toolforge.org/log/4zDQhpUB8tZ8Ohr0koC0, https://sal.toolforge.org/log/nIfrhpUBffdvpiTr0JeP
[ ... ]
4:40 PM <swfrench-wmf> so, that would suggest it's the same kind of issue as has been discussed previously in https://phabricator.wikimedia.org/T371633 around shellbox
#wikimedia-serviceops
4:21 PM <swfrench-wmf> so, these look like deployments
4:22 PM <swfrench-wmf> e.g., mediawiki is still attempting to issue sessionstore requests after the grace period before envoy shutdown expires
4:35 PM <swfrench-wmf> arbitrary 3h time window yesterday has 4 blips of errors: https://logstash.wikimedia.org/goto/7cef358f4205aaa218bddacf51de7d6c
4:38 PM <swfrench-wmf> correlating with the SAL, those appear to be the prod phases of https://sal.toolforge.org/log/_zBzhpUB8tZ8Ohr09E5n, https://sal.toolforge.org/log/FQSshpUBvg159pQr-UFu, https://sal.toolforge.org/log/4zDQhpUB8tZ8Ohr0koC0, https://sal.toolforge.org/log/nIfrhpUBffdvpiTr0JeP
[ ... ]
4:40 PM <swfrench-wmf> so, that would suggest it's the same kind of issue as has been discussed previously in https://phabricator.wikimedia.org/T371633 around shellbox

As noted by @Scott_French on IRC (see above), what seems to be happening here is that: during deployment, traffic is stopped, and then (after a grace period) so is envoy. Any requests still in flight though are going to be abruptly terminated. The solution seems to be sidecar containers, but we are going to have to wait on that feature.

See: T371633: Burst of GuzzleHttp Exception for http://localhost:6025/call/constraint-regex-checker (in particular T371633#10080652 & T371633#10106229)

If this is usually happening right after a deployment, that means it is much more frequent when you are testing to-be-backported patches on the testservers (which does match my experience - I started looking at these errors after seeing them in mwdebug logs frequently during backports). Especially if the patch does have something to do with session handling, it's not a great time to get random session errors, or to mistakenly attribute real problems to random session errors. So, while I agree it's not a high-impact problem, I think the impact is bigger than what the daily error rate implies. If it becomes easier to avoid after some future Kubernetes upgrade, I think it would be worth investing some effort.
In any case, thanks for investigating it!

Eevans claimed this task.
Eevans added a subscriber: KOfori.

I'm going to go ahead and close this, since I don't think there is anything left to do here.

I've created a follow-up for creating an SLO for the sessionstore service (T391724).

@Scott_French do you know if there is an open issue that corresponds to these envoy-related disconnects? I didn't see anything in the T371633 mentions.

If this is usually happening right after a deployment, [...]

One minor clarification: this generally should be happening during a deployment rather than after, since it's an artifact of the container shutdown sequence during pod termination. Once the update of a given stage (e.g., testservers) completes, the errors should stop as well.

[...]
@Scott_French do you know if there is an open issue that corresponds to these envoy-related disconnects? I didn't see anything in the T371633 mentions.

I'm not aware of a specific task to re-work the shutdown behavior in a way that avoids these kinds of errors, but I'll ask around. There is some pending work to replace the workaround we have for k8s Jobs with the sidecar containers feature (T386694). However, jobs are a different / simpler use case vs. making use of the feature in a request-serving context to enable cleaner shutdown. Stated differently, having sidecar contains is just one piece of the puzzle.