Page MenuHomePhabricator

Produce requests to eventgate-logging-external in eqiad occasionally fail.
Closed, ResolvedPublic

Description

Today, we've seen an unusual number of canary event produce failures in the data-engineering-alerts mailing list. Investigation of logs shows that the failures happen occasionally only to eventgate-logging-external.

I can reproduce this my manually curling the /v1/_test/events endpoint. Usually this succeeds, but every 4 or 5th try hangs, and then fails with a HTTP 503:

$ curl -i https://eventgate-logging-external.svc.eqiad.wmnet:4392/v1/_test/events
HTTP/1.1 503 Service Unavailable
content-length: 95
content-type: text/plain
date: Tue, 11 Apr 2023 18:15:32 GMT
server: production-tls

upstream connect error or disconnect/reset before headers. reset reason: connection termination

I thought that perhaps this was a single pod having an issue, so I curled each of the pod container ports individually:

$ kube_env eventgate-logging-external eqiad
$ for ip in $(kubectl get pods -o wide    | awk '{print $6}' | grep -v IP); do url=https://$ip:4392/v1/_test/events; echo "== $url == "; curl -k -i  $url; echo " ";  done

I couldn't find any pattern. Each time I ran this, they might all succeed, or I might encounter a hanging/failed request from any pod IP.

Ah, but I went to look at container logs:

kubectl logs -f -l app=eventgate -c eventgate-logging-external | jq .

I see a lot of errors like:

"msg": "event 1d4ad7f5-992a-41b3-a658-abc2d10dfdb3 of schema at /w3c/reportingapi/network_error/1.0.0 destined to stream w3c.reportingapi.network_error encountered an error: message timed out",

Something is fishy with eventgate-logging-external for sure.

Event Timeline

I have to run for an appointment, but I can try and look at this more tomorrow.

I see also a lot of 503s logged by the eventgate-production-tls-proxy container (to support the issues that we are seeing). I also noticed that the last changes for the eventgate chart are not deployed everywhere, IIRC some stuff changed (mostly no-ops) but maybe it is worth to update all instances with the same code? To remove some variables from the table :)

Change 908244 had a related patch set uploaded (by Ottomata; author: Ottomata):

[operations/deployment-charts@master] Update all eventgate clusters to same image version

https://gerrit.wikimedia.org/r/908244

Change 908244 merged by Ottomata:

[operations/deployment-charts@master] Update all eventgate clusters to same image version

https://gerrit.wikimedia.org/r/908244

maybe it is worth to update all instances with the same code

Done, still seeing same errors. FWIW, the image version bumps were just for schema repo updates to eventgate-main.

Tried to do a little debugging today but not with much luck.

The "message timed out" is ultimately from librdkafka. When I restart a pod, it takes several minutes before there errors start showing up, which makes sense, given that the default Kafka message.timeout.ms is 5 minutes.

Change 909954 had a related patch set uploaded (by Elukey; author: Elukey):

[operations/deployment-charts@master] services: add kafka-logging200[4,5] IPs to eventgate-logging-external

https://gerrit.wikimedia.org/r/909954

I think that this is related to the new kafka logging configs (see T326419). I filed a code change to fix it, but we should figure out how to proceed :)

Change 909954 merged by Elukey:

[operations/deployment-charts@master] services: modify Kafka logging IPs in eventgate-logging-external

https://gerrit.wikimedia.org/r/909954

Yep I can't reproduce the timeout issue anymore, it was definitely due to the new kafka brokers.

Thanks so much for troubleshooting this @elukey.
It occurs to me that we might even be able to make a further improvement by making use of the specific kafka templates a bit more.

We have a mechanism for automatically generating network policies for given kafka clusters, as can be seen [[https://github.com/wikimedia/operations-deployment-charts/blob/master/modules/base/networkpolicy_1.0.0.tpl#L32-L48|here]

I know that we had a bump for eventgate to use common_templates in T303543: eventgate chart should use common_templates and it's since been converted to use the new modules system

I think that we will have to:

  1. add values for .Values.kafka.allowed_clusters to helmfile.d/services/eventgate-*/values-${site}.yaml files
  2. add {{- define "base.networkpolicy.egress.kafka" -}} to charts/eventgate/templates/networkpolicy.yaml

I'll make a follow-up ticket, so we can investigate this, otherwise we might run into the same issue with eventgate whenever we expand/refresh the kafka clusters.

Is there anything to be done here around making this easier to diagnose?

Better logging (whether in our own code or in librdkafka), some consistency checks in monitoring or elsewhere, etc?

In hindsight, The log messages from eventgate were pretty clear. Timeout errors talking to Kafka. I knew of the new kafka logging-eqiad brokers, but the broker hostname configuration looked mostly correct to me, and I didn't even consider the IP based egress rules.

What would have been nicer would be to have known about these errors from an alert other than the email that produce_canary_events job sends to data engineering. That was just an (un)lucky symptom.

I would have expected to see 500s in the eventgate HTTP error metrics. EventGate should return 500 when this happens.

Is there anything to be done here around making this easier to diagnose?

Making sure 5xx errors are in metrics, and alerting when too many of them.

Change 911872 had a related patch set uploaded (by Herron; author: Herron):

[operations/deployment-charts@master] services: add kafka-logging100[12] to network rules and broker list

https://gerrit.wikimedia.org/r/911872

Change 911872 merged by Elukey:

[operations/deployment-charts@master] services: add kafka-logging100[12] to network rules and broker list

https://gerrit.wikimedia.org/r/911872