Skip to content

Bug: Unexpected request number in --debug log #1096

Closed
Closed
Bug: Unexpected request number in --debug log#1096
#1266 (+3)
Labels
bugSomething isn't working
Milestone
v1.2.0-rc.1
@Wwwsylvia

Description

@Wwwsylvia
Wwwsylvia
opened on Aug 31, 2023

What happened in your environment?

The --debug log for oras cp sometimes display duplicated request number (e.g. two Request #0). It looks like the request number is counted per repository.
I think this behavior is confusing and misleading.

repo1 #0
repo2 #0
repo1 #1
repo2 #1

Command

oras cp localhost:8080/testcount_1:v1 localhost:8080/testcount_2:v1 --debug 2>debug.log

Logs

time=2023-08-31T11:02:36+08:00 level=debug msg=Request #0
> Request URL: "http://localhost:8080/v2/testcount_1/manifests/v1"
> Request method: "GET"
> Request headers:
   "Accept": "application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, application/vnd.oci.artifact.manifest.v1+json"
   "User-Agent": "oras/1.1.0-rc.2"
time=2023-08-31T11:02:36+08:00 level=debug msg=Response #0
< Response Status: "200 OK"
< Response headers:
   "Access-Control-Allow-Origin": "*"
   "Content-Length": "985"
   "Content-Type": "application/vnd.oci.image.manifest.v1+json"
   "Docker-Content-Digest": "sha256:fd6c245fe6a450b3cc7cd0229ff0963409ed28498c0f45c98766ed0d7853e965"
   "Date": "Thu, 31 Aug 2023 03:02:36 GMT"
time=2023-08-31T11:02:36+08:00 level=debug msg=Request #0
> Request URL: "http://localhost:8080/v2/testcount_2/manifests/sha256:fd6c245fe6a450b3cc7cd0229ff0963409ed28498c0f45c98766ed0d7853e965"
> Request method: "HEAD"
> Request headers:
   "Accept": "application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.list.v2+json, application/vnd.oci.image.manifest.v1+json, application/vnd.oci.image.index.v1+json, application/vnd.oci.artifact.manifest.v1+json"
   "User-Agent": "oras/1.1.0-rc.2"
time=2023-08-31T11:02:36+08:00 level=debug msg=Response #0
< Response Status: "404 Not Found"
< Response headers:
   "Access-Control-Allow-Origin": "*"
   "Content-Type": "application/json"
   "Date": "Thu, 31 Aug 2023 03:02:36 GMT"
   "Content-Length": "283"
   "Access-Control-Allow-Headers": "Authorization,content-type,X-ZOT-API-CLIENT"
   "Access-Control-Allow-Methods": "HEAD,GET,OPTIONS"
time=2023-08-31T11:02:36+08:00 level=debug msg=Request #2
> Request URL: "http://localhost:8080/v2/testcount_2/blobs/sha256:44136fa355b3678a1146ad16f7e8649e94fb4fc21fe77e8310c060f61caaff8a"
> Request method: "HEAD"
> Request headers:
   "User-Agent": "oras/1.1.0-rc.2"
time=2023-08-31T11:02:36+08:00 level=debug msg=Request #3
> Request URL: "http://localhost:8080/v2/testcount_2/blobs/sha256:b5bb9d8014a0f9b1d61e21e796d78dccdf1352f23cd32812f4850b878ae4944c"
> Request method: "HEAD"
> Request headers:
   "User-Agent": "oras/1.1.0-rc.2"
time=2023-08-31T11:02:36+08:00 level=debug msg=Request #1
> Request URL: "http://localhost:8080/v2/testcount_2/blobs/sha256:7d865e959b2466918c9863afca942d0fb89d7c9ac0c99bafc3749504ded97730"
> Request method: "HEAD"
> Request headers:
   "User-Agent": "oras/1.1.0-rc.2"
time=2023-08-31T11:02:36+08:00 level=debug msg=Response #2
< Response Status: "200 OK"
< Response headers:
   "Accept-Ranges": "bytes"
   "Content-Length": "2"
   "Docker-Content-Digest": "sha256:44136fa355b3678a1146ad16f7e8649e94fb4fc21fe77e8310c060f61caaff8a"
   "Date": "Thu, 31 Aug 2023 03:02:36 GMT"
time=2023-08-31T11:02:36+08:00 level=debug msg=Request #4
> Request URL: "http://localhost:8080/v2/testcount_2/blobs/sha256:bf07a7fbb825fc0aae7bf4a1177b2b31fcf8a3feeaf7092761e18c859ee52a9c"
> Request method: "HEAD"
> Request headers:
   "User-Agent": "oras/1.1.0-rc.2"
time=2023-08-31T11:02:36+08:00 level=debug msg=Response #3
< Response Status: "200 OK"
< Response headers:
   "Accept-Ranges": "bytes"
   "Content-Length": "4"
   "Docker-Content-Digest": "sha256:b5bb9d8014a0f9b1d61e21e796d78dccdf1352f23cd32812f4850b878ae4944c"
   "Date": "Thu, 31 Aug 2023 03:02:36 GMT"
time=2023-08-31T11:02:36+08:00 level=debug msg=Response #1
< Response Status: "200 OK"
< Response headers:
   "Accept-Ranges": "bytes"
   "Content-Length": "4"
   "Docker-Content-Digest": "sha256:7d865e959b2466918c9863afca942d0fb89d7c9ac0c99bafc3749504ded97730"
   "Date": "Thu, 31 Aug 2023 03:02:36 GMT"
time=2023-08-31T11:02:36+08:00 level=debug msg=Response #4
< Response Status: "200 OK"
< Response headers:
   "Accept-Ranges": "bytes"
   "Content-Length": "4"
   "Docker-Content-Digest": "sha256:bf07a7fbb825fc0aae7bf4a1177b2b31fcf8a3feeaf7092761e18c859ee52a9c"
   "Date": "Thu, 31 Aug 2023 03:02:36 GMT"
time=2023-08-31T11:02:36+08:00 level=debug msg=Request #5
> Request URL: "http://localhost:8080/v2/testcount_2/manifests/v1"
> Request method: "PUT"
> Request headers:
   "Content-Type": "application/vnd.oci.image.manifest.v1+json"
   "User-Agent": "oras/1.1.0-rc.2"
time=2023-08-31T11:02:36+08:00 level=debug msg=Response #5
< Response Status: "201 Created"
< Response headers:
   "Docker-Content-Digest": "sha256:fd6c245fe6a450b3cc7cd0229ff0963409ed28498c0f45c98766ed0d7853e965"
   "Location": "/v2/testcount_2/manifests/sha256:fd6c245fe6a450b3cc7cd0229ff0963409ed28498c0f45c98766ed0d7853e965"
   "Date": "Thu, 31 Aug 2023 03:02:36 GMT"
   "Content-Length": "0"
time=2023-08-31T11:02:36+08:00 level=debug msg=Request #6
> Request URL: "http://localhost:8080/v2/testcount_2/manifests/sha256:fd6c245fe6a450b3cc7cd0229ff0963409ed28498c0f45c98766ed0d7853e965"
> Request method: "GET"
> Request headers:
   "Accept": "application/vnd.oci.image.manifest.v1+json"
   "User-Agent": "oras/1.1.0-rc.2"
time=2023-08-31T11:02:36+08:00 level=debug msg=Response #6
< Response Status: "200 OK"
< Response headers:
   "Access-Control-Allow-Origin": "*"
   "Content-Length": "985"
   "Content-Type": "application/vnd.oci.image.manifest.v1+json"
   "Docker-Content-Digest": "sha256:fd6c245fe6a450b3cc7cd0229ff0963409ed28498c0f45c98766ed0d7853e965"
   "Date": "Thu, 31 Aug 2023 03:02:36 GMT"

What did you expect to happen?

It'd be better to merge the two counts into a single count, so that the request number becomes:

repo1 #0
repo2 #1
repo1 #2
repo2 #3

How can we reproduce it?

Run

oras cp $myregistry1/$myrepo:$mytag $myregistry2/$myrepo:$mytag --debug 2>debug.log

against any two remote repositories.

What is the version of your ORAS CLI?

Version:        1.1.0-rc.2
Go version:     go1.21.0
Git commit:     443242e41d469a911af6fa68f3338fcfb2f5f268
Git tree state: clean

What is your OS environment?

Ubuntu 18.04.4

Are you willing to submit PRs to fix it?

  • Yes, I am willing to fix it.

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Fields

    No fields configured for issues without a type.

    Projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions