502 error from long running koji connections (watch-task, chainbuild, watch-logs) #12913
Labels
No labels
announcement
anubis
authentication
aws
backlog
blocked
bodhi
ci
cloud
communishift
copr
database
day-to-day
dc-move
deprecated
dev
discourse
dns
downloads
easyfix
epel
firmitas
forgejo_migration
Gain
High
Gain
Low
Gain
Medium
gitlab
greenwave
hardware
help wanted
high-trouble
koji
koschei
lists
low-trouble
medium-trouble
mirrorlists
monitoring
Needs investigation
odcs
OpenShift
ops
outage
packager_workflow_blocker
pagure
permissions
Priority
Needs Review
Priority
Next Meeting
Priority
🔥 URGENT 🔥
Priority
Waiting on Assignee
Priority
Waiting on External
Priority
Waiting on Reporter
rabbitmq
release-monitoring
releng
request-for-resources
s390x
security
SMTP
sprint-0
sprint-1
src.fp.o
staging
unfreeze
waiverdb
websites-general
wiki
Backlog Status
Needs Review
Backlog Status
Ready
chore
documentation
points
01
points
02
points
03
points
05
points
08
points
13
Priority
High
Priority
Low
Priority
Medium
Sprint Status
Blocked
Sprint Status
Done
Sprint Status
In Progress
Sprint Status
Review
Sprint Status
To Do
Technical Debt
Work Item
Bug
Work Item
Epic
Work Item
Spike
Work Item
Task
Work Item
User Story
No milestone
No project
No assignees
10 participants
Notifications
Due date
No due date set.
Dependencies
No dependencies set.
Reference
infra/tickets#12913
Loading…
Add table
Add a link
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
Since the firewall cluster upgade eariler this week, users have been reporting koji cli giving a:
502 Server Error: Bad Gateway for url: https://koji.fedoraproject.org/kojihub
This is easily duplicated by picking a large/long running build and running a watch-logs on it.
The error doesn't actually affect the underlying tasks, it just errors on the client end, and the user can re-run their watch to resume (but then it will fail again)
The traceback from this looks like this here (rawhide koji):
related/other mentions:
https://pagure.io/fedora-infrastructure/issue/12814#comment-993194
https://pagure.io/releng/issue/13087
So, seems likely something in the new firewall os is somehow being more aggressive in closing connections.
It's worth noting that I see the 502 in the proxy access logs, but there's no error in error log or anything in koji hub log
@mikem have any thoughts on this? would koji be trying to reuse a closed connection here? I can look at adding some kind of keepalives, but we didn't need them before and I would prefer to reason out what to add before we try too much.
Oops. The releng ticket is not related. It's an unrelated outage this morning.
Koji uses a python-requests session for all hub connections, which automatically uses keep-alive. Also keep-alive is the default in the http standard since http/1.1. Koji should automatically detect when a connection gets closed and make a new one. However, the symptom here is not a connection closing, but an active connection returning a 502.
What is probably happening is that the http connection from the proxy to the backend hub is timing out before the the http connection from the client to the proxy. What are the keep-alive timeout settings on each? You probably want to make sure the proxy keep-alive timeout is shorter than the backend.
Fwiw, koji clients can probably work around this by setting
anon_retry=truein their koji config, but I think the real fix should be in the proxy setup.I set the hub to 16s, and the proxies are 15s... but something is still not working right. I was still able to get a 502.
Well, worth a shot at least.
I still haven't replicated it on my end
I did get it to happen once here, but takes a while
ok, we had a mass update/reboot cycle and since then I cannot get it to happen here.
I have been watching a webkitgtk build for 2+ hours now and no problems.
Can you all see if you can duplicate it now?
I can still get it to happen if I let something poll the hub of several hours. Most recently,
Saw it multiple times this morning, including within seconds of doing a
fedpkg build.@adamwill do you have a custom poll_interval setting for koji?
I don't believe so. If I did, where would it be set? The string
polldoesn't appear in my/etc/koji.conf.It's not something most people adjust, but I wanted to make sure for replication purposes. Koji pulls settings from ~/.koji/config, /etc/koji.conf, and /etc/koji.conf.d*
I've been playing with this and while I can't make it replicate readily, I have noticed that backend connection changes during the course of keepalive (at least according to the
X-Fedora-Appserverheader).This implies the two layers of keepalive are untethered. Perhaps the proxy is just grabbing a connection from a pool each time (unless it is not using keepalive?). So my suggestion to make the inner keepalive timeout longer doesn't solve the issue (though perhaps a longer timeout might reduce the problem).
If I spam the hub with
hellocalls (a no-op) as fast as I can, it takes about 10-15 min to hit it. It seems to happen with both proxy01 and proxy10. If I disable keepalive, it takes longer to hit it, but this is probably just because keepalive allows for a faster rate of calls.Unfortunately, this doesn't really give any great insight into what is happening.
Here is my best guess -- the proxy is using a pool of keepalive connections to the backends and not quite handling the inherent race condition in the http keepalive spec. The race happens when the keepalive timeout happens just barely after the client (in this case the proxy) decides to reuse the connection. It fails to connect and passes the error on.
You can see a different example of this race here -- https://github.com/mikem23/keepalive-race
(this code is specific to python-requests, but the general race could happen with different tools).
If this is a race condition, then it seems I'm quite unlucky, because I appear to have been hitting it consistently a few times per minute for the past hour or so. :(
As noted above, folks can work around this by setting anon_retry=true in their koji config.
Just FTR, my experience in past two days is that Zuul is basically unusable for Ruby builds due to this 🤷
https://fedora.softwarefactory-project.io/zuul/build/41e6b1e4e3ef42ed8fb1e372c097e440
While this is an infra issue, not a Koji issue, the anon_retry setting for Koji can help. I'm going to change the default to True in the upcoming release. https://pagure.io/koji/pull-request/4517
In the meantime, any systems that are running into this should be able to just set
anon_retry=truein their koji configs.My script to replicate this is hitting it much faster today. I'm getting it in about 45s instead of the 10-15m I reported before.
Most recently, the script hit it on call number 570.
If I look at the access logs on the hub, I only see entries for the successful calls. The unsuccessful one does not appear to be reaching either of the backend hubs. (Granted this is not surprising, but nice to confirm)
291 + 278 = 569
I.e. one short of the total number of calls in the test run.
None of the access.log entries for my test calls show anything other than a 200 result
(and same on koji02)
@mikem Is this still happening?
Was there some change? I think it was happening e.g. 3 days ago:
https://src.fedoraproject.org/rpms/ruby/pull-request/226#comment-301595
More recent:
https://src.fedoraproject.org/rpms/cucumber-messages/pull-request/2#comment-302505
That is almost surely related to the mass rebuild... nothing to do with this ticket.
I was still seeing this when I finally tried the workaround from https://pagure.io/fedora-infrastructure/issue/12913#comment-993744 last week. I will comment out the workaround and report back if/when I see this again.
To be clear, I haven't done anything to fix this issue, was just saying that those PR issues looked like timeouts caused by the mass rebuild in ci.
But it would indeed be good to know if it's still there or not.
fwiw, https://pagure.io/koji/pull-request/4517 was merged and will be in the upcoming 1.36 Koji release. This doesn't fix whatever underlying issue is happening with Fedora's proxy, but it should lessen the impact for the Koji cli.
I ran my replication script just now. It reproduced the issue in 1m1.953s (1068 calls).
And this morning, 2m17.555s (2316 calls)
I'm definitely seeing this today, eg:
While it's recoverable when doing builds by hand, it breaks my automation for the OCaml rebuild.
Hey everyone, I've opened a PR to fix this.
As @mikem suspected, this is a
mod_proxykeep-alive race condition. Because the proxy and backend keep-alive pools are untethered, the proxy occasionally tries to hand off a pooled connection to a client right as the Koji backend (which has a 16s timeout) closes it.The PR adds
keepalive=on ttl=10to the Kojiproxyoptsin the reverse proxy playbook. This forces Apache to proactively expire its pooled backend connections after 10 seconds, well before the Koji hub ever gets the chance to close them. There should be no more 502s on long-running tasks.infra/ansible#3173
Also check this:
Reference: Apache mod_proxy documentation
Thanks! Excited to see progress on this.
I've merged this and am deploying to staging.
If folks could test against staging that would be great.
Caveat. I've never pointed my script at stage, so I don't have a proper baseline to compare against there.
That said, it's been running for about 20 minutes without error. (In comparison, it encountered the issue on prod in less than 5 minutes just beforehand).
So, stage seems fine, but I technically do not know if the problem was manifesting there before.
Yeah, I think it was... and I've been testing here too and it seems ok.
So, lets try production! Deploying now...
All deployed. Test away.
I still hit one...
2026-03-11 15:58:13,415 [ERROR] koji: HTTPError: 502 Server Error: Bad Gateway for url: https://koji.fedoraproject.org/kojihub
ok, so looking closer at mikem's debug logs where max=450 was showing up, that wasn't a static limit - it was actually counting down from 500.
It turns out our backend Apache configs (kojiweb and the proxy httpd.conf specifically) had MaxKeepAliveRequests 500 hardcoded. If a script spams the hub fast enough to bypass the 10-second idle ttl we just added, it hits exactly 500 requests and the backend just ruthlessly drops the connection. If the proxy tries to hand off a new request to that pooled connection at that exact second, we get the 502.
I've put up a new PR to set MaxKeepAliveRequests 0 (unlimited) on the backend templates so it never hangs up on the proxy unexpectedly. Our previous ttl=10 fix is still completely necessary to clean up idle connections, so the two together should finally kill this bug.
PR is here: infra/ansible#3213
Let's see if that works
fwiw, I ran my script against prod for 40m yesterday after the deployment and did not see an error
BUT, today is a different story. My script is hitting the issue in less than a minute reliably (against prod)
I'm also seeing a number of aborted connections this morning. That seems new.
So, that might be related to the kojipkgs outage / issue this morning, as that was likely filling up connection slots for other applications since they all use the same proxies.
Can you retest now?
@mikem @kevin If we are going to retest I suggest also merging infra/ansible#3213 too so we can double whammy the issue and fix it once and for all
well, I would kind of like @mikem to confirm he's still seeing it, but only after 500 requests before we do that...
because if the underlying issue isn't solved, thats not going to help.
Still seeing it on prod, roughly every 20s right now
Only gateway errors though. Not seeing the aborted connections anymore, at least so far.
Actually I did get one aborted connection in the run. In about 10m, got 19 gateway errors and 1 aborted connection.
Anyway, happy to test whenever
FWIW, I am still seeing occasional
Could not execute scratch_build: 502 Server Error: Bad Gateway for url: https://koji.fedoraproject.org/kojihubduring the watch-logs part of a few recent fedpkg scratch-builds, although the scratch build does seem to complete.Yes, still happening quite readily if I run my test.
Also, I now see a number of connection aborted errors in the mix (about 1 in 5 of them them morning).
FWIW, there was a DDOS against out wiki this morning and those pass through the same proxies, so might have caused instablity in other applications.
ok, I merged infra/ansible#3213 and it did seem to help in staging, so I pushed to prod too.
Can everyone test and see if things seem better?
I ran my script and got plenty of errors still.
Got 50 errors in 422.66 secRight now was possibly a bad time to run it, as we were rebooting stuff for copyfail. Can you try again?
Perhaps not surprising, but a data point: I get the gateway errors even if I disable keepalive on the client end (though of course more slowly)
Looking at infra/ansible!3213 I see it sets
MaxKeepAliveRequests 0in multiple http conf templates -- httpd.conf, kojihub.conf, and kojiweb.conf.If I look at the config on koji01, I do not see this setting applied in /etc/httpd/conf/httpd.conf, just the other two.
It might be useful to add %k to LogFormat for the httpd access logs (unless that breaks something?)
Yeah, koji01 includes all the /etc/httpd/conf.d/*.conf files, so that gets applied in kojihub/kojiweb.conf... httpd.conf is on the proxy side.
Yeah, adding %k would be good...
I just used claude to look at all the things we tried here and what could be missing and it found one thing.
I have fixed that... can folks please retest? I can push the fix to ansible if it turns out to be the fix.
Running the test script and so far: Got 0 errors in 367.63 sec
and did a watch-logs on a big build and it's going along fine.
I'm still seeing errors at the moment
Ah bummer. ok. I will keep digging...
I pushed a number of changes out now:
I'll see if I can find more. :(
ok, found a few more things.
Can you retest? So far here no errors... but you seem to get them a lot quicker/more often than I do for some reason. ;(
ok. I got annoyed and spent more time adding debugging and digging and now I think I see the actual issue.
It's the return path.
backend koji sever sends a 200 reply back -> anubis logs:
So, it's reading from the backend the reply (which was a 200) and gets a EOF and then sends back to the client the 502.
Unfortunately, anubis doesn't log the connection/host that got this, but matching up verbose apache logs shows the times match up, so I am pretty sure this is it.,
I'm trying to figure out what is causing that now. This may be causing other weird anubis things as well...
ok. I tweaked all the keepalives and other things I can think of.
Filed upstream: https://github.com/TecharoHQ/anubis/issues/1624
Getting less errors, but still getting them this morning
Just got a gateway error updating a forgejo PR. Related?
Quite ironically, submitting the above comment also gave me a gateway error
Quite possibly. I see anubis EOF messages, but it's hard to match them up to the request... they don't say what host/url/session/anything is involved.
So, yes, this could be happening on other services as well. ;(
ok. I patched anubis to log more for these cases. It didn't help too much, but reminded me that these are all POSTs...
so on proxy01.fedoraproject.org I set it to just bypass anubis for POSTs (we already just allow them in anubis policy).
Can you test against just proxy01 and see if you still can get it to fail?
This morning it seems about the same for me
Oh, you said
proxy01.fedoraproject.org. I don't know what url to hit there?nm, I figured it out ;)
Zero gateway errors in on proxy01 this morning
FWIW, https://github.com/fedora-copr/copr/issues/4110 seems to report a similar solution (disable anubis for POSTs).
ok. I have rolled out this workaround to prod for koji, riscv-koji and src (Those were the only ones where I was seeing this).
Can folks test and see if things look 'fixed'?
Yeah, that copr problem seems like it might be similar... I'm not sure if they implemented anything though.
i'm gonna close this now... if anyone sees this still happening, please re-open or file a new ticket and add the time/url/info.