Mirror manager check-in with mirrormanager2-client-1.0.0-5.fc41.noarch (rawhide) fails for the last ~24 hours with:
... 'global': { 'enabled': '1', 'server': 'https://admin.fedoraproject.org/mirrormanager/xmlrpc'}, 'host': {'enabled': '1', 'name': 'apt.declera.com'}, ... Error checking in: Service Temporarily Unavailable. Please try again later.
Has been working OK for daily check-ins for a while.
Metadata Update from @zlopez: - Issue priority set to: Waiting on Assignee (was: Needs Review) - Issue tagged with: dev, high-gain, medium-trouble
This seems to be related to new deployment of mirrormanager. @abompard Do you know what is happening here?
I'm also running into this.
I added some debug output so here it is in case it helps.
<ServerProxy for admin.fedoraproject.org/mirrormanager/xmlrpc> send: b'POST /mirrormanager/xmlrpc HTTP/1.1\r\nHost: admin.fedoraproject.org\r\nAccept-Encoding: gzip\r\nContent-Type: text/xml\r\nUser-Agent: Python-xmlrpc/3.11\r\nContent-Length: 5535\r\n\r\n' send: b"<?xml version='1.0'?>\n<methodCall>\n<methodName>checkin</methodName>\n<params>\n<param>\n<value><string>..........snip............</string></value>\n</param>\n</params>\n</methodCall>\n" reply: 'HTTP/1.1 302 Found\r\n' header: Date: Sat, 01 Jun 2024 04:07:21 GMT header: Server: Apache header: Strict-Transport-Security: max-age=31536000; includeSubDomains; preload header: X-Frame-Options: SAMEORIGIN header: X-Xss-Protection: 1; mode=block header: X-Content-Type-Options: nosniff header: Referrer-Policy: same-origin header: Location: https://mirrormanager.fedoraproject.org/xmlrpc header: Content-Length: 230 header: Content-Type: text/html; charset=iso-8859-1 header: AppTime: D=29695 header: X-Fedora-ProxyServer: proxy04.fedoraproject.org header: X-Fedora-RequestID: ZlqeeTV4BAuiKA1-wU7WNgAAA5g
Not only the private mirror was affected, on the public mirror we observe that the mirrormanager frequently requests the file list of the same path through rsync, and the crawler running time is much longer than before, and it cannot even be completed.
This results in many mirrors being marked as outdate, and the number of available mirrors is decreasing.
Changing server= in the config to the redirected url actually makes report _mirror work, so...
I can confirm this works for me too.
Oh, right, I added a redirect to the new location but didn't realize that the XML-RPC client would not follow it. I'll push out a new RPM, but it may take a while as the new version has dependencies that are not yet packaged in Fedora. In the meantime, the best solution is to edit the config file indeed. Sorry about that.
Not only the private mirror was affected, on the public mirror we observe that the mirrormanager frequently requests the file list of the same path through rsync, and the crawler running time is much longer than before, and it cannot even be completed. This results in many mirrors being marked as outdate, and the number of available mirrors is decreasing.
I'm interested in that as well @james58899 : do you have details on those duplicated paths? And at what time? I haven't removed the crawl coming from the staging environment yet, could it be that? ? (it would come from a different IP (I suppose?) ). I'll need to know which mirrors are affected as well, please. Thanks!
Metadata Update from @abompard: - Issue assigned to abompard
All from the same IP (38.145.60.3), it's happening right now. This is the log on our server:
Jun 03 15:20:25 twds-mirror rsyncd[2669548]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:20:25 twds-mirror rsyncd[2669548]: rsync allowed access on module centos-stream from UNDETERMINED (38.145.60.3) Jun 03 15:20:25 twds-mirror rsyncd[2669548]: rsync on centos-stream/ from UNDETERMINED (38.145.60.3) Jun 03 15:20:26 twds-mirror rsyncd[2669548]: building file list Jun 03 15:21:02 twds-mirror rsyncd[2668822]: sent 15393877 bytes received 5011 bytes total size 552351795680 Jun 03 15:21:05 twds-mirror rsyncd[2670012]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:21:06 twds-mirror rsyncd[2670012]: rsync allowed access on module fedora-epel from UNDETERMINED (38.145.60.3) Jun 03 15:21:06 twds-mirror rsyncd[2670012]: rsync on fedora-epel/ from UNDETERMINED (38.145.60.3) Jun 03 15:21:07 twds-mirror rsyncd[2670012]: building file list Jun 03 15:21:45 twds-mirror rsyncd[2669548]: sent 18881800 bytes received 6783 bytes total size 2489648942294 Jun 03 15:21:46 twds-mirror rsyncd[2670383]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:21:46 twds-mirror rsyncd[2670383]: rsync allowed access on module centos-stream from UNDETERMINED (38.145.60.3) Jun 03 15:21:47 twds-mirror rsyncd[2670383]: rsync on centos-stream/ from UNDETERMINED (38.145.60.3) Jun 03 15:21:47 twds-mirror rsyncd[2670383]: building file list Jun 03 15:22:21 twds-mirror rsyncd[2670012]: sent 15393869 bytes received 5071 bytes total size 552351795680 Jun 03 15:22:22 twds-mirror rsyncd[2670701]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:22:22 twds-mirror rsyncd[2670701]: rsync allowed access on module fedora-epel from UNDETERMINED (38.145.60.3) Jun 03 15:22:22 twds-mirror rsyncd[2670701]: rsync on fedora-epel/ from UNDETERMINED (38.145.60.3) Jun 03 15:22:23 twds-mirror rsyncd[2670701]: building file list Jun 03 15:22:54 twds-mirror rsyncd[2668161]: sent 80917557 bytes received 11076 bytes total size 3145772639617 Jun 03 15:22:57 twds-mirror rsyncd[2671011]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:22:57 twds-mirror rsyncd[2671011]: rsync allowed access on module fedora-secondary from UNDETERMINED (38.145.60.3) Jun 03 15:22:57 twds-mirror rsyncd[2671011]: rsync on fedora-secondary/ from UNDETERMINED (38.145.60.3) Jun 03 15:22:58 twds-mirror rsyncd[2671011]: building file list Jun 03 15:23:05 twds-mirror rsyncd[2670383]: sent 18881832 bytes received 6835 bytes total size 2489648942294 Jun 03 15:23:06 twds-mirror rsyncd[2671102]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:23:06 twds-mirror rsyncd[2671102]: rsync allowed access on module centos-stream from UNDETERMINED (38.145.60.3) Jun 03 15:23:07 twds-mirror rsyncd[2671102]: rsync on centos-stream/ from UNDETERMINED (38.145.60.3) Jun 03 15:23:07 twds-mirror rsyncd[2671102]: building file list Jun 03 15:23:36 twds-mirror rsyncd[2670701]: sent 15393853 bytes received 4455 bytes total size 552351795680 Jun 03 15:23:36 twds-mirror rsyncd[2671438]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:23:37 twds-mirror rsyncd[2671438]: rsync allowed access on module fedora-epel from UNDETERMINED (38.145.60.3) Jun 03 15:23:37 twds-mirror rsyncd[2671438]: rsync on fedora-epel/ from UNDETERMINED (38.145.60.3) Jun 03 15:23:38 twds-mirror rsyncd[2671438]: building file list Jun 03 15:24:04 twds-mirror rsyncd[2667878]: sent 101011085 bytes received 12450 bytes total size 5347978835806 Jun 03 15:24:08 twds-mirror rsyncd[2671724]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:24:08 twds-mirror rsyncd[2671724]: rsync allowed access on module fedora from UNDETERMINED (38.145.60.3) Jun 03 15:24:09 twds-mirror rsyncd[2671724]: rsync on fedora/linux/ from UNDETERMINED (38.145.60.3) Jun 03 15:24:09 twds-mirror rsyncd[2671724]: building file list Jun 03 15:24:25 twds-mirror rsyncd[2671102]: sent 18881788 bytes received 6459 bytes total size 2489648942294 Jun 03 15:24:28 twds-mirror rsyncd[2671963]: connect from UNDETERMINED (38.145.60.3) Jun 03 15:24:28 twds-mirror rsyncd[2671963]: rsync allowed access on module centos-stream from UNDETERMINED (38.145.60.3) Jun 03 15:24:28 twds-mirror rsyncd[2671963]: rsync on centos-stream/ from UNDETERMINED (38.145.60.3) Jun 03 15:24:29 twds-mirror rsyncd[2671963]: building file list Jun 03 15:24:53 twds-mirror rsyncd[2671438]: sent 15393881 bytes received 4883 bytes total size 552351795680
You can see that fedora-epel and centos-stream have been accessed repeatedly. Fedora and fedora-secondary modules are also the same, but it takes a long time to generate the file list. This mirror is https://mirrormanager.fedoraproject.org/host/3012
Thanks @james58899 , I think I found the issue. I've fixed it, it should be OK for the next crawler run.
@abompard I just checked the crawler log and found that almost all files were treated as non-existent...
Hi @james58899 , I'm trying to look into what causing the files not being recognized, and I get an rsync error:
@ERROR: access denied to centos-stream from UNDETERMINED (38.145.60.3) rsync error: error starting client-server protocol (code 5) at main.c(1859) [Receiver=3.2.7]
Do you have something about that in your server logs? Thanks.
Hi @james58899 , I'm trying to look into what causing the files not being recognized, and I get an rsync error: @ERROR: access denied to centos-stream from UNDETERMINED (38.145.60.3) rsync error: error starting client-server protocol (code 5) at main.c(1859) [Receiver=3.2.7] Do you have something about that in your server logs? Thanks.
Because the rsync crawler still doesn't seem to be working properly, we temporarily block it and let it fall back to http.
Do I need to unblock it or can you look at other mirrors first? I think all mirrors that support rsync have the same problem, because none of them exist in metalink.
Ah OK, I'll have a look at other rsync mirrors first then. Thanks.
I've seen examples of rsync-based mirrors being crawled successfully, I think you can re-enable it @james58899
OK, I've unblocked it.
Hey @abompard I think I found the problem, it should be == instead of != on this line.
Oh, right, I'll fix it right now. Thanks for debugging it, I couldn't test the rsync crawler as much as the other ones because no mirrors with rsync are available from our staging env
So whats the status here? The fix is to update to the new host right?
So we can close this one?
The mirror is listed as active in MirrorManager, so I think it's OK to close this ticket. Please reopen if there's still something to do here.
Metadata Update from @abompard: - Issue close_status updated to: Fixed - Issue status updated to: Closed (was: Open)
Log in to comment on this ticket.