* fatal: client is offline

[shiva022]

Hello Team,
I am running docker private registry on vm along with notary-server, notary-signer. To run notary server & signer I followed : https://github.com/docker/notary I have used docker-compose to run all components & everything is up and running:
docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
7acbf8a4a527 registry:2 "/entrypoint.sh /e..." 20 hours ago Up 20 hours 0.0.0.0:5000->5000/tcp registry
68afe6a63cd5 notary_server "/usr/bin/env sh -..." 20 hours ago Up 20 hours 0.0.0.0:4443->4443/tcp, 0.0.0.0:32769->8080/tcp notary_server_1
ff6bfeb8b84a notary_signer "/usr/bin/env sh -..." 20 hours ago Up 20 hours notary_signer_1
9ac8a5e488f5 mariadb:10.1.10 "/docker-entrypoin..." 20 hours ago Up 20 hours 3306/tcp notary_mysql_1

go/src/github.com/docker/notary # notary-server version
{"level":"info","msg":"Version: 0.5.0, Git commit: c04e3e6","time":"2017-03-03T16:07:28Z"}
{"level":"fatal","msg":"Could not read config at :, viper error: Unsupported Config Type ""","time":"2017-03-03T16:07:28Z"}

/go/src/github.com/docker/notary # notary-signer version
{"level":"info","msg":"Version: 0.5.0, Git commit: c04e3e6","time":"2017-03-03T16:10:20Z"}
{"level":"fatal","msg":"Could not read config at :, viper error: Unsupported Config Type ""","time":"2017-03-03T16:10:20Z"}
/go/src/github.com/docker/notary #

docker info
Containers: 8
Running: 4
Paused: 0
Stopped: 4
Images: 29
Server Version: 1.13.1
Storage Driver: overlay
Backing Filesystem: xfs
Supports d_type: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: bridge host macvlan null overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: aa8187dbd3b7ad67d8e5e3a15115d3eef43a7ed1
runc version: 9df8b306d01f59d3a8029be411de015b7304dd8f
init version: 949e6fa
Security Options:
seccomp
Profile: default
Kernel Version: 3.10.0-514.el7.x86_64
Operating System: Red Hat Enterprise Linux
OSType: linux
Architecture: x86_64
CPUs: 1
Total Memory: 1.797 GiB
Name: trustimage.test.com
ID: DAMD:CG2G:3FR3:UR3R:CF75:HLWX:OES4:6S2I:TE4I:IR4H:CUTO:DUM5
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false

[root@trustimage fixtures]# docker version
Client:
Version: 1.13.1
API version: 1.26
Go version: go1.7.5
Git commit: 092cba3
Built: Wed Feb 8 06:38:28 2017
OS/Arch: linux/amd64

Server:
Version: 1.13.1
API version: 1.26 (minimum version 1.12)
Go version: go1.7.5
Git commit: 092cba3
Built: Wed Feb 8 06:38:28 2017
OS/Arch: linux/amd64
Experimental: false
[root@trustimage fixtures]#

I have setup docker host on another virtual machine & installed notary client & enable DOCKER_TRUST_CONTENT.
[root@dockerclient .docker]# echo $DOCKER_CONTENT_TRUST
1
[root@dockerclient .docker]# echo $DOCKER_CONTENT_TRUST_SERVER
https://notary-server:4443
[root@dockerclient .docker]#

[root@dockerclient .docker]# docker version
Client:
Version: 1.13.0
API version: 1.25
Go version: go1.7.3
Git commit: 49bf474
Built: Tue Jan 17 09:55:28 2017
OS/Arch: linux/amd64

Server:
Version: 1.13.0
API version: 1.25 (minimum version 1.12)
Go version: go1.7.3
Git commit: 49bf474
Built: Tue Jan 17 09:55:28 2017
OS/Arch: linux/amd64
Experimental: false

[root@dockerclient .docker]# notary version
notary
Version: 0.4.3
Git commit: 9211198

ISSUE:- I got stuck while pushing the image from docker host I am facing the below Issue: -
[root@dockerclient .docker]# docker --debug push trustimage.test.com:5000/regis_no5:v2.1
The push refers to a repository [trustimage.test.com:5000/regis_no5]
ad7b85eab471: Layer already exists
7436cad623e5: Layer already exists
61fd5549d17b: Layer already exists
5cc1e08c7c0e: Layer already exists
7a33e410db32: Layer already exists
0912b310db10: Layer already exists
6767cac03a2d: Layer already exists
f38182d44088: Layer already exists
b5aac7bb5fdf: Layer already exists
9f8566ee5135: Layer already exists
v2.1: digest: sha256:2369cdd47081bfbd26d8f169ed21dde9000cde98d9f7d4fa58411c8dabea131d size: 2395
Signing and pushing trust metadata
DEBU[0000] reading certificate directory: /root/.docker/tls/notary-server:4443
DEBU[0000] crt: /root/.docker/tls/notary-server:4443/ca.crt
DEBU[0000] No yubikey found, using alternative key storage: no library found
DEBU[0000] received HTTP status 404 when requesting root.
DEBU[0000] No yubikey found, using alternative key storage: no library found
DEBU[0000] generated ECDSA key with keyID: 0643b68e02f1b5df36c30dc0402e3476ae1b6182c5d41cc9a01d2f165c70558f
DEBU[0000] generated new ecdsa key for role: root and keyID: 0643b68e02f1b5df36c30dc0402e3476ae1b6182c5d41cc9a01d2f165c70558f
DEBU[0000] No yubikey found, using alternative key storage: no library found
You are about to create a new root signing key passphrase. This passphrase
will be used to protect the most sensitive key in your signing system. Please
choose a long, complex passphrase and be careful to keep the password and the
key file itself secure and backed up. It is highly recommended that you use a
password manager to generate the passphrase and keep it safe. There will be no
way to recover this key. You can find the key in your config directory.
Enter passphrase for new root key with ID 0643b68:
Repeat passphrase for new root key with ID 0643b68:
DEBU[0009] No yubikey found, using alternative key storage: no library found
DEBU[0009] generated ECDSA key with keyID: f50e718989e4f8a10e37f0973b4887d2c50fa13c1b1ec19f35477d25f0b84405
DEBU[0009] generated new ecdsa key for role: targets and keyID: f50e718989e4f8a10e37f0973b4887d2c50fa13c1b1ec19f35477d25f0b84405
Enter passphrase for new repository key with ID f50e718 (trustimage.test.com:5000/regis_no5):
Repeat passphrase for new repository key with ID f50e718 (trustimage.test.com:5000/regis_no5):
DEBU[0015] got remote timestamp ecdsa key with keyID: 7ea8415278180d587d73a0a0b0e050d8dfb26bc10aee33450e75e6bcd353ef8e
DEBU[0015] got remote snapshot ecdsa key with keyID: 3914a421932ca217cf2368925b455a2146ea2382aeacad0da098d26cbc4d5e6d
DEBU[0015] generating new snapshot...
DEBU[0015] Saving changes to Trusted Collection.
DEBU[0015] signing root...
DEBU[0015] sign called with 1/1 required keys
DEBU[0015] No yubikey found, using alternative key storage: no library found
DEBU[0015] sign called with 0/0 required keys
DEBU[0015] sign targets called for role targets
DEBU[0015] sign called with 1/1 required keys
DEBU[0015] No yubikey found, using alternative key storage: no library found
DEBU[0015] sign called with 0/0 required keys
Finished initializing "trustimage.test.com:5000/regis_no5"
DEBU[0015] Making dir path: /root/.docker/trust/tuf/trustimage.test.com:5000/regis_no5/changelist
DEBU[0015] Adding target "v2.1" with sha256 "2369cdd47081bfbd26d8f169ed21dde9000cde98d9f7d4fa58411c8dabea131d" and size 2395 bytes.

DEBU[0015] Making dir path: /root/.docker/trust/tuf/trustimage.test.com:5000/regis_no5/changelist
DEBU[0015] entered ValidateRoot with dns: trustimage.test.com:5000/regis_no5
DEBU[0015] found the following root keys: [5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da]
DEBU[0015] found 1 valid leaf certificates for trustimage.test.com:5000/regis_no5: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] found 1 leaf certs, of which 1 are valid leaf certs for trustimage.test.com:5000/regis_no5
DEBU[0015] checking root against trust_pinning config%!(EXTRA string=trustimage.test.com:5000/regis_no5)
DEBU[0015] checking trust-pinning for cert: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] role has key IDs: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] verifying signature for key ID: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] root validation succeeded for trustimage.test.com:5000/regis_no5
DEBU[0015] entered ValidateRoot with dns: trustimage.test.com:5000/regis_no5
DEBU[0015] found the following root keys: [5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da]
DEBU[0015] found 1 valid leaf certificates for trustimage.test.com:5000/regis_no5: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] found 1 leaf certs, of which 1 are valid leaf certs for trustimage.test.com:5000/regis_no5
DEBU[0015] checking root against trust_pinning config%!(EXTRA string=trustimage.test.com:5000/regis_no5)
DEBU[0015] checking trust-pinning for cert: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] role has key IDs: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] verifying signature for key ID: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] root validation succeeded for trustimage.test.com:5000/regis_no5
DEBU[0015] received HTTP status 404 when requesting root.
DEBU[0015] Loading trusted collection.
DEBU[0015] entered ValidateRoot with dns: trustimage.test.com:5000/regis_no5
DEBU[0015] found the following root keys: [5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da]
DEBU[0015] found 1 valid leaf certificates for trustimage.test.com:5000/regis_no5: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] found 1 leaf certs, of which 1 are valid leaf certs for trustimage.test.com:5000/regis_no5
DEBU[0015] checking root against trust_pinning config%!(EXTRA string=trustimage.test.com:5000/regis_no5)
DEBU[0015] checking trust-pinning for cert: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] role has key IDs: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] verifying signature for key ID: 5e64dc63bfa9678304a877719085ca8672bd7b41ab94d37e8c390a9755a610da
DEBU[0015] root validation succeeded for trustimage.test.com:5000/regis_no5
DEBU[0015] targets role has key IDs: f50e718989e4f8a10e37f0973b4887d2c50fa13c1b1ec19f35477d25f0b84405
DEBU[0015] verifying signature for key ID: f50e718989e4f8a10e37f0973b4887d2c50fa13c1b1ec19f35477d25f0b84405
DEBU[0015] changelist add: v2.1
DEBU[0015] No yubikey found, using alternative key storage: no library found
DEBU[0015] applied 1 change(s)
DEBU[0015] sign targets called for role targets
DEBU[0015] sign called with 1/1 required keys
DEBU[0015] No yubikey found, using alternative key storage: no library found
DEBU[0015] sign called with 0/0 required keys
DEBU[0015] generating new snapshot...
DEBU[0015] signing snapshot...
DEBU[0015] sign called with 1/1 required keys
DEBU[0015] No yubikey found, using alternative key storage: no library found
DEBU[0015] Client does not have the key to sign snapshot. Assuming that server should sign the snapshot.
Failed to sign "trustimage.test.com:5000/regis_no5":v2.1 - The root metadata is invalid: could not validate the path to a trusted root: unable to retrieve valid leaf certificates
The root metadata is invalid: could not validate the path to a trusted root: unable to retrieve valid leaf certificates

Kindly look into it. Your earliest help would be appreciated.

[cyli]

Could you please give us the logs from the notary server container for this attempted push? The logs indicate that the server probably rejected the update. We'd have to see those to confirm why it did.

As a note I have also previously seen this when there was a clock skew inside my docker VM such that containers inside thought that it was many hours or even days before the current time. I saw errors such as "transport: x509: certificate has expired or is not yet valid in the server logs when trying to push a signed image. You can check for a time skew by running date -u on machine your local machine and then docker run --rm alpine date -u to see if there's a difference.

[shiva022]

Thank you for prompt response. As suggested, I ran the command & found the vm itself has wrong date & getting error message while running docker run Please find below :

[root@trustimage ~]# date
Sat Mar 4 00:49:36 IST 2017
[root@trustimage ~]# docker run --rm apline date
Unable to find image 'apline:latest' locally
docker: Error response from daemon: Get https://registry-1.docker.io/v2/: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers).

As you require notary server logs while pushing image from docker daemon (running on different vm) Kindly find the same:

017-03-03T19:40:49.658360901Z {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"759edaa9-70bf-44cd-a9b6-48658e6d4114","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:33510","http.request.uri":"/v2/","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.duration":"49.387µs","http.response.status":200,"http.response.written":2,"level":"info","msg":"response completed","time":"2017-03-03T19:40:49Z"}
2017-03-03T19:40:49.675831620Z {"level":"debug","msg":"error retrieving timestamp: No record found","time":"2017-03-03T19:40:49Z"}
2017-03-03T19:40:49.675881334Z {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"15c20961-56c0-48f5-bfc4-2d8d59586688","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:33512","http.request.uri":"/v2/trustimage.test.com:5000/reg_ex1/_trust/tuf/timestamp.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"404 GET timestamp role","time":"2017-03-03T19:40:49Z","trustimage.test.com:5000/reg_ex1":"gun"}
2017-03-03T19:40:49.675921677Z {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"15c20961-56c0-48f5-bfc4-2d8d59586688","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:33512","http.request.uri":"/v2/trustimage.test.com:5000/reg_ex1/_trust/tuf/timestamp.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"metadata not found: You have requested metadata that does not exist.: No record found","time":"2017-03-03T19:40:49Z"}
2017-03-03T19:40:49.675934714Z {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"15c20961-56c0-48f5-bfc4-2d8d59586688","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:33512","http.request.uri":"/v2/trustimage.test.com:5000/reg_ex1/_trust/tuf/timestamp.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.contenttype":"application/json; charset=utf-8","http.response.duration":"786.275µs","http.response.status":404,"http.response.written":116,"level":"info","msg":"response completed","time":"2017-03-03T19:40:49Z"}
2017-03-03T19:40:49.694286378Z {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"0030163f-f83f-4832-95d4-24869233a715","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:33514","http.request.uri":"/v2/trustimage.test.com:5000/reg_ex1/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"404 GET root role","time":"2017-03-03T19:40:49Z","trustimage.test.com:5000/reg_ex1":"gun"}
2017-03-03T19:40:49.694334094Z {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"0030163f-f83f-4832-95d4-24869233a715","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:33514","http.request.uri":"/v2/trustimage.test.com:5000/reg_ex1/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"metadata not found: You have requested metadata that does not exist.: No record found","time":"2017-03-03T19:40:49Z"}
2017-03-03T19:40:49.694348991Z {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"0030163f-f83f-4832-95d4-24869233a715","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:33514","http.request.uri":"/v2/trustimage.test.com:5000/reg_ex1/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.contenttype":"application/json; charset=utf-8","http.response.duration":"1.003295ms","http.response.status":404,"http.response.written":116,"level":"info","msg":"response completed","time":"2017-03-03T19:40:49Z"}

Kindly suggest.

[cyli]

@shiva022 Thank you for the logs - they don't seem to contain any logs from the POST command, which should have been present from the push.

I'm not sure about the timeout error during the docker run command, but also in the command alpine has been mispelled as apline.

Are you running docker 4 mac by any chance? If so, restarting docker 4 mac should fix the clock skew (see docker/for-mac#17 for the issue).

If it is a general VM (such as via virtualbox, vmware, or qemu or something) could you try setting up NTP in that VM? Or if it's already set up and just not fixing itself, maybe restarting the VM would fix it?

[shiva022]

@cyli As NTP was not setup; so I did fresh installation with NTP setup.
Let me brief out the setup:
I m using VirtualBox (5.1.6) on Ubuntu 16.10. On top of virtual box, one RHEL(7.3) is running for docker private registry & notary-server singer. I am using second RHEL(7.3) for docker daemon & notary client.
I use https://github.com/docker/notary to setup notary-server & signer with help of docker-compose while pushing the Image from docker daemon its shows :

[root@dockerhost .docker]# docker push trustimage.test.com:5000/registry:2
The push refers to a repository [trustimage.test.com:5000/registry]
0912b310db10: Layer already exists
6767cac03a2d: Layer already exists
f38182d44088: Layer already exists
b5aac7bb5fdf: Layer already exists
9f8566ee5135: Layer already exists
2: digest: sha256:437df2cf9a6553a91552f716e7b51f696e98aae6e961bf74e113b0363e913480 size: 1364
Signing and pushing trust metadata
You are about to create a new root signing key passphrase. This passphrase
will be used to protect the most sensitive key in your signing system. Please
choose a long, complex passphrase and be careful to keep the password and the
key file itself secure and backed up. It is highly recommended that you use a
password manager to generate the passphrase and keep it safe. There will be no
way to recover this key. You can find the key in your config directory.
Enter passphrase for new root key with ID 8dea5c2:
Repeat passphrase for new root key with ID 8dea5c2:
Enter passphrase for new repository key with ID 924e203 (trustimage.test.com:5000/registry):
Repeat passphrase for new repository key with ID 924e203 (trustimage.test.com:5000/registry):
Finished initializing "trustimage.test.com:5000/registry"

Failed to sign "trustimage.test.com:5000/registry":2 - trust server rejected operation.

Please find the log of notary-server while pushing docker image;-

docker-compose up
notarymaster_mysql_1 is up-to-date
notarymaster_signer_1 is up-to-date
notarymaster_server_1 is up-to-date
Attaching to notarymaster_mysql_1, notarymaster_signer_1, notarymaster_server_1
signer_1 | waiting for mysql://signer@tcp(mysql:3306)/notarysigner to come up.
signer_1 | waiting for mysql://signer@tcp(mysql:3306)/notarysigner to come up.
signer_1 |
signer_1 | 10.0037 seconds
signer_1 | {"level":"info","msg":"Version: 0.5.0, Git commit: ","time":"2017-03-12T13:47:38Z"}
signer_1 | {"level":"debug","msg":"Trusting 2 certs","time":"2017-03-12T13:47:38Z"}
signer_1 | {"level":"debug","msg":"Default Alias: timestamp_1","time":"2017-03-12T13:47:38Z"}
signer_1 | notarysigner database already at latest version
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] mysqld (mysqld 10.1.10-MariaDB-1jessie) starting as process 1 ...
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Using mutexes to ref count buffer pool pages
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: The InnoDB memory heap is disabled
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Memory barrier is not used
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Compressed tables use zlib 1.2.8
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Using Linux native AIO
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Using SSE crc32 instructions
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Initializing buffer pool, size = 256.0M
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Completed initialization of buffer pool
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Highest supported file format is Barracuda.
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: The log sequence numbers 1616829 and 1616829 in ibdata files do not match the log sequence number 1666161 in the ib_logfiles!
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Database was not shutdown normally!
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Starting crash recovery.
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Reading tablespace information from the .ibd files...
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Restoring possible half-written data pages
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: from the doublewrite buffer...
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: 128 rollback segment(s) are active.
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Waiting for purge to start
mysql_1 | 2017-03-12 13:42:41 140142936942528 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.26-76.0 started; log sequence number 1666161
mysql_1 | 2017-03-12 13:42:42 140142936942528 [Note] Plugin 'FEEDBACK' is disabled.
mysql_1 | 2017-03-12 13:42:42 140142936942528 [Note] Recovering after a crash using tc.log
mysql_1 | 2017-03-12 13:42:42 140142936942528 [Note] Starting crash recovery...
mysql_1 | 2017-03-12 13:42:42 140142936942528 [Note] Crash recovery finished.
mysql_1 | 2017-03-12 13:42:42 140142173980416 [Note] InnoDB: Dumping buffer pool(s) not yet started
mysql_1 | 2017-03-12 13:42:42 140142936942528 [Note] Server socket created on IP: '::'.
mysql_1 | 2017-03-12 13:42:42 140142936942528 [Warning] 'proxies_priv' entry '@% root@5f2aa1aa3660' ignored in --skip-name-resolve mode.
mysql_1 | 2017-03-12 13:42:42 140142936942528 [Note] mysqld: ready for connections.
mysql_1 | Version: '10.1.10-MariaDB-1jessie' socket: '/var/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Start
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Completed
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Completed
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Start
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Start reading clustered index of the table and create temporary files
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : End of reading clustered index of the table and create temporary files
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Completed
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Completed
mysql_1 | 2017-03-12 13:47:29 140142936471296 [Note] InnoDB: Online DDL : Completed
server_1 | waiting for mysql://server@tcp(mysql:3306)/notaryserver to come up.
server_1 | waiting for mysql://server@tcp(mysql:3306)/notaryserver to come up.
server_1 | > 0001_initial.up.sql
server_1 | > 0002_role_on_keys.up.sql
server_1 | > 0003_add_sha256_tuf_files.up.sql
server_1 | > 0004_drop_timestamp_key.up.sql
server_1 | > 0005_changefeed.up.sql
server_1 |
server_1 | 10.1971 seconds
server_1 | {"level":"info","msg":"Version: 0.5.0, Git commit: ","time":"2017-03-12T13:47:39Z"}
server_1 | {"level":"debug","msg":"Trusting 1 certs","time":"2017-03-12T13:47:39Z"}
server_1 | {"level":"info","msg":"Using remote signing service","time":"2017-03-12T13:47:39Z"}
server_1 | {"level":"info","msg":"Using mysql backend","time":"2017-03-12T13:47:39Z"}
server_1 | {"level":"info","msg":"Starting Server","time":"2017-03-12T13:47:39Z"}
server_1 | {"level":"info","msg":"Enabling TLS","time":"2017-03-12T13:47:39Z"}
server_1 | {"level":"info","msg":"Starting on :4443","time":"2017-03-12T13:47:39Z"}
server_1 | notaryserver database migrated to latest version
server_1 | 2017/03/12 14:25:59 http: TLS handshake error from 192.168.43.199:47778: tls: oversized record received with length 29709
server_1 | 2017/03/12 14:26:25 http: TLS handshake error from 192.168.43.189:43894: tls: oversized record received with length 29709

server_1 | 2017/03/12 14:30:58 http: TLS handshake error from 192.168.43.189:43896: tls: first record does not look like a TLS handshake
server_1 | 2017/03/12 14:31:29 http: TLS handshake error from 192.168.43.189:43952: EOF
server_1 | 2017/03/12 14:31:29 http: TLS handshake error from 192.168.43.189:43954: EOF
server_1 | 2017/03/12 14:34:41 http: TLS handshake error from 192.168.43.189:43972: EOF
server_1 | 2017/03/12 14:34:41 http: TLS handshake error from 192.168.43.189:43974: EOF
server_1 | 2017/03/12 14:34:46 http: TLS handshake error from 192.168.43.189:43992: EOF
server_1 | 2017/03/12 14:34:46 http: TLS handshake error from 192.168.43.189:43994: EOF
server_1 | 2017/03/12 14:35:09 http: TLS handshake error from 192.168.43.189:44012: EOF
server_1 | 2017/03/12 14:35:09 http: TLS handshake error from 192.168.43.189:44014: EOF
server_1 | 2017/03/12 14:45:10 http: TLS handshake error from 192.168.43.189:44032: EOF
server_1 | 2017/03/12 14:45:10 http: TLS handshake error from 192.168.43.189:44034: EOF
server_1 | 2017/03/12 14:55:36 http: TLS handshake error from 192.168.43.189:44052: EOF
server_1 | 2017/03/12 14:55:36 http: TLS handshake error from 192.168.43.189:44054: EOF
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"5adaf2ef-be5e-4df5-aab6-ddf203d3c1bb","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44072","http.request.uri":"/v2/","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.duration":"189.829µs","http.response.status":200,"http.response.written":2,"level":"info","msg":"response completed","time":"2017-03-12T15:05:40Z"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"64ae332c-c1f2-4113-82e0-8c6032c9d8a7","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44074","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"404 GET root role","time":"2017-03-12T15:05:40Z","trustimage.test.com:5000/registry":"gun"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"64ae332c-c1f2-4113-82e0-8c6032c9d8a7","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44074","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"metadata not found: You have requested metadata that does not exist.: No record found","time":"2017-03-12T15:05:40Z"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"64ae332c-c1f2-4113-82e0-8c6032c9d8a7","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44074","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.contenttype":"application/json; charset=utf-8","http.response.duration":"1.531993ms","http.response.status":404,"http.response.written":116,"level":"info","msg":"response completed","time":"2017-03-12T15:05:40Z"}
signer_1 | {"level":"debug","msg":"generated ECDSA key with keyID: 1dd4aaa92b4852d32f8b4b720576d8a2ad01a00f9fd930497307e52e227e74a3","time":"2017-03-12T15:06:13Z"}
signer_1 | {"go.version":"go1.7.3","level":"info","msg":"CreateKey: Created KeyID 1dd4aaa92b4852d32f8b4b720576d8a2ad01a00f9fd930497307e52e227e74a3","time":"2017-03-12T15:06:13Z"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"cdd69a7a-053e-4db4-9924-a7c5380a9e5b","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44076","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/timestamp.key","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"debug","msg":"200 GET timestamp key","time":"2017-03-12T15:06:13Z","trustimage.test.com:5000/registry":"gun"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"cdd69a7a-053e-4db4-9924-a7c5380a9e5b","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44076","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/timestamp.key","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.duration":"152.955667ms","http.response.status":200,"http.response.written":181,"level":"info","msg":"response completed","time":"2017-03-12T15:06:13Z"}
signer_1 | {"level":"debug","msg":"generated ECDSA key with keyID: c249974b699fa8cbe9e5ebaa6736f5591cf9fadeba5c706c8a093b877d713add","time":"2017-03-12T15:06:13Z"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"8ce131c2-e982-4d3a-a091-a8ca6e8e20ea","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44078","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/snapshot.key","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"debug","msg":"200 GET snapshot key","time":"2017-03-12T15:06:13Z","trustimage.test.com:5000/registry":"gun"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"8ce131c2-e982-4d3a-a091-a8ca6e8e20ea","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44078","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/snapshot.key","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.duration":"35.18993ms","http.response.status":200,"http.response.written":181,"level":"info","msg":"response completed","time":"2017-03-12T15:06:13Z"}
signer_1 | {"go.version":"go1.7.3","level":"info","msg":"CreateKey: Created KeyID c249974b699fa8cbe9e5ebaa6736f5591cf9fadeba5c706c8a093b877d713add","time":"2017-03-12T15:06:13Z"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"1b827e25-985c-4b7f-af29-8ae854b65934","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44080","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"404 GET root role","time":"2017-03-12T15:06:13Z","trustimage.test.com:5000/registry":"gun"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"1b827e25-985c-4b7f-af29-8ae854b65934","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44080","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"metadata not found: You have requested metadata that does not exist.: No record found","time":"2017-03-12T15:06:13Z"}
server_1 | {"go.version":"go1.7.3","http.request.host":"notary-server:4443","http.request.id":"1b827e25-985c-4b7f-af29-8ae854b65934","http.request.method":"GET","http.request.remoteaddr":"192.168.43.189:44080","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/root.json","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.contenttype":"application/json; charset=utf-8","http.response.duration":"1.079733ms","http.response.status":404,"http.response.written":116,"level":"info","msg":"response completed","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"entered ValidateRoot with dns: trustimage.test.com:5000/registry","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"found the following root keys: [4497c7e790cd492637c96ef60258116734bacb2cf929396edfe6dec8b5787b56]","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"found 1 valid leaf certificates for trustimage.test.com:5000/registry: 4497c7e790cd492637c96ef60258116734bacb2cf929396edfe6dec8b5787b56","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"found 1 leaf certs, of which 1 are valid leaf certs for trustimage.test.com:5000/registry","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"checking root against trust_pinning config for trustimage.test.com:5000/registry","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"checking trust-pinning for cert: 4497c7e790cd492637c96ef60258116734bacb2cf929396edfe6dec8b5787b56","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":" role has key IDs: 4497c7e790cd492637c96ef60258116734bacb2cf929396edfe6dec8b5787b56","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"verifying signature for key ID: 4497c7e790cd492637c96ef60258116734bacb2cf929396edfe6dec8b5787b56","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"root validation succeeded for trustimage.test.com:5000/registry","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"Successfully validated root","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"targets role has key IDs: 924e203cb6b3e5ff46112038b4e60d611d60aec24258cf1f7b8b75bcb0ca0346","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"verifying signature for key ID: 924e203cb6b3e5ff46112038b4e60d611d60aec24258cf1f7b8b75bcb0ca0346","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"Successfully validated targets","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"generating new snapshot...","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"signing snapshot...","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"sign called with 1/1 required keys","time":"2017-03-12T15:06:13Z"}
signer_1 | {"go.version":"go1.7.3","level":"debug","msg":"GetKeyInfo: Returning PublicKey for KeyID c249974b699fa8cbe9e5ebaa6736f5591cf9fadeba5c706c8a093b877d713add","time":"2017-03-12T15:06:13Z"}
signer_1 | {"go.version":"go1.7.3","level":"info","msg":"Sign: Signed {"_type":"Snapshot","expires":"2020-03-11T15:06:13.571701073Z","meta":{"root":{"hashes":{"sha256":"/IUByRbnA7Bu6BTldyMNafRJu2vzEOnmCYXVh+3nLZg=","sha512":"e4iL2YmtOT2nWM5quXQWyG6dDKt6xHDEOCDOuBzA5l/ZEWByE7pE4OrGp+cMLcyLm+Ka3Y1uGGz1RI3UREBrsg=="},"length":2433},"targets":{"hashes":{"sha256":"z6hvSmTrSK2pMKq+AXW0s2MT7C8Grf1JkT9ti+piQNI=","sha512":"wa4GZCLsFrzoDqxq6/Oxa5kr7LUU8Fta+oins/YggNyfg5HJxv4anyrcjV07S+nFJGDPzn4EFyAj8gQ/nfy1UQ=="},"length":432}},"version":1} with KeyID c249974b699fa8cbe9e5ebaa6736f5591cf9fadeba5c706c8a093b877d713add","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"sign called with 0/0 required keys","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"SignTimestamp","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"sign called with 1/1 required keys","time":"2017-03-12T15:06:13Z"}
signer_1 | {"go.version":"go1.7.3","level":"debug","msg":"GetKeyInfo: Returning PublicKey for KeyID 1dd4aaa92b4852d32f8b4b720576d8a2ad01a00f9fd930497307e52e227e74a3","time":"2017-03-12T15:06:13Z"}
signer_1 | {"go.version":"go1.7.3","level":"info","msg":"Sign: Signed {"_type":"Timestamp","expires":"2017-03-26T15:06:13.611064974Z","meta":{"snapshot":{"hashes":{"sha256":"mydsINwf3Nf9bVIuL8OLxrNQzc23w2qWljDdA+Q0EnU=","sha512":"AmAD6fPCdOpCTq60xPB89QEXReHiq2+AJGXtVKsMatZQ4LsiFU/HAEjDldw5/qYA1/LFan+eEZ13nJRWBLvgEg=="},"length":683}},"version":1} with KeyID 1dd4aaa92b4852d32f8b4b720576d8a2ad01a00f9fd930497307e52e227e74a3","time":"2017-03-12T15:06:13Z"}
server_1 | {"level":"debug","msg":"sign called with 0/0 required keys","time":"2017-03-12T15:06:13Z"}
server_1 | {"go.version":"go1.7.3","http.request.contenttype":"multipart/form-data; boundary=a751faa0091dbe9d0b9a2f1bfb4d574a58d9c9c53c4a608b6e0203e9c67c","http.request.host":"notary-server:4443","http.request.id":"e203ff85-d196-4152-b986-830b39e2ac78","http.request.method":"POST","http.request.remoteaddr":"192.168.43.189:44082","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"400 POST old version error","time":"2017-03-12T15:08:21Z","trustimage.test.com:5000/registry":"gun"}
server_1 | {"go.version":"go1.7.3","http.request.contenttype":"multipart/form-data; boundary=a751faa0091dbe9d0b9a2f1bfb4d574a58d9c9c53c4a608b6e0203e9c67c","http.request.host":"notary-server:4443","http.request.id":"e203ff85-d196-4152-b986-830b39e2ac78","http.request.method":"POST","http.request.remoteaddr":"192.168.43.189:44082","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"version: A newer version of metadata is already available.: Error updating metadata. A newer version is already available","time":"2017-03-12T15:08:21Z"}
server_1 | {"go.version":"go1.7.3","http.request.contenttype":"multipart/form-data; boundary=a751faa0091dbe9d0b9a2f1bfb4d574a58d9c9c53c4a608b6e0203e9c67c","http.request.host":"notary-server:4443","http.request.id":"e203ff85-d196-4152-b986-830b39e2ac78","http.request.method":"POST","http.request.remoteaddr":"192.168.43.189:44082","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/","http.request.useragent":"Docker-Client/1.13.0 (linux)","http.response.contenttype":"application/json; charset=utf-8","http.response.duration":"2m8.239535398s","http.response.status":400,"http.response.written":106,"level":"info","msg":"response completed","time":"2017-03-12T15:08:21Z"}
server_1 |
server_1 | (dial tcp 69.172.200.109:3306: getsockopt: connection timed out)
server_1 | [2017-03-12 15:08:21]

[shiva022]

@cyli Sorry for incomplete information. As require please find the output of date command

[root@trustimage ~]# date -u
Sun Mar 12 15:57:48 UTC 2017
[root@trustimage ~]# docker run --rm alpine date -u
Sun Mar 12 15:58:01 UTC 2017
[root@trustimage ~]#

[shiva022]

Please find the push images snapshot with --debug mode:

[root@dockerhost .docker]# docker --debug push trustimage.test.com:5000/registry:2
The push refers to a repository [trustimage.test.com:5000/registry]
0a081b45cb84: Layer already exists
df9d2808b9a9: Layer already exists
2: digest: sha256:7cf9007caaadfee83403cb7ecf75da7d483743627238c296ada1ffc15dbc4210 size: 737
Signing and pushing trust metadata
DEBU[0000] reading certificate directory: /root/.docker/tls/notary-server:4443
DEBU[0000] crt: /root/.docker/tls/notary-server:4443/root-ca.crt
DEBU[0000] No yubikey found, using alternative key storage: no library found
DEBU[0000] received HTTP status 404 when requesting root.
DEBU[0000] No yubikey found, using alternative key storage: no library found
DEBU[0000] generated ECDSA key with keyID: b01d94a2c745ee06730ec316ce63984b2eb87e20a0753baa87b5e10be5496dfe
DEBU[0000] generated new ecdsa key for role: root and keyID: b01d94a2c745ee06730ec316ce63984b2eb87e20a0753baa87b5e10be5496dfe
DEBU[0000] No yubikey found, using alternative key storage: no library found
You are about to create a new root signing key passphrase. This passphrase
will be used to protect the most sensitive key in your signing system. Please
choose a long, complex passphrase and be careful to keep the password and the
key file itself secure and backed up. It is highly recommended that you use a
password manager to generate the passphrase and keep it safe. There will be no
way to recover this key. You can find the key in your config directory.
Enter passphrase for new root key with ID b01d94a:
Repeat passphrase for new root key with ID b01d94a:
DEBU[0007] No yubikey found, using alternative key storage: no library found
DEBU[0007] generated ECDSA key with keyID: fc25fea5ad940d7d08c4430861f8b4b078799dec56a4aeb4ba6379bc9c94c89f
DEBU[0007] generated new ecdsa key for role: targets and keyID: fc25fea5ad940d7d08c4430861f8b4b078799dec56a4aeb4ba6379bc9c94c89f
Enter passphrase for new repository key with ID fc25fea (trustimage.test.com:5000/registry):
Repeat passphrase for new repository key with ID fc25fea (trustimage.test.com:5000/registry):
DEBU[0021] got remote timestamp ecdsa key with keyID: 209fad2e6a4d920404965cd4b9d7c4a995e665bb7d0d70e713036206043091ca
DEBU[0021] got remote snapshot ecdsa key with keyID: 4a09f619e7873c8e671bc80de065e1dfe981f1c62baae0f355317779247592e4
DEBU[0021] generating new snapshot...
DEBU[0021] Saving changes to Trusted Collection.
DEBU[0021] signing root...
DEBU[0021] sign called with 1/1 required keys
DEBU[0021] No yubikey found, using alternative key storage: no library found
DEBU[0021] sign called with 0/0 required keys
DEBU[0021] sign targets called for role targets
DEBU[0021] sign called with 1/1 required keys
DEBU[0021] No yubikey found, using alternative key storage: no library found
DEBU[0021] sign called with 0/0 required keys
Finished initializing "trustimage.test.com:5000/registry"
DEBU[0021] Making dir path: /root/.docker/trust/tuf/trustimage.test.com:5000/registry/changelist
DEBU[0021] Adding target "2" with sha256 "7cf9007caaadfee83403cb7ecf75da7d483743627238c296ada1ffc15dbc4210" and size 737 bytes.

DEBU[0021] Making dir path: /root/.docker/trust/tuf/trustimage.test.com:5000/registry/changelist
DEBU[0021] entered ValidateRoot with dns: trustimage.test.com:5000/registry
DEBU[0021] found the following root keys: [d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac]
DEBU[0021] found 1 valid leaf certificates for trustimage.test.com:5000/registry: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] found 1 leaf certs, of which 1 are valid leaf certs for trustimage.test.com:5000/registry
DEBU[0021] checking root against trust_pinning config%!(EXTRA string=trustimage.test.com:5000/registry)
DEBU[0021] checking trust-pinning for cert: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] role has key IDs: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] verifying signature for key ID: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] root validation succeeded for trustimage.test.com:5000/registry
DEBU[0021] entered ValidateRoot with dns: trustimage.test.com:5000/registry
DEBU[0021] found the following root keys: [d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac]
DEBU[0021] found 1 valid leaf certificates for trustimage.test.com:5000/registry: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] found 1 leaf certs, of which 1 are valid leaf certs for trustimage.test.com:5000/registry
DEBU[0021] checking root against trust_pinning config%!(EXTRA string=trustimage.test.com:5000/registry)
DEBU[0021] checking trust-pinning for cert: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] role has key IDs: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] verifying signature for key ID: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] root validation succeeded for trustimage.test.com:5000/registry
DEBU[0021] received HTTP status 404 when requesting root.
DEBU[0021] Loading trusted collection.
DEBU[0021] entered ValidateRoot with dns: trustimage.test.com:5000/registry
DEBU[0021] found the following root keys: [d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac]
DEBU[0021] found 1 valid leaf certificates for trustimage.test.com:5000/registry: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] found 1 leaf certs, of which 1 are valid leaf certs for trustimage.test.com:5000/registry
DEBU[0021] checking root against trust_pinning config%!(EXTRA string=trustimage.test.com:5000/registry)
DEBU[0021] checking trust-pinning for cert: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] role has key IDs: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] verifying signature for key ID: d9e5db56604d928a2fe719bd54bd48e0854a9a977705209b27c1c921afef51ac
DEBU[0021] root validation succeeded for trustimage.test.com:5000/registry
DEBU[0021] targets role has key IDs: fc25fea5ad940d7d08c4430861f8b4b078799dec56a4aeb4ba6379bc9c94c89f
DEBU[0021] verifying signature for key ID: fc25fea5ad940d7d08c4430861f8b4b078799dec56a4aeb4ba6379bc9c94c89f
DEBU[0021] changelist add: 2
DEBU[0021] No yubikey found, using alternative key storage: no library found
DEBU[0021] applied 1 change(s)
DEBU[0021] sign targets called for role targets
DEBU[0021] sign called with 1/1 required keys
DEBU[0021] No yubikey found, using alternative key storage: no library found
DEBU[0021] sign called with 0/0 required keys
DEBU[0021] generating new snapshot...
DEBU[0021] signing snapshot...
DEBU[0021] sign called with 1/1 required keys
DEBU[0021] No yubikey found, using alternative key storage: no library found
DEBU[0021] Client does not have the key to sign snapshot. Assuming that server should sign the snapshot.
Failed to sign "trustimage.test.com:5000/registry":2 - trust server rejected operation.
trust server rejected operation.

Need your guidance to get it solve asap.

[riyazdf]

@shiva022: I see this error in your notary server logs, it seems that there's a newer version already published on the server.

server_1 | {"go.version":"go1.7.3","http.request.contenttype":"multipart/form-data; boundary=a751faa0091dbe9d0b9a2f1bfb4d574a58d9c9c53c4a608b6e0203e9c67c","http.request.host":"notary-server:4443","http.request.id":"e203ff85-d196-4152-b986-830b39e2ac78","http.request.method":"POST","http.request.remoteaddr":"192.168.43.189:44082","http.request.uri":"/v2/trustimage.test.com:5000/registry/_trust/tuf/","http.request.useragent":"Docker-Client/1.13.0 (linux)","level":"info","msg":"version: A newer version of metadata is already available.: Error updating metadata. A newer version is already available","time":"2017-03-12T15:08:21Z"}

Have you manually edited the database by chance?
It might also be worth trying to run a local metadata deletion in case there's bad state locally (notary -d /root/.docker/trust delete trustimage.test.com:5000/registry)

[shiva022]

@riyazdf By mistake my Virtual machine got shutdown & since running container got exited. I ran the below command to run the container again:
docker-compose down
docker-compose up & then It got stuck now none of any container is running. Please have a look on below & let me know what to do:

[root@trustimage notary-master]# docker-compose down
Removing notarymaster_server_1 ... done
Removing notarymaster_signer_1 ... done
Removing notarymaster_mysql_1 ... done
Removing network notarymaster_mdb
Removing network notarymaster_sig
[root@trustimage notary-master]# docker-compose up
Creating network "notarymaster_mdb" with the default driver
Creating network "notarymaster_sig" with the default driver
Creating notarymaster_mysql_1
Creating notarymaster_signer_1
Creating notarymaster_server_1
Attaching to notarymaster_mysql_1, notarymaster_signer_1, notarymaster_server_1
mysql_1 | 2017-03-13 11:00:49 140381583341504 [Note] mysqld (mysqld 10.1.10-MariaDB-1jessie) starting as process 1 ...
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Using mutexes to ref count buffer pool pages
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: The InnoDB memory heap is disabled
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Memory barrier is not used
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Compressed tables use zlib 1.2.8
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Using Linux native AIO
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Using SSE crc32 instructions
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Initializing buffer pool, size = 256.0M
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Completed initialization of buffer pool
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Highest supported file format is Barracuda.
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: The log sequence numbers 1616829 and 1616829 in ibdata files do not match the log sequence number 1852196 in the ib_logfiles!
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Database was not shutdown normally!
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Starting crash recovery.
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Reading tablespace information from the .ibd files...
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Restoring possible half-written data pages
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: from the doublewrite buffer...
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: 128 rollback segment(s) are active.
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Waiting for purge to start
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.26-76.0 started; log sequence number 1852196
mysql_1 | 2017-03-13 11:00:50 140380817295104 [Note] InnoDB: Dumping buffer pool(s) not yet started
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] Plugin 'FEEDBACK' is disabled.
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] Recovering after a crash using tc.log
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] Starting crash recovery...
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] Crash recovery finished.
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] Server socket created on IP: '::'.
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Warning] 'proxies_priv' entry '@% root@5f2aa1aa3660' ignored in --skip-name-resolve mode.
mysql_1 | 2017-03-13 11:00:50 140381583341504 [Note] mysqld: ready for connections.
mysql_1 | Version: '10.1.10-MariaDB-1jessie' socket: '/var/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution

signer_1 | waiting for mysql://signer@tcp(mysql:3306)/notarysigner to come up.
server_1 | waiting for mysql://server@tcp(mysql:3306)/notaryserver to come up.
signer_1 | waiting for mysql://signer@tcp(mysql:3306)/notarysigner to come up.
server_1 | waiting for mysql://server@tcp(mysql:3306)/notaryserver to come up.

[riyazdf]

@shiva022: looks like your notary services were waiting for the database to come up (after crash recovery), did it eventually connect? If not, can you try restarting the services?

[shiva022]

@riyazdf I restarted the service by the below command :
docker-compose restart. still no changes. Even I tried it by removing the running containers and building it again however it doesn't help. Lastly I tried by restarting the virtual machine but am jammed on the same place. Kindly help!

[cyli]

@shiva022 Would it be ok to delete all your existing data and try again? If so, could you try docker-compose down -v and then docker-compose up again?

[shiva022]

@cyli The Issue is resolved. Since I neither configure DNS nor made host entry in host file hence, while pushing the image it was resolving the host by searching host trustimage.test.com globally. which causing the failure.

[cyli]

Ah ok, thanks for letting us know!