[Bug]: can't download image (error for several blobs) from s3 even right after image was pushed

[lictw]

zot version

v2.1.1 (and early)

Describe the bug

There are many images with same base (eclipse-temurin:17-jdk-focal for ex.) and seems that a deduplication bug happens at some time: after some pushes and retention intervals a real ones blobs are deleted, all other ones have zero size and Zot can't find the real blobs to return to client.

So I build an image, sucessfully push it and immediately can't download it:

$ cat Dockefile
FROM eclipse-temurin:17-jdk-focal
WORKDIR /maven
RUN touch 1.txt
ENTRYPOINT ["echo"]
CMD ["foo"]

$ docker buildx build . -t zot.com/devops/zot-issue:latest --output=type=registry,oci-mediatypes=true --provenance false --builder d1
[+] Building 3.1s (8/8) FINISHED                                                                                                                                                 docker-container:d1
 => [internal] load build definition from Dockerfile                                                                                                                                            0.0s
 => => transferring dockerfile: 134B                                                                                                                                                            0.0s
 => [internal] load metadata for docker.io/library/eclipse-temurin:17-jdk-focal                                                                                                                 1.7s
 => [internal] load .dockerignore                                                                                                                                                               0.0s
 => => transferring context: 2B                                                                                                                                                                 0.0s
 => [1/3] FROM docker.io/library/eclipse-temurin:17-jdk-focal@sha256:948030386d896a407cb9235d502e4b9a17f00385e6cd339d383c02940daa956e                                                           0.0s
 => => resolve docker.io/library/eclipse-temurin:17-jdk-focal@sha256:948030386d896a407cb9235d502e4b9a17f00385e6cd339d383c02940daa956e                                                           0.0s
 => CACHED [2/3] WORKDIR /maven                                                                                                                                                                 0.0s
 => CACHED [3/3] RUN touch 1.txt                                                                                                                                                                0.0s
 => exporting to image                                                                                                                                                                          1.4s
 => => exporting layers                                                                                                                                                                         0.0s
 => => exporting manifest sha256:ad32a591b51aad5b433c4781b8137f223ae685f62a1663d398e6a024764c582f                                                                                               0.0s
 => => exporting config sha256:c8e5d1e259d08d6d3964549c74c99b976e88785d59e3a5cf948ab86025452a70                                                                                                 0.0s
 => => pushing layers                                                                                                                                                                           0.5s
 => => pushing manifest for zot.com/devops/zot-issue:latest@sha256:ad32a591b51aad5b433c4781b8137f223ae685f62a1663d398e6a024764c582f

$ docker pull zot.com/devops/zot-issue:latest 
latest: Pulling from devops/zot-issue
560c024910be: Already exists 
cb5aedc0e1fd: Retrying in 4 seconds 
460b26a845b3: Retrying in 4 seconds 
01e3f73af39d: Retrying in 4 seconds 
882e4ba000be: Waiting 
62570a53daba: Waiting 
8b44663f42e0: Waiting 
^C

Logs:

{"level":"error","error":"s3aws: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable\n\tstatus code: 416, request id: 58bec63d-9f2e-4c76-a0e6-f529129450b6, host id: ","blob":"/aplan/aggregation-manager/master/blobs/sha256/cb5aedc0e1fdb7b1e0021df89491ab1ecb1d06f9ed9029843e236b44cc81d167","goroutine":10040,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1394","time":"2024-08-22T22:28:41.966178229Z","message":"failed to open blob"}
{"level":"error","error":"s3aws: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable\n\tstatus code: 416, request id: 58bec63d-9f2e-4c76-a0e6-f529129450b6, host id: ","goroutine":10040,"caller":"zotregistry.dev/zot/pkg/api/routes.go:1134","time":"2024-08-22T22:28:41.966271481Z","message":"unexpected error"}

Config:

  "distSpecVersion": "1.1.0-dev",
  "storage": {
    "rootDirectory": "/var/lib/registry",
    "gc": true,
    "gcDelay": "5m",
    "gcInterval": "1h",
    "dedupe": true,
    "remoteCache": false,
    "storageDriver": {
        "name": "s3",
        "region": "...",
        "regionEndpoint": "...",
        "secure": true,
        "accessKey": "...",
        "secretKey": "...",
        "bucket": "zot",
        "rootDirectory": "/"
    },

To reproduce

I do not know what actions exactly need to be done. Once I cleared the registry completely (deleted everything on s3) and everything worked for me for a while, and then it broke again..

Expected behavior

No response

Screenshots

No response

Additional context

S3 bucket contains path /aplan/aggregation-manager/master/blobs/sha256/cb5aedc0e1fdb7b1e0021df89491ab1ecb1d06f9ed9029843e236b44cc81d167 for ex., the file has zero size and it's pretty fresh (1 day).

I also have docker.hub as mirror and it's may be interesting that this test image, that I built directly from the hub image, Zot links with mirrored image that it has. But I really use this mirrored image for most real images, so it's real base image.

[rchincha]

@lictw you seem to have a cloud use case with dedupe

I would refer to https://github.com/project-zot/zot/blob/main/test/blackbox/cloud_only.bats#L23 for this.

Note that dedupe is global across all repos and tries to keep only one copy of a blob - hence other blobs in repos with the same hash are sized zero. However, this requires we keep a cache/metadata db, dynamodb in this case.

Let us know if this didn't work for you.

[lictw]

@rchincha hm, must I always to use remote cache when my storage is s3? This and this say that zot should be able to work with local cache.

Even with s3 my setup has PV for cache, andzot has BoltDB files, but they are pretty new.. Does zot drop local cache at some moment? This then explains why it works for a while from scratch, and then breaks.

root@zot-0:/# ls -l /proc/1/root/var/lib/registry/
total 8880
-rw------- 1 root root 2097152 Aug 23 14:35 cache.db
-rw------- 1 root root 8388608 Aug 24 02:30 meta.db

Also, just for understanding, if cache broken, why zot does not fix it when I upload an image? In my case I upload first, only then I try to download it, so I suggest all blobs to zot and zot should accept missing blob, but it does not.

About DynamoDB, I can try to setup this, but my s3 storage is not AWS, my s3 provider does not have this DB, so it's not very convenient for me.. And zot seems does not accept any other remote DB, so there is a some problem.

[rchincha]

@lictw so you are using a remote storage backend (S3 compatible) and a local cache. We will look at this.

[rchincha]

@lictw

after some pushes and retention intervals a real ones blobs are deleted,

^ can you post your full config (anonymized) especially wrt retention config etc.
Also, zot logs are very informative. Pls also post relevant logs, will be easier to triage.
What is your s3 backend?

[lictw]

Config

{
  "distSpecVersion": "1.1.0-dev",
  "storage": {
    "rootDirectory": "/var/lib/registry",
    "gc": true,
    "gcDelay": "5m",
    "gcInterval": "1h",
    "dedupe": true,
    "remoteCache": false,
    "storageDriver": {
        "name": "s3",
        "region": ".",
        "regionEndpoint": ".",
        "secure": true,
        "accessKey": ".",
        "secretKey": ".",
        "bucket": "zot",
        "rootDirectory": "/"
    },
    "retention": {
      "delay": "24h",
      "policies": [
        {
          "repositories": ["devops/**"]
        }, {
          "repositories": ["docker.io/**"],
          "keepTags": [{
            "pulledWithin": "720h"
          }]
        }, {
          "repositories": ["aplan/*/{main,master}"],
          "keepTags": [{
            "patterns": ["^latest$"]
          },{
            "mostRecentlyPushedCount": 5
          }]
        }, {
          "repositories": ["aplan/**"],
          "keepTags": [{
            "pushedWithin": "8h",
            "pulledWithin": "18h"
          }]
        }, {
          "repositories": ["**"],
          "deleteUntagged": true,
          "deleteReferrers": true,
          "keepTags": [{
            "patterns": ["v([0-9]+)\\..+"],
            "pulledWithin": "720h",
            "mostRecentlyPushedCount": 3
          },{
            "patterns": ["^production(|\\..+)$"],
            "pushedWithin": "720h",
            "mostRecentlyPushedCount": 5
          },{
            "patterns": ["^(main|master)(|\\..+)$"],
            "mostRecentlyPushedCount": 3
          },{
            "patterns": ["^(stages-[a-z-]+)(|\\..+)$"],
            "mostRecentlyPushedCount": 0
          },{
            "pushedWithin": "72h",
            "pulledWithin": "720h"
          }]
        }
      ]
    }
  },
  "http": {
    "address": "0.0.0.0",
    "port": "5000",
    "auth": {"htpasswd": {"path": "/etc/zot/htpasswd" }},
    "accessControl": { <redacted> },
  },
  "log": {"level": "error"},
  "extensions": {
    "sync": {
      "enable": true,
      "downloadDir": "/tmp/zot",
      "credentialsFile": "/etc/zot/registries.json",
      "registries": [
        {
          "urls": ["https://docker.io/library"],
          "onDemand": true, "tlsVerify": true,
          "content": [{"prefix": "**", "destination": "/docker.io"}]
        }, {
          "urls": ["https://<Nexus based registry, main for now>"],
          "onDemand": true
        }
      ]
    },
    "search": {
      "enable": true,
      "cve": null
    },
    "ui": {"enable": true},
    "mgmt": {"enable": true},
    "scrub": {
      "enable": false,
      "interval": "24h"
    }
  }
}

Logs (debug level while pulling aplan/security-server/master:latest):

{"level":"info","module":"http","component":"session","clientIP":"10.42.0.38:54150","method":"GET","path":"/v2/","statusCode":401,"latency":"0s","bodySize":253,"headers":{"Accept-Encoding":["gzip"],"User-Agent":["docker/24.0.5 go/go1.20.6 git-commit/a61e2b4c9c kernel/6.4.12-arch1-1 os/linux arch/amd64 UpstreamClient(Docker-Client/24.0.5 \\(linux\\))"],"X-Forwarded-For":["<<<REDACTED>>>"],"X-Forwarded-Host":["<<<REDACTED>>>"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"],"X-Forwarded-Scheme":["https"],"X-Real-Ip":["<<<REDACTED>>>"],"X-Request-Id":["719dd1644b6e51b711509b1b987be04c"],"X-Scheme":["https"]},"goroutine":3100,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2024-08-26T16:52:20.484686277Z","message":"HTTP API"}
{"level":"info","identity":"devops","goroutine":3101,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:20.748092258Z","message":"user profile successfully set"}
{"level":"info","repository":"aplan/security-server/master","reference":"latest","goroutine":3101,"caller":"zotregistry.dev/zot/pkg/api/routes.go:2023","time":"2024-08-26T16:52:20.748228941Z","message":"trying to get updated image by syncing on demand"}
{"level":"info","goroutine":3103,"caller":"zotregistry.dev/zot/pkg/extensions/sync/service.go:508","time":"2024-08-26T16:52:20.748270752Z","message":"getting available client"}
{"level":"info","remote":"https://docker.io/library","repository":"aplan/security-server/master","reference":"latest","goroutine":3103,"caller":"zotregistry.dev/zot/pkg/extensions/sync/service.go:301","time":"2024-08-26T16:52:21.357370396Z","message":"will not sync image, filtered out by content"}
{"level":"info","goroutine":3103,"caller":"zotregistry.dev/zot/pkg/extensions/sync/service.go:508","time":"2024-08-26T16:52:21.357410997Z","message":"getting available client"}
{"level":"info","remote":"https://<<<Nexus based registry>>>","repository":"aplan/security-server/master","reference":"latest","goroutine":3103,"caller":"zotregistry.dev/zot/pkg/extensions/sync/service.go:310","time":"2024-08-26T16:52:21.417824968Z","message":"syncing image"}
{"level":"error","error":"reading manifest latest in <<<REDACTED>>>/aplan/security-server/master: manifest unknown","repository":"aplan/security-server/master","reference":"latest","goroutine":3103,"caller":"zotregistry.dev/zot/pkg/extensions/sync/service.go:427","time":"2024-08-26T16:52:21.526909574Z","message":"couldn't get upstream image manifest details"}
{"level":"error","error":"reading manifest latest in <<<REDACTED>>>/aplan/security-server/master: manifest unknown","repository":"aplan/security-server/master","reference":"latest","goroutine":3101,"caller":"zotregistry.dev/zot/pkg/api/routes.go:2027","time":"2024-08-26T16:52:21.527097849Z","message":"failed to sync image"}
{"level":"info","module":"http","username":"devops","component":"session","clientIP":"10.42.0.38:54170","method":"HEAD","path":"/v2/aplan/security-server/master/manifests/latest","statusCode":200,"latency":"1s","bodySize":0,"headers":{"Accept":["application/vnd.oci.image.index.v1+json","application/vnd.docker.distribution.manifest.v1+prettyjws","application/json","application/vnd.oci.image.manifest.v1+json","application/vnd.docker.distribution.manifest.v2+json","application/vnd.docker.distribution.manifest.list.v2+json"],"Authorization":["******"],"User-Agent":["docker/24.0.5 go/go1.20.6 git-commit/a61e2b4c9c kernel/6.4.12-arch1-1 os/linux arch/amd64 UpstreamClient(Docker-Client/24.0.5 \\(linux\\))"],"X-Forwarded-For":["<<<REDACTED>>>"],"X-Forwarded-Host":["<<<REDACTED>>>"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"],"X-Forwarded-Scheme":["https"],"X-Real-Ip":["<<<REDACTED>>>"],"X-Request-Id":["1f0eb995efc1f2542f0a28e55d795576"],"X-Scheme":["https"]},"goroutine":3101,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2024-08-26T16:52:21.765697396Z","message":"HTTP API"}
{"level":"info","identity":"devops","goroutine":3184,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:22.02605451Z","message":"user profile successfully set"}
{"level":"info","module":"http","username":"devops","component":"session","clientIP":"10.42.0.38:54332","method":"GET","path":"/v2/aplan/security-server/master/manifests/sha256:eb0bf4b46759ccd4c9d212313166d00fa5007ad16bfd31bd2f600c1cc8e93ed0","statusCode":200,"latency":"0s","bodySize":1626,"headers":{"Accept":["application/vnd.docker.distribution.manifest.list.v2+json","application/vnd.oci.image.index.v1+json","application/vnd.docker.distribution.manifest.v1+prettyjws","application/json","application/vnd.oci.image.manifest.v1+json","application/vnd.docker.distribution.manifest.v2+json"],"Accept-Encoding":["gzip"],"Authorization":["******"],"User-Agent":["docker/24.0.5 go/go1.20.6 git-commit/a61e2b4c9c kernel/6.4.12-arch1-1 os/linux arch/amd64 UpstreamClient(Docker-Client/24.0.5 \\(linux\\))"],"X-Forwarded-For":["<<<REDACTED>>>"],"X-Forwarded-Host":["<<<REDACTED>>>"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"],"X-Forwarded-Scheme":["https"],"X-Real-Ip":["<<<REDACTED>>>"],"X-Request-Id":["e6d63594a7866095230e76e6cb59f230"],"X-Scheme":["https"]},"goroutine":3184,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2024-08-26T16:52:22.124867947Z","message":"HTTP API"}
{"level":"info","identity":"devops","goroutine":3101,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:22.372154202Z","message":"user profile successfully set"}
{"level":"info","identity":"devops","goroutine":3219,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:22.374722267Z","message":"user profile successfully set"}
{"level":"info","identity":"devops","goroutine":3204,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:22.376366429Z","message":"user profile successfully set"}
{"level":"info","module":"http","username":"devops","component":"session","clientIP":"10.42.0.38:54170","method":"GET","path":"/v2/aplan/security-server/master/blobs/sha256:52d5dc21084d23985e1f2eab73c99d31257e9844cfbee673803991e5d69d1816","statusCode":200,"latency":"0s","bodySize":6532,"headers":{"Accept-Encoding":["gzip"],"Authorization":["******"],"User-Agent":["docker/24.0.5 go/go1.20.6 git-commit/a61e2b4c9c kernel/6.4.12-arch1-1 os/linux arch/amd64 UpstreamClient(Docker-Client/24.0.5 \\(linux\\))"],"X-Forwarded-For":["<<<REDACTED>>>"],"X-Forwarded-Host":["<<<REDACTED>>>"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"],"X-Forwarded-Scheme":["https"],"X-Real-Ip":["<<<REDACTED>>>"],"X-Request-Id":["792df8495efbbc1e2539ebecaace5254"],"X-Scheme":["https"]},"goroutine":3101,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2024-08-26T16:52:22.384025382Z","message":"HTTP API"}
{"level":"info","identity":"devops","goroutine":3196,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:22.390641808Z","message":"user profile successfully set"}
{"level":"debug","digest":"sha256:460b26a845b3dacac3596a292cd7a4fc0b933f99c647ae88429fdb474e1b5705","dstRecord":"/aplan/aggregation-manager/master/blobs/sha256/460b26a845b3dacac3596a292cd7a4fc0b933f99c647ae88429fdb474e1b5705","component":"cache","goroutine":3219,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1267","time":"2024-08-26T16:52:22.392827653Z","message":"found dedupe record"}
{"level":"debug","digest":"sha256:01e3f73af39d0d03cfbec4869402d3c3b955717f2cc4c435e1a262c4769ce07e","dstRecord":"/aplan/aggregation-manager/master/blobs/sha256/01e3f73af39d0d03cfbec4869402d3c3b955717f2cc4c435e1a262c4769ce07e","component":"cache","goroutine":3204,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1267","time":"2024-08-26T16:52:22.394326951Z","message":"found dedupe record"}
{"level":"error","error":"s3aws: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable\n\tstatus code: 416, request id: 8cb86976-b442-4686-b473-02eecf626e8c, host id: ","blob":"/aplan/aggregation-manager/master/blobs/sha256/460b26a845b3dacac3596a292cd7a4fc0b933f99c647ae88429fdb474e1b5705","goroutine":3219,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1394","time":"2024-08-26T16:52:22.402023804Z","message":"failed to open blob"}
{"level":"error","error":"s3aws: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable\n\tstatus code: 416, request id: 8cb86976-b442-4686-b473-02eecf626e8c, host id: ","goroutine":3219,"caller":"zotregistry.dev/zot/pkg/api/routes.go:1134","time":"2024-08-26T16:52:22.402109477Z","message":"unexpected error"}
{"level":"info","module":"http","username":"devops","component":"session","clientIP":"10.42.0.38:54420","method":"GET","path":"/v2/aplan/security-server/master/blobs/sha256:460b26a845b3dacac3596a292cd7a4fc0b933f99c647ae88429fdb474e1b5705","statusCode":500,"latency":"0s","bodySize":0,"headers":{"Accept-Encoding":["gzip"],"Authorization":["******"],"User-Agent":["docker/24.0.5 go/go1.20.6 git-commit/a61e2b4c9c kernel/6.4.12-arch1-1 os/linux arch/amd64 UpstreamClient(Docker-Client/24.0.5 \\(linux\\))"],"X-Forwarded-For":["<<<REDACTED>>>"],"X-Forwarded-Host":["<<<REDACTED>>>"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"],"X-Forwarded-Scheme":["https"],"X-Real-Ip":["<<<REDACTED>>>"],"X-Request-Id":["e49bc9e3fc6500b61a86fa2fd567c246"],"X-Scheme":["https"]},"goroutine":3219,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2024-08-26T16:52:22.402215349Z","message":"HTTP API"}
{"level":"error","error":"s3aws: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable\n\tstatus code: 416, request id: e24fc531-4f9e-4c47-896d-f330eb7d72f1, host id: ","blob":"/aplan/aggregation-manager/master/blobs/sha256/01e3f73af39d0d03cfbec4869402d3c3b955717f2cc4c435e1a262c4769ce07e","goroutine":3204,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1394","time":"2024-08-26T16:52:22.403688556Z","message":"failed to open blob"}
{"level":"error","error":"s3aws: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable\n\tstatus code: 416, request id: e24fc531-4f9e-4c47-896d-f330eb7d72f1, host id: ","goroutine":3204,"caller":"zotregistry.dev/zot/pkg/api/routes.go:1134","time":"2024-08-26T16:52:22.403803359Z","message":"unexpected error"}
{"level":"info","module":"http","username":"devops","component":"session","clientIP":"10.42.0.38:54422","method":"GET","path":"/v2/aplan/security-server/master/blobs/sha256:01e3f73af39d0d03cfbec4869402d3c3b955717f2cc4c435e1a262c4769ce07e","statusCode":500,"latency":"0s","bodySize":0,"headers":{"Accept-Encoding":["gzip"],"Authorization":["******"],"User-Agent":["docker/24.0.5 go/go1.20.6 git-commit/a61e2b4c9c kernel/6.4.12-arch1-1 os/linux arch/amd64 UpstreamClient(Docker-Client/24.0.5 \\(linux\\))"],"X-Forwarded-For":["<<<REDACTED>>>"],"X-Forwarded-Host":["<<<REDACTED>>>"],"X-Forwarded-Port":["443"],"X-Forwarded-Proto":["https"],"X-Forwarded-Scheme":["https"],"X-Real-Ip":["<<<REDACTED>>>"],"X-Request-Id":["226d333e0fd96c1f33f17f1037097cd3"],"X-Scheme":["https"]},"goroutine":3204,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2024-08-26T16:52:22.403922642Z","message":"HTTP API"}
{"level":"info","identity":"devops","goroutine":2835,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:22.444895074Z","message":"user profile successfully set"}
{"level":"info","module":"http","username":"devops","component":"session","clientIP":"10.42.0.1:52322","method":"GET","path":"/v2/","statusCode":200,"latency":"0s","bodySize":0,"headers":{"Accept":["*/*"],"Authorization":["******"],"Connection":["close"],"User-Agent":["kube-probe/1.27"]},"goroutine":2835,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2024-08-26T16:52:22.444947595Z","message":"HTTP API"}
{"level":"info","identity":"devops","goroutine":3266,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:22.665399335Z","message":"user profile successfully set"}
{"level":"info","identity":"devops","goroutine":3253,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:22.672863073Z","message":"user profile successfully set"}
{"level":"debug","digest":"sha256:01e3f73af39d0d03cfbec4869402d3c3b955717f2cc4c435e1a262c4769ce07e","dstRecord":"/aplan/aggregation-manager/master/blobs/sha256/01e3f73af39d0d03cfbec4869402d3c3b955717f2cc4c435e1a262c4769ce07e","component":"cache","goroutine":3266,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1267","time":"2024-08-26T16:52:22.721656481Z","message":"found dedupe record"}
{"level":"debug","digest":"sha256:460b26a845b3dacac3596a292cd7a4fc0b933f99c647ae88429fdb474e1b5705","dstRecord":"/aplan/aggregation-manager/master/blobs/sha256/460b26a845b3dacac3596a292cd7a4fc0b933f99c647ae88429fdb474e1b5705","component":"cache","goroutine":3253,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1267","time":"2024-08-26T16:52:22.723648861Z","message":"found dedupe record"}
{"level":"error","error":"s3aws: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable\n\tstatus code: 416, request id: 24a635e0-f797-492b-9e1a-cacf42a72ab8, host id: ","blob":"/aplan/aggregation-manager/master/blobs/sha256/01e3f73af39d0d03cfbec4869402d3c3b955717f2cc4c435e1a262c4769ce07e","goroutine":3266,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1394","time":"2024-08-26T16:52:22.768657264Z","message":"failed to open blob"}
{"level":"error","error":"s3aws: RequestedRangeNotSatisfiable: Requested Range Not Satisfiable\n\tstatus code: 416, request id: 24a635e0-f797-492b-9e1a-cacf42a72ab8, host id: ","goroutine":3266,"caller":"zotregistry.dev/zot/pkg/api/routes.go:1134","time":"2024-08-26T16:52:22.768768777Z","message":"unexpected error"}

<<REMOVED SOME LINES THAT SEEMS SAME>>

{"level":"debug","component":"scheduler","generator":"GCTaskGenerator","goroutine":1977,"caller":"zotregistry.dev/zot/pkg/scheduler/scheduler.go:311","time":"2024-08-26T16:52:50.771342132Z","message":"waiting generator is ready, pushing to ready generators"}
{"level":"debug","component":"scheduler","worker":10,"task":"{Name: GCTask, repo: aplan/model-api/master}","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/scheduler/scheduler.go:133","time":"2024-08-26T16:52:51.152143159Z","message":"starting task"}
{"level":"info","module":"gc","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/storage/gc/gc.go:84","time":"2024-08-26T16:52:51.15220167Z","message":"executing gc of orphaned blobs for /aplan/model-api/master"}
{"level":"info","module":"retention","dry-run":false,"repository":"aplan/model-api/master","mediaType":"application/vnd.oci.image.manifest.v1+json","digest":"sha256:7531708dfaa7b60ae96f245728445cb9a0c91230220fe9bcb804bfb683ad0fef","tag":"362682","lastPullTimestamp":"1970-01-01 00:00:00 +0000 UTC","pushTimestamp":"2024-08-23 13:46:03.994878268 +0000 UTC","decision":"keep","reason":"retained by mostRecentlyPushedCount:5 policy","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/retention/retention.go:263","time":"2024-08-26T16:52:51.173959428Z","message":"applied policy"}
{"level":"info","module":"retention","dry-run":false,"repository":"aplan/model-api/master","mediaType":"application/vnd.oci.image.manifest.v1+json","digest":"sha256:f110e1c43475aec54c8857c24cc6d90c7f5930c9a18c37fd2761cb66c3d1766e","tag":"362333","lastPullTimestamp":"1970-01-01 00:00:00 +0000 UTC","pushTimestamp":"2024-08-22 10:38:27.777316503 +0000 UTC","decision":"keep","reason":"retained by mostRecentlyPushedCount:5 policy","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/retention/retention.go:263","time":"2024-08-26T16:52:51.174026749Z","message":"applied policy"}
{"level":"info","module":"retention","dry-run":false,"repository":"aplan/model-api/master","mediaType":"application/vnd.oci.image.manifest.v1+json","digest":"sha256:fa5635b2eca28c8d5afb8a57e71a900800f6d975f66cfd945ab2aa9077e72e78","tag":"362320","lastPullTimestamp":"1970-01-01 00:00:00 +0000 UTC","pushTimestamp":"2024-08-22 10:34:46.999809968 +0000 UTC","decision":"keep","reason":"retained by mostRecentlyPushedCount:5 policy","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/retention/retention.go:263","time":"2024-08-26T16:52:51.174078621Z","message":"applied policy"}
{"level":"info","module":"retention","dry-run":false,"repository":"aplan/model-api/master","mediaType":"application/vnd.oci.image.manifest.v1+json","digest":"sha256:ee76da585b30f07291096b90129b66fb7be0b5ccab8b51c134a97e8758864971","tag":"361828","lastPullTimestamp":"1970-01-01 00:00:00 +0000 UTC","pushTimestamp":"2024-08-20 14:31:06.182375066 +0000 UTC","decision":"keep","reason":"retained by mostRecentlyPushedCount:5 policy","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/retention/retention.go:263","time":"2024-08-26T16:52:51.174134122Z","message":"applied policy"}
{"level":"info","module":"retention","dry-run":false,"repository":"aplan/model-api/master","mediaType":"application/vnd.oci.image.manifest.v1+json","digest":"sha256:af2f280f3355fbe699c69640bed0f30729f5a2ac50e1644ea5af42c92008c5d9","tag":"361551","lastPullTimestamp":"1970-01-01 00:00:00 +0000 UTC","pushTimestamp":"2024-08-19 21:31:32.541990632 +0000 UTC","decision":"keep","reason":"retained by mostRecentlyPushedCount:5 policy","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/retention/retention.go:263","time":"2024-08-26T16:52:51.174189124Z","message":"applied policy"}
{"level":"info","module":"retention","dry-run":false,"repository":"aplan/model-api/master","mediaType":"application/vnd.oci.image.manifest.v1+json","digest":"sha256:7531708dfaa7b60ae96f245728445cb9a0c91230220fe9bcb804bfb683ad0fef","tag":"latest","lastPullTimestamp":"1970-01-01 00:00:00 +0000 UTC","pushTimestamp":"2024-08-23 13:46:03.994878268 +0000 UTC","decision":"keep","reason":"retained by patterns policy","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/retention/retention.go:263","time":"2024-08-26T16:52:51.174243165Z","message":"applied policy"}
{"level":"debug","module":"gc","repository":"aplan/model-api/master","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/storage/gc/gc.go:464","time":"2024-08-26T16:52:51.271537904Z","message":"manifests without tags"}
{"level":"debug","module":"gc","repository":"aplan/model-api/master","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/storage/gc/gc.go:552","time":"2024-08-26T16:52:51.356689758Z","message":"cleaning orphan blobs"}
{"level":"debug","repository":"aplan/model-api/master","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/storage/imagestore/imagestore.go:1577","time":"2024-08-26T16:52:51.512087789Z","message":"failed to list .uploads/ dir"}
{"level":"info","module":"gc","repository":"aplan/model-api/master","count":0,"goroutine":2023,"caller":"zotregistry.dev/zot/pkg/storage/gc/gc.go:616","time":"2024-08-26T16:52:51.512154471Z","message":"garbage collected blobs"}
{"level":"info","module":"gc","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/storage/gc/gc.go:96","time":"2024-08-26T16:52:51.512193722Z","message":"gc successfully completed for /aplan/model-api/master"}
{"level":"debug","component":"scheduler","worker":10,"task":"{Name: GCTask, repo: aplan/model-api/master}","goroutine":2023,"caller":"zotregistry.dev/zot/pkg/scheduler/scheduler.go:157","time":"2024-08-26T16:52:51.512228773Z","message":"finished task"}
{"level":"info","identity":"devops","goroutine":3810,"caller":"zotregistry.dev/zot/pkg/api/authn.go:144","time":"2024-08-26T16:52:52.446775019Z","message":"user profile successfully set"}
{"level":"info","module":"http","username":"devops","component":"session","clientIP":"10.42.0.1:55732","method":"GET","path":"/v2/","statusCode":200,"latency":"0s","bodySize":0,"headers":{"Accept":["*/*"],"Authorization":["******"],"Connection":["close"],"User-Agent":["kube-probe/1.27"]},"goroutine":3810,"caller":"zotregistry.dev/zot/pkg/api/session.go:137","time":"2024-08-26T16:52:52.44683565Z","message":"HTTP API"}

About s3 backend, it's the largest russian hosting - https://selectel.ru/en/. It has some docs in EN like this and this, and it has a compability table with AWS here, in russian, but the table (methods) should be clear.

[rchincha]

@lictw

 "retention": {
      "delay": "24h",
      "policies": [
        {
          "repositories": ["devops/**"]
        }, 

Are you seeing the same issue with all repos or only devops/ ?

[lictw]

@rchincha with all, main repository is aplan here, I just upload a test image into devops. Even this test image has "predicted" dedupe blob from aplan/aggregation-manager as you can see from logs.

[rchincha]

@peusebiu can you pls take a look at this and triage?

[eusebiu-constantin-petu-dbk]

Hello @lictw I tried finding the issue here with the same config as you used, but the s3 backend(I used localstack).
I couldn't reproduced your issue. The only way to reproduce it was to delete the boltdb cache from disk and restart.

That being said, zot doesn't drop the cache.

Your retention config overlaps a bit with the sync config, but retention/gc doesn't delete blobs with content without moving the content to the next blob candidate, so that shouldn't happen.

You can use this: https://github.com/br0xen/boltbrowser to look inside boltdb and check if there is any discrepancy between cache's original blob(the blob with content) and storage.

Even with s3 my setup has PV for cache, andzot has BoltDB files, but they are pretty new.. Does zot drop local cache at some moment? This then explains why it works for a while from scratch, and then breaks.

Maybe something is removing the content from that PV?

Also, just for understanding, if cache broken, why zot does not fix it when I upload an image? In my case I upload first, only then I try to download it, so I suggest all blobs to zot and zot should accept missing blob, but it does not.

Actually we do a sort of repairing at startup but maybe it needs improvements.
Can you send some startup logs please. Look after "component": "dedupe". This would help a lot.

Thank you!