Crates.io: Crate in index but not in database

[carols10cents]

From https://github.com/rust-lang/crates.io-index/pull/11#issuecomment-400916853:

I'm not sure how version 0.1.1 showed up, but it's not on crates.io web (crates.io/crates/linux_l6470) and the download URL gives a "Not Found" error: crates.io/api/v1/crates/linux_l6470/0.1.1/download

The missing download breaks some mirroring processes, so this change proposes to remove the metadata.

The metadata still says there's a valid, unyanked 0.1.1 version, but it doesn't exist.

[carols10cents]

So there are two problems here: fixing this version so it doesn't break mirroring processes, and fixing whatever made this fail.

Regarding fixing this version, @alexcrichton you said:

the current solution is to publish a new version.

Publishing, say, 0.1.2 won't fix that the index has 0.1.1 but the database doesn't? Unless you meant publish 0.1.1, which I think would just result in 2 git index entries for this crate?

Regarding figuring out what made this fail, I downloaded the logs from June 6 (the date this commit was made to the index) and found this:

940969961277521931       2018-06-06T10:45:43     2018-06-06T10:45:43Z    
57942823        crates-io       54.157.213.241  Local7  Info    app/web.2
at=error method=PUT path="/api/v1/crates/new" request_id=32b41f8f-4f26-4a02-ad7e-ffaec0bbe296 
fwd="85.5.94.54" service=283893ms status=500 
user_agent="cargo 1.26.0 (0e7c5a931 2018-04-06)" referer="" 
error="could not add crate `linux_l6470` to the git repo" SLOW REQUEST

which is great, because... adding it to the git repo is the only thing it DID do :P That error message comes from here.

The commit was made at 2018-06-06T10:43:41Z and the request time is 2018-06-06T10:45:43Z, not sure if that's useful... doesn't explain the full 283,893ms.

[sgrif]

It's probably just a coincidence, but the timing is extremely close to a Heroku timeout (however, the recorded response time should be just over 30 seconds in that case)

[alexcrichton]

Yeah publishing a new crate wouldn't delete the invalid line in the index, but it'd probably prevent anyone from using it

[carols10cents]

Except for the mirrors trying to download all crates in the index

[carols10cents]

From #1458:

I asked @alexcrichton about this and it looks like the crate was uploaded and deleted from S3 in a ~5-10 minute window which leads me to believe that we reverted the upload due to a failed index push or something along those lines.

But the index push didn't fail, which is the problem :(

To fix this particular crate (and thus crater), I think we should indeed remove this version from the index because it isn't on S3.

@alexcrichton do I need to make my own commit or can I merge https://github.com/rust-lang/crates.io-index/pull/11 now that we understand the situation more completely?

[alexcrichton]

Last we looked I remember this request probably hitting the 30s timeout limit, in which case the timeout on heroku may not have propagated to a timeout in the app meaning the github push succeeded and then when the write of the body failed to the client it undid the publish.

In general crates.io has no mechanism to rollback a github push, it assumes that if that succeeds everything succeeds and is ready to commit, but there may be a bug where we shouldn't have deleted the s3 crate when we did.

And sure yeah pushing up a commit is fine, I'd prefer to not do a merge.

[carols10cents]

Done: https://github.com/rust-lang/crates.io-index/commit/dffd660dca6382422fa31b41729d21f030ece187

[sgrif]

That still doesn't explain why the file isn't on s3

[jtgeibel]

Okay, here is my theory. Some unknown git operation failed while our git client was pushing to GitHub, such that GitHub saw the operation complete and updated HEAD but the client did not receive confirmation that the operation completed (and generated an error). I've seen similar behavior at work, where my connection to a particular cgit server is through a proxy. I don't know exactly what the proxy is interfering with, but when I first push up changes I receive some "RPC Error" message, but if I immediately push again I see "Already up to date."

My best guess is that there was some intermittent network error between us and GitHub. The log shows that the request took 4.72 minutes before failing, so I'm guessing that includes a few network timeouts before we either hit 20 iterations or some other intermittent error was returned.

Unfortunately the log only shows the outermost error: "could not add crate linux_l6470 to the git repo". As an enhancement, we should probably update the logging to walk through the chain of all caused_by errors to be sure we include the root cause. That would give us more information as to which specific operation resulted in an Err(_) value.

Explanation of the observed behavior

The logged (outermost) error message is from here.

Because the lines (163 and 164) immediately following this call were not executed, the readme and crate bombs were dropped while the path field was still Some(_). The Drop implementation for Bomb in uploaders.rs is what is deleting these files from S3. This also seems to explain why it was noted that the files were "deleted from S3 in a ~5-10 minute window". The 5 minute estimate aligns with the request duration noted in the log. (So most of the request duration was probably spent attempting git operations after the S3 files were uploaded.)

Finally, the database transaction ends at line 186 and would be rolled back as well.