One fun way to try to tackle this problem would be to try to rewrite https://github.com/fedora-infra/mirrormanager2/tree/master/mirrorlist into Rust and use actix-web/raw http server [0]. Currently it is httpd+mod_wsgi+python - i believe this might be a potential bottleneck although it is just a wild guess (some stress tests could help confirming that).

Just mentioning the possibility. I tried to kind of figure out the problem yesterday and didn't really figure out anything. Maybe you can just do some simple tweak to the setup....but not sure about it.

[0] https://www.techempower.com/benchmarks/#section=test&runid=bebca46e-899f-4958-8052-d5f5f5c81eb2&hw=ph&test=plaintext

(btw. there also used to be a problem with downloading from dl.fedoraproject.org but that is some other problem)

clime, thank you for the suggestion. I am not sure we could get to a rewrite until 2021? at our current list of projects. If you want to tackle it yourself that is cool. Please be aware that the majority of complications in mirror-managing is are all the real world exceptions which are either in the database or logic of when to serve something.

OK I have been looking at this over the weekend. So there are two levels of 503 noise. In general the noise of 503's has been 0.2% per day

Date , #of503 , #of200 , #total , %of503/day
2018-12-01 , 56941 , 22975383 , 23032364 , 0.247222 %
2018-12-02 , 51907 , 21645387 , 21697357 , 0.239232 %
2018-12-03 , 41263 , 22073050 , 22114356 , 0.186589 %
2018-12-04 , 117510 , 22660837 , 22778394 , 0.515884 %
2018-12-05 , 2386 , 23480396 , 23482824 , 0.0101606 %
2018-12-06 , 3384 , 23336208 , 23339629 , 0.0144989 %
2018-12-07 , 7597 , 23438501 , 23446139 , 0.0324019 %
2018-12-08 , 3892 , 23323290 , 23327224 , 0.0166844 %
2018-12-09 , 6711 , 21665992 , 21672743 , 0.0309652 %
2018-12-10 , 1478 , 22155013 , 22156533 , 0.00667072 %
2018-12-11 , 2996 , 23123085 , 23126125 , 0.012955 %
2018-12-12 , 10077 , 23559012 , 23569130 , 0.0427551 %
2018-12-13 , 15573 , 21206015 , 21221628 , 0.0733827 %
2018-12-14 , 9965 , 20995640 , 21005637 , 0.0474396 %
2018-12-15 , 6960 , 22198925 , 22205939 , 0.031343 %
2018-12-16 , 4578 , 21724817 , 21729395 , 0.0210682 %
2018-12-17 , 8238 , 14024545 , 14032807 , 0.0587053 %
2018-12-18 , 3699 , 8119437 , 8123221 , 0.0455361 %
2018-12-19 , 9182 , 18618230 , 18627723 , 0.0492921 %
2018-12-20 , 644040 , 23634904 , 24279894 , 2.65257 %
2018-12-21 , 56298 , 22842765 , 22899194 , 0.245851 %
2018-12-22 , 5200 , 22754292 , 22759528 , 0.0228476 %
2018-12-23 , 6818 , 21937969 , 21944846 , 0.0310688 %
2018-12-24 , 6835 , 22210581 , 22217633 , 0.0307639 %
2018-12-25 , 3745 , 22166182 , 22170037 , 0.0168922 %
2018-12-26 , 2357 , 21878709 , 21881106 , 0.0107719 %
2018-12-27 , 2341 , 22276147 , 22278530 , 0.0105079 %
2018-12-28 , 4339 , 22148998 , 22153378 , 0.0195862 %
2018-12-29 , 5870 , 22121341 , 22127251 , 0.0265284 %
2018-12-30 , 4922 , 21586852 , 21591814 , 0.0227957 %
2018-12-31 , 4544 , 21687980 , 21692564 , 0.0209473 %
2019-01-01 , 3345 , 21887063 , 21890448 , 0.0152806 %
2019-01-02 , 5130 , 21666348 , 21671518 , 0.0236716 %
2019-01-03 , 7277 , 22919189 , 22926506 , 0.0317406 %
2019-01-04 , 6410 , 23048159 , 23054613 , 0.0278035 %
2019-01-05 , 1722 , 22961006 , 22962765 , 0.0074991 %
2019-01-06 , 1728 , 21931856 , 21933631 , 0.00787831 %
2019-01-07 , 2401 , 19902351 , 19904789 , 0.0120624 %
2019-01-08 , 4417 , 19489918 , 19494360 , 0.0226578 %
2019-01-09 , 19699 , 21395976 , 21415748 , 0.0919837 %
2019-01-10 , 39810 , 23570751 , 23610640 , 0.16861 %
2019-01-11 , 40792 , 22956259 , 22997091 , 0.177379 %
2019-01-12 , 15202 , 23176596 , 23191840 , 0.0655489 %
2019-01-13 , 37766 , 22077268 , 22115076 , 0.17077 %
2019-01-14 , 24267 , 22094689 , 22118998 , 0.109711 %
2019-01-15 , 41517 , 23299131 , 23340689 , 0.177874 %
2019-01-16 , 35833 , 23574671 , 23610564 , 0.151767 %
2019-01-17 , 46661 , 23397469 , 23444199 , 0.19903 %
2019-01-18 , 66054 , 23552938 , 23619158 , 0.279663 %
2019-01-19 , 69131 , 23183530 , 23252918 , 0.2973 %
2019-01-20 , 86320 , 22185191 , 22271885 , 0.387574 %
2019-01-21 , 147824 , 22005857 , 22155267 , 0.667218 %
2019-01-22 , 185294 , 23268426 , 23455730 , 0.789973 %
2019-01-23 , 119633 , 23494097 , 23614549 , 0.506607 %
2019-01-24 , 162624 , 23510747 , 23674713 , 0.68691 %
2019-01-25 , 168543 , 23502620 , 23672633 , 0.711974 %
2019-01-26 , 492194 , 22589135 , 23081385 , 2.13243 %
2019-01-27 , 370126 , 21689837 , 22061944 , 1.67767 %
2019-01-28 , 336304 , 21702442 , 22041483 , 1.52578 %
2019-01-29 , 341971 , 23003396 , 23348205 , 1.46466 %
2019-01-30 , 536851 , 22747963 , 23289165 , 2.30515 %
2019-01-31 , 366617 , 23052978 , 23421699 , 1.56529 %
2019-02-01 , 239720 , 23339784 , 23581335 , 1.01657 %
2019-02-02 , 39806 , 23562370 , 23602217 , 0.168654 %
2019-02-03 , 196604 , 22371007 , 22567750 , 0.871172 %
2019-02-04 , 56619 , 22103783 , 22160483 , 0.255495 %
2019-02-05 , 46726 , 23538816 , 23585605 , 0.198112 %
2019-02-06 , 49002 , 23816568 , 23865650 , 0.205324 %

Just concentrating on the ip addresses for COPR and internal sees similar increase in 503's on the bad days. I am looking to see if we have a time frame which is more likely.

Is it from all proxies? Would it be possible to get stats only for proxy01? Because COPR is currently pointed to that one (by an /etc/hosts record).

Btw. i am ok with providing the rust implementation but I would need to make sure it is really load related first.

That was a merged log of all proxies. Looking at cloud requests on proxy01 look similar with an uptick starting at the end of January (here are snapshots)

./2019/01/05/  0 17592 17592 0 1
./2019/01/10/  4 14343 14347 0.000278804 0.999721
./2019/01/15/ 9 16841 16850 0.000534125 0.999466
./2019/01/20/  1 3655 3656 0.000273523 0.999726
./2019/01/25/  31 12818 12849 0.00241264 0.997587
./2019/01/30/  134 16434 16569 0.00808739 0.991852
./2019/02/01/  91 13609 13700 0.00664234 0.993358
./2019/02/02/  105 20296 20401 0.00514681 0.994853
./2019/02/03/  87 9831 9918 0.00877193 0.991228
./2019/02/04/  67 10623 10690 0.00626754 0.993732
./2019/02/05/  66 11459 11525 0.00572668 0.994273
./2019/02/06/  72 15825 15897 0.00452916 0.995471
./2019/02/07/  81 15673 15754 0.00514155 0.994858
./2019/02/08/  53 15000 15053 0.00352089 0.996479

The majority of 503's seem to happen at the following hours:

  23734 04:
  20030 21:
  19593 20:
  19105 07:
  18678 23:

The least hours are

  10507 14:
   9202 09:
   8793 15:
   8146 10:
   7890 17:

The majority of them over a week seem to happen just after the top of the hour.

 254702 02:
  51121 01:
  35301 03:
   2420 00:
   1057 40:
   1003 23:
    925 04:
    158 38:
    127 30:
    114 43:
     91 41:
...

The problem may be load related or config related as we have a pkl change starting at the top of the hour but we also have the largest number of requests at the top of the hour:

 626354 05:
 619371 04:
 608320 06:
 607119 10:
 606728 15:
 594243 11:
 592665 03:
 587889 07:
 586602 12:
 584760 13:
 581538 09:
 577081 08:
 576055 14:
 467887 01:
 311640 02:
 282953 00:
 226961 30:

Looking at the data it seems that at :02 after the hour we will have close to 50% of all failures occurring.

The new pkl syncs out at about :55 after, but pods are not restarted until :15 after... so not sure what could be causing issues at top of the hour...

Looking at haproxy I see 0 errors, so it has to be something in the containers themselves.

I wonder if we shouldn't first get a updated container with httpd updates and see if that helps?

and/or try and get logs from in the container and try and see why it's sending that 5xx...

The new pkl syncs out at about :55 after, but pods are not restarted until :15 after... so not sure what could be causing issues at top of the hour...
Looking at haproxy I see 0 errors, so it has to be something in the containers themselves.

Does it mean that haproxy itself does not timeout when waiting for a response from the container but instead container itself gives 503s?

If the latter is the case, then the errors are most likely coming from here: https://github.com/fedora-infra/mirrormanager2/blob/master/mirrorlist/mirrorlist_client.wsgi#L145

So basically, if the error was socket.timeout there, we would know the mirrorlist server takes too long time to answer through the socket.

Potentially, also logging the response time (or only those >1s) in the mirrorlist client could give some clues.

Does it mean that haproxy itself does not timeout when waiting for a response from the container but instead container itself gives 503s?

Yes, I think so.

If the latter is the case, then the errors are most likely coming from here: https://github.com/fedora-infra/mirrormanager2/blob/master/mirrorlist/mirrorlist_client.wsgi#L145
So basically, if the error was socket.timeout there, we would know the mirrorlist server takes too long time to answer through the socket.
Potentially, also logging the response time (or only those >1s) in the mirrorlist client could give some clues.

Adding @adrian for input here too.

I am following this discussion, but I cannot really comment. The MirrorManager instances I am running for another repository has 2000000 hits per day distributed on four mirrorlist servers.

I do not see any 503, but I am only running the mirrorlist directly without any containers or proxies in between. The only problems I had was memory related. never CPU related.

So the only things I have access to it just works, but it has less load than the Fedora instances.

The strange thing about this is, is that it seems to be a new problem.

So looking at the data, we have had 503's regularly for many years.. with it dipping and growing depending on where and how mirrorlist is set up. I think the major problem is that we see a large influx of connections at the beginning of every hour. We serve over 20 million requests a day but
38% go from :00 to :10 minutes and 23% from 10 minutes to 20% minutes. All the rest of the hour we seem to equal amounts.

It is probably worse than that because the time in the log is when we responded to their request versus when they requested it.

OK looking in the container the problem that is being reported is:

[Wed Feb 13 21:02:36.774319 2019] [wsgi:error] [pid 26286:tid 140136494905088] (11)Resource temporarily unavailable: [client 10.88.0.1:58258] mod_wsgi (pid=26286): Unable to connect to WSGI daemon process 'mirrorlist' on '/run/httpd/wsgi.9.0.1.sock' after multiple attempts as listener backlog limit was exceeded or the socket does not exist.
[Wed Feb 13 21:02:36.774350 2019] [wsgi:error] [pid 26286:tid 140136520083200] (11)Resource temporarily unavailable: [client 10.88.0.1:58248] mod_wsgi (pid=26286): Unable to connect to WSGI daemon process 'mirrorlist' on '/run/httpd/wsgi.9.0.1.sock' after multiple attempts as listener backlog limit was exceeded or the socket does not exist.
[Wed Feb 13 21:02:36.774443 2019] [wsgi:error] [pid 26286:tid 140136125822720] (11)Resource temporarily unavailable: [client 10.88.0.1:58250] mod_wsgi (pid=26286): Unable to connect to WSGI daemon process 'mirrorlist' on '/run/httpd/wsgi.9.0.1.sock' after multiple attempts as listener backlog limit was exceeded or the socket does not exist.
[Wed Feb 13 21:02:36.774228 2019] [wsgi:error] [pid 26286:tid 140136058681088] (11)Resource temporarily unavailable: [client 10.88.0.1:58228] mod_wsgi (pid=26286): Unable to connect to WSGI daemon process 'mirrorlist' on '/run/httpd/wsgi.9.0.1.sock' after multiple attempts as listener backlog limit was exceeded or the socket does not exist.

The file does exist.. so it must be an overload problem that happens at the rampaging bulls of :00 minutes

srwx------. 1 apache root      0 Feb 13 20:20 wsgi.9.0.1.sock=

OK it looks like we have too many requests at once for our 60 threads and we need to play around with WSGI options:

WSGIDaemonProcess mirrorlist user=apache processes=60 threads=1 display-name=mirrorlist maximum-requests=1000

The older mirrormanager configs had less processes and more so I am thinking of dropping that down to 45 and increase the backlog queue and queue timeout

WSGIDaemonProcess mirrorlist user=apache processes=20 threads=1 display-name=mirrorlist graceful-timeout=30 maximum-requests=1000 request-timeout=30 listen-backlog=1000 queue-timeout=30

In the containers we are just using the stock config in the mirrormanager2-mirrorlist package, which is:

WSGIDaemonProcess mirrorlist user=apache processes=45 threads=1 display-name=mirrorlist maximum-requests=1000

so, only 45 instead of 60... but otherwise yeah.

I can try and build a test container tomorrow with the proposed changes and we can try it out.
Thanks for the detective work smooge!

Maybe it's a nooby remark but I recommend also having look at net.core.somaxconn in /etc/sysctl.conf because the settings affects max backlog size afaik.

That is what I get for reading ansible files (I was reading roles/mirrormanager/mirrorlist2/templates/mirrorlist-server.conf )

An updated container has been pushed out to all the proxies and for the last couple of bad periods the system has not given any 503's. I have also found that the majority of the 503's for the last 2 days have been on one proxy (proxy01.fedoraproject.org) which makes sense if copr has hard-wired it as the proxy to use.

With the updates to this and the updates to the copr builders we should see how this does over the weekend.

An updated container has been pushed out to all the proxies and for the last couple of bad periods the system has not given any 503's. I have also found that the majority of the 503's for the last 2 days have been on one proxy (proxy01.fedoraproject.org) which makes sense if copr has hard-wired it as the proxy to use.
With the updates to this and the updates to the copr builders we should see how this does over the weekend.

This is great news! I wanted to ask whether tweaking net.core.somaxconn wasn't needed in the end? I would assume the listen backlog is still trimmed down to 128, which default for net.core.somaxconn on f29.

OK we are down by 3 orders of magnitude with only a couple hundred on the proxies during the worst hours of 04:00.

@clime I didn't make the change to the somaxconn. I was thinking these were two different backlogs but it does seem that my backlog change is not really the fix. So the fix should be:

request-timeout=30
 queue-timeout=30

or something in containers is getting larger than somaxconn

@smooge

I needed to look it up:

At:

https://github.com/GrahamDumpleton/mod_wsgi/blob/develop/src/server/mod_wsgi.c#L8520

there is:

listen(sockfd, process->listen_backlog)

and from man listen:

   int listen(int sockfd, int backlog);
   ....
   If  the backlog argument is greater than the value in /proc/sys/net/core/somaxconn, then it is silently truncated to that value; the default value in this file is 128.  In kernels
   before 2.4.25, this limit was a hard coded value, SOMAXCONN, with the value 128.

So maybe it would be worth to check /proc/sys/net/core/somaxconn in the container and raise the value if it is lower than 1000.

But if we are down by 3 orders of magnitude, we could maybe also just say we are done here. Great job.

But yeah, it would also be worth checking that we didn't raise occurrence of some other return codes than 503. E.g. lowering queue-timeout can produce more 504s.

so looking at the errors.. we only see a couple hundred 504's a week. I will check to see if we see more over the weekend or so. There has been a pickup on proxy01 since I first checked this morning but we are down 1 order of magnitude

[root@proxy01 ~][PROD]# xzcat /var/log/httpd/mirrors.fedoraproject.org-access.log-20190212.xz | awk '{if (($7~/metalink.repo/)||($7~/mirrorlist.repo/)){print $9}}' | sort | uniq -c | sort -bnr
2388477 200
48444 503
40 502
[root@proxy01 ~][PROD]# xzcat /var/log/httpd/mirrors.fedoraproject.org-access.log-20190213.xz | awk '{if (($7~/metalink.repo/)||($7~/mirrorlist.repo/)){print $9}}' | sort | uniq -c | sort -bnr
2442433 200
57328 503
3 504
[root@proxy01 ~][PROD]# xzcat /var/log/httpd/mirrors.fedoraproject.org-access.log-20190214.xz | awk '{if (($7~/metalink.repo/)||($7~/mirrorlist.repo/)){print $9}}' | sort | uniq -c | sort -bnr
2402769 200
53979 503
43 504
[root@proxy01 ~][PROD]# xzcat /var/log/httpd/mirrors.fedoraproject.org-access.log-20190215.xz | awk '{if (($7~/metalink.repo/)||($7~/mirrorlist.repo/)){print $9}}' | sort | uniq -c | sort -bnr
2341806 200
38110 503
107 502
[root@proxy01 ~][PROD]# cat /var/log/httpd/mirrors.fedoraproject.org-access.log | awk '{if (($7~/metalink.repo/)||($7~/mirrorlist.repo/)){print $9}}' | sort | uniq -c | sort -bnr
1296123 200
4090 503

OK the pickup happened at 13:00 and 15:00 UTC when a large number failed. I have upped /proc/sys/net/core/somaxconn and will see if that helps lower that

OK the pickup happened at 13:00 and 15:00 UTC when a large number failed. I have upped /proc/sys/net/core/somaxconn and will see if that helps lower that

Thank you!

Working with @clime and @kevin on IRC we found that the container did not have the items I thought were inherited. We have added a change to the podman run command and are testing if that helps lower the problem down furhter.

So, where are we now? Can we close this?

I know it's vastly better, but not sure what else we can do...

I have gone through the last couple of weeks of data, and we only have 1 proxy with problems which we will need to drop from mirrors I think. However even its number of 503's is only in the low thousands unless more traffic hits it during an outage.

Closing this as done :massage: