Hi team,

This request is to benefit the support teams, regarding a misleading error log. Allow me to explain.

The image has many layers. Some succeed and sometimes one fail. The root cause is unknown at this point, and the issue does manifest itself at the moment. But, this is not the ask. Please, continue reading.

The error we observed is:

~~~

podman pull --log-level=debug image-registry.openshift-image-registry.svc:5000/$ns/$app:$version
...
Copying blob da676fc70a17 [--------------------------------------] 0.0b / 3.9MiB
DEBU[0001] Error pulling candidate image-registry.openshift-image-registry.svc:5000/$ns/$app:$version: reading blob sha256:da...24: fetching blob: received unexpected HTTP status: 500 Internal Server Error 
Error: reading blob sha256:da...24: fetching blob: received unexpected HTTP status: 500 Internal Server Error
~~~

The IR logs with debug show:

~~~

level=error msg="response completed with error" err.code=unknown err.detail="filesystem: Path not found: /docker/registry/v2/blobs/sha256/da/da...24/data" err.message="unknown error"

~~~

The blob does not exist, which is correct!

When an upstream mirroring succeeds we observe:

~~~
level=info msg="Found digest location by search \"sha256:da...24\" in \"$upstream_source/$app\""

level=debug msg="copyContent: starting with dgst=sha256:da...24"
level=debug msg="(*remoteBlobGetterService).Stat: starting with  ...
level=info msg="response completed"
level=debug msg="(*blobWriter).Commit"
level=debug msg="filesystem.PutContent(\"/docker/registry/v2/repositories/...

level=info msg="Completed mirroring of \"sha256:da...24\""
~~~

When the upstream mirroring fails the logs sequence is:

~~~

level=info msg="Found digest location by search \"sha256:e8...a1\" in \"$upstream_source/$app\""

level=debug msg="copyContent: starting with ...

level=info msg="Start background mirroring of ...

level=debug msg="copyContent: starting with ...

level=debug msg="(*remoteBlobGetterService).Open: starting with ...

level=debug msg="copyContent: BlobGetterService.Open error=unknown blob"    <== Real error.
level=debug msg="unexpected error getting blob HTTP handler: unknown blob"
level=error msg="response completed with error"

level=debug msg="(*remoteBlobGetterService).Open: starting with ...

level=debug msg="copyContent: BlobGetterService.Open error=unknown blob"
level=debug msg="(*blobWriter).Cancel"

level=debug msg="filesystem.PutContent ...

level=error msg="error closing blobwriter: sync /registry/docker/registry/v2/repositories/.../_uploads/bc...5f/data: file already closed"

level=debug msg="filesystem.Delete ... 

level=error msg="Background mirroring failed: error committing to storage: unknown blob" <== Perceived error.

~~~

It looks like that in case of a fail, the error may be misinterpreted with a storage issue.
The error "error committing to storage: unknown blob" happens as a cascade effect because there is no blob to write.

This mis-interpretation caused many hours of troubleshooting in the wrong direction: Storage instead of mirror, network, upstream registry.

The ask is: Is it possible to improve the logging sequence so that the real error is highlighted?

Thank you