cli icon indicating copy to clipboard operation
cli copied to clipboard
verified publisher icon docker

Occasional failure with `docker trust signer add` on Windows

Open shizhMSFT opened this issue 4 years ago • 2 comments

Description

On Windows, docker trust signer add fails by chance due to the root cause of https://github.com/theupdateframework/notary/issues/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 https://github.com/theupdateframework/notary/issues/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

shizhMSFT avatar Apr 27 '21 10:04 shizhMSFT

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

shizhMSFT avatar Apr 27 '21 11:04 shizhMSFT

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

MrazqRuby avatar Jun 17 '23 07:06 MrazqRuby