Hello!
I run Cargobot -- an IRC bot that announces new and updated crates to #rust-bots on irc.mozilla.org. It discovers these crates by polling the crates.io API once per minute. The source code can be found here.
Recently, I've found that the requests made by the bot have been failing with 403 Forbidden. Indeed, when I run curl https://crates.io/api/v1/summary --verbose on that machine, I get the same response:
* Trying 50.16.227.190...
* Connected to crates.io (50.16.227.190) port 443 (#0)
* found 173 certificates in /etc/ssl/certs/ca-certificates.crt
* found 696 certificates in /etc/ssl/certs
* ALPN, offering http/1.1
* SSL connection using TLS1.2 / ECDHE_RSA_AES_128_GCM_SHA256
* server certificate verification OK
* server certificate status verification SKIPPED
* common name: crates.io (matched)
* server certificate expiration date OK
* server certificate activation date OK
* certificate public key: RSA
* certificate version: #3
* subject: CN=crates.io
* start date: Sun, 18 Mar 2018 00:14:17 GMT
* expire date: Sat, 16 Jun 2018 00:14:17 GMT
* issuer: C=US,O=Let's Encrypt,CN=Let's Encrypt Authority X3
* compression: NULL
* ALPN, server accepted to use http/1.1
> GET /api/v1/summary HTTP/1.1
> Host: crates.io
> User-Agent: curl/7.47.0
> Accept: */*
>
< HTTP/1.1 403 Forbidden
< Connection: keep-alive
< Server: nginx
< Date: Sat, 21 Apr 2018 06:56:10 GMT
< Content-Length: 211
< X-Xss-Protection: 1; mode=block
< Set-Cookie: cargo_session=sJIiNcfM9yvCHoGNENQaO8JrPoTF1c7xuZ6xe/LTieY=; HttpOnly; Secure; Path=/
< X-Frame-Options: SAMEORIGIN
< Content-Security-Policy: default-src 'self'; connect-src 'self' https://docs.rs https://static.crates.io; script-src 'self' 'unsafe-eval' https://www.google.com; style-src 'self' https://www.google.com https://ajax.googleapis.com; img-src *; object-src 'none'
< X-Content-Type-Options: nosniff
< Strict-Transport-Security: max-age=31536000
< Via: 1.1 vegur
<
* Connection #0 to host crates.io left intact
We are unable to process your request at this time. Please open an issue at https://github.com/rust-lang/crates.io or email [email protected] and provide the request id 9a403c22-18fb-4a46-a6ff-c6129cf2d8e9
Running the same command on my laptop returns the expected JSON data. It looks like all requests from the machine that runs Cargobot are being blocked.
What should I do to avoid getting this error? Should I increase the polling delay on Cargobot (to 2 or 5 minutes), or is crates.io too overzealous about blocking requests?
Thanks!
Can you provide either the IP your crawler is accessing from, or a request ID so I can look into our logs further?
@sgrif
IP address is 37.247.50.150.
Unfortunately my bot doesn't log request bodies so I don't have an ID for the requests it made. But the curl request I made afterward has ID 9a403c22-18fb-4a46-a6ff-c6129cf2d8e9 as per the description.
Your crawler was definitely hitting us much more than once per minute. It was every few seconds. It was primarily blocked because /api/v1/summary wasn't an endpoint we expected crawler traffic to, and it looked suspicious. Additionally, since it was blocked, it's been hitting us 5 times per second, every second nonstop which is not great behavior.
This crawler wasn't major load, it was mostly just one that we wanted to ensure was being used for something real and not just an abandoned bot somewhere since it was an uncommon endpoint. I'm happy to unblock it if you reduce your rate to once every few minutes. Also, it would be appreciated if you could introduce exponential backoff in the event that we actually do have load issues in the future, to ensure that you are not adding onto them.
seconding @sgrif here, we are working on a clearer crawler policy (expect a PR on monday!) but we understand that crates.io is a community resource that we need to ensure is being used by all in a friendly way. let us know if you want any help/documentation on crawler best practices! it will help us shape our new policies :)
Thanks for the info @sgrif !
I re-read the logs and confirmed that many of those requests were happening in the same second. Sorry about that :flushed:
After some investigation, I'm pretty sure the root cause relates to how the bot handles threads. When it encounters an IRC connection error, it kills the IRC thread but doesn't kill the crawler thread. So when the bot restarts, we end up with two copies of the crawler running at the same time. Multiply that by a few months and we get the behavior observed here.
(Implementation details; feel free to skip this.) That issue was caused by a misunderstanding of the slave-thread library, which my bot used for managing its threads. The intention was that one thread terminating would kill the other thread automatically. But for this automatic cleanup to work, every thread in the chain must have been created by slave-thread (see this comment by the author). Unfortunately, I didn't know about that invariant until this morning. I'll do an audit of the code later today.
I'm happy to unblock it if you reduce your rate to once every few minutes. Also, it would be appreciated if you could introduce exponential backoff in the event that we actually do have load issues in the future, to ensure that you are not adding onto them.
I'm all right with increasing the delay to 5 minutes. I considered exponential backoff, but I think just terminating the process on any error would be a safer solution. Automatic retrying is risky (as this incident shows!) and in my experience most errors need manual intervention anyway.
Okay, I've applied and tested the changes mentioned above. Can the bot please be unblocked? :)
Done. Will be keeping an eye on it and I'll comment here if we take further action.
Hi @ashleygwilliams, did that crawler policy ever get published? I can't find it, and I think I've been triggering the same sort of 403s.
The crawler policy hasn't been published yet. I'm going to prioritize it for the team to discuss this week. Feel free to email [email protected] with details about your case, and we'll get you sorted
Most helpful comment
Your crawler was definitely hitting us much more than once per minute. It was every few seconds. It was primarily blocked because
/api/v1/summarywasn't an endpoint we expected crawler traffic to, and it looked suspicious. Additionally, since it was blocked, it's been hitting us 5 times per second, every second nonstop which is not great behavior.This crawler wasn't major load, it was mostly just one that we wanted to ensure was being used for something real and not just an abandoned bot somewhere since it was an uncommon endpoint. I'm happy to unblock it if you reduce your rate to once every few minutes. Also, it would be appreciated if you could introduce exponential backoff in the event that we actually do have load issues in the future, to ensure that you are not adding onto them.