RancherOS becomes unstable when cni config doesn't match what system-docker is running

[janeczku]

Docker 17.03

jan-test-host-504:~$ sudo ros os upgrade -i rancher/os:v1.0.0                                                                                             
Upgrading to rancher/os:v1.0.0
Continue [y/N]: y
Pulling os-upgrade (rancher/os:v1.0.0)...
v1.0.0: Pulling from rancher/os
627beaf3eaaf: Pull complete 
8cd4da28feed: Pull complete 
5d75ece5df69: Pull complete 
38bb5e38fdc9: Pull complete 
9565a5c14df5: Pull complete 
fe52d1c928cd: Pull complete 
4d3675c97e57: Pull complete 
d9dbc11ef46d: Pull complete 
3deb8f716c46: Pull complete 
e465707aa88c: Pull complete 
Digest: sha256:ed2ee4fbb12adfce363d6433769ad3cb0f3f8acf81f699101ca9f0108ae2ea0b
Status: Downloaded newer image for rancher/os:v1.0.0
os-upgrade_1 | Installing from :v1.0.0
Continue with reboot [y/N]: y
> INFO[0018] Rebooting                                    
> FATA[0018] Error response from daemon: oci runtime error: exit status 1: time="2017-06-07T21:35:23Z" level=fatal msg="\"docker-sys\" already has an IP address different from 10.0.0.1/16" 
jan-test-host-504:~$ sudo ros -v  

resolution plan: (updated by Sven)

for v1.0.x and v11.0, its best to move the customisation of the docker-sys bridge into the installation phase, and then reboot - that way it'll be ready when the system docker is started (using cloud-init write-file shouldn't really work)
for 1.2.0, 1.1.x and possibly 1.0.x I'll work on adding a cloud-init setting for this (and hopefully other settings)

[SvenDowideit]

so with debug off:

sven@y260:~$ machine ssh downgrade
[rancher@downgrade ~]$ ros -v
ros version v1.0.1
[rancher@downgrade ~]$ docker -v
Docker version 17.03.1-ce, build c6d412e
[rancher@downgrade ~]$ sudo ros os upgrade -f -i rancher/os:v1.0.0
Upgrading to rancher/os:v1.0.0
Pulling os-upgrade (rancher/os:v1.0.0)...
v1.0.0: Pulling from rancher/os

627beaf3eaaf: Pull complete 
8cd4da28feed: Pull complete 
5d75ece5df69: Pull complete 
38bb5e38fdc9: Pull complete 
9565a5c14df5: Pull complete 
fe52d1c928cd: Pull complete 
4d3675c97e57: Pull complete 
d9dbc11ef46d: Pull complete 
3deb8f716c46: Pull complete 
e465707aa88c: Pull complete 
Digest: sha256:ed2ee4fbb12adfce363d6433769ad3cb0f3f8acf81f699101ca9f0108ae2ea0b
Status: Downloaded newer image for rancher/os:v1.0.0
os-upgrade_1 | Installing from :v1.0.0
> INFO[0014] Rebooting                                    
Connection to 34.211.31.193 closed by remote host.
exit status 255

[SvenDowideit]

and with debug on:

sven@y260:~$ machine ssh downgrade2
[rancher@downgrade2 ~]$ sudo ros config set rancher.debug=true
[rancher@downgrade2 ~]$ ros -v
ros version v1.0.1
[rancher@downgrade2 ~]$ docker -v
Docker version 17.03.1-ce, build c6d412e
[rancher@downgrade2 ~]$ sudo ros os upgrade -f -i rancher/os:v1.0.0
Upgrading to rancher/os:v1.0.0
Pulling os-upgrade (rancher/os:v1.0.0)...
v1.0.0: Pulling from rancher/os

627beaf3eaaf: Pull complete 
8cd4da28feed: Pull complete 
5d75ece5df69: Pull complete 
38bb5e38fdc9: Pull complete 
9565a5c14df5: Pull complete 
fe52d1c928cd: Pull complete 
4d3675c97e57: Pull complete 
d9dbc11ef46d: Pull complete 
3deb8f716c46: Pull complete 
e465707aa88c: Pull complete 
Digest: sha256:ed2ee4fbb12adfce363d6433769ad3cb0f3f8acf81f699101ca9f0108ae2ea0b
Status: Downloaded newer image for rancher/os:v1.0.0
os-upgrade_1 | Installing from :v1.0.0
> INFO[0005] Rebooting                                    
Connection to 34.209.182.251 closed by remote host.
exit status 255
sven@y260:~$ machine ssh downgrade2
[rancher@downgrade2 ~]$ ros -v
ros version v1.0.0

so its not just downgrading any ros - @janeczku we need more specific details.

[janeczku]

@SvenDowideit This is reproducible 3/5 when trying to upgrade our preconfigured VMware vSphere hosts from v1.0.0 to v1.0.1. The upgrade fails with "oci runtime error". Then also manually forcing a reboot fails with the same error making it impossible to reboot and complete the upgrade. To recover we have to reset the host via the vSphere console.

Steps to reproduce
Run these commands on a freshly installed v1.0.0 host configured with cloud-config:

jantest-501.hosts.generic.acme.com:~$ ros -v  
ros version v1.0.0
jantest-501.hosts.generic.acme.com:~$ docker -v                                                                                                                         
Docker version 17.03.1-ce, build c6d412e
jantest-501.hosts.generic.acme.com:~$ docker run -d redis                                                                                                               
Unable to find image 'redis:latest' locally
latest: Pulling from library/redis
f5cc0ee7a6f6: Pull complete 
5fc25ed18e87: Pull complete 
e025bc8872f6: Pull complete 
9561c3f55930: Pull complete 
592ed969e475: Pull complete 
186417381037: Pull complete 
Digest: sha256:c2a9a89edc0902356955f14c947c4b16e67a18316210515641e24842b63078bb
Status: Downloaded newer image for redis:latest
d29a464edb7cf53060ef907738ffea1de42c2f8cc98522bb5a8571c54ec81815                    
jantest-501.hosts.generic.acme.com:~$ sudo ros os list                                                                                                                  
rancher/os:v1.0.3 remote latest 
rancher/os:v1.0.2 remote available 
rancher/os:v1.0.1 remote available 
rancher/os:v1.0.0 remote available running
rancher/os:v0.9.2 remote available 
rancher/os:v0.9.1 remote available 
rancher/os:v0.9.0 remote available 
rancher/os:v0.8.1 remote available 
rancher/os:v0.8.0 remote available 
rancher/os:v0.7.1 remote available 
rancher/os:v0.7.0 remote available 
rancher/os:v0.6.1 remote available 
rancher/os:v0.6.0 remote available 
rancher/os:v0.5.0 remote available 
rancher/os:v0.4.5 remote available 
rancher/os:v0.4.4 remote available 
rancher/os:v0.4.3 remote available 
rancher/os:v0.4.2 remote available 
rancher/os:v0.4.1 remote available 
rancher/os:v0.4.0 remote available 
jantest-501.hosts.generic.acme.com:~$ sudo ros engine list                                                                                                              
disabled docker-1.10.3
disabled docker-1.11.2
disabled docker-1.12.6
disabled docker-1.13.1
current  docker-17.03.1-ce
disabled docker-17.04.0-ce
jantest-501.hosts.generic.acme.com:~$ sudo ros config set rancher.debug=true                                                                                            
jantest-501.hosts.generic.acme.com:~$ sudo ros os upgrade -i rancher/os:v1.0.1                                                                                          
Upgrading to rancher/os:v1.0.1
Continue [y/N]: y
Pulling os-upgrade (rancher/os:v1.0.1)...
v1.0.1: Pulling from rancher/os
627beaf3eaaf: Pull complete 
56ecb7539042: Pull complete 
ab6a6aa500c0: Pull complete 
237fe36f0593: Pull complete 
959d9773a286: Pull complete 
f62d8177237f: Pull complete 
25a6fb770b97: Pull complete 
6235a630e44b: Pull complete 
fb3adec6ce09: Pull complete 
c7354f67942a: Pull complete 
Digest: sha256:6656686f65c3820a8399ec64f80b2511cc0441d9202dba445d8d4cab7dfd85e0
Status: Downloaded newer image for rancher/os:v1.0.1
os-upgrade_1 | Installing from :v1.0.1
Continue with reboot [y/N]: y
> INFO[0006] Rebooting                                    
> FATA[0007] Error response from daemon: oci runtime error: exit status 1: time="2017-07-22T12:36:04Z" level=fatal msg="\"docker-sys\" already has an IP address different from 10.0.0.1/16" 
jantest-501.hosts.generic.acme.com:~$ sudo shutdown -r now                                                                                                              
> FATA[0000] Error response from daemon: oci runtime error: exit status 1: time="2017-07-22T12:40:23Z" level=fatal msg="\"docker-sys\" already has an IP address different from 10.0.0.1/16" 

Configuration

jantest-501.hosts.generic.acme.com:~$ sudo ros config export                                                                                                            
EXTRA_CMDLINE: /init
hostname: jantest-501.hosts.generic.acme.com
rancher:
  docker:
    extra_args:
    - --bip=10.4.0.1/14
  environment:
    EXTRA_CMDLINE: /init
  network:
    dns:
      nameservers:
      - 64.XXX.XXX.XXX
      - 173.XXX.XXX.XXX
  services:
    acme-dyndns:
      image: dockerhub.acme.com/os-services/r3dyndns:latest
      labels:
        io.rancher.os.after: console
        io.rancher.os.scope: system
      net: host
  services_include:
    open-vm-tools: true
  state:
    dev: LABEL=RANCHER_STATE
    wait: true
  sysctl:
    kernel.dmesg_restrict: 1
    kernel.kptr_restrict: 1
    vm.max_map_count: 262144
ssh_authorized_keys:
- ssh-rsa AAAABBBBB...
write_files:
- content: |+
    {
      "name": "bridge",
      "type": "bridge",
      "bridge": "docker-sys",
      "isDefaultGateway": true,
      "ipMasq": true,
      "hairpinMode": true,
      "ipam": {
        "type": "host-local",
        "subnet": "10.0.0.0/16"
      }
    }
  owner: root
  path: /etc/docker/cni/bridge.d/bridge.conf
  permissions: "0644"

system-docker

jantest-501.hosts.generic.acme.com:~$ sudo system-docker info                                                                                                           
Containers: 18
 Running: 9
 Paused: 0
 Stopped: 9
Images: 7
Server Version: library-import
Storage Driver: overlay
 Backing Filesystem: extfs
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins: 
 Volume: local
 Network: 
Kernel Version: 4.9.21-rancher
Operating System: <unknown>
OSType: linux
Architecture: x86_64
CPUs: 6
Total Memory: 9.766 GiB
Name: jantest-501.hosts.generic.acme.com
ID: NXT4:2EOA:32XN:RR3G:34AX:FYE4:E3Q5:Y37J:BY7S:3AXB:YNNC:3YWN
Docker Root Dir: /var/lib/system-docker
Debug mode (client): false
Debug mode (server): false
Registry: https://index.docker.io/v1/

jantest-501.hosts.generic.acme.com:~$ sudo system-docker ps -a --format "table {{.Names}}\t{{.Image}}\t{{.Command}}\t{{.Status}}"                                       
NAMES                    IMAGE                                                COMMAND                  STATUS
reboot                   rancher/os-console:v1.0.0                            "/usr/bin/ros entrypo"   Created
open-vm-tools            rancher/os-openvmtools:v1.0.0                        "/usr/bin/ros entrypo"   Up 9 minutes
acme-dyndns              dockerhub.acme.com/os-services/r3dyndns:latest       "/bin/sh -c /app/auto"   Up 9 minutes
preload-user-images      rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Exited (0) 9 minutes ago
docker                   rancher/os-docker:17.03.1                            "ros user-docker"        Up 9 minutes
console                  rancher/os-console:v1.0.0                            "/usr/bin/ros entrypo"   Up 9 minutes
cloud-init-execute       rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Exited (0) 9 minutes ago
ntp                      rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Up 9 minutes
network                  rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Up 9 minutes
udev                     rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Up 9 minutes
all-volumes              rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Created
syslog                   rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Up 9 minutes
udev-cold                rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Exited (0) 9 minutes ago
acpid                    rancher/os-acpid:v1.0.0                              "/usr/bin/ros entrypo"   Up 9 minutes
user-volumes             rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Created
media-volumes            rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Created
container-data-volumes   rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Created
system-volumes           rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Created
command-volumes          rancher/os-base:v1.0.0                               "/usr/bin/ros entrypo"   Created

user-docker

jantest-501.hosts.generic.acme.com:~$ docker ps --format "table {{.Names}}\t{{.Image}}\t{{.Command}}\t{{.Status}}"                                                      
NAMES               IMAGE               COMMAND                  STATUS
hardcore_hamilton   redis               "docker-entrypoint..."   Up 28 minutes

dmesg snippet

[  191.873347] DEBU[0000] START: [ros os upgrade -i rancher/os:v1.0.1] in /home/rancher 
[  197.651327] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[  197.759386] time="2017-07-22T12:21:34Z" level=debug msg="START: [/bin/ros install -t rancher-upgrade -r v1.0.0] in /" 
[  197.759555] time="2017-07-22T12:21:34Z" level=debug msg="/var/lib/rancher/conf/cloud-config.d does not exist" 
[  197.759998] time="2017-07-22T12:21:34Z" level=debug msg="running installation" 
[  197.760008] time="2017-07-22T12:21:34Z" level=debug msg="mountdevice , raw false" 
[  197.760025] time="2017-07-22T12:21:34Z" level=debug msg="/var/lib/rancher/conf/cloud-config.d does not exist" 
[  197.778951] time="2017-07-22T12:21:34Z" level=debug msg="Run(&{/bin/lsblk [lsblk -no pkname /dev/sda1] []  <nil> <nil> <nil> [] <nil> <nil> <nil> <nil> <nil> false [] [] [] [] <nil> <nil>})" 
[  197.779913] time="2017-07-22T12:21:34Z" level=debug msg="mountdevice return2 -> d: /dev/sda, p: /dev/sda1" 
[  197.781230] time="2017-07-22T12:21:34Z" level=debug msg="upgrading - /dev/sda, /mnt/new_img, boot/, msdos" 
[  197.781245] time="2017-07-22T12:21:34Z" level=debug msg="start upgradeBootloader" 
[  197.782346] time="2017-07-22T12:21:34Z" level=debug msg="/mnt/new_img/boot/grub does not exist - no need to upgrade bootloader" 
[  197.782935] time="2017-07-22T12:21:34Z" level=debug msg=installRancher 
[  197.782959] time="2017-07-22T12:21:34Z" level=debug msg=installRancher 
[  197.783150] time="2017-07-22T12:21:34Z" level=debug msg="Not copying /dist/global.cfg => /mnt/new_img/boot/global.cfg already exists" 
[  197.783848] time="2017-07-22T12:21:34Z" level=debug msg="Copying /dist/initrd-v1.0.1 => /mnt/new_img/boot/initrd-v1.0.1" 
[  197.807909] time="2017-07-22T12:21:34Z" level=debug msg="Copying /dist/linux-current.cfg => /mnt/new_img/boot/linux-current.cfg" 
[  197.807980] time="2017-07-22T12:21:34Z" level=debug msg="Copying /dist/vmlinuz-4.9.24-rancher => /mnt/new_img/boot/vmlinuz-4.9.24-rancher" 
[  197.812092] time="2017-07-22T12:21:34Z" level=debug msg="Not copying /dist/isolinux/isolinux.cfg => /mnt/new_img/boot/syslinux/syslinux.cfg already exists" 
[  197.812786] time="2017-07-22T12:21:34Z" level=debug msg="installRancher done" 
[  203.459920] INFO[0011] Rebooting                                    
[  203.688513] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[  203.701501] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[  203.701618] docker-sys: port 1(veth23206963) entered blocking state
[  203.701619] docker-sys: port 1(veth23206963) entered disabled state
[  203.701675] device veth23206963 entered promiscuous mode
[  203.701705] docker-sys: port 1(veth23206963) entered blocking state
[  203.701706] docker-sys: port 1(veth23206963) entered forwarding state
[  203.788945] docker-sys: port 1(veth23206963) entered disabled state
[  203.790392] device veth23206963 left promiscuous mode
[  203.790393] docker-sys: port 1(veth23206963) entered disabled state
[  203.905561] FATA[0012] Error response from daemon: oci runtime error: exit status 1: time="2017-07-22T12:21:40Z" level=fatal msg="\"docker-sys\" already has an IP address different from 10.0.0.1/16" 

Logs

log-files.zip

[janeczku]

So this seems to be caused by the custom docker-sys bridge configuration not being applied reliably when we install RancherOS initially.

We have the following configuration in the cloud-config passed to ros install that changes the subnet of the docker-sys bridge to 10.0.0.0/16

write_files:
- content: |+
    {
      "name": "bridge",
      "type": "bridge",
      "bridge": "docker-sys",
      "isDefaultGateway": true,
      "ipMasq": true,
      "hairpinMode": true,
      "ipam": {
        "type": "host-local",
        "subnet": "10.0.0.0/16"
      }
    }
  owner: root
  path: /etc/docker/cni/bridge.d/bridge.conf
  permissions: "0644"

On the hosts where the upgrade to v1.0.1 fails with level=fatal msg="\"docker-sys\" already has an IP address different from 10.0.0.1/16 we can actually see that the docker-sys bridge is not configured according to the cloud-config and has an IP of 172.18.42.2:

jantest-502.hosts.generic.acme.com:~$ ifconfig
docker-sys Link encap:Ethernet  HWaddr 00:00:00:00:00:00  
          inet addr:172.18.42.2  Bcast:0.0.0.0  Mask:255.255.0.0
          inet6 addr: fe80::9c79:13ff:feee:1f51/64 Scope:Link
          UP BROADCAST MULTICAST  MTU:1500  Metric:1
          RX packets:2 errors:0 dropped:0 overruns:0 frame:0
          TX packets:3 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:140 (140.0 B)  TX bytes:258 (258.0 B)

docker0   Link encap:Ethernet  HWaddr 02:42:A7:1D:32:2C  
          inet addr:10.4.0.1  Bcast:0.0.0.0  Mask:255.252.0.0
          UP BROADCAST MULTICAST  MTU:1500  Metric:1
          RX packets:0 errors:0 dropped:0 overruns:0 frame:0
          TX packets:0 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0 
          RX bytes:0 (0.0 B)  TX bytes:0 (0.0 B)

event though the custom bridge.config has been written as expected:

jantest-502.hosts.generic.acme.com:$ cat /etc/docker/cni/bridge.d/bridge.conf
  "name": "bridge",
  "type": "bridge",
  "bridge": "docker-sys",
  "isDefaultGateway": true,
  "ipMasq": true,
  "hairpinMode": true,
  "ipam": {
    "type": "host-local",
    "subnet": "10.0.0.0/16"
  }
}

On the hosts where the upgrade succeeds the bridge is configured correctly:

jantest-501.hosts.generic.acme.com:~$ ifconfig
docker-sys Link encap:Ethernet  HWaddr 00:00:00:00:00:00  
          inet addr:10.0.0.1  Bcast:0.0.0.0  Mask:255.255.0.0
          inet6 addr: fe80::9cb3:2eff:fe4f:297c/64 Scope:Link
          UP BROADCAST MULTICAST  MTU:1500  Metric:1
          RX packets:3 errors:0 dropped:0 overruns:0 frame:0
          TX packets:5 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:216 (216.0 B)  TX bytes:418 (418.0 B)

[janeczku]

TLDR: the workaround we use to configure a custom bridge IP by overwriting the /etc/docker/cni/bridge.d/bridge.conf is not reliable (probably some race).
The documentation states that extra_args are supported for system-docker, but this does not seem to work for the --bip parameter, see #797 and #1870.

http://rancher.com/docs/os/configuration/docker/#system-docker-settings

@SvenDowideit

[SvenDowideit]

merci for the info. looking into it.

[SvenDowideit]

@janeczku I would think that as the /etc/docker dir is persistent, that the safe way to do this (at the moment) would be something like

ros install --no-reboot ....
mount /dev/sda1 /mnt
write your changed conf
reboot

not good, but that way the config is definitely going to be written before you boot into the persistence partition.

In my testing I also noticed that after you reboot after the first boot from persistent disk - though you do need to use the vmware power button to do it. in v1.1.0, there's a poweroff -f to force it to poweroff without cleaning up running the docker containers.

given http://rancher.com/docs/os/configuration/write-files/#writing-files-in-specific-system-services says that the default is to write files in the console container, I don't really see how the write-files above would work reliably.

and yup, this bumps #1870 up as something I may have to get going in 1.2.0 and then think about backporting depending on how intrusive a change it is.