Concurrent uploads of the same file can cause intermittent 500 responses

[peter-esik]

When concurrent upload requests of the same blob are issued to an lfs-test-server instance, sometimes an HTTP status of 500 is returned with a response body such as this:

{"message":"open lfs-content/4c/d3/7f1a69b723d958eff48fd27495c05d13c8bc91693f1bd7f2b44239a3d9cb.tmp: file exists"}

Here's a Python script for repro'ing the problem: https://gist.github.com/peter-esik/b0057ecca6890463b4a113771b15bae9

This can happen in legitimate use cases, such as the following:

• user A and B both add a commit containing an LFS-tracked file with identical content (unknowingly)
• they push their changes at the ~same time

There's a chance that one of them will receive an error. It's quite benign, as if they try to push again, it will succeed.

I'm not sure how relevant this issue is, but I felt like reporting it, so if someone encounters this in the future, this issue can provide more information.

I ran the repro script against rudolfs and giftless, and experienced no issues (I did not check whether the uploaded blobs were garbled or not due to a potential race condition, though...).

[chrisd8088]

Hey, I'm sorry you're having trouble, and thanks very much for the bug report and reproduction script!

It certainly sounds like some kind of race issue is at fault, probably because we create a temporary file on upload but always use the same path for it for identical object IDs, so the call to os.OpenFile() with the os.O_EXCL flag fails for the second upload because the temporary file already exists.

If you still have your test environment available, would you mind trying the following patch to see if it help resolves the problem? As a caveat, I haven't tested this beyond checking that it compiles:

diff --git a/content_store.go b/content_store.go
index c534e97..c6ac2b7 100644
--- a/content_store.go
+++ b/content_store.go
@@ -46,34 +46,22 @@ func (s *ContentStore) Get(meta *MetaObject, fromByte int64) (io.ReadCloser, err
 // Put takes a Meta object and an io.Reader and writes the content to the store.
 func (s *ContentStore) Put(meta *MetaObject, r io.Reader) error {
 	path := filepath.Join(s.basePath, transformKey(meta.Oid))
-	tmpPath := path + ".tmp"
 
 	dir := filepath.Dir(path)
 	if err := os.MkdirAll(dir, 0750); err != nil {
 		return err
 	}
 
-	file, err := os.OpenFile(tmpPath, os.O_CREATE|os.O_WRONLY|os.O_EXCL, 0640)
-	if err != nil {
-		return err
-	}
+	tmpPath, written, shaStr, err := s.putTemp(dir, filepath.Base(path) + ".*.tmp", r)
 	defer os.Remove(tmpPath)
-
-	hash := sha256.New()
-	hw := io.MultiWriter(hash, file)
-
-	written, err := io.Copy(hw, r)
 	if err != nil {
-		file.Close()
 		return err
 	}
-	file.Close()
 
 	if written != meta.Size {
 		return errSizeMismatch
 	}
 
-	shaStr := hex.EncodeToString(hash.Sum(nil))
 	if shaStr != meta.Oid {
 		return errHashMismatch
 	}
@@ -84,6 +72,32 @@ func (s *ContentStore) Put(meta *MetaObject, r io.Reader) error {
 	return nil
 }
 
+func (s *ContentStore) putTemp(dir string, pattern string, r io.Reader) (string, int64, string, error) {
+	file, err := os.CreateTemp(dir, pattern)
+	if err != nil {
+		return "", 0, "", err
+	}
+	defer file.Close()
+
+	tmpPath := file.Name()
+
+	if err := file.Chmod(0640); err != nil {
+		return tmpPath, 0, "", err
+	}
+
+	hash := sha256.New()
+	hw := io.MultiWriter(hash, file)
+
+	written, err := io.Copy(hw, r)
+	if err != nil {
+		return tmpPath, 0, "", err
+	}
+
+	shaStr := hex.EncodeToString(hash.Sum(nil))
+
+	return tmpPath, written, shaStr, nil
+}
+
 // Exists returns true if the object exists in the content store.
 func (s *ContentStore) Exists(meta *MetaObject) bool {
 	path := filepath.Join(s.basePath, transformKey(meta.Oid))

[peter-esik]

Looks like there is another "variation" of this issue, with the following sequence of events:

1. concurrent threads are trying to upload the same blob
2. first one gets the batch response
3. second one gets the batch response
4. first one successfully uploads the blob
5. second one tries to upload the blob

Sometimes the second request for upload gets HTTP status 404. I think what happens in this case is the upload link for the second uploader is invalidated as the first upload finishes (so between 3 and 5). The original repro script also repros this one, but it's less frequent than 500s.

I tried to work around this with the following logic:

1. try to upload a blob
2. if I get 404, then I issue another batch request
3. if there are no actions or there is only a download action in the response, then the blob must have been already uploaded

Sometimes this works, but sometimes at step 3 I get back an upload action/link again, however issuing an upload request still gets me 404s, which is very weird.

The spec does not say that performing an action invalidates the action URL. It does include expires_at and expires_in fields though, which should govern expiry, if present. In lfs-test-server's case, the batch responses include expires_at, but it's always set to 0001-01-01 00:00:00, which is Go's default time.Time value, if I'm not mistaken.

Interestingly, git-lfs itself has no issues with action links expired ~2000 years ago. :)