[Bug]: Push stuck because of restoring deduped blobs

[shcherbak]

zot version

v2.1.3-rc2

Describe the bug

Push to registry is blocked because of deduplication process runing with storage locking

It takes up to 30 minites to push new tag with all image layers existing in registry

logs are full with messages:

restoring deduped blobs for digest finished successfully

To reproduce

1. Configuration

{
    "distSpecVersion": "1.1.0",
    "storage": {
        "rootDirectory": "/srv/data/zot/tmp",
        "dedupe": false,
        "gc": true,
        "gcDelay": "2h",
        "gcInterval": "1h",
        "retention": {
           "dryRun": false,
           "delay": "2h",
           "policies": [
               {
                   "repositories": ["REDACTED/*","REDACTED/*","REDACTED/*","REDACTED/*","REDACTED/*","REDACTED/*","REDACTED/*"],
                   "deleteReferrers": true,
                   "deleteUntagged": true,
                   "keepTags": [{
                       "patterns": ["v?[0-9]{1,}.[0-9]{1,}.[0-9]{1,}.*", "latest"],
                       "mostRecentlyPushedCount": 50,
                       "mostRecentlyPulledCount": 50,
                       "pulledWithin": "2880h",
                       "pushedWithin": "2880h"
                   }]
               }
           ]
        },
        "remoteCache": true,
        "cacheDriver": {
            "name": "redis",
            "url": "redis://10.12.18.52:6379",
            "keyprefix": "zot"
        },
        "storageDriver": {
            "name": "s3",
            "region": "us-east-1",
            "bucket": "registry",
            "secure": false,
            "skipverify": true,
            "accesskey": "REDACTED",
            "secretkey": "REDACTED",
            "regionEndpoint": "http://127.0.0.1:8090",
            "encrypt": false,
            "v4auth": true,
            "forcepathstyle": true
        }
    },
    "scheduler": {
        "numWorkers": 96
    },
    "http": {
        "compat": ["docker2s2"],
        "address": "10.12.18.51",
        "port": "8080",
        "auth": {
            "htpasswd": {
                "path": "/etc/zot/htpasswd"
            }
        },
        "accessControl": {
            "groups": {
                "ro": {
                    "users": [REDACTED]
                },
                "rw": {
                    "users": [REDACTED]
                },
                "devops": {
                    "users": ["REDACTED"]
                }
            },
            "metrics":{
                "users": ["metrics-pw","metrics"]
            },
            "repositories": {
                "**": {
                    "policies": [
                        {
                            "groups": ["rw"],
                            "actions": ["read", "create", "update"]
                        },
                        {
                            "groups": ["ro"],
                            "actions": ["read"]
                        }
                    ],
                    "defaultPolicy": ["read"]
                }
            },
            "adminPolicy": {
                "groups": ["devops"],
                "actions": ["read", "create", "update", "delete"]
            }
        }
    },
    "cluster": {
        "members": ["10.12.18.51:8080","10.12.18.52:8080","10.12.18.53:8080"],
        "hashKey": "siphash-rand-str"
    },
    "extensions": {
        "search": {
            "enable": true
        },
        "metrics": {
            "enable": true,
            "prometheus": {
                "path": "/metrics"
            }
        },
        "ui": {
            "enable": true
        }
    },
    "log": {
        "level": "debug",
        "output": "/var/log/zot/zot.log",
        "audit": "/var/log/zot/zot-audit.log"
    }
}

2. Client tool used
   docker 24.0.4
3. Seen error

ac575fa18186: Retrying in 4 seconds
52b064bff28f: Retrying in 4 seconds
f6d5418577c2: Retrying in 4 seconds
20b567afaaa4: Retrying in 4 seconds
47b7ffd87a6b: Retrying in 4 seconds
ac575fa18186: Retrying in 3 seconds
52b064bff28f: Retrying in 3 seconds
f6d5418577c2: Retrying in 3 seconds
20b567afaaa4: Retrying in 3 seconds
47b7ffd87a6b: Retrying in 3 seconds
ac575fa18186: Retrying in 2 seconds
52b064bff28f: Retrying in 2 seconds
f6d5418577c2: Retrying in 2 seconds
20b567afaaa4: Retrying in 2 seconds
47b7ffd87a6b: Retrying in 2 seconds
ac575fa18186: Retrying in 1 second
52b064bff28f: Retrying in 1 second
f6d5418577c2: Retrying in 1 second
20b567afaaa4: Retrying in 1 second
47b7ffd87a6b: Retrying in 1 second

received unexpected HTTP status: 500 Internal Server Error

registry contains 103 repositories, 4900 tags, 6207 blobs in s3

Expected behavior

No response

Screenshots

Additional context

log from zot

:{"level":"info","clusterMember":"10.12.18.51:8080","clusterMemberIndex":"0","module":"http","username":"gitlab","component":"session","clientIP":"10.12.18.51:49244","method":"POST","path":"/v2/REDACTED/blobs/uploads/","statusCode":500,"latency":"5m0s","bodySize":135,"headers":{"Accept-Encoding":["gzip"],"Authorization":["******"],"Content-Length":["0"],"User-Agent":["docker/24.0.5 go/go1.20.6 git-commit/a61e2b4 kernel/5.8.0-0.bpo.2-amd64 os/linux arch/amd64 UpstreamClient(Docker-Client/27.5.0 \\(linux\\))"],"X-Forwarded-For":["REDACTED"],"X-Forwarded-Proto":["https"],"X-Real-Ip":["REDACTED"]},"goroutine":538617,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2025-03-02T15:15:57.241286551Z","message":"HTTP API"}

...

{"level":"error","clusterMember":"10.12.18.51:8080","clusterMemberIndex":"0","error":"s3aws: s3aws: append to zero-size path /REDACTED/.uploads/05e9d412-007f-4287-a553-5aa7a49ab238 unsupported\ns3aws: s3aws: append to zero-size path /REDACTED/.uploads/edf88d3c-5a44-46d4-81a3-ec6570388cb1 unsupported","module":"gc","goroutine":51444,"caller":"zotregistry.dev/zot/pkg/storage/gc/gc.go:90","time":"2025-03-02T15:19:16.217060501Z","message":"failed to run GC for /REDACTED"}

[shcherbak]

here is a profile during this process
profile.pb.gz

[andaaron]

Hi @shcherbak, we're working on solving this. We have refactored the code as part of #2968.

Do you think you could try out #2968? It would be a good opportunity to test the change in a realistic environment.

[shcherbak]

ok @andaaron , I'm building it now

[shcherbak]

@andaaron it works like a charm,
I'v run 20 concurent builds ant they took seconds

[shcherbak]

can You please make rc release right after merging this rescue patch to main brunch?

[andaaron]

Not sure if we're going to merge this one first or the sync/regclient PR, I would make an RC for each.

#2968 is a significant change of basic functionality (we used to lock access for read/writes on all repos, and with this PR we lock per-repo), can you run it for a few more days, and let us know in case there are any bugs?

[rchincha]

Duplicate of #2964

[rchincha]

@andaaron it works like a charm, I'v run 20 concurent builds ant they took seconds

@shcherbak would also mix in some deletes as well in your workflow, to test.

[shcherbak]

@rchincha , I will try to test deletes during push process

[shcherbak]

Not sure if we're going to merge this one first or the sync/regclient PR, I would make an RC for each.

#2968 is a significant change of basic functionality (we used to lock access for read/writes on all repos, and with this PR we lock per-repo), can you run it for a few more days, and let us know in case there are any bugs?

I will stage it next week with such builds:

docker buildx build --provenance false --cache-to=type=registry,ref=REDACTED:buildcache --cache-from=type=registry,ref=REDACTED:buildcache  --push -t REDACTED:$CI_COMMIT_SHA -f docker/fpm/prod/Dockerfile .

(apx, 150 per day)

[shcherbak]

fixing storage lock metrics for today

18-40 - time of upgrade