Google-cloud-dotnet: Google.Cloud.Storage.V1.UploadValidationException: Upload validation failed

[NPSF3000]

Environment details

• OS: microsoft/dotnet:2.2-aspnetcore-runtime
• .NET version: 2.2
• Package name and version: Google.Cloud.Storage.V1 2.3.0

Steps to reproduce

We have a backend running in AppEngine that processes a lot of small file uploads to GCS. We've started noticing that we get a small, infrequent but persistent errors that 'Google.Cloud.Storage.V1.UploadValidationException: Upload validation failed'. When spot-checking several of these errors we found that the file was not successfully uploaded. Adding retry logic appears to fix the upload issue.

The remaining issue is why we're receiving validation errors - GCP support could not see any errors when they looked at this from their side. Network errors we could understand, but not validation errors.

[jskeet]

I'll have a look tomorrow. When you say that "the file was not successfully uploaded" do you mean it wasn't present afterwards? The default action on a validation failure is to delete the corrupt file afterwards, so that would probably explain why you don't see the files afterwards. You can change that with UploadObjectOptions.UploadValidationMode.

Basically the client library computes a CRC as it uploads, and then checks that the resulting object has the same CRC. I can't say that I've ever seen it occur though.

Is there anything "interesting" about these files? Are they compressed files for example?

[NPSF3000]

@jskeet Yes, I mean the file was not present - not sure if it never got there or was deleted. I would make the change to not delete it, but that would clash with the retry upload fix.

Most of the uploads are jpegs, but the error is not exclusive to them.

Here's a snippet of incident rate:

date Count(*)
2019-07-18 622
2019-07-17 1619
2019-07-16 722
2019-07-15 94
2019-07-14 23
2019-07-13 39
2019-07-12 137
2019-07-11 248
2019-07-10 107
2019-07-09 169
2019-07-08 54
2019-07-07 12
2019-07-06 21
2019-07-05 32
2019-07-04 65
2019-07-03 236
2019-07-02 485
2019-07-01 121

It's worth noting that in the same time period we uploaded over half a billion items - so it's not super common (occurring ~0.000905% of the time).

[jskeet]

Thanks for the details. Are you in a position where you can try the same sort of rate of upload in a sandbox environment? I'd be interested to see what happens if you change UploadValidationMode to ThrowOnly, then log those exceptions (including the object being uploaded). I can imagine a few scenarios:

• The object doesn't end up in storage
• The object ends up in storage correctly (both data and crc32 hash)
• The object ends up in storage with the right data, but the wrong crc32 hash
• The object ends up in storage with corrupted data, and a hash that matches it

The fact that retrying fixes the issue _suggests_ it's not a matter of the C# CRC32 implementation being broken. I do wonder whether there's some cross-threading race condition somewhere. Given the amount of data you're uploading, is it fair to assume this is being done in a highly parallel way? If so, are you using a single StorageClient across multiple threads, or separate StorageClient instances? To be clear, it should be absolutely fine to use StorageClient across multiple threads - I'm just trying to think diagnostically.

Please let me know if you're able to conduct this sort of test in a sandbox away from your production data. If you can't, I'll try doing so myself - but I can easily see this ending up with me failing to reproduce it :(

[NPSF3000]

No problem, glad to have your assistance.

I made a change that let me see the 'broken' object and the retry, based upon your ThrowOnly suggestion.

After looking at a handful of instances 'broken' object exists, and is identical to the successfully retried object. For example:

sha1sum: aed6d4b6c27d515d86b3a4cca2d6ca7ec5b1b712
Validation Local CRC: uQJksw==
Validation Uploaded CRC: 33rgBw==

gsutils hash - Hash (crc32c): 33rgBw==
gsutils hash - Hash (md5): 9ld/mSUzJ+Otm3qDg2Othg==

To be clear, we upload the object, receive the validation error, upload again (to a separate location) with no error. I then downloaded both objects and compared.

This is done in a highly parallel way, using a single StorageClient to handle many requests.

[jskeet]

Right. So it at least looks like it's the local CRC computation that's failing, if I've understood you right - the hash you get from UploadValidationException.ClientSideHash is incorrect, whereas UploadValidationException.UploadedObject.Crc32c is the same value that you get with the working upload?

If I've read that correctly, there's a relatively small piece of code to look through - I really hope I can find it. Thanks very much for the response, and I'll let you know how I get on.

[NPSF3000]

@jskeet your understanding is correct. Good luck!

[jskeet]

Okay, I've had a look through the code, and I can't see room for any race conditions. The hash update is only called on a successful request chunk, too. So it looks like I'm going to need to reproduce this.

Could you let me know:

• What size of file you've noticed this with
• Your degree of parallelism (or whatever figures you have available) on a per-StorageClient basis

I'll then try to create a stress test approximating that and run it on GKE. That might not be exactly the same as on AppEngine, but it's likely to be faster to iterate.

Apologies that this is taking a while to diagnose :(

[NPSF3000]

No problem, if this was a common occurrence then it would have been resolved long ago.

The file sizes are small, think 0B to 1MB.

Parallelism is hard to measure with the metrics we have... I can derive a ballpark of around 10 objects/s per s3client as an average - what that means in terms of min/max inflight I do not know.

The uploaded streams are memory streams - which eliminates some complexity. We do use that stream for other operations (some GCP services, some basic manipulation) before sending to GCS. As such it's possible that the stream was modified during GCS reading it. I can rule this out because:

• Not every object goes through this manipulation. One specific object goes through no manipulation of any kind, yet has occasional validation errors.
• A review shows no obvious problems.
• Looking at ResumeableUpload.SendNextChunkAsync the code takes a copy of a chunk before uploading and hashing, so even if the stream was being manipulated the hash shouldn't be affected.

[jskeet]

I concur with your observation about modifying the stream not being a problem.
Okay, will try this with randomly generated objects tomorrow.

[jskeet]

Just uploaded 100,000 objects without seeing this - have stopped it for the weekend, but will try again on Monday with smaller objects (so it's faster).

[NPSF3000]

@jskeet thanks for the update.

The incident rate is so low that 100,000 objects aren't enough to guarantee an encounter with the issue - assuming everything else is right.

I hope Monday is more fruitful, and if it's not, let me know if there are any additional diagnostics I can add to our codebase.

[jskeet]

Yup, I wasn't particularly surprised that it didn't show up after 100,000 - that was just where I'd got to before finishing for the day :)

I can ramp it up in various ways to create objects more quickly. Thanks for you patience.

[jskeet]

Hooray - I've reproduced it! Only took uploading 700,000 objects to get one error...
Having seen it once, I can now try to work out how to actually track it down. But at least I'm reasonably confident I won't need to ask you to perform any other custom tests, until I've got to the point of "I think it's working now, please try this next package" :)

[NPSF3000]

FANTASTIC!

It makes me feel a little less crazy having independent confirmation.

Thank you so much for the effort, and good luck trying to track this down!

[jskeet]

More good news - I reproduced this again, with very small files. Interestingly, it happened twice within a couple of seconds (I've changed my test to stop after a failure, so that "within a couple of seconds" might actually be closer.

My new code generates a Guid and uses it for both filename (ToString) and content (ToByteArray). Here are the logs I've got:

a04ee050-7e46-4834-a086-bb76e0e2ac3b; expected BNj+bw== but was libMPw==
729ea5f5-eb60-4116-befa-804188534fee; expected pcCZbA== but was fD3LeQ==

(Here the "expected" is "as calculated client-side" and "was" is "the server returned".)

That means the byte arrays in question were:

50-E0-4E-A0-46-7E-34-48-A0-86-BB-76-E0-E2-AC-3B
F5-A5-9E-72-60-EB-16-41-BE-FA-80-41-88-53-4F-EE

When testing that data locally, I get the same hash that the server returned - which is what we expected given your earlier diagnostics.

Next steps I'm going to try:

• Running just the hashing in a massively parallel manner
• Trying to fake a local server to see whether something odd is happening within the HTTP request pipeline

[jskeet]

Scratch the stress test - I can see where the bad hashes are coming from. They're being hashed multiple times.

If you update the hash with the first data twice, you get a result of BNj+bw==.
If you update the hash with the first data three times, you get a result of pcCZbA==.

So for some reason, the hashing code is being called multiple times. I'm hoping that'll be easier to diagnose than race conditions leading to memory corruption. I suspect it's some kind of retry I hadn't been thinking of...

[jskeet]

Okay, I think I've found it. It's possible for the server to return a 308 status and indicate how many bytes it's received, in a way that means those bytes are retried.

I've got a local build of Google.Apis where I reproduced the problem having added some logging for when I expected it to fail - and it did indeed fail.
I'm now trying another build which still logs where it would have failed, but with a fix. I'm expecting to see the log entries but no failures. If that works for (say) 3 million objects uploaded, and I see the log entries where it would have failed, then I'll be pretty confident in the fix.
It may take a little while to get rolled out due to various team member vacations - in the meantime, I'd recommend continuing to retry as you're already doing.

[jskeet]

Just to keep this up to date, I've uploaded about a million objects with no problems now - but no detection of what would have been the problem either :( Will keep it running...

[jskeet]

Aha - I've now seen one log entry for this, and the fix worked. I'll leave it going for another few hours for more confidence, but I think we're there.

[NPSF3000]

That makes sense, sounds like a grand adventure with a mundane cause. If you're even in Dallas I'll buy you a drink.

When you have a fixed package let me know and we'll test it in the wild.

[jskeet]

I've stopped my experiment now as I've seen another couple of log entries, and no further exceptions.
I've filed an issue in the relevant repo; you may want to subscribe to that for updates while I'm on vacation, as I suspect @chrisdunelm will merge the fix PR (that I'm about to create) and release it. You could then add a direct dependency on that new version of Google.Api and that should fix it. Of course, we'll release a new version of the Storage library with the updated dependency when we get a chance too.

[chrisdunelm]

@NPSF3000 The underlying issue is now fixed and released in v1.40.3 As Jon said, if you now add a direct dependency from your project to Google.Api v1.40.3 this should fix the issue you're seeing.

[pblachut]

Is there any ETA for the stable version of package?

[jskeet]

@pblachut: If you want to stick with stable versions, you should be able to use Google.Cloud.Storage.V1 version 2.3.0, but add a direct dependency on Google.Apis.Auth 1.41.1 - which will give you dependencies to Google.Apis and Google.Apis.Core on the same version.

I'd like to release a new stable Google.Cloud.Storage.V1 soon, but we're updating other aspects of the dependencies which mean we can't do that right now.