search

rancher / os

Tiny Linux distro that runs the entire OS as Docker containers
https://rancher.com/docs/os/v1.x/en/
Apache License 2.0
6.44k stars 655 forks source link

User generated certificate is not working #2643

Open pan1nx opened 5 years ago

pan1nx commented 5 years ago

RancherOS Version: v1.5.0

Where are you running RancherOS? baremetal

After I did the steps from documentation (https://rancher.com/docs/os/v1.x/en/installation/configuration/setting-up-docker-tls/) I am still not able to connect.

docker --tlsverify version Version: 18.06.1-ce API version: 1.38 Go version: go1.10.3 Git commit: e68fc7a Built: Tue Aug 21 17:20:43 2018 OS/Arch: linux/amd64 Experimental: false error during connect: Get https://localhost:2376/v1.38/version: x509: certificate has expired or is not yet valid

Logs from /var/log/docker.log 2019-01-10 12:51:10.621318 I | http: TLS handshake error from [::1]:45608: remote error: tls: bad certificate

Any idea what can cause such problem?

pan1nx commented 5 years ago

Here is also my tls configurations: sudo ros config get rancher.docker.tls_args

kingsd041 commented 5 years ago

@pan1nx
I did not reproduce this issue in v1.5.0, not sure if I missed any key information:

[rancher@ip-172-31-44-185 ~]$ sudo ros config set rancher.docker.tls true
[rancher@ip-172-31-44-185 ~]$ sudo ros tls gen --server -H localhost
[rancher@ip-172-31-44-185 ~]$ sudo system-docker restart docker
[rancher@ip-172-31-44-185 ~]$ sudo ros tls gen
[rancher@ip-172-31-44-185 ~]$ sudo ros -v
version v1.5.0 from os image rancher/os:v1.5.0
[rancher@ip-172-31-44-185 ~]$ docker --tlsverify version
Client:
 Version:           18.06.1-ce
 API version:       1.38
 Go version:        go1.10.3
 Git commit:        e68fc7a
 Built:             Tue Aug 21 17:20:43 2018
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          18.06.1-ce
  API version:      1.38 (minimum version 1.12)
  Go version:       go1.10.3
  Git commit:       e68fc7a
  Built:            Tue Aug 21 17:28:38 2018
  OS/Arch:          linux/amd64
  Experimental:     false
pan1nx commented 5 years ago

Here is what I get doing the same:

rancher@ip-10-0-0-2:~$ sudo ros config set rancher.docker.tls true
rancher@ip-10-0-0-2:~$ sudo ros tls gen --server -H localhost
INFO[0000] Out directory (-d, --dir) not specified, using default: /etc/docker/tls 
rancher@ip-10-0-0-2:~$ sudo system-docker restart docker
docker
rancher@ip-10-0-0-2:~$ sudo ros tls gen
INFO[0000] Out directory (-d, --dir) not specified, using default: /home/rancher/.docker 
rancher@ip-10-0-0-2:~$  sudo ros -v
version v1.5.0 from os image rancher/os:v1.5.0
rancher@ip-10-0-0-2:~$ docker --tlsverify version
Client:
 Version:           18.06.1-ce
 API version:       1.38
 Go version:        go1.10.3
 Git commit:        e68fc7a
 Built:             Tue Aug 21 17:20:43 2018
 OS/Arch:           linux/amd64
 Experimental:      false
error during connect: Get https://localhost:2376/v1.38/version: x509: certificate signed by unknown authority (possibly because of "crypto/rsa: verification error" while trying to verify candidate authority certificate "rancher")
rancher@ip-10-0-0-2:~$

What does this command return on your side, @kingsd041:

sudo ros config get rancher.docker.tls_args

pan1nx commented 5 years ago

@kingsd041, here is my full log after I stopped the TLS (via sudo ros config set rancher.docker.tls false), remove the /etc/docker/tls folder, then restarted the docker:

rancher@ip-10-0-0-2:~$ sudo ros config get rancher.docker.tls_args
- --tlsverify
- --tlscacert=/etc/docker/tls/ca.pem
- --tlscert=/etc/docker/tls/server-cert.pem
- --tlskey=/etc/docker/tls/server-key.pem
- -H=0.0.0.0:2376

rancher@ip-10-0-0-2:~$ sudo ros config set rancher.docker.tls true
rancher@ip-10-0-0-2:~$ sudo ros tls gen --server -H localhost
INFO[0000] Out directory (-d, --dir) not specified, using default: /etc/docker/tls 
rancher@ip-10-0-0-2:~$ sudo system-docker restart docker
docker
rancher@ip-10-0-0-2:~$ sudo ros tls gen
INFO[0000] Out directory (-d, --dir) not specified, using default: /home/rancher/.docker 
rancher@ip-10-0-0-2:~$ sudo ros -v
version v1.5.0 from os image rancher/os:v1.5.0
rancher@ip-10-0-0-2:~$ docker --tlsverify version
Client:
 Version:           18.06.1-ce
 API version:       1.38
 Go version:        go1.10.3
 Git commit:        e68fc7a
 Built:             Tue Aug 21 17:20:43 2018
 OS/Arch:           linux/amd64
 Experimental:      false
error during connect: Get https://localhost:2376/v1.38/version: x509: certificate has expired or is not yet valid
rancher@ip-10-0-0-2:~$

Any idea what is going on?

Thanks!

kingsd041 commented 5 years ago

@pan1nx Returned the same content as you

[rancher@hailong-ros-test ~]$ sudo ros config get rancher.docker.tls_args
- --tlsverify
- --tlscacert=/etc/docker/tls/ca.pem
- --tlscert=/etc/docker/tls/server-cert.pem
- --tlskey=/etc/docker/tls/server-key.pem
- -H=0.0.0.0:2376

Please follow the steps below to troubleshoot:

  1. Remove the pem files in /etc/docker/tls/ and /home/rancher/.docker and re-up Docker TLS.
  2. Check that the 2376 port is up?
  3. Please confirm that user-docker has started.
  4. If up Docker TLS fails, check /var/log/docker.log and /var/log/boot/dockerlaunch.log for TLS error logs.
pan1nx commented 5 years ago

I will check and get back to you. Problem started after the upgrade. Earlier, it worked.

pan1nx commented 5 years ago

Hi @kingsd041 ,

No luck even with docker down and removing all the folders with TLS. How is the cacert (ca.pem) file generated by the ros?

Here are my shell commands with with output:

rancher@ip-10-0-0-2:~$ sudo system-docker stop docker
docker
rancher@ip-10-0-0-2:~$ sudo system-docker ps|grep docker
rancher@ip-10-0-0-2:~$ sudo ros config get rancher.docker.tls_args 
- --tlsverify
- --tlscacert=/etc/docker/tls/ca.pem
- --tlscert=/etc/docker/tls/server-cert.pem
- --tlskey=/etc/docker/tls/server-key.pem
- -H=0.0.0.0:2376

rancher@ip-10-0-0-2:~$ sudo rm -rf /etc/docker/tls/
rancher@ip-10-0-0-2:~$ sudo ls -al /etc/docker/tls/
ls: cannot access '/etc/docker/tls/': No such file or directory
rancher@ip-10-0-0-2:~$ sudo rm -rf /home/rancher/.docker/
rancher@ip-10-0-0-2:~$ sudo ls -al /home/rancher/.docker/
ls: cannot access '/home/rancher/.docker/': No such file or directory
rancher@ip-10-0-0-2:~$ sudo system-docker start docker
docker
rancher@ip-10-0-0-2:~$ sudo system-docker ps|grep docker
7b44a2831eed        rancher/os-docker:18.06.1          "ros user-docker"        11 days ago         Up 6 seconds                            docker
rancher@ip-10-0-0-2:~$ cat /var/log/docker.log
time="2019-01-22T11:34:22.781362185Z" level=info msg="libcontainerd: started new docker-containerd process" pid=14144
time="2019-01-22T11:34:22.781446252Z" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-01-22T11:34:22.781467671Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-01-22T11:34:22.781545240Z" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/docker-containerd.sock 0  }]" module=grpc
time="2019-01-22T11:34:22.781582477Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-01-22T11:34:22.781674715Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc4201d3a80, CONNECTING" module=grpc
time="2019-01-22T11:34:22Z" level=info msg="starting containerd" revision=468a545b9edcd5932818eb9de8e72413e616e86e version=v1.1.2 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.content.v1.content"..." type=io.containerd.content.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.btrfs"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:34:22Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.btrfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter" 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.aufs"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:34:22Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.aufs" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/4.14.85-rancher\n": exit status 1" 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.native"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.overlayfs"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.zfs"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:34:22Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.zfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter" 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.metadata.v1.bolt"..." type=io.containerd.metadata.v1 
time="2019-01-22T11:34:22Z" level=warning msg="could not use snapshotter aufs in metadata plugin" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/4.14.85-rancher\n": exit status 1" 
time="2019-01-22T11:34:22Z" level=warning msg="could not use snapshotter zfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter" 
time="2019-01-22T11:34:22Z" level=warning msg="could not use snapshotter btrfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter" 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.differ.v1.walking"..." type=io.containerd.differ.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.gc.v1.scheduler"..." type=io.containerd.gc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.service.v1.containers-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.service.v1.content-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.service.v1.diff-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.service.v1.images-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.service.v1.leases-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.service.v1.namespaces-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.service.v1.snapshots-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.monitor.v1.cgroups"..." type=io.containerd.monitor.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.runtime.v1.linux"..." type=io.containerd.runtime.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.service.v1.tasks-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.containers"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.content"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.diff"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.events"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.healthcheck"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.images"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.leases"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.namespaces"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.snapshots"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.tasks"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.version"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg="loading plugin "io.containerd.grpc.v1.introspection"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:34:22Z" level=info msg=serving... address="/var/run/docker/containerd/docker-containerd-debug.sock" 
time="2019-01-22T11:34:22Z" level=info msg=serving... address="/var/run/docker/containerd/docker-containerd.sock" 
time="2019-01-22T11:34:22Z" level=info msg="containerd successfully booted in 0.009015s" 
time="2019-01-22T11:34:22.812685984Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc4201d3a80, READY" module=grpc
time="2019-01-22T11:34:22.814602770Z" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-01-22T11:34:22.814647949Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-01-22T11:34:22.814734929Z" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/docker-containerd.sock 0  }]" module=grpc
time="2019-01-22T11:34:22.814776625Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-01-22T11:34:22.814848014Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc42017cc30, CONNECTING" module=grpc
time="2019-01-22T11:34:22.815144478Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc42017cc30, READY" module=grpc
time="2019-01-22T11:34:22.818302967Z" level=info msg="[graphdriver] using prior storage driver: overlay"
time="2019-01-22T11:34:22.982157779Z" level=error msg="migrate container error: open /var/lib/docker/containers/dd045b006cafb03fcef9b8bd218eb63a1dab85c7d1365f3def0573a5ed5f8a31/config.json: no such file or directory"
time="2019-01-22T11:34:22.982236843Z" level=info msg="Graph migration to content-addressability took 0.00 seconds"
time="2019-01-22T11:34:22.983013183Z" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-01-22T11:34:22.983038003Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-01-22T11:34:22.983082250Z" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/docker-containerd.sock 0  }]" module=grpc
time="2019-01-22T11:34:22.983100944Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-01-22T11:34:22.983143945Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc420193cc0, CONNECTING" module=grpc
time="2019-01-22T11:34:22.983295330Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc420193cc0, READY" module=grpc
time="2019-01-22T11:34:22.983324296Z" level=info msg="Loading containers: start."
time="2019-01-22T11:34:22.985202410Z" level=error msg="Failed to load container mount 245eff312d45aa7636c82e3f1b556805330f0a9fd573d27c6b15a4ea55318468: mount does not exist"
time="2019-01-22T11:34:22.989644210Z" level=error msg="Failed to load container dd045b006cafb03fcef9b8bd218eb63a1dab85c7d1365f3def0573a5ed5f8a31: open /var/lib/docker/containers/dd045b006cafb03fcef9b8bd218eb63a1dab85c7d1365f3def0573a5ed5f8a31/config.v2.json: no such file or directory"
time="2019-01-22T11:34:22.991211250Z" level=error msg="Failed to load container mount e1e0d70eb2088a4c674e1a9c3918da3b893a25b071e0df6342c4d272bb192219: mount does not exist"
time="2019-01-22T11:34:24.784209335Z" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address"
time="2019-01-22T11:34:26Z" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/3454432cd498a116deb8a1bf1a924f4e2a859407c951b02cf5286add891a4152/shim.sock" debug=false pid=14326 
time="2019-01-22T11:34:26Z" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/bc5ce06d2501e73da469c7405894813265b96392bf5da3558f53660321caef75/shim.sock" debug=false pid=14430 
time="2019-01-22T11:34:26Z" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/965c0944340a2b36693cc31c5dcce16535ab00669a817a73158dd9c822c2bc3e/shim.sock" debug=false pid=14448 
time="2019-01-22T11:34:26Z" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/2ec67acd093db786a91ca5259abf56bec41f1bb8ed033ec881c7302db072467f/shim.sock" debug=false pid=14469 
time="2019-01-22T11:34:28.878350942Z" level=info msg="Loading containers: done."
time="2019-01-22T11:34:28.884756178Z" level=info msg="Docker daemon" commit=e68fc7a graphdriver(s)=overlay version=18.06.1-ce
time="2019-01-22T11:34:28.884841449Z" level=info msg="Daemon has completed initialization"
time="2019-01-22T11:34:28.929114289Z" level=warning msg="Could not register builder git source: failed to find git binary: exec: \"git\": executable file not found in $PATH"
time="2019-01-22T11:34:28.934930411Z" level=info msg="API listen on [::]:2376"
time="2019-01-22T11:34:28.934952030Z" level=info msg="API listen on /var/run/docker.sock"
rancher@ip-10-0-0-2:~$ sudo ros config set rancher.docker.tls true
rancher@ip-10-0-0-2:~$ sudo ros tls gen --server -H localhost
INFO[0000] Out directory (-d, --dir) not specified, using default: /etc/docker/tls 
rancher@ip-10-0-0-2:~$ sudo system-docker restart docker
docker
rancher@ip-10-0-0-2:~$ sudo system-docker ps|grep docker
7b44a2831eed        rancher/os-docker:18.06.1          "ros user-docker"        11 days ago         Up 9 seconds                            docker
rancher@ip-10-0-0-2:~$ cat /var/log/docker.log
[...PREVIOUT LOG REMOVED...]
time="2019-01-22T11:34:28.934952030Z" level=info msg="API listen on /var/run/docker.sock"
time="2019-01-22T11:38:33.977962174Z" level=info msg="Processing signal 'terminated'"
time="2019-01-22T11:38:34Z" level=info msg="shim reaped" id=965c0944340a2b36693cc31c5dcce16535ab00669a817a73158dd9c822c2bc3e 
time="2019-01-22T11:38:34.102490039Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
time="2019-01-22T11:38:34Z" level=info msg="shim reaped" id=2ec67acd093db786a91ca5259abf56bec41f1bb8ed033ec881c7302db072467f 
time="2019-01-22T11:38:34.160196953Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
time="2019-01-22T11:38:35Z" level=info msg="shim reaped" id=3454432cd498a116deb8a1bf1a924f4e2a859407c951b02cf5286add891a4152 
time="2019-01-22T11:38:35.935869039Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
time="2019-01-22T11:38:38Z" level=info msg="shim reaped" id=bc5ce06d2501e73da469c7405894813265b96392bf5da3558f53660321caef75 
time="2019-01-22T11:38:38.646187313Z" level=info msg="ignoring event" module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
time="2019-01-22T11:38:39.422935445Z" level=info msg="stopping healthcheck following graceful shutdown" module=libcontainerd
time="2019-01-22T11:38:39.423091120Z" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=plugins.moby
time="2019-01-22T11:38:39.423116076Z" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=moby
time="2019-01-22T11:38:39.423263800Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc42017cc30, TRANSIENT_FAILURE" module=grpc
time="2019-01-22T11:38:39.423281810Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc420193cc0, TRANSIENT_FAILURE" module=grpc
time="2019-01-22T11:38:39.423303626Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc42017cc30, CONNECTING" module=grpc
time="2019-01-22T11:38:39.423320093Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc420193cc0, CONNECTING" module=grpc
time="2019-01-22T11:38:44.219901129Z" level=info msg="libcontainerd: started new docker-containerd process" pid=15361
time="2019-01-22T11:38:44.219986129Z" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-01-22T11:38:44.220010844Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-01-22T11:38:44.220083387Z" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/docker-containerd.sock 0  }]" module=grpc
time="2019-01-22T11:38:44.220121430Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-01-22T11:38:44.220234531Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc4204fe460, CONNECTING" module=grpc
time="2019-01-22T11:38:44Z" level=info msg="starting containerd" revision=468a545b9edcd5932818eb9de8e72413e616e86e version=v1.1.2 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.content.v1.content"..." type=io.containerd.content.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.btrfs"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:38:44Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.btrfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter" 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.aufs"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:38:44Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.aufs" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/4.14.85-rancher\n": exit status 1" 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.native"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.overlayfs"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.snapshotter.v1.zfs"..." type=io.containerd.snapshotter.v1 
time="2019-01-22T11:38:44Z" level=warning msg="failed to load plugin io.containerd.snapshotter.v1.zfs" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter" 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.metadata.v1.bolt"..." type=io.containerd.metadata.v1 
time="2019-01-22T11:38:44Z" level=warning msg="could not use snapshotter btrfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.btrfs must be a btrfs filesystem to be used with the btrfs snapshotter" 
time="2019-01-22T11:38:44Z" level=warning msg="could not use snapshotter aufs in metadata plugin" error="modprobe aufs failed: "modprobe: FATAL: Module aufs not found in directory /lib/modules/4.14.85-rancher\n": exit status 1" 
time="2019-01-22T11:38:44Z" level=warning msg="could not use snapshotter zfs in metadata plugin" error="path /var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.zfs must be a zfs filesystem to be used with the zfs snapshotter" 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.differ.v1.walking"..." type=io.containerd.differ.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.gc.v1.scheduler"..." type=io.containerd.gc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.service.v1.containers-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.service.v1.content-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.service.v1.diff-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.service.v1.images-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.service.v1.leases-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.service.v1.namespaces-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.service.v1.snapshots-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.monitor.v1.cgroups"..." type=io.containerd.monitor.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.runtime.v1.linux"..." type=io.containerd.runtime.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.service.v1.tasks-service"..." type=io.containerd.service.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.containers"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.content"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.diff"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.events"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.healthcheck"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.images"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.leases"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.namespaces"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.snapshots"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.tasks"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.version"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg="loading plugin "io.containerd.grpc.v1.introspection"..." type=io.containerd.grpc.v1 
time="2019-01-22T11:38:44Z" level=info msg=serving... address="/var/run/docker/containerd/docker-containerd-debug.sock" 
time="2019-01-22T11:38:44Z" level=info msg=serving... address="/var/run/docker/containerd/docker-containerd.sock" 
time="2019-01-22T11:38:44Z" level=info msg="containerd successfully booted in 0.012955s" 
time="2019-01-22T11:38:44.251367701Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc4204fe460, READY" module=grpc
time="2019-01-22T11:38:44.257442698Z" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-01-22T11:38:44.257470996Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-01-22T11:38:44.257534255Z" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/docker-containerd.sock 0  }]" module=grpc
time="2019-01-22T11:38:44.257561559Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-01-22T11:38:44.257613533Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc4204febe0, CONNECTING" module=grpc
time="2019-01-22T11:38:44.257833398Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc4204febe0, READY" module=grpc
time="2019-01-22T11:38:44.260884785Z" level=info msg="[graphdriver] using prior storage driver: overlay"
time="2019-01-22T11:38:44.471510490Z" level=error msg="migrate container error: open /var/lib/docker/containers/dd045b006cafb03fcef9b8bd218eb63a1dab85c7d1365f3def0573a5ed5f8a31/config.json: no such file or directory"
time="2019-01-22T11:38:44.471590378Z" level=info msg="Graph migration to content-addressability took 0.00 seconds"
time="2019-01-22T11:38:44.472340219Z" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-01-22T11:38:44.472362349Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-01-22T11:38:44.472398970Z" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///var/run/docker/containerd/docker-containerd.sock 0  }]" module=grpc
time="2019-01-22T11:38:44.472416616Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-01-22T11:38:44.472453360Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc420199e90, CONNECTING" module=grpc
time="2019-01-22T11:38:44.472743796Z" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc420199e90, READY" module=grpc
time="2019-01-22T11:38:44.472825393Z" level=info msg="Loading containers: start."
time="2019-01-22T11:38:44.475962980Z" level=error msg="Failed to load container mount 245eff312d45aa7636c82e3f1b556805330f0a9fd573d27c6b15a4ea55318468: mount does not exist"
time="2019-01-22T11:38:44.479223739Z" level=error msg="Failed to load container dd045b006cafb03fcef9b8bd218eb63a1dab85c7d1365f3def0573a5ed5f8a31: open /var/lib/docker/containers/dd045b006cafb03fcef9b8bd218eb63a1dab85c7d1365f3def0573a5ed5f8a31/config.v2.json: no such file or directory"
time="2019-01-22T11:38:44.479840536Z" level=error msg="Failed to load container mount e1e0d70eb2088a4c674e1a9c3918da3b893a25b071e0df6342c4d272bb192219: mount does not exist"
time="2019-01-22T11:38:46.265109111Z" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a preferred IP address"
time="2019-01-22T11:38:47Z" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/3454432cd498a116deb8a1bf1a924f4e2a859407c951b02cf5286add891a4152/shim.sock" debug=false pid=15554 
time="2019-01-22T11:38:48Z" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/2ec67acd093db786a91ca5259abf56bec41f1bb8ed033ec881c7302db072467f/shim.sock" debug=false pid=15636 
time="2019-01-22T11:38:48Z" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/965c0944340a2b36693cc31c5dcce16535ab00669a817a73158dd9c822c2bc3e/shim.sock" debug=false pid=15718 
time="2019-01-22T11:38:48Z" level=info msg="shim docker-containerd-shim started" address="/containerd-shim/moby/bc5ce06d2501e73da469c7405894813265b96392bf5da3558f53660321caef75/shim.sock" debug=false pid=15740 
time="2019-01-22T11:38:49.458440938Z" level=info msg="Loading containers: done."
time="2019-01-22T11:38:49.465670258Z" level=info msg="Docker daemon" commit=e68fc7a graphdriver(s)=overlay version=18.06.1-ce
time="2019-01-22T11:38:49.465767875Z" level=info msg="Daemon has completed initialization"
time="2019-01-22T11:38:49.489603021Z" level=warning msg="Could not register builder git source: failed to find git binary: exec: \"git\": executable file not found in $PATH"
time="2019-01-22T11:38:49.496381461Z" level=info msg="API listen on /var/run/docker.sock"
time="2019-01-22T11:38:49.496463565Z" level=info msg="API listen on [::]:2376"
rancher@ip-10-0-0-2:~$ sudo ros tls gen
INFO[0000] Out directory (-d, --dir) not specified, using default: /home/rancher/.docker 
rancher@ip-10-0-0-2:~$ sudo ros -v
version v1.5.0 from os image rancher/os:v1.5.0
rancher@ip-10-0-0-2:~$ docker --tlsverify version
Client:
 Version:           18.06.1-ce
 API version:       1.38
 Go version:        go1.10.3
 Git commit:        e68fc7a
 Built:             Tue Aug 21 17:20:43 2018
 OS/Arch:           linux/amd64
 Experimental:      false
error during connect: Get https://localhost:2376/v1.38/version: x509: certificate has expired or is not yet valid
rancher@ip-10-0-0-2:~$ cat /var/log/docker.log
[...PREVIOUS LOG REMOVED...]
time="2019-01-22T11:38:49.465670258Z" level=info msg="Docker daemon" commit=e68fc7a graphdriver(s)=overlay version=18.06.1-ce
time="2019-01-22T11:38:49.465767875Z" level=info msg="Daemon has completed initialization"
time="2019-01-22T11:38:49.489603021Z" level=warning msg="Could not register builder git source: failed to find git binary: exec: \"git\": executable file not found in $PATH"
time="2019-01-22T11:38:49.496381461Z" level=info msg="API listen on /var/run/docker.sock"
time="2019-01-22T11:38:49.496463565Z" level=info msg="API listen on [::]:2376"
2019-01-22 11:39:29.046148 I | http: TLS handshake error from [::1]:37712: remote error: tls: bad certificate
rancher@ip-10-0-0-2:~$

I hope this help, but I see no direction as to what goes wrong...

Thanks again!

kingsd041 commented 5 years ago

Hi @pan1nx

There is a temporary plan that should fix your problem. You can generate server and client keys and certificates on other RancherOS, then move those certificates to the corresponding directory of the RanacherOS you are using, and finally execute sudo ros config set rancher.docker.tls true and sudo system-docker restart docker

You can try it, I have already verified it.

pan1nx commented 5 years ago

Hi @kingsd041,

I did that and it works like that. But that means that you will always depend on the other server to generate the certificates for users. Every time I run sudo ros tls generate it will not generate a good user certificate, at least that part didn't work for me :(

Thanks!

pan1nx commented 5 years ago

@kingsd041 , any other ideas what goes wrong there?

Thank you!

pan1nx commented 5 years ago

So, a month has passed and still there is no resolution. Anybody else with an idea?

kingsd041 commented 5 years ago

@pan1nx I am very sorry to reply to you so late. I have been dealing with other things this month. It is too busy. I didn't reproduce the issue, so it's not easy to troubleshoot. Can you reproduce it on other devices?

pan1nx commented 5 years ago

Hi @kingsd041. Same here... so, totally understand it. The bare metal machine that I have it uses a rancheros since v0.4.5. I started having problem after upgrade to v1.5.0. Then I had the user docker images gone missing and also I the certificate causing problems after the docker images fix... I will give it a try later this month for the v1.5.1 and see if there are some fixes in the area and let you know.

I would really like to know were is it generating the certificates and why are they so wrong...

Thanks!

kingsd041 commented 5 years ago

You mean that after upgrading from v0.4.5 to v1.5.0, the certificate cannot be generated in v1.5.0? If you use the new v1.5.0 will have problems?

pan1nx commented 5 years ago

Hi @kingsd041 , yes, after the upgrade I started having the issue...

kingsd041 commented 5 years ago

V0.4.5 is a very old version, it is recommended that you install the latest rancheros

pan1nx commented 5 years ago

Currently it is v1.5.0... All the problem started after I upgraded to latest which was v1.5.0. But I didn't upgrade from v0.4.5, it was only installed first version with that one. I upgraded regularly and the last one caused the trouble.

djbingham commented 3 years ago

I'm having either the same issue or one very similar, which started the day after my original Docker certificates expired. I've tried generating new client and server certificates, but both client and server ca.pem have not updated (cert.pem has). This is after I removed all .pem files from the Docker folders and then ran the ros tls gen commands to create new ones.

Does anyone know why sudo ros tls gen is reproducing the original ca.pem, rather than creating a new one when /etc/docker/tls and /home/rancher/.docker have been emptied? Is there any way to force a full update of all certificate files?

I can't deploy any upgrades to my running services at the moment because my CI tools cannot execute remote Docker commands with expired certificates.

Here's the full process I went through (with outputs) to try to update both client and server certificates:

# Turn off Docker TLS and stop Docker
$ sudo ros config set rancher.docker.tls false
$ sudo system-docker stop docker
docker

# Move existing certificates to a backup folder
$ mkdir -p ~/backup/tls/client ~/backup/tls/server
$ find /home/rancher/.docker -name "*.pem" -exec mv '{}' '/home/rancher/backup/tls/client/' \;
$ sudo find /etc/docker/tls -name "*.pem" -exec mv '{}' '/home/rancher/backup/tls/server/' \;

# Check that no certificates remain in Docker folders
$ sudo ls -la /etc/docker/tls
total 8
drwx------    2 root     root          4096 Mar  3 18:13 .
drwxr-xr-x    5 root     root          4096 Mar  3 17:54 ..

$ ls -la ~/.docker
total 16
drwx------    2 rancher  rancher       4096 Mar  3 18:13 .
drwxr-xr-x    5 rancher  rancher       4096 Mar  3 16:34 ..
-r--------    1 rancher  rancher       1679 Mar  3 18:08 ca-key.pem
-rw-------    1 rancher  rancher        103 Aug 14  2018 config.json

# Generate new server certificates
$ sudo ros tls gen --server -H localhost
INFO[0000] Out directory (-d, --dir) not specified, using default: /etc/docker/tls

# Enable Docker TLS and restart Docker
$ sudo ros config set rancher.docker.tls true
$ sudo system-docker restart docker
docker

# Generate new client certificates
$ sudo ros tls gen -H localhost
INFO[0000] Out directory (-d, --dir) not specified, using default: /home/rancher/.docker

# Verify TLS configuration
$ docker --tlsverify version
Client: Docker Engine - Community
 Version:           19.03.4
 API version:       1.40
 Go version:        go1.12.10
 Git commit:        9013bf583a
 Built:             Fri Oct 18 15:49:05 2019
 OS/Arch:           linux/amd64
 Experimental:      false
error during connect: Get https://localhost:2376/v1.40/version: x509: certificate has expired or is not yet valid

I downloaded the client certificate files to my local machine and used openssl to check the expiry dates.

$ openssl x509 -enddate -noout -in ca.pem
notAfter=Mar  1 14:12:00 2021 GMT

$ openssl x509 -enddate -noout -in cert.pem
notAfter=Feb 16 17:54:00 2024 GMT

I compared the ca.pem contents before and after the above process - they are 100% identical. Somehow sudo ros tls gen --server generated a new cert.pem but brought back the original ca.pem (which I had removed from .docker/).

Versions:

$ sudo ros -v
version v1.5.4 from os image rancher/os:v1.5.4

$ docker version
Client: Docker Engine - Community
 Version:           19.03.4
 API version:       1.40
 Go version:        go1.12.10
 Git commit:        9013bf583a
 Built:             Fri Oct 18 15:49:05 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.4
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.10
  Git commit:       9013bf583a
  Built:            Fri Oct 18 15:55:51 2019
  OS/Arch:          linux/amd64
  Experimental:     true
 containerd:
  Version:          v1.2.10
  GitCommit:        b34a5c8af56e510852c35414db4c1f4fa6172339
 runc:
  Version:          1.0.0-rc8+dev
  GitCommit:        3e425f80a8c931f88e6d94a8c831b9d5aa481657
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

Any ideas?

szunny commented 2 years ago

i have the exact same problem right now with 1.5.6. did you find a solution? I'm pulling my hair put for 2 straight days now.

ShuP1 commented 1 year ago

Same there :cry: Any news ?