Upload with pin fails second time

[ldeffenb]

Context

Bee 2.0.0

Summary

Uploading a single file with /bzz or /bytes (at least) twice with the pinning option fails the second time with a 500 error. Details below.

Expected behavior

Uploading a file multiple times should successfully return the same reference each time, regardless of pinned or not. It works on subsequent uploads if pinning is not requested.

Actual behavior

The first upload succeeds and provides the reference. Subsequent attempts with pinning fail with 500.

First upload:

swarm-cli upload 12-2442-1805.png --pin --bee-api-url http://192.168.10.38:1633 --bee-debug-api-url http://192.168.10.38:1635 --curl
curl "http://192.168.10.38:1635/health" -H "accept: application/json, text/plain, */*"
curl "http://192.168.10.38:1635/stamps" -H "accept: application/json, text/plain, */*"
curl -X POST "http://192.168.10.38:1633/bzz?name=12-2442-1805.png" -H "accept: application/json, text/plain, */*" -H "swarm-postage-batch-id: cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41" -H "swarm-pin: true" -H "content-type: image/png" --data @12-2442-1805.png
Swarm hash: 1611af0b9caad5cc96f10c9570aecf0d7bd759ac8933c39f3ef165cf6c9014dd
URL: http://192.168.10.38:1633/bzz/1611af0b9caad5cc96f10c9570aecf0d7bd759ac8933c39f3ef165cf6c9014dd/
curl "http://192.168.10.38:1635/stamps/cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41" -H "accept: application/json, text/plain, */*"
Stamp ID: cf5ab2db
Usage: 19%
Expires: 2044-01-22

Second upload:

swarm-cli upload 12-2442-1805.png --pin --bee-api-url http://192.168.10.38:1633 --bee-debug-api-url http://192.168.10.38:1635 --curl
curl "http://192.168.10.38:1635/health" -H "accept: application/json, text/plain, */*"
curl "http://192.168.10.38:1635/stamps" -H "accept: application/json, text/plain, */*"
curl -X POST "http://192.168.10.38:1633/bzz?name=12-2442-1805.png" -H "accept: application/json, text/plain, */*" -H "swarm-postage-batch-id: cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41" -H "swarm-pin: true" -H "content-type: image/png" --data @12-2442-1805.png
ERROR Bee responded with HTTP 500 (Internal Server Error).

The error message is: done split failed

There may be additional information in the Bee logs.

Third upload without the --pin:

swarm-cli upload 12-2442-1805.png --bee-api-url http://192.168.10.38:1633 --bee-debug-api-url http://192.168.10.38:1635 --curl
curl "http://192.168.10.38:1635/health" -H "accept: application/json, text/plain, */*"
curl "http://192.168.10.38:1635/stamps" -H "accept: application/json, text/plain, */*"
curl -X POST "http://192.168.10.38:1633/bzz?name=12-2442-1805.png" -H "accept: application/json, text/plain, */*" -H "swarm-postage-batch-id: cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41" -H "content-type: image/png" --data @12-2442-1805.png
Swarm hash: 1611af0b9caad5cc96f10c9570aecf0d7bd759ac8933c39f3ef165cf6c9014dd
URL: http://192.168.10.38:1633/bzz/1611af0b9caad5cc96f10c9570aecf0d7bd759ac8933c39f3ef165cf6c9014dd/
curl "http://192.168.10.38:1635/stamps/cf5ab2db3f836eb8d78dcfc3f5e21ab510c15ee627e59d7bea357b0a12375d41" -H "accept: application/json, text/plain, */*"
Stamp ID: cf5ab2db
Usage: 19%
Expires: 2044-01-22

--verbosity 5 logs around the second failed upload:

"time"="2024-04-03 12:05:58.483088" "level"="debug" "logger"="node/api/post_bzz" "msg"="info" "encrypt"=false "file_name"="12-2442-1805.png" "hash"="68d8fd3a0d5a73395a0f1d4815aeaa69d4d2ec5b084d80d41add41257c67d242" "metadata"={"Content-Type":"image/png","Filename":"12-2442-1805.png"}
"time"="2024-04-03 12:05:58.483723" "level"="debug" "logger"="node/api/post_bzz" "msg"="store" "manifest_reference"="1611af0b9caad5cc96f10c9570aecf0d7bd759ac8933c39f3ef165cf6c9014dd"
"time"="2024-04-03 12:05:58.483772" "level"="debug" "logger"="node/api/post_bzz" "msg"="done split failed" "error"="pin store: duplicate pin collection"
"time"="2024-04-03 12:05:58.483781" "level"="error" "logger"="node/api/post_bzz" "msg"="done split failed"
"time"="2024-04-03 12:05:58.484368" "level"="info" "logger"="node/api" "msg"="api access" "ip"="192.168.10.177" "method"="POST" "host"="192.168.10.38:1633" "uri"="/bzz?name=12-2442-1805.png" "proto"="HTTP/1.1" "status"=500 "size"=68 "duration"="2.053938ms" "user-agent"="axios/1.4.0"

Steps to reproduce

Simply upload a single file twice with the pinning option. It fails on /bzz (in this example) as well as with /bytes with a single content.
swarm-cli upload 12-2442-1805.png --bee-api-url http://192.168.10.38:1633 --bee-debug-api-url http://192.168.10.38:1635 --curl

Possible solution

This problem was introduced in the fix for #4558 The issue is that the error is returned from Close() which is properly recognized and causes Cleanup() to be invoked. But since an error came from Close(), the upload believes it has failed. My solution is to detect the duplicate pin in Close() and directly invoke Cleanup and prevent that specific error from being visible to the upload, allowing it to properly succeed. This makes sense because technically the pin Close() succeeded and it should not rely on the original invoker to come back into Cleanup().

I saw this coming and commented on the PR https://github.com/ethersphere/bee/pull/4558/files#r1466951665 but didn't follow through to actually test it because I didn't have a sepolia node running at the time. I accepted @notanatol 's explanation (https://github.com/ethersphere/bee/pull/4558/files#r1468895966), which was correct from the pinning point of view, but has this negative side-effect of failing the second upload.

Anyway, I worked around this issue by inserting the following code at

bee/pkg/storer/uploadstore.go

Line 114 in 501f8a4

return pinningPutter.Close(s, b, address)

	pinErr := pinningPutter.Close(s, b, address)
	if errors.Is(pinErr, pinstore.ErrDuplicatePinCollection) {
		pinErr = pinningPutter.Cleanup(db)
	}
	return pinErr

But I also had to make the error message visible by a leading capital letter, which may not be the accepted way of doing things.

bee/pkg/storer/internal/pinning/pinning.go

Line 44 in 501f8a4

errDuplicatePinCollection = errors.New("pin store: duplicate pin collection")

Note that I further suspect that there's still an issue coming up with pinning of duplicate uploads of root chunks when various redundancy options are selected. In my earlier testing, uploading a small (<4KB) chunk of data with /bytes with pinning and various redundancy options properly returned the same single reference. But if the pins were examined closely (or more detailed logs around the uploading pinning activity), the dispersed replica SOC references were also included in the pin. With the current DuplicatePinCollection detection, only the first upload set of chunks would actually be pinned and subsequent differing redundancy uploads of the same chunk of data would actually not end up pinning the replica SOCs. I haven't thought of a solution for this issue yet (aside from trying to merge the pinned chunks between the original and new pin instead of deleting the new pin (or is it the original pin that gets cleaned up?)), but please don't hold off on fixing this issue until that next one can be figured out!