Boot order for cloud-config services not working (DHCP delay causes unstablility)

[janeczku]

RancherOS Version: (ros os version)
v1.0.1

1. Use the following cloud-config:

#cloud-config
ssh_authorized_keys:
  - ssh-rsa  123
rancher:
  services_include:
    open-vm-tools: true
  services:
    service-dyndns:
      image: dockerhub.myrepo.com/services/dyndns:latest
      labels:
        io.rancher.os.scope: system
        io.rancher.os.after: console
      net: host

Expected behaviour

service-dyndns is started after the console

Actual behaviour

service-dyndns is started before the console according to the logs.

This also seems to cause this service to win a race against DHCPd writing the local nameservers to /etc/resolv.conf. As a result Docker is using the default Google DNS to resolve the repository, which fails because its not a public DNS name.

[10.541505] INFO[0001] [10/17] [network]: Starting
[10.546390] time="2017-06-07T15:46:26Z" level=debug msg="START: [/usr/bin/ros entrypoint udevd] in /" 
[10.566894] udevd[1]: starting version 3.2
[10.566942] udevd[1]: starting eudev-3.2
[10.590523] DEBU[0001] Rebuild values  newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[10.666823] time="2017-06-07T15:46:26Z" level=debug msg="START: [/usr/bin/ros entrypoint netconf] in /" 
[10.670019] INFO[0001] [11/17] [network]: Started 
[10.705479] time="2017-06-07T15:46:27Z" level=debug msg="START: [netconf] in /" 
[10.714023] time="2017-06-07T15:46:27Z" level=info msg="Apply Network Config" 
[10.714187] time="2017-06-07T15:46:27Z" level=debug msg="Config: &netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig{\"lo\":netconf.InterfaceConfig{Match:\"\", DHCP:false, DHCPArgs:\"\", Address:\"\", Addresses:[]string{\"127.0.0.1/8\", \"::1/128\"}, IPV4LL:false, Gateway:\"\", GatewayIpv6:\"\", MTU:0, Bridge:\"\", Bond:\"\", BondOpts:map[string]string(nil), PostUp:[]string(nil), PreUp:[]string(nil), Vlans:\"\"}, \"eth*\":netconf.InterfaceConfig{Match:\"\", DHCP:true, DHCPArgs:\"\", Address:\"\", Addresses:[]string(nil), IPV4LL:false, Gateway:\"\", GatewayIpv6:\"\", MTU:0, Bridge:\"\", Bond:\"\", BondOpts:map[string]string(nil), PostUp:[]string(nil), PreUp:[]string(nil), Vlans:\"\"}}, PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[10.715383] time="2017-06-07T15:46:27Z" level=info msg="Applying 127.0.0.1/8 to lo" 
[10.715513] time="2017-06-07T15:46:27Z" level=info msg="Applying ::1/128 to lo" 
[10.715634] time="2017-06-07T15:46:27Z" level=info msg="Apply Network Config RunDhcp" 
[10.715782] time="2017-06-07T15:46:27Z" level=debug msg=RunDhcp 
[10.715901] time="2017-06-07T15:46:27Z" level=info msg="Running DHCP on eth0: dhcpcd -MA4 eth0" 
[10.761547] DEBU[0001] Loaded open-vm-tools from https://raw.githubusercontent.com/rancher/os-services/v1.0.1/o/open-vm-tools.yml 
[10.762336] DEBU[0001] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.24-rancher 
[10.762474] DEBU[0001] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.24-rancher 
[10.762628] DEBU[0001] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.24-rancher 
[10.769237] INFO[0001] [11/18] [ntp]: Starting 
[10.769352] INFO[0001] [11/18] [open-vm-tools]: Starting
[10.770567] INFO[0001] [11/18] [service-dyndns]: Starting 
[10.823837] DEBU[0001] Rebuild values  newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[10.906008] time="2017-06-07T15:46:27Z" level=debug msg="START: [/usr/bin/ros entrypoint ntpd --nofork -g] in /" 
[10.906315] INFO[0002] [12/18] [ntp]: Started  
[10.906463] INFO[0002] [12/18] [cloud-init-execute]: Starting 
[10.959001] DEBU[0002] Rebuild values  newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[11.040162] time="2017-06-07T15:46:27Z" level=debug msg="START: [/usr/bin/ros entrypoint cloud-init-execute -pre-console] in /" 
[11.060808] time="2017-06-07T15:46:27Z" level=debug msg="START: [cloud-init-execute -pre-console] in /" 
[11.060824] time="2017-06-07T15:46:27Z" level=info msg="Running cloud-init-execute: pre-console=true, console=false" 
[11.206411] ERRO[0002] Failed to pull image dockerhub.myrepo.com/services/dyndns:latest: Error response from daemon: Get https://dockerhub.myrepo.com/v1/_ping: dial tcp: lookup dockerhub.myrepo.com on 8.8.4.4:53: server misbehaving 
[11.206848] ERRO[0002] Failed Starting service-dyndns : Error response from daemon: Get https://dockerhub.cisco.com/v1/_ping: dial tcp: lookup dockerhub.myrepo.com on 8.8.4.4:53: server misbehaving 
[11.326026] INFO[0002] [13/18] [cloud-init-execute]: Started  
[11.326178] INFO[0002] [13/18] [console]: Starting
[11.405223] DEBU[0002] Rebuild values  newRebuildLabel=always origRebuildLabel=always outOfSync=false rebuildLabelChanged=false
[11.405372] INFO[0002] Rebuilding console
[11.540496] INFO[0002] [14/18] [console]: Started 
[11.540671] INFO[0002] [14/18] [docker]: Starting 
[11.540828] INFO[0002] [14/18] [preload-user-images]: Starting

[janeczku]

And here is the DHCPd side of the race condition:

tail /var/log/syslog:

(...)
Jun  7 15:46:28 rancher dhcpcd[1023]: eth0: soliciting a DHCP lease
Jun  7 15:46:28 rancher dhcpcd[1023]: eth0: offered xx.xx.13.228 from xx.xx.49.191
Jun  7 15:46:28 rancher dhcpcd[1023]: eth0: leased xx.xx.13.228 for 3535 seconds
Jun  7 15:46:28 rancher dhcpcd[1023]: eth0: adding route to xx.xx.13.0/24
Jun  7 15:46:28 rancher dhcpcd[1023]: eth0: adding default route via xx.xx.13.1
Jun  7 15:46:28 rancher dhcpcd[1023]: forked to background, child pid 1213
(...)

DHCP lease (and setting nameservers from DHCP) is not completed until 15:46:28, ie. after the service-dyndns container was already started and the docker pull failed.

[SvenDowideit]

ah, wow, this'll be "fun" to make tests for.

[lynsei]

yeah, it's been fun trying to figure out what's causing our vms not to boot correct lol

[SvenDowideit]

ok, I'm starting to unpack this using the following cloud-config:

#cloud-config
rancher:
  bootstrap_docker:
    registry_mirror: "http://10.10.10.23:5555"
    insecure_registry:
    - 10.10.10.23:5000
    - arian:5000
  docker:
    registry_mirror: "http://10.10.10.23:5555"
    insecure_registry:
    - 10.10.10.23:5000
    - arian:5000
  system_docker:
    registry_mirror: "http://10.10.10.23:5555"
    insecure_registry:
    - 10.10.10.23:5000
    - arian:5000
  services:
    local-registry:
      image: registry
      labels:
        io.rancher.os.scope: system
        io.rancher.os.after: console
      ports:
      - 5000:5000
ssh_authorized_keys:
  - ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC85w9stZyiLQp/DkVO6fqwiShYcj1ClKdtCqgHtf+PLpJkFReSFu8y21y+ev09gsSMRRrjF7yt0pUHV6zncQhVeqsZtgc5WbELY2DOYUGmRn/CCvPbXovoBrQjSorqlBmpuPwsStYLr92Xn+VVsMNSUIegHY22DphGbDKG85vrKB8HxUxGIDxFBds/uE8FhSy+xsoyT/jUZDK6pgq2HnGl6D81ViIlKecpOpWlW3B+fea99ADNyZNVvDzbHE5pcI3VRw8u59WmpWOUgT6qacNVACl8GqpBvQk8sw7O/X9DSZHCKafeD9G5k+GYbAUz92fKWrx/lOXfUXPS3+c8dRIF

test1: use Docker Hub (via the registry-mirror)

works: > INFO[0013] [17/17] [local-registry]: Started

one observation is that the Started debug log line is printed after the service's image has been pulled and sucessfully "started" - this is not an indicator of the actual order :(

[SvenDowideit]

test2: use registry on my network using IP address

image: 10.10.10.23:5000/registry

and yup, same result - its 17/18

test3: use local registry with dns name

same.

so @janeczku - the issue, with the amount of detail reported, works here. I need more details.

[SvenDowideit]

mmm, after lunch I'm going to add the open-vm-tools bit - maybe there's something happening due to that. (mmm, and without a mirror)

[SvenDowideit]

even then, the (successfully pulled) local-registry is started after console.

So far, I'm thinking that none of the Starting and Started log output's tell us anything about actual start order - because the ordering is a loose cfg - if that container takes longer to start, the next will have already started.

Its worth changing your local registry from a hostname to an IP address to test if successful and fast pulling results in the order you expect...

At this point, this issue appears to be a continuation of the DHCP DNS setting problem - and hopefully not a libcompose issue. (but if you can give me more info...)

[SvenDowideit]

@forktheweb @janeczku the other thing is to set the DNS from our cmdline / os-config - as you obviously can't rely on your DHCP server to answer in a timely way.

[lynsei]

@SvenDowideit Jan and I were talking about this and because it's an intermittent issue we're wondering if there's any way we could possibly pass a parameter or something that would extend the DHCP timeout? Because I think what's happening is the DHCP container has a race condition and it's defaulting. This might be a stop-gap until we can find a better way to deal with it. Right now we can pass the DNS into the cloud-config but only for certain data centers, and because those change, this is only a temporary solution.

[SvenDowideit]

we've added the dhcpcd --wait option in 1.0.3, and so far, it seems to have resolve the ordering problem.

[SvenDowideit]

#1921 seems to make a huge difference to this issue.

I'll be backporting it to 1.0.4

[SvenDowideit]

the DHCP wait change in #2021 should fix the problem