Skip to content

Occasional failure with docker trust signer add on Windows #3066

Closed as not planned
Closed as not planned
Occasional failure with docker trust signer add on Windows#3066
Labels
area/trustkind/bugversion/20.10

Description

@shizhMSFT
shizhMSFT
opened on Apr 27, 2021

Description

On Windows, docker trust signer add fails by chance due to the root cause of notaryproject/notary#1599

Steps to reproduce the issue:

  1. Setup a notary server
  2. Generate key by docker trust key generate signingkey
  3. Run docker -D trust signer add --key "signingkey.pub" signingkey <registry>/<repo> against a new trust collection
  4. Retry step 3 on success

Describe the results you received:

C:\Testing>docker -D trust signer add --key "signingkey.pub" signingkey <registry>/<repo>
Adding signer "signingkey" to <registry>/<repo>...
time="2021-04-27T07:26:29Z" level=debug msg="reading certificate directory: C:\\Users\\testuser\\.docker\\tls\\<registry>"
time="2021-04-27T07:26:29Z" level=debug msg="Making dir path: C:\\Users\\testuser\\.docker\\trust\\tuf\\<registry>\\<repo>\\changelist"
time="2021-04-27T07:26:30Z" level=debug msg="received HTTP status 404 when requesting root."
Initializing signed repository for <registry>/<repo>...
time="2021-04-27T07:26:30Z" level=debug msg="generated ECDSA key with keyID: 94547a5f82c10fc951f9060ac5399cf4846057a8dc1bd7bfb2f77b028f999155"
time="2021-04-27T07:26:30Z" level=debug msg="generated new ecdsa key for role: targets and keyID: 94547a5f82c10fc951f9060ac5399cf4846057a8dc1bd7bfb2f77b028f999155"
time="2021-04-27T07:26:30Z" level=debug msg="got remote timestamp ecdsa key with keyID: 214c0a2cd795c5e1beb7ebf44ef4305e86452126e38fcf2d86c8e1ca7844f3e1"
time="2021-04-27T07:26:30Z" level=debug msg="got remote snapshot ecdsa key with keyID: e15a4b9c23bed60640cb4b0a875a00297e6e6e63dd7c430b2edca54df6684594"
time="2021-04-27T07:26:30Z" level=debug msg="generating new snapshot..."
time="2021-04-27T07:26:30Z" level=debug msg="Saving changes to Trusted Collection."
time="2021-04-27T07:26:30Z" level=debug msg="signing root..."
time="2021-04-27T07:26:30Z" level=debug msg="sign called with 1/1 required keys"
time="2021-04-27T07:26:30Z" level=debug msg="sign called with 0/0 required keys"
time="2021-04-27T07:26:30Z" level=debug msg="sign targets called for role targets"
time="2021-04-27T07:26:30Z" level=debug msg="sign called with 1/1 required keys"
time="2021-04-27T07:26:30Z" level=debug msg="sign called with 0/0 required keys"
Successfully initialized "<registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="Adding delegation \"targets/signingkey\" with threshold 1, and 1 keys\\n"
time="2021-04-27T07:26:30Z" level=debug msg="Adding [] paths to delegation targets/signingkey\\n"
time="2021-04-27T07:26:30Z" level=debug msg="Adding delegation \"targets/releases\" with threshold 1, and 1 keys\\n"
time="2021-04-27T07:26:30Z" level=debug msg="Adding [] paths to delegation targets/releases\\n"
time="2021-04-27T07:26:30Z" level=debug msg="entered ValidateRoot with dns: <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="found the following root keys: [87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557]"
time="2021-04-27T07:26:30Z" level=debug msg="found 1 valid leaf certificates for <registry>/<repo>: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="found 1 leaf certs, of which 1 are valid leaf certs for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="checking root against trust_pinning config for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="checking trust-pinning for cert: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg=" role has key IDs: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="verifying signature for key ID: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="root validation succeeded for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="entered ValidateRoot with dns: <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="found the following root keys: [87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557]"
time="2021-04-27T07:26:30Z" level=debug msg="found 1 valid leaf certificates for <registry>/<repo>: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="found 1 leaf certs, of which 1 are valid leaf certs for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="checking root against trust_pinning config for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="checking trust-pinning for cert: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg=" role has key IDs: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="verifying signature for key ID: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="root validation succeeded for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="received HTTP status 404 when requesting root."
time="2021-04-27T07:26:30Z" level=debug msg="Loading trusted collection."
time="2021-04-27T07:26:30Z" level=debug msg="entered ValidateRoot with dns: <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="found the following root keys: [87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557]"
time="2021-04-27T07:26:30Z" level=debug msg="found 1 valid leaf certificates for <registry>/<repo>: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="found 1 leaf certs, of which 1 are valid leaf certs for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="checking root against trust_pinning config for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="checking trust-pinning for cert: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg=" role has key IDs: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="verifying signature for key ID: 87b2ecd0eace017951ac5acf70cb130d25c5520c8794bf52abd6924959f38557"
time="2021-04-27T07:26:30Z" level=debug msg="root validation succeeded for <registry>/<repo>"
time="2021-04-27T07:26:30Z" level=debug msg="targets role has key IDs: 94547a5f82c10fc951f9060ac5399cf4846057a8dc1bd7bfb2f77b028f999155"
time="2021-04-27T07:26:30Z" level=debug msg="verifying signature for key ID: 94547a5f82c10fc951f9060ac5399cf4846057a8dc1bd7bfb2f77b028f999155"
time="2021-04-27T07:26:30Z" level=debug msg="role targets/signingkey with no Paths will never be able to publish content until one or more are added"
time="2021-04-27T07:26:30Z" level=debug msg="error attempting to apply change #0: create, on scope: targets/signingkey path:  type: delegation"
time="2021-04-27T07:26:30Z" level=debug msg="Error applying changelist"
tuf: invalid role targets/signingkey.

Failed to add signer to: <registry>/<repo>

Describe the results you expected:

C:\Testing>docker -D trust signer add --key "signingkey.pub" signingkey <registry>/<repo>
Adding signer "signingkey" to <registry>/<repo>...
time="2021-04-27T07:26:30Z" level=debug msg="reading certificate directory: C:\\Users\\testuser\\.docker\\tls\\<registry>"
time="2021-04-27T07:26:30Z" level=debug msg="Making dir path: C:\\Users\\testuser\\.docker\\trust\\tuf\\<registry>\\<repo>\\changelist"
time="2021-04-27T07:26:30Z" level=debug msg="received HTTP status 404 when requesting root."
Initializing signed repository for <registry>/<repo>...
time="2021-04-27T07:26:30Z" level=debug msg="generated ECDSA key with keyID: 98b3bd922af753ff6b82e877df1fb34094ef351928c3a95f6255ad35dafcc374"
time="2021-04-27T07:26:30Z" level=debug msg="generated new ecdsa key for role: targets and keyID: 98b3bd922af753ff6b82e877df1fb34094ef351928c3a95f6255ad35dafcc374"
time="2021-04-27T07:26:30Z" level=debug msg="got remote timestamp ecdsa key with keyID: 5e543105ca16689f13de4c49c906c93ff4b684d640fabc5044e7b2493fcac5c9"
time="2021-04-27T07:26:31Z" level=debug msg="got remote snapshot ecdsa key with keyID: 9023480e4fba7c4c8568ef405fb9c15150880958ea51a3b835734b4ce920a001"
time="2021-04-27T07:26:31Z" level=debug msg="generating new snapshot..."
time="2021-04-27T07:26:31Z" level=debug msg="Saving changes to Trusted Collection."
time="2021-04-27T07:26:31Z" level=debug msg="signing root..."
time="2021-04-27T07:26:31Z" level=debug msg="sign called with 1/1 required keys"
time="2021-04-27T07:26:31Z" level=debug msg="sign called with 0/0 required keys"
time="2021-04-27T07:26:31Z" level=debug msg="sign targets called for role targets"
time="2021-04-27T07:26:31Z" level=debug msg="sign called with 1/1 required keys"
time="2021-04-27T07:26:31Z" level=debug msg="sign called with 0/0 required keys"
Successfully initialized "<registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="Adding delegation \"targets/signingkey\" with threshold 1, and 1 keys\\n"
time="2021-04-27T07:26:31Z" level=debug msg="Adding [] paths to delegation targets/signingkey\\n"
time="2021-04-27T07:26:31Z" level=debug msg="Adding delegation \"targets/releases\" with threshold 1, and 1 keys\\n"
time="2021-04-27T07:26:31Z" level=debug msg="Adding [] paths to delegation targets/releases\\n"
time="2021-04-27T07:26:31Z" level=debug msg="entered ValidateRoot with dns: <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="found the following root keys: [06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873]"
time="2021-04-27T07:26:31Z" level=debug msg="found 1 valid leaf certificates for <registry>/<repo>: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="found 1 leaf certs, of which 1 are valid leaf certs for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="checking root against trust_pinning config for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="checking trust-pinning for cert: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg=" role has key IDs: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="verifying signature for key ID: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="root validation succeeded for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="entered ValidateRoot with dns: <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="found the following root keys: [06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873]"
time="2021-04-27T07:26:31Z" level=debug msg="found 1 valid leaf certificates for <registry>/<repo>: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="found 1 leaf certs, of which 1 are valid leaf certs for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="checking root against trust_pinning config for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="checking trust-pinning for cert: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg=" role has key IDs: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="verifying signature for key ID: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="root validation succeeded for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="received HTTP status 404 when requesting root."
time="2021-04-27T07:26:31Z" level=debug msg="Loading trusted collection."
time="2021-04-27T07:26:31Z" level=debug msg="entered ValidateRoot with dns: <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="found the following root keys: [06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873]"
time="2021-04-27T07:26:31Z" level=debug msg="found 1 valid leaf certificates for <registry>/<repo>: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="found 1 leaf certs, of which 1 are valid leaf certs for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="checking root against trust_pinning config for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="checking trust-pinning for cert: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg=" role has key IDs: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="verifying signature for key ID: 06cbb4d0c2071c8d87d69c674fae35a9ac02ba3fe308076be309ef20d065c873"
time="2021-04-27T07:26:31Z" level=debug msg="root validation succeeded for <registry>/<repo>"
time="2021-04-27T07:26:31Z" level=debug msg="targets role has key IDs: 98b3bd922af753ff6b82e877df1fb34094ef351928c3a95f6255ad35dafcc374"
time="2021-04-27T07:26:31Z" level=debug msg="verifying signature for key ID: 98b3bd922af753ff6b82e877df1fb34094ef351928c3a95f6255ad35dafcc374"
time="2021-04-27T07:26:31Z" level=debug msg="role targets/signingkey with no Paths will never be able to publish content until one or more are added"
time="2021-04-27T07:26:31Z" level=debug msg="role targets/releases with no Paths will never be able to publish content until one or more are added"
time="2021-04-27T07:26:31Z" level=debug msg="applied 4 change(s)"
time="2021-04-27T07:26:31Z" level=debug msg="sign targets called for role targets"
time="2021-04-27T07:26:31Z" level=debug msg="sign called with 1/1 required keys"
time="2021-04-27T07:26:31Z" level=debug msg="sign called with 0/0 required keys"
time="2021-04-27T07:26:31Z" level=debug msg="generating new snapshot..."
time="2021-04-27T07:26:31Z" level=debug msg="signing snapshot..."
time="2021-04-27T07:26:31Z" level=debug msg="sign called with 1/1 required keys"
time="2021-04-27T07:26:31Z" level=debug msg="Client does not have the key to sign snapshot. Assuming that server should sign the snapshot."
Successfully added signer: signingkey to <registry>/<repo>

Additional information you deem important:

Issue happens only occasionally due to notaryproject/notary#1599

Output of docker version:

Client: Docker Engine - Community
 Cloud integration: 1.0.12
 Version:           20.10.5
 API version:       1.41
 Go version:        go1.13.15
 Git commit:        55c4c88
 Built:             Tue Mar  2 20:14:53 2021
 OS/Arch:           windows/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.5
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.13.15
  Git commit:       363e9a8
  Built:            Tue Mar  2 20:15:47 2021
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.4.4
  GitCommit:        05f951a3781f4f2c1911b05e61c160e9c30eaa8e
 runc:
  Version:          1.0.0-rc93
  GitCommit:        12644e614e25b05da6fd08a38ffa0cfe1903fdec
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0

Output of docker info:

Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.5.1-docker)
  scan: Docker Scan (Docker Inc., v0.6.0)

Server:
 Containers: 0
  Running: 0
  Paused: 0
  Stopped: 0
 Images: 0
 Server Version: 20.10.5
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 05f951a3781f4f2c1911b05e61c160e9c30eaa8e
 runc version: 12644e614e25b05da6fd08a38ffa0cfe1903fdec
 init version: de40ad0
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 5.4.72-microsoft-standard-WSL2
 Operating System: Docker Desktop
 OSType: linux
 Architecture: x86_64
 CPUs: 4
 Total Memory: 12.48GiB
 Name: docker-desktop
 ID: 7JSG:F7AS:7FNJ:QXYK:GRBZ:WOD2:MQ5L:GWLV:OGAD:GHDT:A7IS:6MC5
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: No blkio throttle.read_bps_device support
WARNING: No blkio throttle.write_bps_device support
WARNING: No blkio throttle.read_iops_device support
WARNING: No blkio throttle.write_iops_device support

Additional environment details (AWS, VirtualBox, physical, etc.):
None

Activity

  1. shizhMSFT commented on Apr 27, 2021

    @shizhMSFT
    shizhMSFT
    on Apr 27, 2021
    Author

    Precisely, the change AddDelegationPaths is applied before AddDelegationRoleAndKeys since the file based change list does not preserve order.

  2. tsaniprodanov commented on Jun 17, 2023

    @tsaniprodanov
    tsaniprodanov
    on Jun 17, 2023

    Is there any workaround for this?
    I'm hitting the same issue for some Azure CR repositories with 100% reproducibility

  3. thaJeztah
    added
    area/trust
    version/20.10
    on Jun 23, 2023
  4. thaJeztah
    added
    kind/bug
    on Apr 24, 2025

  5. thaJeztah commented on May 14, 2026

    @thaJeztah
    thaJeztah
    on May 14, 2026
    Member
  6. thaJeztah
    closed this as not plannedon May 14, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    area/trustkind/bugversion/20.10

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions