Skip to content

External CA is not being accepted by new swarm node #33216

New issue
New issue
Closed
#33341
Closed
External CA is not being accepted by new swarm node#33216
#33341
Labels
kind/bugBugs are bugs. The cause may or may not be known at triage time so debugging may be needed.platform/armpriority/P2Normal priority: default priority applied.version/17.05
Milestone
17.06.0
@splytech

Description

@splytech
splytech
opened on May 16, 2017

Description

Following the little documentation for setting a swarmkit cluster based on the following URL:

https://docs.docker.com/engine/reference/commandline/swarm_init/

While I am using RPi's to do this, I am doing nothing more than setting up a basic swarm cluster using an external CA with the cfssl service.

I am using a local compiled version of cfssl:

cfssl version:
Version: 1.2.0
Revision: dev
Runtime: go1.8.1

I could be doing something wrong but I am not sure what I am missing. It appears to be a bug and there isn't much on setting up an external CA with swarmkit.

Steps to reproduce the issue:

  1. Setup a CA cert with cfssl, on the manager node:

ca-csr.json:

{
    "CN": "piworkernet",
    "hosts": [
        "piworkernet.net",
        "www.piworkernet.net"
    ],
    "key": {
        "algo": "rsa",
        "size": 2048
    },
    "names": [
        {
            "C": "US",
            "ST": "CA",
            "L": "London",
        "O": "piworkernet",
        "OU": "pidocker"
        }
    ]
}

To create the ca itself:

cfssl gencert -initca ca-csr.json | cfssljson -bare ca -
  1. Setup the cert on both the manager and the worker node:
    Copy and update the ca certificates globally:
sudo cp ~/ca.pem /usr/local/share/ca-certificates/piworkernet.crt
cd /usr/local/share/ca-certificates/
sudo mkdir piworkernet && cd piworkernet
sudo cp ~/ca.pem ./ca.crt
sudo update-ca-certificates

Yes, I copied it twice because I am not sure which one dockerd will pick up.

  1. Start cfssl server on manager:
    NOTE: Local IP for the manager: 10.0.20.130
    Command:
cfssl serve -ca ca.pem -ca-key ca-key.pem -config ca-config.json -address=10.0.20.130

Output:

2017/05/16 01:33:53 [INFO] Initializing signer
2017/05/16 01:33:53 [WARNING] couldn't initialize ocsp signer: open : no such file or directory
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/gencrl' is enabled
2017/05/16 01:33:53 [INFO] bundler API ready
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/bundle' is enabled
2017/05/16 01:33:53 [WARNING] endpoint 'ocspsign' is disabled: signer not initialized
2017/05/16 01:33:53 [INFO] endpoint '/' is enabled
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/info' is enabled
2017/05/16 01:33:53 [WARNING] endpoint 'crl' is disabled: cert db not configured (missing -db-config)
2017/05/16 01:33:53 [WARNING] endpoint 'revoke' is disabled: cert db not configured (missing -db-config)
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/sign' is enabled
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/scan' is enabled
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/newcert' is enabled
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/certinfo' is enabled
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/init_ca' is enabled
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/scaninfo' is enabled
2017/05/16 01:33:53 [WARNING] endpoint 'authsign' is disabled: {"code":5200,"message":"Invalid or unknown policy"}
2017/05/16 01:33:53 [INFO] setting up key / CSR generator
2017/05/16 01:33:53 [INFO] endpoint '/api/v1/cfssl/newkey' is enabled
2017/05/16 01:33:53 [INFO] Handler set up complete.
2017/05/16 01:33:53 [INFO] Now listening on 10.0.20.130:8888
  1. Init Swarm Cluster on manager node:
docker swarm init --advertise-addr 10.0.20.130 --external-ca protocol=cfssl,url=http://10.0.20.130:8888/api/v1/cfssl/sign

Log output during init, w/ debug mode on:

May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.328995224Z" level=debug msg="Calling GET /_ping"
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.593284786Z" level=debug msg="Calling GET /_ping"
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.597594217Z" level=debug msg="Calling POST /v1.29/swarm/init"
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.599448415Z" level=debug msg="form data: {\"AdvertiseAddr\":\"10.0.20.130\",\"AutoLockManagers\":false,\"Availability\":\"\",\"ForceNewCluster\":false,\"ListenAddr\":\"0.0.0.0:2377\",\"Spec\":{\"CAConfig\":{\"ExternalCAs\":[{\"Protocol\":\"cfssl\",\"URL\":\"http://10.0.20.130:8888/api/v1/cfssl/sign\"}]},\"Dispatcher\":{},\"EncryptionConfig\":{\"AutoLockManagers\":false},\"Labels\":null,\"Orchestration\":{},\"Raft\":{\"ElectionTick\":0,\"HeartbeatTick\":0},\"TaskDefaults\":{}}}"
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.755405921Z" level=debug msg="generated CA key and certificate" module=node
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.755650762Z" level=debug msg="no node credentials found in: /var/lib/docker/swarm/certificates/swarm-node.crt" error="open /var/lib/docker/swarm/certificates/swarm-node.key: no such file or directory" module=node
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.837578689Z" level=debug msg="issued new TLS certificate" module="node/tls" node.id=t5pusiwwxwrpy16wddkg1d7a3 node.role=swarm-manager
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.839163254Z" level=debug msg="new node credentials generated: /var/lib/docker/swarm/certificates/swarm-node.crt" module="node/tls" node.id=t5pusiwwxwrpy16wddkg1d7a3 node.role=swarm-manager
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.857974396Z" level=debug msg="next certificate renewal scheduled for 1631h54m42.142117478s from now" module="node/tls" node.id=t5pusiwwxwrpy16wddkg1d7a3 node.role=swarm-manager time=2017-07-23 01:30:00.000002708 +0000 UTC
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.889961534Z" level=info msg="Listening for connections" addr="[::]:2377" module=node node.id=t5pusiwwxwrpy16wddkg1d7a3 proto=tcp
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.890043147Z" level=info msg="Listening for local connections" addr="/var/run/docker/swarm/control.sock" module=node node.id=t5pusiwwxwrpy16wddkg1d7a3 proto=unix
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.905902864Z" level=info msg="7340972b77480346 became follower at term 0" module=raft node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.906074216Z" level=info msg="newRaft 7340972b77480346 [peers: [], term: 0, commit: 0, applied: 0, lastindex: 0, lastterm: 0]" module=raft node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.906171194Z" level=info msg="7340972b77480346 became follower at term 1" module=raft node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.912924764Z" level=info msg="7340972b77480346 is starting a new election at term 1" module=raft node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.913175646Z" level=info msg="7340972b77480346 became candidate at term 2" module=raft node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.913323769Z" level=info msg="7340972b77480346 received MsgVoteResp from 7340972b77480346 at term 2" module=raft node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.913440695Z" level=info msg="7340972b77480346 became leader at term 2" module=raft node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.913517049Z" level=info msg="raft.node: 7340972b77480346 elected leader 7340972b77480346 at term 2" module=raft node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.916513525Z" level=info msg="Creating default ingress network" module=node node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.921649404Z" level=debug msg="RequestPool(GlobalDefault, 10.255.0.0/16, , map[], false)"
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.921907474Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, <nil>, map[RequestAddressType:com.docker.network.gateway])"
May 16 01:35:17 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:17.931283462Z" level=debug msg="Updating security config due to change in cluster Root CA" cluster.id=yxar145djq2bswnhyv71cpokb method="(*Server).UpdateRootCA" module=ca node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.008212852Z" level=debug msg="(*Agent).run" module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.044459577Z" level=debug msg="(*session).start" module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.048695311Z" level=debug msg="Root CA updated successfully" cluster.id=yxar145djq2bswnhyv71cpokb method="(*Server).UpdateRootCA" module=ca node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.048897288Z" level=debug msg="Updating security config due to change in cluster Root CA or cluster spec" cluster.id=yxar145djq2bswnhyv71cpokb method="(*Server).UpdateRootCA" module=ca node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.052690422Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, <nil>, map[])"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.054578005Z" level=debug msg="node status updated" method="(*Dispatcher).processUpdates" module=dispatcher node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.073626747Z" level=debug method="(*session).logSubscriptions" module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3 session.id=ncb3w5ocs8enxwab8ckrrn1wf
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.075372874Z" level=debug method="(*session).watch" module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3 session.id=ncb3w5ocs8enxwab8ckrrn1wf
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.075617246Z" level=debug msg="(*session).heartbeat" module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3 session.id=ncb3w5ocs8enxwab8ckrrn1wf
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.075372926Z" level=debug msg="(*session).listen" module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3 session.id=ncb3w5ocs8enxwab8ckrrn1wf
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.077254519Z" level=debug msg="node registered" method="(*LogBroker).ListenSubscriptions" node=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.078274507Z" level=debug method="(*Dispatcher).Assignments" node.id=t5pusiwwxwrpy16wddkg1d7a3 node.session=ncb3w5ocs8enxwab8ckrrn1wf
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.082916278Z" level=info msg="Initializing Libnetwork Agent Listen-Addr=0.0.0.0 Local-addr=10.0.20.130 Adv-addr=10.0.20.130 Remote-addr ="
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.083101172Z" level=debug msg="(*worker).Assign" len(assignments)=0 module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.083331429Z" level=debug msg="(*worker).reconcileSecrets" len(removedSecrets)=0 len(updatedSecrets)=0 module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.083433095Z" level=debug msg="(*worker).reconcileTaskState" len(removedTasks)=0 len(updatedTasks)=0 module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.087128522Z" level=debug msg="agent: registered" module="node/agent" node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.087562423Z" level=info msg="Initializing Libnetwork Agent Listen-Addr=0.0.0.0 Local-addr=10.0.20.130 Adv-addr=10.0.20.130 Remote-addr ="
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.087976637Z" level=info msg="Gossip cluster hostname pi3coreserver-477a29027df3"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.088236426Z" level=debug msg="Encryption key 1: f153a"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.088301321Z" level=debug msg="Encryption key 2: 8f4f1"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.088353143Z" level=debug msg="Encryption key 3: 31cb9"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.091135768Z" level=debug msg="Initial encryption keys: [(key: 44332, tag: 0xce33) (key: 55585, tag: 0xce32) (key: a8ba1, tag: 0xce34)]"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.093016528Z" level=debug msg="Initial encryption keys: [(key: 44332, tag: 0xce33) (key: 55585, tag: 0xce32) (key: a8ba1, tag: 0xce34)]"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.094449845Z" level=debug msg="Allocating IPv4 pools for network ingress (da6bdp3kszj1podctsott7wiw)"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.094595573Z" level=debug msg="RequestPool(LocalDefault, 10.255.0.0/16, , map[], false)"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.094941402Z" level=debug msg="RequestAddress(LocalDefault/10.255.0.0/16, 10.255.0.1, map[RequestAddressType:com.docker.network.gateway])"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.095132702Z" level=debug msg="overlay: Received vxlan IDs: 4096"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.095265409Z" level=debug msg="/sbin/iptables, [--wait -t mangle -C OUTPUT -p udp --dport 4789 -m u32 --u32 0>>22&0x3C@12&0xFFFFFF00=1048576 -j MARK --set-mark 13681891]"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.111976626Z" level=debug msg="Updating security config due to change in cluster Root CA or cluster spec" cluster.id=yxar145djq2bswnhyv71cpokb method="(*Server).UpdateRootCA" module=node node.id=t5pusiwwxwrpy16wddkg1d7a3
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.118576760Z" level=debug msg="Calling GET /v1.29/nodes/t5pusiwwxwrpy16wddkg1d7a3"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.127713375Z" level=debug msg="/sbin/iptables, [--wait -t filter -C INPUT -m policy --dir in --pol ipsec -p udp --dport 4789 -m u32 --u32 0>>22&0x3C@12&0xFFFFFF00=1048576 -j ACCEPT]"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.130717820Z" level=debug msg="Calling GET /v1.29/swarm"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.139022778Z" level=debug msg="/sbin/iptables, [--wait -t filter -C INPUT -p udp --dport 4789 -m u32 --u32 0>>22&0x3C@12&0xFFFFFF00=1048576 -j DROP]"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.150966185Z" level=debug msg="pi3coreserver-477a29027df3: joined network da6bdp3kszj1podctsott7wiw"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.151092277Z" level=debug msg="pi3coreserver-477a29027df3: Initiating bulk sync with nodes [pi3coreserver-477a29027df3]"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.151707270Z" level=debug msg="/sbin/iptables, [--wait -t filter -L DOCKER-INGRESS]"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.357188070Z" level=debug msg="Assigning addresses for endpoint ingress-endpoint's interface on network ingress"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.357351662Z" level=debug msg="RequestAddress(LocalDefault/10.255.0.0/16, 10.255.0.2, map[])"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.363363001Z" level=debug msg="Assigning addresses for endpoint ingress-endpoint's interface on network ingress"
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.370504118Z" level=error msg="Failed to create testvxlan interface: error creating vxlan interface: operation not supported"
May 16 01:35:18 pi3coreserver kernel: [315751.833142] br0: renamed from ov-001000-da6bd
May 16 01:35:18 pi3coreserver dockerd[6236]: time="2017-05-16T01:35:18.590359599Z" level=error msg="Failed joining ingress sandbox to ingress endpoint: subnet sandbox join failed for \"10.255.0.0/16\": error creating vxlan interface: operation not supported"
  1. Join the worker node:

Command on worker:

docker swarm join \
>     --token SWMTKN-1-3m1d6ra0gpj4gs5dyo1o5pd3t521m5a9t102zk18ojev2deqcd-8gltbkjrl8y98e0mrq33nljbz \
>     10.0.20.130:2377

Log during worker failure:

May 16 01:26:36 pizdocker1 systemd[1]: Started Docker Application Container Engine.
May 16 01:26:36 pizdocker1 dockerd[8522]: time="2017-05-16T01:26:36.554780842Z" level=info msg="API listen on /var/run/docker.sock"
May 16 01:26:36 pizdocker1 dockerd[8522]: time="2017-05-16T01:26:36.555594842Z" level=info msg="API listen on 10.0.11.2:2376"
May 16 01:26:43 pizdocker1 dockerd[8522]: time="2017-05-16T01:26:43.066865555Z" level=debug msg="Calling GET /_ping"
May 16 01:26:43 pizdocker1 dockerd[8522]: time="2017-05-16T01:26:43.099027539Z" level=debug msg="Calling GET /v1.29/info"
May 16 01:40:34 pizdocker1 dockerd[8522]: time="2017-05-16T01:40:34.302342476Z" level=debug msg="Calling GET /_ping"
May 16 01:40:34 pizdocker1 rsyslogd-2007: action 'action 17' suspended, next retry is Tue May 16 01:42:04 2017 [try http://www.rsyslog.com/e/2007 ]
May 16 01:40:34 pizdocker1 dockerd[8522]: time="2017-05-16T01:40:34.315925469Z" level=debug msg="Calling GET /v1.29/info"
May 16 01:40:59 pizdocker1 dockerd[8522]: time="2017-05-16T01:40:59.448975611Z" level=debug msg="Calling GET /_ping"
May 16 01:41:00 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:00.060481322Z" level=debug msg="Calling GET /_ping"
May 16 01:41:00 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:00.079034313Z" level=debug msg="Calling POST /v1.29/swarm/join"
May 16 01:41:00 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:00.083550311Z" level=debug msg="form data: {\"AdvertiseAddr\":\"\",\"Availability\":\"\",\"JoinToken\":\"*****\",\"ListenAddr\":\"0.0.0.0:2377\",\"RemoteAddrs\":[\"10.0.20.130:2377\"]}"
May 16 01:41:00 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:00.458580134Z" level=debug msg="retrieved remote CA certificate: /var/lib/docker/swarm/certificates/swarm-root-ca.crt" module=node
May 16 01:41:00 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:00.462288132Z" level=debug msg="downloaded CA certificate" module=node
May 16 01:41:00 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:00.462953132Z" level=debug msg="no node credentials found in: /var/lib/docker/swarm/certificates/swarm-node.crt" error="open /var/lib/docker/swarm/certificates/swarm-node.key: no such file or directory" module=node
May 16 01:41:01 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:01.038571860Z" level=error msg="failed to request save new certificate" error="x509: certificate signed by unknown authority" module="node/tls"
May 16 01:41:01 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:01.042770858Z" level=error msg="cluster exited with error: x509: certificate signed by unknown authority"
May 16 01:41:01 pizdocker1 dockerd[8522]: time="2017-05-16T01:41:01.048404855Z" level=error msg="Handler for POST /v1.29/swarm/join returned error: x509: certificate signed by unknown authority"

Log from the manager for the same event:

May 16 01:39:30 pi3coreserver dockerd[6236]: time="2017-05-16T01:39:30.551167183Z" level=debug msg="Calling GET /_ping"
May 16 01:39:30 pi3coreserver dockerd[6236]: time="2017-05-16T01:39:30.553821841Z" level=debug msg="Calling GET /v1.29/swarm"
May 16 01:39:30 pi3coreserver dockerd[6236]: time="2017-05-16T01:39:30.560401350Z" level=debug msg="Calling GET /v1.29/info"
May 16 01:39:30 pi3coreserver dockerd[6236]: time="2017-05-16T01:39:30.606321460Z" level=debug msg="Calling GET /v1.29/nodes/t5pusiwwxwrpy16wddkg1d7a3"
May 16 01:39:30 pi3coreserver dockerd[6236]: time="2017-05-16T01:39:30.613553098Z" level=debug msg="Calling GET /v1.29/swarm"
May 16 01:39:56 pi3coreserver dockerd[6236]: time="2017-05-16T01:39:56.004692216Z" level=debug msg="Calling GET /_ping"
May 16 01:39:56 pi3coreserver dockerd[6236]: time="2017-05-16T01:39:56.007612131Z" level=debug msg="Calling GET /v1.29/info"
May 16 01:41:00 pi3coreserver dockerd[6236]: time="2017-05-16T01:41:00.888428027Z" level=debug msg="RequestAddress(GlobalDefault/10.255.0.0/16, <nil>, map[])"
May 16 01:41:00 pi3coreserver rsyslogd-2007: action 'action 17' suspended, next retry is Tue May 16 01:42:30 2017 [try http://www.rsyslog.com/e/2007 ]
May 16 01:41:00 pi3coreserver dockerd[6236]: time="2017-05-16T01:41:00.888368809Z" level=debug msg="new certificate entry added" method=IssueNodeCertificate node.id=lupxyz3540mozq64ehvze47k3 node.role=WORKER
May 16 01:41:00 pi3coreserver dockerd[6236]: time="2017-05-16T01:41:00.902339277Z" level=debug msg="started watching for certificate updates" method=NodeCertificateStatus node.id=lupxyz3540mozq64ehvze47k3 status={PENDING }
May 16 01:41:01 pi3coreserver dockerd[6236]: time="2017-05-16T01:41:01.025868101Z" level=debug msg="certificate issued" method="(*Server).signNodeCert" module=ca node.id=lupxyz3540mozq64ehvze47k3 node.role=WORKER
May 16 01:41:01 pi3coreserver dockerd[6236]: time="2017-05-16T01:41:01.127878207Z" level=debug msg="certificate issued" method="(*Server).signNodeCert" module=ca node.id=lupxyz3540mozq64ehvze47k3 node.role=WORKER

Log output from the cfssl server:

2017/05/16 01:41:00 [INFO] signature request received
2017/05/16 01:41:01 [INFO] signed certificate with serial number 319411067249206302477646405448783018625588284486
2017/05/16 01:41:01 [INFO] wrote response
2017/05/16 01:41:01 [INFO] 10.0.20.130:57464 - "POST /api/v1/cfssl/sign" 200
2017/05/16 01:41:01 [INFO] signature request received
2017/05/16 01:41:01 [INFO] signed certificate with serial number 536477945527195995995792321903226089752622670549
2017/05/16 01:41:01 [INFO] wrote response
2017/05/16 01:41:01 [INFO] 10.0.20.130:57464 - "POST /api/v1/cfssl/sign" 200

Describe the results you received:

The result was a simple and cryptic error from the worker:

Error response from daemon: x509: certificate signed by unknown authority

Describe the results you expected:

A clean connection from the swarm worker to the manager with the external CA.

Additional information you deem important (e.g. issue happens only occasionally):

This is extremely repeatable. I put the cert all over the place on the system as well as added certs to the daemon config like so:

{
        "hosts": ["tcp://10.0.20.130:2376", "unix:///var/run/docker.sock"],
        "dns": ["8.8.8.8", "8.8.4.4"],
        "tlsverify": true,
        "tlscacert": "/opt/certs/ca.pem",
        "tlscert": "/opt/certs/pi3coreserver.pem",
        "tlskey": "/opt/certs/pi3coreserver-key.pem",
        "debug": true
}

I put the cert in the following locations:

/usr/local/share/ca-certificates/ca.crt
/usr/local/share/ca-certificates/ca-local.crt
/usr/local/share/ca-certificates/piworkernet.crt
/usr/local/share/ca-certificates/piworkernet/ca.crt
/etc/docker/certs.d/piworkernet/ca.crt

Output of docker version:
For manager node:

Client:
 Version:      17.05.0-ce
 API version:  1.29
 Go version:   go1.7.5
 Git commit:   89658be
 Built:        Thu May  4 22:30:54 2017
 OS/Arch:      linux/arm

Server:
 Version:      17.05.0-ce
 API version:  1.29 (minimum version 1.12)
 Go version:   go1.7.5
 Git commit:   89658be
 Built:        Thu May  4 22:30:54 2017
 OS/Arch:      linux/arm
 Experimental: false

For client node:

Client:
 Version:      17.05.0-ce
 API version:  1.29
 Go version:   go1.7.5
 Git commit:   89658be
 Built:        Thu May  4 22:30:54 2017
 OS/Arch:      linux/arm

Server:
 Version:      17.05.0-ce
 API version:  1.29 (minimum version 1.12)
 Go version:   go1.7.5
 Git commit:   89658be
 Built:        Thu May  4 22:30:54 2017
 OS/Arch:      linux/arm
 Experimental: false

Output of docker info:

For manager node after worker node connection attempt:

Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 3
Server Version: 17.05.0-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins: 
 Volume: local
 Network: bridge host macvlan null overlay
Swarm: active
 NodeID: t5pusiwwxwrpy16wddkg1d7a3
 Is Manager: true
 ClusterID: yxar145djq2bswnhyv71cpokb
 Managers: 1
 Nodes: 2
 Orchestration:
  Task History Retention Limit: 5
 Raft:
  Snapshot Interval: 10000
  Number of Old Snapshots to Retain: 0
  Heartbeat Tick: 1
  Election Tick: 3
 Dispatcher:
  Heartbeat Period: 5 seconds
 CA Configuration:
  Expiry Duration: 3 months
  External CAs:
    cfssl: http://10.0.20.130:8888/api/v1/cfssl/sign
 Node Address: 10.0.20.130
 Manager Addresses:
  10.0.20.130:2377
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 9048e5e50717ea4497b757314bad98ea3763c145
runc version: 9c2d8d184e5da67c95d601382adf14862e4f2228
init version: 949e6fa
Kernel Version: 4.4.50-v7+
Operating System: Raspbian GNU/Linux 8 (jessie)
OSType: linux
Architecture: armv7l
CPUs: 4
Total Memory: 925.5MiB
Name: pi3coreserver
ID: 3ZNS:66AM:54YT:D5BN:Z7GU:SPL4:ANPK:AA4B:5HCJ:2LCH:F7TN:YRTC
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 30
 Goroutines: 124
 System Time: 2017-05-16T01:49:59.739391665Z
 EventsListeners: 0
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

WARNING: No swap limit support
WARNING: No kernel memory limit support
WARNING: No cpu cfs quota support
WARNING: No cpu cfs period support
WARNING: No cpuset support

For worker node after connection attempt:

Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 2
Server Version: 17.05.0-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: 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: 9048e5e50717ea4497b757314bad98ea3763c145
runc version: 9c2d8d184e5da67c95d601382adf14862e4f2228
init version: 949e6fa
Kernel Version: 4.9.24+
Operating System: Raspbian GNU/Linux 8 (jessie)
OSType: linux
Architecture: armv6l
CPUs: 1
Total Memory: 481.7MiB
Name: pizdocker1
ID: OBJL:BQ4U:YEDI:I4T2:VEIL:G5DA:3GJD:MUEX:T7AM:3JMQ:GOHT:IIXN
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 17
 Goroutines: 23
 System Time: 2017-05-16T01:53:55.055424678Z
 EventsListeners: 0
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

WARNING: No swap limit support
WARNING: No cpu cfs quota support
WARNING: No cpu cfs period support
WARNING: No cpuset support

Additional environment details (AWS, VirtualBox, physical, etc.):
There are 2 RPI's in use but it appears to matter little to allow this to work.

Metadata

Metadata

Assignees

No one assigned

    Labels

    kind/bugBugs are bugs. The cause may or may not be known at triage time so debugging may be needed.platform/armpriority/P2Normal priority: default priority applied.version/17.05

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions