RancherOS takes ages to boot after enabling kernel-extras service

RancherOS Version: v1.0.2

Where are you running RancherOS? openstack

Steps to reproduce:

Boot RancherOS based instance
Reboot just to check that boot time is normal.
sudo ros service enable kernel-extras
sudo ros service up kernel-extras
Reboot and have coffee meanwhile, you'll have plenty of time.
sudo ros service disable kernel-extras
Reboot and have another coffee, as boot time never will go back to normal values.

In my tests, boot time goes from 50s to 317s as observed in dmesg, which is completely unacceptable for our needs.

If the service is not "upped" before reboot, the effects won't be observed immediately but on subsequent reboots.

Before enabling kernel-extras service:

[    0.000000] Linux version 4.9.30-rancher (root@908de85bc32b) (gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.4) ) #1 SMP Thu May 25 21:38:11 UTC 2017
[    0.000000] Command line: BOOT_IMAGE=../vmlinuz-4.9.30-rancher printk.devkmsg=on rancher.state.dev=LABEL=RANCHER_STATE rancher.state.wait console=tty0 console=tty1 printk.devkmsg=on rancher.autologin=ttyS0 initrd=../initrd-v1.0.2
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000]   AMD AuthenticAMD
[    0.000000]   Centaur CentaurHauls
[    0.000000] x86/fpu: Legacy x87 FPU detected.
[    0.000000] x86/fpu: Using 'eager' FPU context switches.
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007ffdbfff] usable
[    0.000000] BIOS-e820: [mem 0x000000007ffdc000-0x000000007fffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.8 present.
[    0.000000] DMI: RDO OpenStack Compute, BIOS 1.9.1-5.el7_3.2 04/01/2014
[    0.000000] Hypervisor detected: KVM
[    0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000000] e820: last_pfn = 0x7ffdc max_arch_pfn = 0x400000000
[    0.000000] MTRR default type: write-back
[    0.000000] MTRR fixed ranges enabled:
[    0.000000]   00000-9FFFF write-back
[    0.000000]   A0000-BFFFF uncachable
[    0.000000]   C0000-FFFFF write-protect
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 080000000 mask F80000000 uncachable
[    0.000000]   1 disabled
[    0.000000]   2 disabled
[    0.000000]   3 disabled
[    0.000000]   4 disabled
[    0.000000]   5 disabled
[    0.000000]   6 disabled
[    0.000000]   7 disabled
[    0.000000] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
[    0.000000] found SMP MP-table at [mem 0x000f73d0-0x000f73df] mapped at [ffff8d69000f73d0]
[    0.000000] Scanning 1 areas for low memory corruption
[    0.000000] Base memory trampoline at [ffff8d6900099000] 99000 size 24576
[    0.000000] BRK [0x2801b000, 0x2801bfff] PGTABLE
[    0.000000] BRK [0x2801c000, 0x2801cfff] PGTABLE
[    0.000000] BRK [0x2801d000, 0x2801dfff] PGTABLE
[    0.000000] BRK [0x2801e000, 0x2801efff] PGTABLE
[    0.000000] BRK [0x2801f000, 0x2801ffff] PGTABLE
[    0.000000] BRK [0x28020000, 0x28020fff] PGTABLE
[    0.000000] RAMDISK: [mem 0x7dbc7000-0x7ffdbfff]
[    0.000000] ACPI: Early table checksum verification disabled
[    0.000000] ACPI: RSDP 0x00000000000F71A0 000014 (v00 BOCHS )
[    0.000000] ACPI: RSDT 0x000000007FFE181B 00002C (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: FACP 0x000000007FFE172F 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
[    0.000000] ACPI: DSDT 0x000000007FFE0040 0016EF (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: FACS 0x000000007FFE0000 000040
[    0.000000] ACPI: APIC 0x000000007FFE17A3 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000007ffdbfff]
[    0.000000] NODE_DATA(0) allocated [mem 0x7dbc2000-0x7dbc6fff]
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 0:7dbbe001, primary cpu clock
[    0.000000] kvm-clock: using sched offset of 123747103953 cycles
[    0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x000000007ffdbfff]
[    0.000000]   Normal   empty
[    0.000000]   Device   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000001000-0x000000000009efff]
[    0.000000]   node   0: [mem 0x0000000000100000-0x000000007ffdbfff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000007ffdbfff]
[    0.000000] On node 0 totalpages: 524154
[    0.000000]   DMA zone: 64 pages used for memmap
[    0.000000]   DMA zone: 21 pages reserved
[    0.000000]   DMA zone: 3998 pages, LIFO batch:0
[    0.000000]   DMA32 zone: 8128 pages used for memmap
[    0.000000]   DMA32 zone: 520156 pages, LIFO batch:31
[    0.000000] ACPI: PM-Timer IO Port: 0x608
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.000000] ACPI: IRQ0 used by override.
[    0.000000] ACPI: IRQ5 used by override.
[    0.000000] ACPI: IRQ9 used by override.
[    0.000000] ACPI: IRQ10 used by override.
[    0.000000] ACPI: IRQ11 used by override.
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
[    0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[    0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff]
[    0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[    0.000000] e820: [mem 0x80000000-0xfeffbfff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on KVM
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.000000] setup_percpu: NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:1 nr_node_ids:1
[    0.000000] percpu: Embedded 36 pages/cpu @ffff8d697d800000 s107928 r8192 d31336 u2097152
[    0.000000] pcpu-alloc: s107928 r8192 d31336 u2097152 alloc=1*2097152
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] KVM setup async PF for cpu 0
[    0.000000] kvm-stealtime: cpu 0, msr 7d80d900
[    0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 515941
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: BOOT_IMAGE=../vmlinuz-4.9.30-rancher printk.devkmsg=on rancher.state.dev=LABEL=RANCHER_STATE rancher.state.wait console=tty0 console=tty1 printk.devkmsg=on rancher.autologin=ttyS0 initrd=../initrd-v1.0.2
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Calgary: detecting Calgary via BIOS EBDA area
[    0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[    0.000000] Memory: 2010032K/2096616K available (7074K kernel code, 1454K rwdata, 3716K rodata, 1456K init, 1260K bss, 86584K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000]  Build-time adjustment of leaf fanout to 64.
[    0.000000]  RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=1.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
[    0.000000] NR_IRQS:16640 nr_irqs:256 16
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] tsc: Detected 2393.902 MHz processor
[    0.324961] Calibrating delay loop (skipped) preset value.. 4787.80 BogoMIPS (lpj=9575608)
[    0.328141] pid_max: default: 32768 minimum: 301
[    0.329761] ACPI: Core revision 20160831
[    0.334142] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.336083] Security Framework initialized
[    0.337643] Yama: becoming mindful.
[    0.339159] SELinux:  Initializing.
[    0.340771] SELinux:  Starting in permissive mode
[    0.340774] AppArmor: AppArmor disabled by boot time parameter
[    0.342705] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.346689] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.349513] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.351259] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.353861] mce: CPU supports 10 MCE banks
[    0.355560] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.357391] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[    0.382061] Freeing SMP alternatives memory: 20K (ffffffff9fed9000 - ffffffff9fede000)
[    0.387792] ftrace: allocating 34171 entries in 134 pages
[    0.445770] smpboot: Max logical packages: 1
[    0.447808] x2apic enabled
[    0.449704] Switched APIC routing to physical x2apic.
[    0.453203] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.454892] TSC deadline timer enabled
[    0.454898] smpboot: CPU0: Intel Westmere E56xx/L56xx/X56xx (Nehalem-C) (family: 0x6, model: 0x2c, stepping: 0x1)
[    0.458567] Performance Events: unsupported p6 CPU model 44 no PMU driver, software events only.
[    0.461923] KVM setup paravirtual spinlock
[    0.465430] x86: Booted up 1 node, 1 CPUs
[    0.467029] smpboot: Total of 1 processors activated (4787.80 BogoMIPS)
[    0.470053] devtmpfs: initialized
[    0.471757] x86/mm: Memory block size: 128MB
[    0.480462] evm: security.selinux
[    0.482027] evm: security.SMACK64
[    0.483653] evm: security.SMACK64EXEC
[    0.485271] evm: security.SMACK64TRANSMUTE
[    0.486920] evm: security.SMACK64MMAP
[    0.488482] evm: security.ima
[    0.489978] evm: security.capability
[    0.492161] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.495898] futex hash table entries: 256 (order: 2, 16384 bytes)
[    0.498064] pinctrl core: initialized pinctrl subsystem
[    0.500175] RTC time: 13:03:32, date: 06/15/17
[    0.502284] NET: Registered protocol family 16
[    0.504584] cpuidle: using governor ladder
[    0.506188] cpuidle: using governor menu
[    0.507758] PCCT header not found.
[    0.509570] ACPI: bus type PCI registered
[    0.511150] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.513123] PCI: Using configuration type 1 for base access
[    0.518526] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.520984] ACPI: Added _OSI(Module Device)
[    0.522553] ACPI: Added _OSI(Processor Device)
[    0.524110] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.525706] ACPI: Added _OSI(Processor Aggregator Device)
[    0.529336] ACPI: Interpreter enabled
[    0.530941] ACPI: (supports S0 S5)
[    0.532481] ACPI: Using IOAPIC for interrupt routing
[    0.534156] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.546346] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.548057] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
[    0.549796] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
[    0.551536] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[    0.555948] acpiphp: Slot [3] registered
[    0.557740] acpiphp: Slot [4] registered
[    0.559431] acpiphp: Slot [5] registered
[    0.561123] acpiphp: Slot [6] registered
[    0.562788] acpiphp: Slot [7] registered
[    0.564422] acpiphp: Slot [8] registered
[    0.566038] acpiphp: Slot [9] registered
[    0.567663] acpiphp: Slot [10] registered
[    0.569287] acpiphp: Slot [11] registered
[    0.570905] acpiphp: Slot [12] registered
[    0.572506] acpiphp: Slot [13] registered
[    0.574138] acpiphp: Slot [14] registered
[    0.575761] acpiphp: Slot [15] registered
[    0.577415] acpiphp: Slot [16] registered
[    0.579139] acpiphp: Slot [17] registered
[    0.580865] acpiphp: Slot [18] registered
[    0.582568] acpiphp: Slot [19] registered
[    0.584308] acpiphp: Slot [20] registered
[    0.585996] acpiphp: Slot [21] registered
[    0.587718] acpiphp: Slot [22] registered
[    0.589481] acpiphp: Slot [23] registered
[    0.591190] acpiphp: Slot [24] registered
[    0.627211] acpiphp: Slot [25] registered
[    0.628908] acpiphp: Slot [26] registered
[    0.630593] acpiphp: Slot [27] registered
[    0.632332] acpiphp: Slot [28] registered
[    0.634015] acpiphp: Slot [29] registered
[    0.635718] acpiphp: Slot [30] registered
[    0.637491] acpiphp: Slot [31] registered
[    0.639133] PCI host bridge to bus 0000:00
[    0.640740] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.642506] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.644249] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.647328] pci_bus 0000:00: root bus resource [mem 0x80000000-0xfebfffff window]
[    0.650342] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.652149] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[    0.653198] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[    0.654571] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180
[    0.667919] pci 0000:00:01.1: reg 0x20: [io  0xc0a0-0xc0af]
[    0.673828] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
[    0.675599] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
[    0.678247] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
[    0.679968] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
[    0.682478] pci 0000:00:01.2: [8086:7020] type 00 class 0x0c0300
[    0.694497] pci 0000:00:01.2: reg 0x20: [io  0xc040-0xc05f]
[    0.699530] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000
[    0.700458] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
[    0.704278] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
[    0.706650] pci 0000:00:02.0: [1013:00b8] type 00 class 0x030000
[    0.725968] pci 0000:00:02.0: reg 0x10: [mem 0xfc000000-0xfdffffff pref]
[    0.731506] pci 0000:00:02.0: reg 0x14: [mem 0xfebd0000-0xfebd0fff]
[    0.764822] pci 0000:00:02.0: reg 0x30: [mem 0xfebc0000-0xfebcffff pref]
[    0.766333] pci 0000:00:03.0: [1af4:1000] type 00 class 0x020000
[    0.774429] pci 0000:00:03.0: reg 0x10: [io  0xc060-0xc07f]
[    0.780440] pci 0000:00:03.0: reg 0x14: [mem 0xfebd1000-0xfebd1fff]
[    0.802850] pci 0000:00:03.0: reg 0x20: [mem 0xfe000000-0xfe003fff 64bit pref]
[    0.809050] pci 0000:00:03.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref]
[    0.811891] pci 0000:00:04.0: [1af4:1001] type 00 class 0x010000
[    0.818102] pci 0000:00:04.0: reg 0x10: [io  0xc000-0xc03f]
[    0.824365] pci 0000:00:04.0: reg 0x14: [mem 0xfebd2000-0xfebd2fff]
[    0.846837] pci 0000:00:04.0: reg 0x20: [mem 0xfe004000-0xfe007fff 64bit pref]
[    0.859150] pci 0000:00:05.0: [1af4:1002] type 00 class 0x00ff00
[    0.864644] pci 0000:00:05.0: reg 0x10: [io  0xc080-0xc09f]
[    0.886457] pci 0000:00:05.0: reg 0x20: [mem 0xfe008000-0xfe00bfff 64bit pref]
[    0.893666] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[    0.897612] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[    0.900234] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[    0.902894] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[    0.905624] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
[    0.908329] ACPI: Enabled 3 GPEs in block 00 to 0F
[    0.911252] vgaarb: setting as boot device: PCI:0000:00:02.0
[    0.912918] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[    0.916154] vgaarb: loaded
[    0.917664] vgaarb: bridge control possible 0000:00:02.0
[    0.920228] SCSI subsystem initialized
[    0.922169] libata version 3.00 loaded.
[    0.922271] ACPI: bus type USB registered
[    0.923943] usbcore: registered new interface driver usbfs
[    0.925909] usbcore: registered new interface driver hub
[    0.927605] usbcore: registered new device driver usb
[    0.929863] PCI: Using ACPI for IRQ routing
[    0.931456] PCI: pci_cache_line_size set to 64 bytes
[    0.931857] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[    0.931868] e820: reserve RAM buffer [mem 0x7ffdc000-0x7fffffff]
[    0.932919] NetLabel: Initializing
[    0.934838] NetLabel:  domain hash size = 128
[    0.936635] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.938335] NetLabel:  unlabeled traffic allowed by default
[    0.940767] clocksource: Switched to clocksource kvm-clock
[    0.988213] VFS: Disk quotas dquot_6.6.0
[    0.989908] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.994135] pnp: PnP ACPI init
[    0.995867] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.995969] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.996066] pnp 00:02: Plug and Play ACPI device, IDs PNP0f13 (active)
[    0.996091] pnp 00:03: [dma 2]
[    0.996158] pnp 00:03: Plug and Play ACPI device, IDs PNP0700 (active)
[    0.996395] pnp 00:04: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.996531] pnp 00:05: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.997317] pnp: PnP ACPI: found 6 devices
[    1.010240] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    1.013327] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    1.013331] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
[    1.013334] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[    1.013336] pci_bus 0000:00: resource 7 [mem 0x80000000-0xfebfffff window]
[    1.013536] NET: Registered protocol family 2
[    1.016155] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
[    1.020092] TCP bind hash table entries: 16384 (order: 6, 262144 bytes)
[    1.022057] TCP: Hash tables configured (established 16384 bind 16384)
[    1.023969] UDP hash table entries: 1024 (order: 3, 32768 bytes)
[    1.025723] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes)
[    1.027884] NET: Registered protocol family 1
[    1.029589] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    1.031287] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[    1.033025] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    1.113135] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
[    1.196850] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    1.199952] PCI: CLS 0 bytes, default 64
[    1.200215] Trying to unpack rootfs image as initramfs...
[   16.152684] Freeing initrd memory: 36948K (ffff8d697dbc7000 - ffff8d697ffdc000)
[   16.156995] Scanning for low memory corruption every 60 seconds
[   16.160080] audit: initializing netlink subsys (disabled)
[   16.162049] audit: type=2000 audit(1497531828.699:1): initialized
[   16.164956] Initialise system trusted keyrings
[   16.167169] workingset: timestamp_bits=40 max_order=19 bucket_order=0
[   16.174095] zbud: loaded
[   16.177066] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[   16.179810] fuse init (API version 7.26)
[   16.182269] SELinux:  Registering netfilter hooks
[   16.183840] Key type asymmetric registered
[   16.185723] Asymmetric key parser 'x509' registered
[   16.188012] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
[   16.191835] io scheduler noop registered
[   16.193747] io scheduler deadline registered
[   16.195979] io scheduler cfq registered (default)
[   16.198271] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[   16.200728] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[   16.203092] intel_idle: does not run on family 6 model 44
[   16.203284] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[   16.207294] ACPI: Power Button [PWRF]
[   16.209863] GHES: HEST is not enabled!
[   16.297482] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 10
[   16.464432] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
[   16.470537] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[   16.508386] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[   16.547242] 00:05: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[   16.554447] Linux agpgart interface v0.103
[   16.562553] brd: module loaded
[   16.567178] loop: module loaded
[   16.571811]  vda: vda1
[   16.574152] ata_piix 0000:00:01.1: version 2.13
[   16.576703] scsi host0: ata_piix
[   16.578715] scsi host1: ata_piix
[   16.580383] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14
[   16.582153] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15
[   16.585155] libphy: Fixed MDIO Bus: probed
[   16.586794] tun: Universal TUN/TAP device driver, 1.6
[   16.588410] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[   16.593275] PPP generic driver version 2.4.2
[   16.595057] VMware vmxnet3 virtual NIC driver - version 1.4.a.0-k-NAPI
[   16.597007] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[   16.598766] ehci-pci: EHCI PCI platform driver
[   16.600462] ehci-platform: EHCI generic platform driver
[   16.602265] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[   16.604031] ohci-pci: OHCI PCI platform driver
[   16.605801] ohci-platform: OHCI generic platform driver
[   16.607554] uhci_hcd: USB Universal Host Controller Interface driver
[   16.685300] uhci_hcd 0000:00:01.2: UHCI Host Controller
[   16.687775] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1
[   16.690907] uhci_hcd 0000:00:01.2: detected 2 ports
[   16.692809] uhci_hcd 0000:00:01.2: irq 11, io base 0x0000c040
[   16.696162] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001
[   16.698127] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[   16.702124] usb usb1: Product: UHCI Host Controller
[   16.704065] usb usb1: Manufacturer: Linux 4.9.30-rancher uhci_hcd
[   16.706039] usb usb1: SerialNumber: 0000:00:01.2
[   16.708439] hub 1-0:1.0: USB hub found
[   16.710406] hub 1-0:1.0: 2 ports detected
[   16.712982] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[   16.719047] serio: i8042 KBD port at 0x60,0x64 irq 1
[   16.720877] serio: i8042 AUX port at 0x60,0x64 irq 12
[   16.723324] mousedev: PS/2 mouse device common for all mice
[   16.726245] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[   16.730177] rtc_cmos 00:00: RTC can wake from S4
[   16.733437] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
[   16.735676] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram
[   16.737692] i2c /dev entries driver
[   16.739670] device-mapper: uevent: version 1.0.3
[   16.742517] ata1.01: NODEV after polling detection
[   16.743074] ata1.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
[   16.746215] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com
[   16.750336] ata1.00: configured for MWDMA2
[   16.752968] ledtrig-cpu: registered to indicate activity on CPUs
[   16.755742] scsi 0:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.5+ PQ: 0 ANSI: 5
[   16.761800] sr 0:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
[   16.763792] cdrom: Uniform CD-ROM driver Revision: 3.20
[   16.766441] NET: Registered protocol family 10
[   16.769386] NET: Registered protocol family 17
[   16.771337] 9pnet: Installing 9P2000 support
[   16.773752] sr 0:0:0:0: Attached scsi CD-ROM sr0
[   16.774021] sr 0:0:0:0: Attached scsi generic sg0 type 5
[   16.777265] Key type dns_resolver registered
[   16.779746] microcode: sig=0x206c1, pf=0x1, revision=0x1
[   16.781910] microcode: Microcode Update Driver: v2.01 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
[   16.785980] registered taskstats version 1
[   16.787890] Loading compiled-in X.509 certificates
[   16.793165] Loaded X.509 cert 'Build time autogenerated kernel key: f4430a0236c5170016e60217325314360b2a154d'
[   16.796891] zswap: loaded using pool lzo/zbud
[   16.800098] Key type trusted registered
[   16.804216] Key type encrypted registered
[   16.806236] ima: No TPM chip found, activating TPM-bypass!
[   16.808272] evm: HMAC attrs: 0x1
[   16.811251]   Magic number: 5:19:79
[   16.814330] rtc_cmos 00:00: setting system clock to 2017-06-15 13:03:49 UTC (1497531829)
[   16.818168] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found
[   16.820033] EDD information not available.
[   16.822021] PM: Hibernation image not present or could not be loaded.
[   16.827587] Freeing unused kernel memory: 1456K (ffffffff9fd6d000 - ffffffff9fed9000)
[   16.831050] Write protecting the kernel read-only data: 12288k
[   16.835222] Freeing unused kernel memory: 1104K (ffff8d69276ec000 - ffff8d6927800000)
[   16.842582] Freeing unused kernel memory: 380K (ffff8d6927ba1000 - ffff8d6927c00000)
[   17.056840] usb 1-1: new full-speed USB device number 2 using uhci_hcd
[   17.233662] usb 1-1: New USB device found, idVendor=0627, idProduct=0001
[   17.235842] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=5
[   17.237995] usb 1-1: Product: QEMU USB Tablet
[   17.239901] usb 1-1: Manufacturer: QEMU
[   17.241950] usb 1-1: SerialNumber: 42
[   17.808224] random: fast init done
[   18.114589] EXT4-fs (vda1): recovery complete
[   18.121192] EXT4-fs (vda1): mounted filesystem with ordered data mode. Opts: (null)
[   18.352072] time="2017-06-15T13:03:51Z" level=debug msg="START: [/usr/bin/system-docker daemon --host unix:///var/run/system-docker.sock --group root --restart=false --storage-driver overlay --bridge none --graph /var/lib/system-docker --userland-proxy=false] in /" 
[   26.001806] cgroup: docker-runc (186) created nested cgroup for controller "memory" which has incomplete hierarchy support. Nested cgroups may change behavior in the future.
[   26.006800] cgroup: "memory" requires setting use_hierarchy to 1 on the root
[   26.243562] time="2017-06-15T13:03:58Z" level=debug msg="START: [/usr/bin/ros entrypoint cloud-init-save] in /" 
[   26.333085] time="2017-06-15T13:03:59Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   26.384175] time="2017-06-15T13:03:59Z" level=debug msg="START: [cloud-init-save] in /" 
[   26.387963] time="2017-06-15T13:03:59Z" level=info msg="Running cloud-init-save" 
[   26.395168] udevd[213]: starting version 3.2
[   26.405157] udevd[214]: starting eudev-3.2
[   26.512115] hidraw: raw HID events driver (C) Jiri Kosina
[   26.521667] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0
[   26.577378] usbcore: registered new interface driver usbhid
[   26.579313] usbhid: USB HID core driver
[   26.593545] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4
[   26.600690] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3
[   26.695668] SSE version of gcm_enc/dec engaged.
[   26.752189] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input5
[   26.764672] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Pointer [QEMU QEMU USB Tablet] on usb-0000:00:01.2-1/input0
[   26.832398] time="2017-06-15T13:03:59Z" level=debug msg=SaveCloudConfig 
[   26.916731] time="2017-06-15T13:03:59Z" level=debug msg="init: SaveCloudConfig(pre ApplyNetworkConfig): netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig(nil), PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[   26.925184] time="2017-06-15T13:03:59Z" level=info msg="Apply Network Config" 
[   26.928882] time="2017-06-15T13:03:59Z" 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:\"\"}" 
[   26.948967] time="2017-06-15T13:03:59Z" level=info msg="Applying 127.0.0.1/8 to lo" 
[   26.952530] time="2017-06-15T13:03:59Z" level=info msg="Applying ::1/128 to lo" 
[   26.956184] time="2017-06-15T13:03:59Z" level=info msg="Apply Network Config RunDhcp" 
[   26.959703] time="2017-06-15T13:03:59Z" level=debug msg=RunDhcp 
[   26.962041] time="2017-06-15T13:03:59Z" level=info msg="Running DHCP on eth0: dhcpcd -MA4 -e force_hostname=true eth0" 
[   27.148611] time="2017-06-15T13:03:59Z" level=info msg="Apply Network Config SyncHostname" 
[   27.153060] time="2017-06-15T13:03:59Z" level=debug msg="datasources that will be consided: []string{\"configdrive:/media/config-2\"}" 
[   27.157041] time="2017-06-15T13:03:59Z" level=info msg="cloud-init: Checking availability of \"cloud-drive\"\n" 
[   27.191514] ISO 9660 Extensions: Microsoft Joliet Level 3
[   27.197128] ISO 9660 Extensions: RRIP_1991A
[   27.198630] time="2017-06-15T13:03:59Z" level=info msg="cloud-init: Datasource available: cloud-drive: /media/config-2" 
[   27.202342] time="2017-06-15T13:03:59Z" level=info msg="Fetching user-data from datasource cloud-drive: /media/config-2" 
[   27.226114] ISO 9660 Extensions: Microsoft Joliet Level 3
[   27.228375] ISO 9660 Extensions: RRIP_1991A
[   27.228589] time="2017-06-15T13:03:59Z" level=debug msg="Attempting to read from \"/media/config-2/openstack/latest/user_data\"\n" 
[   27.235457] time="2017-06-15T13:03:59Z" level=info msg="Fetching meta-data from datasource of type cloud-drive" 
[   27.259244] ISO 9660 Extensions: Microsoft Joliet Level 3
[   27.260978] ISO 9660 Extensions: RRIP_1991A
[   27.261186] time="2017-06-15T13:03:59Z" level=debug msg="Attempting to read from \"/media/config-2/openstack/latest/meta_data.json\"\n" 
[   27.268893] time="2017-06-15T13:03:59Z" level=error msg="Unrecognized user-data\n()" 
[   27.273687] time="2017-06-15T13:03:59Z" level=info msg="Wrote to /var/lib/rancher/conf/metadata" 
[   27.278195] time="2017-06-15T13:03:59Z" level=info msg="Wrote to /var/lib/rancher/conf/cloud-config.d/network.yml" 
[   27.359530] time="2017-06-15T13:04:00Z" level=debug msg="init: SaveCloudConfig(post ApplyNetworkConfig): netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig(nil), PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[   27.368012] time="2017-06-15T13:04:00Z" level=info msg="Apply Network Config" 
[   27.374798] time="2017-06-15T13:04:00Z" level=debug msg="Config: &netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig{\"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:\"\"}, \"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:\"\"}}, PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[   27.394653] time="2017-06-15T13:04:00Z" level=info msg="Applying 127.0.0.1/8 to lo" 
[   27.398146] time="2017-06-15T13:04:00Z" level=info msg="Applying ::1/128 to lo" 
[   27.401832] time="2017-06-15T13:04:00Z" level=info msg="Apply Network Config RunDhcp" 
[   27.405279] time="2017-06-15T13:04:00Z" level=debug msg=RunDhcp 
[   27.407529] time="2017-06-15T13:04:00Z" level=info msg="Running DHCP on eth0: dhcpcd -MA4 eth0" 
[   27.417110] time="2017-06-15T13:04:00Z" level=info msg="Apply Network Config SyncHostname" 
[   28.477127] time="2017-06-15T13:04:01Z" level=debug msg="START: [system-docker daemon --log-opt max-file=2 --log-opt max-size=25m --restart=false --userland-proxy=false --group root --graph /var/lib/system-docker --storage-driver overlay --config-file /etc/docker/system-docker.json --exec-root /var/run/system-docker --host unix:///var/run/system-docker.sock --pidfile /var/run/system-docker.pid] in /" 
[   28.491514] DEBU[0000] START: [/usr/bin/ros-sysinit] in /           
[   28.695757] INFO[0000] [1/4] Starting loadImages                    
[   28.700468] DEBU[0000] Looking for images at /usr/share/ros         
[   28.704502] DEBU[0000] Found images.tar                             
[   28.978005] INFO[0000] Loading images from /usr/share/ros/images.tar 
[   31.756324] INFO[0003] Done loading images from /usr/share/ros/images.tar 
[   31.760101] DEBU[0003] [1/4] Done loadImages                        
[   31.764416] INFO[0003] [2/4] Starting start project                 
[   31.889335] INFO[0003] Project [os]: Starting project               
[   31.891296] DEBU[0003] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   31.936468] DEBU[0003] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   31.943941] DEBU[0003] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   32.063796] INFO[0003] [0/16] [command-volumes]: Starting           
[   32.118918] INFO[0003] [0/16] [system-volumes]: Starting            
[   32.212443] INFO[0003] [0/16] [user-volumes]: Starting              
[   32.280363] INFO[0004] [0/16] [media-volumes]: Starting             
[   32.284088] INFO[0004] [0/16] [container-data-volumes]: Starting    
[   32.318486] DEBU[0004] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.345706] INFO[0004] [1/16] [command-volumes]: Started            
[   32.753426] DEBU[0004] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.773363] INFO[0004] [2/16] [system-volumes]: Started             
[   32.777037] INFO[0004] [2/16] [acpid]: Starting                     
[   32.782570] INFO[0004] [2/16] [udev-cold]: Starting                 
[   32.786336] INFO[0004] [2/16] [syslog]: Starting                    
[   32.823337] DEBU[0004] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.834306] INFO[0004] [3/16] [user-volumes]: Started               
[   32.882368] DEBU[0004] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.887732] DEBU[0004] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.915219] INFO[0004] [4/16] [container-data-volumes]: Started     
[   32.919220] INFO[0004] [5/16] [media-volumes]: Started              
[   32.923768] INFO[0004] [5/16] [all-volumes]: Starting               
[   33.249985] DEBU[0004] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   33.301023] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   33.318770] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   34.050829] INFO[0005] [6/16] [syslog]: Started                     
[   34.154670] INFO[0005] [7/16] [acpid]: Started                      
[   34.178092] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   34.197057] INFO[0005] [8/16] [all-volumes]: Started                
[   34.199449] time="2017-06-15T13:04:06Z" level=debug msg="START: [/usr/bin/ros entrypoint rsyslogd -n] in /" 
[   34.356293] time="2017-06-15T13:04:07Z" level=debug msg="START: [/usr/bin/ros entrypoint /usr/sbin/acpid -f] in /" 
[   34.842916] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   34.857220] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   34.868076] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   34.881273] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   34.893148] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   34.903250] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   34.911063] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   34.915293] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   34.922575] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   34.929091] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   34.940157] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   34.948142] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   34.959940] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   34.973160] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   34.986286] time="2017-06-15T13:04:07Z" level=debug msg="START: [/usr/bin/ros entrypoint ros udev-settle] in /" 
[   35.110221] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   35.114005] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   35.117707] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   35.121230] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   35.124693] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   35.129078] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   35.132617] time="2017-06-15T13:04:07Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   35.183824] time="2017-06-15T13:04:07Z" level=debug msg="START: [ros udev-settle] in /" 
[   35.202209] udevd[14]: starting version 3.2
[   35.228412] udevd[17]: starting eudev-3.2
[   35.780437] INFO[0007] [9/16] [udev-cold]: Started                  
[   35.791086] INFO[0007] [9/16] [udev]: Starting                      
[   35.933487] DEBU[0007] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   36.264966] INFO[0008] [10/16] [udev]: Started                      
[   36.275637] INFO[0008] [10/16] [network]: Starting                  
[   36.372830] time="2017-06-15T13:04:09Z" level=debug msg="START: [/usr/bin/ros entrypoint udevd] in /" 
[   36.533329] DEBU[0008] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   36.625541] time="2017-06-15T13:04:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   36.633291] time="2017-06-15T13:04:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   36.640308] time="2017-06-15T13:04:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   36.649183] time="2017-06-15T13:04:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   36.653306] time="2017-06-15T13:04:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   36.662283] time="2017-06-15T13:04:09Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   36.668651] time="2017-06-15T13:04:09Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   36.690862] udevd[1]: starting version 3.2
[   36.707653] udevd[1]: starting eudev-3.2
[   36.950226] INFO[0008] [11/16] [network]: Started                   
[   37.050341] time="2017-06-15T13:04:09Z" level=debug msg="START: [/usr/bin/ros entrypoint netconf] in /" 
[   37.177005] DEBU[0008] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   37.183061] DEBU[0008] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   37.188969] DEBU[0008] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   37.302047] INFO[0009] [11/16] [ntp]: Starting                      
[   37.400659] time="2017-06-15T13:04:10Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   37.409270] time="2017-06-15T13:04:10Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   37.419588] time="2017-06-15T13:04:10Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   37.423240] time="2017-06-15T13:04:10Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   37.437345] time="2017-06-15T13:04:10Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   37.445155] time="2017-06-15T13:04:10Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   37.451681] time="2017-06-15T13:04:10Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   37.555803] time="2017-06-15T13:04:10Z" level=debug msg="START: [netconf] in /" 
[   37.569987] DEBU[0009] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   37.875141] time="2017-06-15T13:04:10Z" level=info msg="Apply Network Config" 
[   37.885612] time="2017-06-15T13:04:10Z" level=debug msg="Config: &netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig{\"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:\"\"}, \"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:\"\"}}, PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[   37.951151] time="2017-06-15T13:04:10Z" level=info msg="Applying 127.0.0.1/8 to lo" 
[   37.959673] time="2017-06-15T13:04:10Z" level=info msg="Applying ::1/128 to lo" 
[   37.967514] time="2017-06-15T13:04:10Z" level=info msg="Apply Network Config RunDhcp" 
[   37.976593] time="2017-06-15T13:04:10Z" level=debug msg=RunDhcp 
[   37.980953] time="2017-06-15T13:04:10Z" level=info msg="Running DHCP on eth0: dhcpcd -MA4 eth0" 
[   38.219982] INFO[0009] [12/16] [ntp]: Started                       
[   38.238244] INFO[0009] [12/16] [cloud-init-execute]: Starting       
[   38.323203] time="2017-06-15T13:04:11Z" level=debug msg="START: [/usr/bin/ros entrypoint ntpd --nofork -g] in /" 
[   38.474852] DEBU[0010] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   38.581629] time="2017-06-15T13:04:11Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   38.588039] time="2017-06-15T13:04:11Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   38.597543] time="2017-06-15T13:04:11Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   38.607192] time="2017-06-15T13:04:11Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   38.614041] time="2017-06-15T13:04:11Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   38.622413] time="2017-06-15T13:04:11Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   38.633168] time="2017-06-15T13:04:11Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   38.919687] time="2017-06-15T13:04:11Z" level=info msg="Apply Network Config SyncHostname" 
[   38.933147] time="2017-06-15T13:04:11Z" level=info msg="Restart syslog" 
[   39.115336] time="2017-06-15T13:04:11Z" level=debug msg="START: [/usr/bin/ros entrypoint cloud-init-execute -pre-console] in /" 
[   39.650417] time="2017-06-15T13:04:12Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   39.657523] time="2017-06-15T13:04:12Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   39.669154] time="2017-06-15T13:04:12Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   39.680682] time="2017-06-15T13:04:12Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   39.690579] time="2017-06-15T13:04:12Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   39.701187] time="2017-06-15T13:04:12Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   39.711423] time="2017-06-15T13:04:12Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   39.828453] time="2017-06-15T13:04:12Z" level=debug msg="START: [cloud-init-execute -pre-console] in /" 
[   39.833045] time="2017-06-15T13:04:12Z" level=info msg="Running cloud-init-execute: pre-console=true, console=false" 
[   40.005042] time="2017-06-15T13:04:12Z" level=debug msg="START: [/usr/bin/ros entrypoint rsyslogd -n] in /" 
[   40.162446] time="2017-06-15T13:04:13Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   40.166021] time="2017-06-15T13:04:13Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   40.170673] time="2017-06-15T13:04:13Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   40.193133] time="2017-06-15T13:04:13Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   40.213007] time="2017-06-15T13:04:13Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   40.216271] time="2017-06-15T13:04:13Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   40.234222] time="2017-06-15T13:04:13Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   40.453655] INFO[0012] [13/16] [cloud-init-execute]: Started        
[   40.463615] INFO[0012] [13/16] [console]: Starting                  
[   40.581912] DEBU[0012] Rebuild values                                newRebuildLabel=always origRebuildLabel=always outOfSync=false rebuildLabelChanged=false
[   40.589007] INFO[0012] Rebuilding console                           
[   40.974498] INFO[0012] [14/16] [console]: Started                   
[   40.984502] INFO[0012] [14/16] [docker]: Starting                   
[   41.008732] INFO[0012] [14/16] [preload-user-images]: Starting      
[   41.078304] time="2017-06-15T13:04:14Z" level=debug msg="START: [/usr/bin/ros entrypoint ros console-init] in /" 
[   41.419780] time="2017-06-15T13:04:14Z" level=debug msg="START: [ros console-init] in /" 
[   41.473175] DEBU[0013] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   41.499558] DEBU[0013] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   42.140342] time="2017-06-15T13:04:15Z" level=debug msg="START: [respawn -f /etc/respawn.conf] in /" 
[   42.425629] INFO[0014] [15/16] [docker]: Started                    
[   42.463057] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[   42.524548] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   42.534901] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   42.535496] docker-sys: port 1(veth831d049e) entered blocking state
[   42.535498] docker-sys: port 1(veth831d049e) entered disabled state
[   42.535682] device veth831d049e entered promiscuous mode
[   42.535788] docker-sys: port 1(veth831d049e) entered blocking state
[   42.535790] docker-sys: port 1(veth831d049e) entered forwarding state
[   42.588893] IPv6: eth0: IPv6 duplicate address fe80::e43e:22ff:fedd:1b24 detected!
[   42.634073] time="2017-06-15T13:04:15Z" level=debug msg="START: [ros user-docker] in /" 
[   42.899566] ip_tables: (C) 2000-2006 Netfilter Core Team
[   42.967187] nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
[   43.323353] time="2017-06-15T13:04:16Z" level=debug msg="START: [/usr/bin/ros entrypoint ros preload-images] in /" 
[   43.510102] time="2017-06-15T13:04:16Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   43.510454] time="2017-06-15T13:04:16Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   43.510782] time="2017-06-15T13:04:16Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   43.511187] time="2017-06-15T13:04:16Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   43.511537] time="2017-06-15T13:04:16Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   43.511872] time="2017-06-15T13:04:16Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   43.512277] time="2017-06-15T13:04:16Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   43.643835] time="2017-06-15T13:04:16Z" level=debug msg="START: [ros preload-images] in /" 
[   43.647146] docker-sys: port 1(veth831d049e) entered disabled state
[   43.647566] device veth831d049e left promiscuous mode
[   43.647572] docker-sys: port 1(veth831d049e) entered disabled state
[   44.351778] INFO[0016] [16/16] [preload-user-images]: Started       
[   44.352498] INFO[0016] Project [os]: Project started                
[   44.353034] DEBU[0016] [2/4] Done start project                     
[   44.353843] INFO[0016] [3/4] Starting sync                          
[   44.485609] DEBU[0016] [3/4] Done sync                              
[   44.487026] INFO[0016] [4/4] Starting banner                        
[   44.499980] INFO[0016] RancherOS v1.0.2 started                     
[   44.500062] DEBU[0016] [4/4] Done banner                            
[   47.498172] time="2017-06-15T13:04:20Z" level=info msg="Starting Docker in context: console" 
[   47.722605] time="2017-06-15T13:04:20Z" level=info msg="Getting PID for service: console" 
[   47.852062] time="2017-06-15T13:04:20Z" level=info msg="console PID 691" 
[   47.953029] time="2017-06-15T13:04:20Z" level=debug msg="User Docker args: [daemon --host unix:///var/run/docker.sock --group docker --storage-driver overlay --log-opt max-file=2 --log-opt max-size=25m]" 
[   47.959331] time="2017-06-15T13:04:20Z" level=info msg="[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin HOSTNAME=test.novalocal HOME=/]" 
[   47.960414] time="2017-06-15T13:04:20Z" level=info msg="Running [docker-runc exec -- e01f1033736cc55f2701ff2a54404d7a6df9329144115634d65aed0cb3d5bc55 env PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin HOSTNAME=test.novalocal HOME=/ ros docker-init daemon --host unix:///var/run/docker.sock --group docker --storage-driver overlay --log-opt max-file=2 --log-opt max-size=25m]" 
[   48.163175] time="2017-06-15T13:04:21Z" level=debug msg="START: [ros docker-init daemon --host unix:///var/run/docker.sock --group docker --storage-driver overlay --log-opt max-file=2 --log-opt max-size=25m] in /" 
[   48.364040] time="2017-06-15T13:04:21Z" level=debug msg="START: [/usr/bin/dockerlaunch /usr/bin/docker daemon --host unix:///var/run/docker.sock --group docker --storage-driver overlay --log-opt max-file=2 --log-opt max-size=25m] in /" 
[   48.364212] time="2017-06-15T13:04:21Z" level=debug msg="Launch config dfs.Config{Fork:false, PidOne:false, CommandName:\"\", DNSConfig:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, BridgeName:\"\", BridgeAddress:\"\", BridgeMtu:0, CgroupHierarchy:map[string]string(nil), LogFile:\"\", NoLog:false, NoFiles:0x0, Environment:[]string(nil), GraphDirectory:\"\", DaemonConfig:\"\"}" 
[   48.364271] time="2017-06-15T13:04:21Z" level=debug msg="Mounting devtmpfs /dev devtmpfs " 
[   48.366618] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /dev/pts devpts " 
[   48.368967] time="2017-06-15T13:04:21Z" level=debug msg="Mounting shm /dev/shm tmpfs rw,nosuid,nodev,noexec,relatime,size=65536k" 
[   48.370999] time="2017-06-15T13:04:21Z" level=debug msg="Mounting mqueue /dev/mqueue mqueue rw,nosuid,nodev,noexec,relatime" 
[   48.373130] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /proc proc " 
[   48.375198] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /run tmpfs " 
[   48.377296] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys sysfs " 
[   48.379784] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup tmpfs " 
[   48.382001] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/selinux selinuxfs ro" 
[   48.384203] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: #subsys_name\thierarchy\tnum_cgroups\tenabled" 
[   48.384248] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: cpuset\t8\t9\t1" 
[   48.384313] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: cpu\t9\t9\t1" 
[   48.384355] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: cpuacct\t9\t9\t1" 
[   48.384417] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: blkio\t10\t9\t1" 
[   48.384462] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: memory\t2\t14\t1" 
[   48.384502] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: devices\t3\t9\t1" 
[   48.384557] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: freezer\t4\t9\t1" 
[   48.384598] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: net_cls\t1\t9\t1" 
[   48.384650] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: perf_event\t5\t9\t1" 
[   48.384691] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: net_prio\t1\t9\t1" 
[   48.384732] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: hugetlb\t6\t9\t1" 
[   48.384930] time="2017-06-15T13:04:21Z" level=debug msg="/proc/cgroups: pids\t7\t9\t1" 
[   48.385022] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/perf_event cgroup perf_event" 
[   48.387061] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/hugetlb cgroup hugetlb" 
[   48.389361] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/pids cgroup pids" 
[   48.391393] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/cpu,cpuacct cgroup cpu,cpuacct" 
[   48.393669] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/blkio cgroup blkio" 
[   48.395753] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/memory cgroup memory" 
[   48.398014] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/devices cgroup devices" 
[   48.400221] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/freezer cgroup freezer" 
[   48.402351] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/cpuset cgroup cpuset" 
[   48.404414] time="2017-06-15T13:04:21Z" level=debug msg="Mounting none /sys/fs/cgroup/net_cls,net_prio cgroup net_cls,net_prio" 
[   48.406577] time="2017-06-15T13:04:21Z" level=debug msg="Done mouting cgroupfs" 
[   48.406758] time="2017-06-15T13:04:21Z" level=debug msg="Creating /root/.ssh" 
[   48.407387] time="2017-06-15T13:04:21Z" level=debug msg="Not copying /usr/etc/ssl/certs/ca-certificates.crt, does not exists" 
[   48.407443] time="2017-06-15T13:04:21Z" level=debug msg="Not copying /usr/etc/passwd, does not exists" 
[   48.407493] time="2017-06-15T13:04:21Z" level=debug msg="Not copying /usr/etc/group, does not exists" 
[   48.407590] time="2017-06-15T13:04:21Z" level=debug msg="Copying folder /etc/docker" 
[   48.407650] time="2017-06-15T13:04:21Z" level=debug msg="Copying folder /etc/selinux" 
[   48.407701] time="2017-06-15T13:04:21Z" level=debug msg="Copying folder /etc/selinux/ros" 
[   48.407754] time="2017-06-15T13:04:21Z" level=debug msg="Copying folder /etc/selinux/ros/policy" 
[   48.407829] time="2017-06-15T13:04:21Z" level=debug msg="Copying folder /etc/selinux/ros/contexts" 
[   48.407902] time="2017-06-15T13:04:21Z" level=debug msg="Copying folder /var/lib/cni" 
[   48.408567] time="2017-06-15T13:04:21Z" level=debug msg="Launching Docker /usr/bin/docker docker [daemon --host unix:///var/run/docker.sock --group docker --storage-driver overlay --log-opt max-file=2 --log-opt max-size=25m]" 
[   49.701457] Bridge firewalling registered
[   49.926962] Initializing XFRM netlink socket
[   50.024235] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready

After enabling kernel-extras service:

[    0.000000] Linux version 4.9.30-rancher (root@908de85bc32b) (gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1~16.04.4) ) #1 SMP Thu May 25 21:38:11 UTC 2017
[    0.000000] Command line: BOOT_IMAGE=../vmlinuz-4.9.30-rancher printk.devkmsg=on rancher.state.dev=LABEL=RANCHER_STATE rancher.state.wait console=tty0 console=tty1 printk.devkmsg=on rancher.autologin=ttyS0 initrd=../initrd-v1.0.2
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000]   AMD AuthenticAMD
[    0.000000]   Centaur CentaurHauls
[    0.000000] x86/fpu: Legacy x87 FPU detected.
[    0.000000] x86/fpu: Using 'eager' FPU context switches.
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000007ffdbfff] usable
[    0.000000] BIOS-e820: [mem 0x000000007ffdc000-0x000000007fffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.8 present.
[    0.000000] DMI: RDO OpenStack Compute, BIOS 1.9.1-5.el7_3.2 04/01/2014
[    0.000000] Hypervisor detected: KVM
[    0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000000] e820: last_pfn = 0x7ffdc max_arch_pfn = 0x400000000
[    0.000000] MTRR default type: write-back
[    0.000000] MTRR fixed ranges enabled:
[    0.000000]   00000-9FFFF write-back
[    0.000000]   A0000-BFFFF uncachable
[    0.000000]   C0000-FFFFF write-protect
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 080000000 mask F80000000 uncachable
[    0.000000]   1 disabled
[    0.000000]   2 disabled
[    0.000000]   3 disabled
[    0.000000]   4 disabled
[    0.000000]   5 disabled
[    0.000000]   6 disabled
[    0.000000]   7 disabled
[    0.000000] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
[    0.000000] found SMP MP-table at [mem 0x000f73d0-0x000f73df] mapped at [ffff902c000f73d0]
[    0.000000] Scanning 1 areas for low memory corruption
[    0.000000] Base memory trampoline at [ffff902c00099000] 99000 size 24576
[    0.000000] BRK [0x7601b000, 0x7601bfff] PGTABLE
[    0.000000] BRK [0x7601c000, 0x7601cfff] PGTABLE
[    0.000000] BRK [0x7601d000, 0x7601dfff] PGTABLE
[    0.000000] BRK [0x7601e000, 0x7601efff] PGTABLE
[    0.000000] BRK [0x7601f000, 0x7601ffff] PGTABLE
[    0.000000] BRK [0x76020000, 0x76020fff] PGTABLE
[    0.000000] RAMDISK: [mem 0x7dbc7000-0x7ffdbfff]
[    0.000000] ACPI: Early table checksum verification disabled
[    0.000000] ACPI: RSDP 0x00000000000F71A0 000014 (v00 BOCHS )
[    0.000000] ACPI: RSDT 0x000000007FFE181B 00002C (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: FACP 0x000000007FFE172F 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
[    0.000000] ACPI: DSDT 0x000000007FFE0040 0016EF (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: FACS 0x000000007FFE0000 000040
[    0.000000] ACPI: APIC 0x000000007FFE17A3 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000007ffdbfff]
[    0.000000] NODE_DATA(0) allocated [mem 0x7dbc2000-0x7dbc6fff]
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 0:7dbbe001, primary cpu clock
[    0.000000] kvm-clock: using sched offset of 1258221530123 cycles
[    0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x000000007ffdbfff]
[    0.000000]   Normal   empty
[    0.000000]   Device   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000001000-0x000000000009efff]
[    0.000000]   node   0: [mem 0x0000000000100000-0x000000007ffdbfff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000007ffdbfff]
[    0.000000] On node 0 totalpages: 524154
[    0.000000]   DMA zone: 64 pages used for memmap
[    0.000000]   DMA zone: 21 pages reserved
[    0.000000]   DMA zone: 3998 pages, LIFO batch:0
[    0.000000]   DMA32 zone: 8128 pages used for memmap
[    0.000000]   DMA32 zone: 520156 pages, LIFO batch:31
[    0.000000] ACPI: PM-Timer IO Port: 0x608
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.000000] ACPI: IRQ0 used by override.
[    0.000000] ACPI: IRQ5 used by override.
[    0.000000] ACPI: IRQ9 used by override.
[    0.000000] ACPI: IRQ10 used by override.
[    0.000000] ACPI: IRQ11 used by override.
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
[    0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[    0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff]
[    0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[    0.000000] e820: [mem 0x80000000-0xfeffbfff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on KVM
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.000000] setup_percpu: NR_CPUS:256 nr_cpumask_bits:256 nr_cpu_ids:1 nr_node_ids:1
[    0.000000] percpu: Embedded 36 pages/cpu @ffff902c7d800000 s107928 r8192 d31336 u2097152
[    0.000000] pcpu-alloc: s107928 r8192 d31336 u2097152 alloc=1*2097152
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] KVM setup async PF for cpu 0
[    0.000000] kvm-stealtime: cpu 0, msr 7d80d900
[    0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 515941
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: BOOT_IMAGE=../vmlinuz-4.9.30-rancher printk.devkmsg=on rancher.state.dev=LABEL=RANCHER_STATE rancher.state.wait console=tty0 console=tty1 printk.devkmsg=on rancher.autologin=ttyS0 initrd=../initrd-v1.0.2
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Calgary: detecting Calgary via BIOS EBDA area
[    0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[    0.000000] Memory: 2010032K/2096616K available (7074K kernel code, 1454K rwdata, 3716K rodata, 1456K init, 1260K bss, 86584K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000]  Build-time adjustment of leaf fanout to 64.
[    0.000000]  RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=1.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
[    0.000000] NR_IRQS:16640 nr_irqs:256 16
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] tsc: Detected 2393.902 MHz processor
[    0.307972] Calibrating delay loop (skipped) preset value.. 4787.80 BogoMIPS (lpj=9575608)
[    0.311272] pid_max: default: 32768 minimum: 301
[    0.312891] ACPI: Core revision 20160831
[    0.317311] ACPI: 1 ACPI AML tables successfully acquired and loaded
[    0.319396] Security Framework initialized
[    0.322304] Yama: becoming mindful.
[    0.323892] SELinux:  Initializing.
[    0.325431] SELinux:  Starting in permissive mode
[    0.325435] AppArmor: AppArmor disabled by boot time parameter
[    0.327428] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.331511] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.334926] Mount-cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.336622] Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes)
[    0.339382] mce: CPU supports 10 MCE banks
[    0.341021] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
[    0.342673] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
[    0.366696] Freeing SMP alternatives memory: 20K (ffffffff8ded9000 - ffffffff8dede000)
[    0.372589] ftrace: allocating 34171 entries in 134 pages
[    0.431385] smpboot: Max logical packages: 1
[    0.433439] x2apic enabled
[    0.435370] Switched APIC routing to physical x2apic.
[    0.438854] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.440712] TSC deadline timer enabled
[    0.440719] smpboot: CPU0: Intel Westmere E56xx/L56xx/X56xx (Nehalem-C) (family: 0x6, model: 0x2c, stepping: 0x1)
[    0.444397] Performance Events: unsupported p6 CPU model 44 no PMU driver, software events only.
[    0.447806] KVM setup paravirtual spinlock
[    0.451186] x86: Booted up 1 node, 1 CPUs
[    0.452777] smpboot: Total of 1 processors activated (4787.80 BogoMIPS)
[    0.455410] devtmpfs: initialized
[    0.457092] x86/mm: Memory block size: 128MB
[    0.466303] evm: security.selinux
[    0.467875] evm: security.SMACK64
[    0.469384] evm: security.SMACK64EXEC
[    0.470906] evm: security.SMACK64TRANSMUTE
[    0.472678] evm: security.SMACK64MMAP
[    0.474196] evm: security.ima
[    0.475689] evm: security.capability
[    0.477626] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.480640] futex hash table entries: 256 (order: 2, 16384 bytes)
[    0.482559] pinctrl core: initialized pinctrl subsystem
[    0.484586] RTC time: 13:22:27, date: 06/15/17
[    0.486443] NET: Registered protocol family 16
[    0.488711] cpuidle: using governor ladder
[    0.490263] cpuidle: using governor menu
[    0.492002] PCCT header not found.
[    0.493773] ACPI: bus type PCI registered
[    0.495310] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.497292] PCI: Using configuration type 1 for base access
[    0.502864] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    0.505306] ACPI: Added _OSI(Module Device)
[    0.506872] ACPI: Added _OSI(Processor Device)
[    0.508432] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.510025] ACPI: Added _OSI(Processor Aggregator Device)
[    0.513816] ACPI: Interpreter enabled
[    0.515412] ACPI: (supports S0 S5)
[    0.516928] ACPI: Using IOAPIC for interrupt routing
[    0.518551] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.529301] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.530985] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
[    0.532853] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
[    0.534520] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[    0.538551] acpiphp: Slot [3] registered
[    0.540136] acpiphp: Slot [4] registered
[    0.541752] acpiphp: Slot [5] registered
[    0.543473] acpiphp: Slot [6] registered
[    0.545059] acpiphp: Slot [7] registered
[    0.546678] acpiphp: Slot [8] registered
[    0.548281] acpiphp: Slot [9] registered
[    0.549869] acpiphp: Slot [10] registered
[    0.551477] acpiphp: Slot [11] registered
[    0.553205] acpiphp: Slot [12] registered
[    0.554800] acpiphp: Slot [13] registered
[    0.556413] acpiphp: Slot [14] registered
[    0.558003] acpiphp: Slot [15] registered
[    0.559609] acpiphp: Slot [16] registered
[    0.561226] acpiphp: Slot [17] registered
[    0.563071] acpiphp: Slot [18] registered
[    0.564670] acpiphp: Slot [19] registered
[    0.566292] acpiphp: Slot [20] registered
[    0.567883] acpiphp: Slot [21] registered
[    0.569479] acpiphp: Slot [22] registered
[    0.571107] acpiphp: Slot [23] registered
[    0.572892] acpiphp: Slot [24] registered
[    0.608155] acpiphp: Slot [25] registered
[    0.609753] acpiphp: Slot [26] registered
[    0.611369] acpiphp: Slot [27] registered
[    0.613022] acpiphp: Slot [28] registered
[    0.614806] acpiphp: Slot [29] registered
[    0.616418] acpiphp: Slot [30] registered
[    0.618047] acpiphp: Slot [31] registered
[    0.619621] PCI host bridge to bus 0000:00
[    0.621169] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.622883] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.624711] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.627647] pci_bus 0000:00: root bus resource [mem 0x80000000-0xfebfffff window]
[    0.630565] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.632326] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000
[    0.633316] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100
[    0.634736] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180
[    0.647728] pci 0000:00:01.1: reg 0x20: [io  0xc0a0-0xc0af]
[    0.652021] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
[    0.654314] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
[    0.655994] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
[    0.657670] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
[    0.660522] pci 0000:00:01.2: [8086:7020] type 00 class 0x0c0300
[    0.672595] pci 0000:00:01.2: reg 0x20: [io  0xc040-0xc05f]
[    0.678013] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000
[    0.678901] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
[    0.682960] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
[    0.685262] pci 0000:00:02.0: [1013:00b8] type 00 class 0x030000
[    0.698601] pci 0000:00:02.0: reg 0x10: [mem 0xfc000000-0xfdffffff pref]
[    0.704978] pci 0000:00:02.0: reg 0x14: [mem 0xfebd0000-0xfebd0fff]
[    0.738903] pci 0000:00:02.0: reg 0x30: [mem 0xfebc0000-0xfebcffff pref]
[    0.740430] pci 0000:00:03.0: [1af4:1000] type 00 class 0x020000
[    0.747020] pci 0000:00:03.0: reg 0x10: [io  0xc060-0xc07f]
[    0.754319] pci 0000:00:03.0: reg 0x14: [mem 0xfebd1000-0xfebd1fff]
[    0.775937] pci 0000:00:03.0: reg 0x20: [mem 0xfe000000-0xfe003fff 64bit pref]
[    0.782463] pci 0000:00:03.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref]
[    0.786762] pci 0000:00:04.0: [1af4:1001] type 00 class 0x010000
[    0.793487] pci 0000:00:04.0: reg 0x10: [io  0xc000-0xc03f]
[    0.801171] pci 0000:00:04.0: reg 0x14: [mem 0xfebd2000-0xfebd2fff]
[    0.822367] pci 0000:00:04.0: reg 0x20: [mem 0xfe004000-0xfe007fff 64bit pref]
[    0.832677] pci 0000:00:05.0: [1af4:1002] type 00 class 0x00ff00
[    0.837252] pci 0000:00:05.0: reg 0x10: [io  0xc080-0xc09f]
[    0.857395] pci 0000:00:05.0: reg 0x20: [mem 0xfe008000-0xfe00bfff 64bit pref]
[    0.866514] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[    0.869230] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[    0.873117] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[    0.875895] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[    0.878413] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
[    0.880979] ACPI: Enabled 3 GPEs in block 00 to 0F
[    0.883914] vgaarb: setting as boot device: PCI:0000:00:02.0
[    0.885544] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[    0.888530] vgaarb: loaded
[    0.890019] vgaarb: bridge control possible 0000:00:02.0
[    0.892545] SCSI subsystem initialized
[    0.894455] libata version 3.00 loaded.
[    0.894552] ACPI: bus type USB registered
[    0.921759] usbcore: registered new interface driver usbfs
[    0.923543] usbcore: registered new interface driver hub
[    0.926356] usbcore: registered new device driver usb
[    0.928562] PCI: Using ACPI for IRQ routing
[    0.930130] PCI: pci_cache_line_size set to 64 bytes
[    0.930552] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[    0.930562] e820: reserve RAM buffer [mem 0x7ffdc000-0x7fffffff]
[    0.931090] NetLabel: Initializing
[    0.932862] NetLabel:  domain hash size = 128
[    0.934583] NetLabel:  protocols = UNLABELED CIPSOv4
[    0.936613] NetLabel:  unlabeled traffic allowed by default
[    0.939503] clocksource: Switched to clocksource kvm-clock
[    0.987658] VFS: Disk quotas dquot_6.6.0
[    0.990626] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.993807] pnp: PnP ACPI init
[    0.995724] pnp 00:00: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.995826] pnp 00:01: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.995922] pnp 00:02: Plug and Play ACPI device, IDs PNP0f13 (active)
[    0.995946] pnp 00:03: [dma 2]
[    0.996185] pnp 00:03: Plug and Play ACPI device, IDs PNP0700 (active)
[    0.996601] pnp 00:04: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.996792] pnp 00:05: Plug and Play ACPI device, IDs PNP0501 (active)
[    0.997283] pnp: PnP ACPI: found 6 devices
[    1.010009] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    1.013355] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    1.013359] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
[    1.013362] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[    1.013365] pci_bus 0000:00: resource 7 [mem 0x80000000-0xfebfffff window]
[    1.013558] NET: Registered protocol family 2
[    1.016133] TCP established hash table entries: 16384 (order: 5, 131072 bytes)
[    1.022719] TCP bind hash table entries: 16384 (order: 6, 262144 bytes)
[    1.024743] TCP: Hash tables configured (established 16384 bind 16384)
[    1.026712] UDP hash table entries: 1024 (order: 3, 32768 bytes)
[    1.028567] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes)
[    1.030600] NET: Registered protocol family 1
[    1.032572] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    1.034315] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[    1.036076] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    1.113649] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
[    1.191920] pci 0000:00:02.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    1.195250] PCI: CLS 0 bytes, default 64
[    1.195598] Trying to unpack rootfs image as initramfs...
[   15.085970] Freeing initrd memory: 36948K (ffff902c7dbc7000 - ffff902c7ffdc000)
[   15.089570] Scanning for low memory corruption every 60 seconds
[   15.092213] audit: initializing netlink subsys (disabled)
[   15.093913] audit: type=2000 audit(1497532962.104:1): initialized
[   15.096376] Initialise system trusted keyrings
[   15.098208] workingset: timestamp_bits=40 max_order=19 bucket_order=0
[   15.104390] zbud: loaded
[   15.107016] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[   15.109502] fuse init (API version 7.26)
[   15.111649] SELinux:  Registering netfilter hooks
[   15.112999] Key type asymmetric registered
[   15.114709] Asymmetric key parser 'x509' registered
[   15.116650] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
[   15.119719] io scheduler noop registered
[   15.121260] io scheduler deadline registered
[   15.123060] io scheduler cfq registered (default)
[   15.124972] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[   15.126614] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[   15.128467] intel_idle: does not run on family 6 model 44
[   15.128646] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0
[   15.131674] ACPI: Power Button [PWRF]
[   15.133745] GHES: HEST is not enabled!
[   15.208368] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 10
[   15.360356] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
[   15.366096] Serial: 8250/16550 driver, 32 ports, IRQ sharing enabled
[   15.391854] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[   15.425764] 00:05: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A
[   15.433152] Linux agpgart interface v0.103
[   15.449151] brd: module loaded
[   15.453699] loop: module loaded
[   15.468510]  vda: vda1
[   15.470739] ata_piix 0000:00:01.1: version 2.13
[   15.480712] scsi host0: ata_piix
[   15.483013] scsi host1: ata_piix
[   15.484846] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14
[   15.486528] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15
[   15.491325] libphy: Fixed MDIO Bus: probed
[   15.492982] tun: Universal TUN/TAP device driver, 1.6
[   15.494571] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
[   15.507740] PPP generic driver version 2.4.2
[   15.509572] VMware vmxnet3 virtual NIC driver - version 1.4.a.0-k-NAPI
[   15.511404] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[   15.513214] ehci-pci: EHCI PCI platform driver
[   15.515003] ehci-platform: EHCI generic platform driver
[   15.516904] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[   15.518801] ohci-pci: OHCI PCI platform driver
[   15.520587] ohci-platform: OHCI generic platform driver
[   15.522549] uhci_hcd: USB Universal Host Controller Interface driver
[   15.648667] ata1.01: NODEV after polling detection
[   15.649178] ata1.00: ATAPI: QEMU DVD-ROM, 2.5+, max UDMA/100
[   15.655049] uhci_hcd 0000:00:01.2: UHCI Host Controller
[   15.657304] ata1.00: configured for MWDMA2
[   15.659980] scsi 0:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.5+ PQ: 0 ANSI: 5
[   15.664660] sr 0:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
[   15.666396] cdrom: Uniform CD-ROM driver Revision: 3.20
[   15.668052] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1
[   15.671030] uhci_hcd 0000:00:01.2: detected 2 ports
[   15.673104] sr 0:0:0:0: Attached scsi CD-ROM sr0
[   15.673221] sr 0:0:0:0: Attached scsi generic sg0 type 5
[   15.675590] uhci_hcd 0000:00:01.2: irq 11, io base 0x0000c040
[   15.677478] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001
[   15.679225] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[   15.682334] usb usb1: Product: UHCI Host Controller
[   15.683962] usb usb1: Manufacturer: Linux 4.9.30-rancher uhci_hcd
[   15.685629] usb usb1: SerialNumber: 0000:00:01.2
[   15.687612] hub 1-0:1.0: USB hub found
[   15.689162] hub 1-0:1.0: 2 ports detected
[   15.691174] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[   15.697289] serio: i8042 KBD port at 0x60,0x64 irq 1
[   15.698886] serio: i8042 AUX port at 0x60,0x64 irq 12
[   15.700851] mousedev: PS/2 mouse device common for all mice
[   15.703536] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1
[   15.706769] rtc_cmos 00:00: RTC can wake from S4
[   15.709331] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
[   15.711415] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram
[   15.713252] i2c /dev entries driver
[   15.715087] device-mapper: uevent: version 1.0.3
[   15.716980] device-mapper: ioctl: 4.35.0-ioctl (2016-06-23) initialised: dm-devel@redhat.com
[   15.720277] ledtrig-cpu: registered to indicate activity on CPUs
[   15.722693] NET: Registered protocol family 10
[   15.725438] NET: Registered protocol family 17
[   15.727613] 9pnet: Installing 9P2000 support
[   15.729640] Key type dns_resolver registered
[   15.732046] microcode: sig=0x206c1, pf=0x1, revision=0x1
[   15.734441] microcode: Microcode Update Driver: v2.01 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
[   15.738416] registered taskstats version 1
[   15.740311] Loading compiled-in X.509 certificates
[   15.745056] Loaded X.509 cert 'Build time autogenerated kernel key: f4430a0236c5170016e60217325314360b2a154d'
[   15.748494] zswap: loaded using pool lzo/zbud
[   15.750979] Key type trusted registered
[   15.754134] Key type encrypted registered
[   15.755958] ima: No TPM chip found, activating TPM-bypass!
[   15.757757] evm: HMAC attrs: 0x1
[   15.760312]   Magic number: 5:328:382
[   15.762019] container PNP0A06:00: hash matches
[   15.763749] acpi PNP0A06:00: hash matches
[   15.765542] rtc_cmos 00:00: setting system clock to 2017-06-15 13:22:42 UTC (1497532962)
[   15.768942] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found
[   15.770615] EDD information not available.
[   15.772381] PM: Hibernation image not present or could not be loaded.
[   15.777348] Freeing unused kernel memory: 1456K (ffffffff8dd6d000 - ffffffff8ded9000)
[   15.780581] Write protecting the kernel read-only data: 12288k
[   15.785203] Freeing unused kernel memory: 1104K (ffff902c756ec000 - ffff902c75800000)
[   15.791578] Freeing unused kernel memory: 380K (ffff902c75ba1000 - ffff902c75c00000)
[   16.055556] usb 1-1: new full-speed USB device number 2 using uhci_hcd
[   16.250447] usb 1-1: New USB device found, idVendor=0627, idProduct=0001
[   16.252359] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=5
[   16.262641] usb 1-1: Product: QEMU USB Tablet
[   16.264306] usb 1-1: Manufacturer: QEMU
[   16.266194] usb 1-1: SerialNumber: 42
[   16.600585] random: fast init done
[   16.983646] EXT4-fs (vda1): recovery complete
[   16.988901] EXT4-fs (vda1): mounted filesystem with ordered data mode. Opts: (null)
[   17.164260] time="2017-06-15T13:22:43Z" level=debug msg="START: [/usr/bin/system-docker daemon --graph /var/lib/system-docker --userland-proxy=false --group root --storage-driver overlay --bridge none --host unix:///var/run/system-docker.sock --restart=false] in /" 
[   23.848403] cgroup: docker-runc (188) created nested cgroup for controller "memory" which has incomplete hierarchy support. Nested cgroups may change behavior in the future.
[   23.853466] cgroup: "memory" requires setting use_hierarchy to 1 on the root
[   24.110838] time="2017-06-15T13:22:50Z" level=debug msg="START: [/usr/bin/ros entrypoint cloud-init-save] in /" 
[   24.207658] time="2017-06-15T13:22:50Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   24.303914] time="2017-06-15T13:22:51Z" level=debug msg="START: [cloud-init-save] in /" 
[   24.307997] time="2017-06-15T13:22:51Z" level=info msg="Running cloud-init-save" 
[   24.315732] udevd[217]: starting version 3.2
[   24.324647] udevd[218]: starting eudev-3.2
[   24.452580] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0
[   24.474285] hidraw: raw HID events driver (C) Jiri Kosina
[   24.549105] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4
[   24.557773] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3
[   24.646082] usbcore: registered new interface driver usbhid
[   24.647854] usbhid: USB HID core driver
[   24.705305] SSE version of gcm_enc/dec engaged.
[   24.792005] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input5
[   24.796303] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Pointer [QEMU QEMU USB Tablet] on usb-0000:00:01.2-1/input0
[   24.866897] time="2017-06-15T13:22:51Z" level=debug msg=SaveCloudConfig 
[   24.962702] time="2017-06-15T13:22:51Z" level=debug msg="init: SaveCloudConfig(pre ApplyNetworkConfig): netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig(nil), PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[   24.971558] time="2017-06-15T13:22:51Z" level=info msg="Apply Network Config" 
[   24.975768] time="2017-06-15T13:22:51Z" 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:\"\"}" 
[   24.996631] time="2017-06-15T13:22:51Z" level=info msg="Applying 127.0.0.1/8 to lo" 
[   25.000552] time="2017-06-15T13:22:51Z" level=info msg="Applying ::1/128 to lo" 
[   25.004617] time="2017-06-15T13:22:51Z" level=info msg="Apply Network Config RunDhcp" 
[   25.008778] time="2017-06-15T13:22:51Z" level=debug msg=RunDhcp 
[   25.011222] time="2017-06-15T13:22:51Z" level=info msg="Running DHCP on eth0: dhcpcd -MA4 -e force_hostname=true eth0" 
[   25.559783] time="2017-06-15T13:22:52Z" level=info msg="Apply Network Config SyncHostname" 
[   25.564196] time="2017-06-15T13:22:52Z" level=debug msg="datasources that will be consided: []string{\"configdrive:/media/config-2\"}" 
[   25.568385] time="2017-06-15T13:22:52Z" level=info msg="cloud-init: Checking availability of \"cloud-drive\"\n" 
[   25.605114] ISO 9660 Extensions: Microsoft Joliet Level 3
[   25.610963] ISO 9660 Extensions: RRIP_1991A
[   25.612580] time="2017-06-15T13:22:52Z" level=info msg="cloud-init: Datasource available: cloud-drive: /media/config-2" 
[   25.616227] time="2017-06-15T13:22:52Z" level=info msg="Fetching user-data from datasource cloud-drive: /media/config-2" 
[   25.641117] ISO 9660 Extensions: Microsoft Joliet Level 3
[   25.642808] ISO 9660 Extensions: RRIP_1991A
[   25.643035] time="2017-06-15T13:22:52Z" level=debug msg="Attempting to read from \"/media/config-2/openstack/latest/user_data\"\n" 
[   25.650131] time="2017-06-15T13:22:52Z" level=info msg="Fetching meta-data from datasource of type cloud-drive" 
[   25.673808] ISO 9660 Extensions: Microsoft Joliet Level 3
[   25.675684] ISO 9660 Extensions: RRIP_1991A
[   25.675961] time="2017-06-15T13:22:52Z" level=debug msg="Attempting to read from \"/media/config-2/openstack/latest/meta_data.json\"\n" 
[   25.691277] time="2017-06-15T13:22:52Z" level=error msg="Unrecognized user-data\n()" 
[   25.699451] time="2017-06-15T13:22:52Z" level=info msg="Wrote to /var/lib/rancher/conf/metadata" 
[   25.707777] time="2017-06-15T13:22:52Z" level=info msg="Wrote to /var/lib/rancher/conf/cloud-config.d/network.yml" 
[   25.816925] time="2017-06-15T13:22:52Z" level=debug msg="init: SaveCloudConfig(post ApplyNetworkConfig): netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig(nil), PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[   25.827542] time="2017-06-15T13:22:52Z" level=info msg="Apply Network Config" 
[   25.834579] time="2017-06-15T13:22:52Z" level=debug msg="Config: &netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig{\"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:\"\"}, \"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:\"\"}}, PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[   25.855857] time="2017-06-15T13:22:52Z" level=info msg="Applying 127.0.0.1/8 to lo" 
[   25.859410] time="2017-06-15T13:22:52Z" level=info msg="Applying ::1/128 to lo" 
[   25.863251] time="2017-06-15T13:22:52Z" level=info msg="Apply Network Config RunDhcp" 
[   25.866482] time="2017-06-15T13:22:52Z" level=debug msg=RunDhcp 
[   25.868788] time="2017-06-15T13:22:52Z" level=info msg="Running DHCP on eth0: dhcpcd -MA4 eth0" 
[   25.879821] time="2017-06-15T13:22:52Z" level=info msg="Apply Network Config SyncHostname" 
[   27.145990] time="2017-06-15T13:22:53Z" level=debug msg="START: [system-docker daemon --storage-driver overlay --graph /var/lib/system-docker --pidfile /var/run/system-docker.pid --restart=false --group root --log-opt max-file=2 --log-opt max-size=25m --exec-root /var/run/system-docker --userland-proxy=false --config-file /etc/docker/system-docker.json --host unix:///var/run/system-docker.sock] in /" 
[   27.157492] DEBU[0000] START: [/usr/bin/ros-sysinit] in /           
[   27.392903] INFO[0000] [1/4] Starting loadImages                    
[   27.394811] DEBU[0000] Looking for images at /usr/share/ros         
[   27.397389] DEBU[0000] Found images.tar                             
[   27.653729] INFO[0000] Loading images from /usr/share/ros/images.tar 
[   30.918953] INFO[0003] Done loading images from /usr/share/ros/images.tar 
[   30.922539] DEBU[0003] [1/4] Done loadImages                        
[   30.927443] INFO[0003] [2/4] Starting start project                 
[   31.043764] INFO[0004] Project [os]: Starting project               
[   31.081870] DEBU[0004] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   31.085790] DEBU[0004] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   31.089382] DEBU[0004] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[   31.256218] INFO[0004] [0/16] [command-volumes]: Starting           
[   31.268209] INFO[0004] [0/16] [container-data-volumes]: Starting    
[   31.278913] INFO[0004] [0/16] [media-volumes]: Starting             
[   31.313816] INFO[0004] [0/16] [system-volumes]: Starting            
[   31.357206] INFO[0004] [0/16] [user-volumes]: Starting              
[   31.957744] DEBU[0004] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   31.978003] INFO[0004] [1/16] [command-volumes]: Started            
[   32.050593] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.059688] INFO[0005] [2/16] [container-data-volumes]: Started     
[   32.066596] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.073589] INFO[0005] [3/16] [system-volumes]: Started             
[   32.078474] INFO[0005] [3/16] [acpid]: Starting                     
[   32.082439] INFO[0005] [3/16] [udev-cold]: Starting                 
[   32.086585] INFO[0005] [3/16] [syslog]: Starting                    
[   32.091865] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.097644] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.104981] INFO[0005] [4/16] [user-volumes]: Started               
[   32.108948] INFO[0005] [5/16] [media-volumes]: Started              
[   32.113043] INFO[0005] [5/16] [all-volumes]: Starting               
[   32.600546] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.613292] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.620321] INFO[0005] [6/16] [all-volumes]: Started                
[   32.623197] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   32.630012] DEBU[0005] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   33.004410] INFO[0006] [7/16] [syslog]: Started                     
[   33.100289] time="2017-06-15T13:22:59Z" level=debug msg="START: [/usr/bin/ros entrypoint rsyslogd -n] in /" 
[   33.622521] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   33.630218] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   33.642157] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   33.651564] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   33.661871] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   33.670302] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   33.682024] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   33.764175] INFO[0006] [8/16] [acpid]: Started                      
[   33.958420] time="2017-06-15T13:23:00Z" level=debug msg="START: [/usr/bin/ros entrypoint /usr/sbin/acpid -f] in /" 
[   34.041523] time="2017-06-15T13:23:00Z" level=debug msg="START: [/usr/bin/ros entrypoint ros udev-settle] in /" 
[   34.243645] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   34.251627] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   34.259620] time="2017-06-15T13:23:00Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   34.267895] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   34.273773] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   34.280045] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   34.287924] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   34.300359] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   34.305415] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   34.309237] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   34.313232] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   34.317011] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   34.320584] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   34.324590] time="2017-06-15T13:23:01Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   34.380289] time="2017-06-15T13:23:01Z" level=debug msg="START: [ros udev-settle] in /" 
[   34.399867] udevd[13]: starting version 3.2
[   34.453499] udevd[16]: starting eudev-3.2
[   34.512566] evbug: Connected device: input0 (Power Button at LNXPWRBN/button/input0)
[   34.512571] evbug: Connected device: input1 (AT Translated Set 2 keyboard at isa0060/serio0/input0)
[   34.512574] evbug: Connected device: input4 (VirtualPS/2 VMware VMMouse at isa0060/serio1/input1)
[   34.512576] evbug: Connected device: input3 (VirtualPS/2 VMware VMMouse at isa0060/serio1/input0)
[   34.571625] evbug: Connected device: input5 (QEMU QEMU USB Tablet at usb-0000:00:01.2-1/input0)
[   34.584662] FDC 0 is a S82078B
[   34.606026] cirrusfb 0000:00:02.0: Cirrus Logic chipset on PCI bus, RAM (4096 kB) at 0xfc000000
[   34.654688] fbcon: CL Picasso4 (fb0) is primary device
[   34.722648] input: PC Speaker as /devices/platform/pcspkr/input/input6
[   34.730825] evbug: Connected device: input6 (PC Speaker at isa0061/input0)
[   34.851027] Error: Driver 'pcspkr' is already registered, aborting...
[   35.869270] Console: switching to colour frame buffer device 80x30
[   36.724052] [drm] Initialized
[   38.642088] INFO[0011] [9/16] [udev-cold]: Started                  
[   40.447346] DEBU[0013] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   41.880959] time="2017-06-15T13:23:08Z" level=debug msg="START: [/usr/bin/ros entrypoint udevd] in /" 
[   42.341201] time="2017-06-15T13:23:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   42.342235] time="2017-06-15T13:23:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   42.342538] time="2017-06-15T13:23:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   42.342866] time="2017-06-15T13:23:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   42.343192] time="2017-06-15T13:23:09Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   42.343654] time="2017-06-15T13:23:09Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   42.343894] time="2017-06-15T13:23:09Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   42.381352] udevd[1]: starting version 3.2
[   42.396112] udevd[1]: starting eudev-3.2
[   69.645035] INFO[0042] [9/16] [udev]: Starting                      
[   72.204286] INFO[0045] [10/16] [udev]: Started                      
[   73.689009] DEBU[0046] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[   75.076286] time="2017-06-15T13:23:41Z" level=debug msg="START: [/usr/bin/ros entrypoint netconf] in /" 
[   75.485878] time="2017-06-15T13:23:42Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[   75.487139] time="2017-06-15T13:23:42Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[   75.487696] time="2017-06-15T13:23:42Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[   75.488235] time="2017-06-15T13:23:42Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[   75.488548] time="2017-06-15T13:23:42Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[   75.489134] time="2017-06-15T13:23:42Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[   75.489420] time="2017-06-15T13:23:42Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[   75.691175] time="2017-06-15T13:23:42Z" level=debug msg="START: [netconf] in /" 
[   79.143017] time="2017-06-15T13:23:45Z" level=info msg="Apply Network Config" 
[   79.144097] time="2017-06-15T13:23:45Z" level=debug msg="Config: &netconf.NetworkConfig{PreCmds:[]string(nil), DNS:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, Interfaces:map[string]netconf.InterfaceConfig{\"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:\"\"}, \"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:\"\"}}, PostCmds:[]string(nil), HTTPProxy:\"\", HTTPSProxy:\"\", NoProxy:\"\"}" 
[   79.145527] time="2017-06-15T13:23:45Z" level=info msg="Applying 127.0.0.1/8 to lo" 
[   79.146064] time="2017-06-15T13:23:45Z" level=info msg="Applying ::1/128 to lo" 
[   81.544143] time="2017-06-15T13:23:48Z" level=info msg="Apply Network Config RunDhcp" 
[   81.544228] time="2017-06-15T13:23:48Z" level=debug msg=RunDhcp 
[   83.842798] time="2017-06-15T13:23:48Z" level=info msg="Running DHCP on eth0: dhcpcd -MA4 eth0" 
[  128.062050] INFO[0101] [10/16] [network]: Starting                  
[  130.064332] time="2017-06-15T13:24:36Z" level=info msg="Apply Network Config SyncHostname" 
[  130.078445] time="2017-06-15T13:24:36Z" level=info msg="Restart syslog" 
[  131.988600] time="2017-06-15T13:24:38Z" level=debug msg="START: [/usr/bin/ros entrypoint rsyslogd -n] in /" 
[  134.702187] time="2017-06-15T13:24:41Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[  134.702412] time="2017-06-15T13:24:41Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[  134.702629] time="2017-06-15T13:24:41Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[  134.702832] time="2017-06-15T13:24:41Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[  134.703042] time="2017-06-15T13:24:41Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[  134.703269] time="2017-06-15T13:24:41Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[  134.703593] time="2017-06-15T13:24:41Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[  158.405292] INFO[0131] [11/16] [network]: Started                   
[  159.796215] DEBU[0132] Using cached file: /var/lib/rancher/cache/79a736f9cb448fe10083b5837917553a 
[  162.619339] DEBU[0135] Loaded kernel-extras from https://raw.githubusercontent.com/rancher/os-services/v1.0.2/k/kernel-extras.yml 
[  165.236325] DEBU[0138] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[  167.821571] DEBU[0140] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[  170.653880] DEBU[0143] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[  174.065411] DEBU[0147] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[  176.723004] DEBU[0149] Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher 
[  180.263361] DEBU[0153] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[  181.658411] time="2017-06-15T13:25:28Z" level=debug msg="START: [/usr/bin/ros entrypoint ntpd --nofork -g] in /" 
[  182.041132] time="2017-06-15T13:25:28Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[  182.044496] time="2017-06-15T13:25:28Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[  182.044687] time="2017-06-15T13:25:28Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[  182.044899] time="2017-06-15T13:25:28Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[  182.045019] time="2017-06-15T13:25:28Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[  182.045143] time="2017-06-15T13:25:28Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[  182.045268] time="2017-06-15T13:25:28Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[  207.545190] INFO[0181] [11/17] [ntp]: Starting                      
[  209.245295] DEBU[0182] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[  210.549895] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[  210.659148] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[  210.694056] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[  210.696663] docker-sys: port 1(veth6ebe7bc6) entered blocking state
[  210.696665] docker-sys: port 1(veth6ebe7bc6) entered disabled state
[  210.696921] device veth6ebe7bc6 entered promiscuous mode
[  210.697056] docker-sys: port 1(veth6ebe7bc6) entered blocking state
[  210.697058] docker-sys: port 1(veth6ebe7bc6) entered forwarding state
[  211.121362] ip_tables: (C) 2000-2006 Netfilter Core Team
[  211.190138] nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
[  211.508871] IPv6: eth0: IPv6 duplicate address fe80::6cf3:80ff:fe5c:8f2f detected!
[  215.656258] docker-sys: port 1(veth6ebe7bc6) entered disabled state
[  215.659348] device veth6ebe7bc6 left promiscuous mode
[  215.659353] docker-sys: port 1(veth6ebe7bc6) entered disabled state
[  236.612780] INFO[0210] [11/17] [kernel-extras]: Starting            
[  239.396765] INFO[0213] [12/17] [ntp]: Started                       
[  240.956888] DEBU[0214] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[  242.378178] time="2017-06-15T13:26:29Z" level=debug msg="START: [/usr/bin/ros entrypoint cloud-init-execute -pre-console] in /" 
[  242.825161] time="2017-06-15T13:26:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[  242.825552] time="2017-06-15T13:26:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[  242.825887] time="2017-06-15T13:26:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[  242.826300] time="2017-06-15T13:26:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[  242.826636] time="2017-06-15T13:26:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[  242.826968] time="2017-06-15T13:26:30Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[  242.836315] time="2017-06-15T13:26:30Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[  243.031032] time="2017-06-15T13:26:30Z" level=debug msg="START: [cloud-init-execute -pre-console] in /" 
[  243.040533] time="2017-06-15T13:26:30Z" level=info msg="Running cloud-init-execute: pre-console=true, console=false" 
[  271.222938] INFO[0244] [12/17] [cloud-init-execute]: Starting       
[  273.767269] INFO[0247] [13/17] [kernel-extras]: Started             
[  276.209784] INFO[0249] [14/17] [cloud-init-execute]: Started        
[  277.956156] DEBU[0251] Rebuild values                                newRebuildLabel=always origRebuildLabel=always outOfSync=false rebuildLabelChanged=false
[  282.917700] INFO[0256] [14/17] [console]: Starting                  
[  286.556416] INFO[0260] Rebuilding console                           
[  288.568813] time="2017-06-15T13:27:15Z" level=debug msg="START: [/usr/bin/ros entrypoint ros console-init] in /" 
[  293.714087] INFO[0267] [15/17] [console]: Started                   
[  295.966114] DEBU[0269] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[  298.442365] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[  298.463068] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[  298.463656] docker-sys: port 1(vethc171185d) entered blocking state
[  298.463658] docker-sys: port 1(vethc171185d) entered disabled state
[  298.463925] device vethc171185d entered promiscuous mode
[  298.464048] docker-sys: port 1(vethc171185d) entered blocking state
[  298.464049] docker-sys: port 1(vethc171185d) entered forwarding state
[  298.490963] IPv6: eth0: IPv6 duplicate address fe80::8815:c9ff:fe44:8ad7 detected!
[  298.505033] time="2017-06-15T13:27:25Z" level=debug msg="START: [ros console-init] in /" 
[  302.538178] time="2017-06-15T13:27:29Z" level=debug msg="START: [/usr/bin/ros entrypoint ros preload-images] in /" 
[  302.719893] time="2017-06-15T13:27:30Z" level=debug msg="START: [respawn -f /etc/respawn.conf] in /" 
[  302.754763] time="2017-06-15T13:27:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-execute: file exists" 
[  302.755168] time="2017-06-15T13:27:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/cloud-init-save: file exists" 
[  302.755395] time="2017-06-15T13:27:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/dockerlaunch: file exists" 
[  302.755714] time="2017-06-15T13:27:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/respawn: file exists" 
[  302.755947] time="2017-06-15T13:27:30Z" level=error msg="symlink /usr/bin/ros /usr/bin/system-docker: file exists" 
[  302.756178] time="2017-06-15T13:27:30Z" level=error msg="symlink /usr/bin/ros /usr/sbin/netconf: file exists" 
[  302.756420] time="2017-06-15T13:27:30Z" level=error msg="symlink /usr/bin/ros /usr/sbin/wait-for-docker: file exists" 
[  302.820526] time="2017-06-15T13:27:30Z" level=debug msg="START: [ros preload-images] in /" 
[  303.617689] INFO[0277] [15/17] [preload-user-images]: Starting      
[  303.632900] docker-sys: port 1(vethc171185d) entered disabled state
[  303.635251] device vethc171185d left promiscuous mode
[  303.635260] docker-sys: port 1(vethc171185d) entered disabled state
[  304.156924] INFO[0277] [15/17] [docker]: Starting                   
[  304.546818] DEBU[0278] Rebuild values                                newRebuildLabel= origRebuildLabel= outOfSync=false rebuildLabelChanged=false
[  305.252170] INFO[0278] [16/17] [preload-user-images]: Started       
[  306.238548] INFO[0279] [17/17] [docker]: Started                    
[  306.239364] DEBU[0279] [2/4] Done start project                     
[  306.304193] time="2017-06-15T13:27:33Z" level=debug msg="START: [ros user-docker] in /" 
[  306.384329] INFO[0280] Project [os]: Project started                
[  306.442931] INFO[0280] [3/4] Starting sync                          
[  306.528954] DEBU[0280] [3/4] Done sync                              
[  306.576678] random: crng init done
[  306.639644] INFO[0280] [4/4] Starting banner                        
[  306.765326] INFO[0280] RancherOS v1.0.2 started                     
[  306.768991] DEBU[0280] [4/4] Done banner                            
[  312.548679] time="2017-06-15T13:27:39Z" level=info msg="Starting Docker in context: console" 
[  312.997000] time="2017-06-15T13:27:40Z" level=debug msg="Using cached file: /var/lib/rancher/cache/79a736f9cb448fe10083b5837917553a" 
[  312.997147] time="2017-06-15T13:27:40Z" level=debug msg="Loaded kernel-extras from https://raw.githubusercontent.com/rancher/os-services/v1.0.2/k/kernel-extras.yml" 
[  313.009062] time="2017-06-15T13:27:40Z" level=debug msg="Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher" 
[  313.009247] time="2017-06-15T13:27:40Z" level=debug msg="Using /proc/version to set rancher.environment.KERNEL_VERSION = 4.9.30-rancher" 
[  313.027773] time="2017-06-15T13:27:40Z" level=info msg="Getting PID for service: console" 
[  313.172051] time="2017-06-15T13:27:40Z" level=info msg="console PID 845" 
[  313.281226] time="2017-06-15T13:27:40Z" level=debug msg="User Docker args: [daemon --group docker --storage-driver overlay --host unix:///var/run/docker.sock --log-opt max-file=2 --log-opt max-size=25m]" 
[  313.308002] time="2017-06-15T13:27:40Z" level=info msg="[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin HOSTNAME=test.novalocal HOME=/]" 
[  313.308557] time="2017-06-15T13:27:40Z" level=info msg="Running [docker-runc exec -- 90330a79f812fd46701b3b81ca9fe469da25966bc1ed9f39c081a93db3335754 env PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin HOSTNAME=test.novalocal HOME=/ ros docker-init daemon --group docker --storage-driver overlay --host unix:///var/run/docker.sock --log-opt max-file=2 --log-opt max-size=25m]" 
[  314.167749] time="2017-06-15T13:27:41Z" level=debug msg="START: [ros docker-init daemon --group docker --storage-driver overlay --host unix:///var/run/docker.sock --log-opt max-file=2 --log-opt max-size=25m] in /" 
[  314.739401] time="2017-06-15T13:27:42Z" level=debug msg="START: [/usr/bin/dockerlaunch /usr/bin/docker daemon --group docker --storage-driver overlay --host unix:///var/run/docker.sock --log-opt max-file=2 --log-opt max-size=25m] in /" 
[  314.740195] time="2017-06-15T13:27:42Z" level=debug msg="Launch config dfs.Config{Fork:false, PidOne:false, CommandName:\"\", DNSConfig:netconf.DNSConfig{Nameservers:[]string(nil), Search:[]string(nil)}, BridgeName:\"\", BridgeAddress:\"\", BridgeMtu:0, CgroupHierarchy:map[string]string(nil), LogFile:\"\", NoLog:false, NoFiles:0x0, Environment:[]string(nil), GraphDirectory:\"\", DaemonConfig:\"\"}" 
[  314.740280] time="2017-06-15T13:27:42Z" level=debug msg="Mounting devtmpfs /dev devtmpfs " 
[  314.745126] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /dev/pts devpts " 
[  314.748924] time="2017-06-15T13:27:42Z" level=debug msg="Mounting shm /dev/shm tmpfs rw,nosuid,nodev,noexec,relatime,size=65536k" 
[  314.752776] time="2017-06-15T13:27:42Z" level=debug msg="Mounting mqueue /dev/mqueue mqueue rw,nosuid,nodev,noexec,relatime" 
[  314.804496] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /proc proc " 
[  314.833917] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /run tmpfs " 
[  314.840020] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys sysfs " 
[  314.845069] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup tmpfs " 
[  314.848488] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/selinux selinuxfs ro" 
[  314.865070] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: #subsys_name\thierarchy\tnum_cgroups\tenabled" 
[  314.865195] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: cpuset\t1\t9\t1" 
[  314.865279] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: cpu\t2\t9\t1" 
[  314.865332] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: cpuacct\t2\t9\t1" 
[  314.865682] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: blkio\t6\t9\t1" 
[  314.865735] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: memory\t7\t15\t1" 
[  314.865777] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: devices\t3\t9\t1" 
[  314.865816] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: freezer\t4\t9\t1" 
[  314.865856] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: net_cls\t8\t9\t1" 
[  314.866033] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: perf_event\t9\t9\t1" 
[  314.866088] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: net_prio\t8\t9\t1" 
[  314.866132] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: hugetlb\t5\t9\t1" 
[  314.866202] time="2017-06-15T13:27:42Z" level=debug msg="/proc/cgroups: pids\t10\t9\t1" 
[  314.866719] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/pids cgroup pids" 
[  314.884405] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/cpu,cpuacct cgroup cpu,cpuacct" 
[  314.889482] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/memory cgroup memory" 
[  314.917152] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/devices cgroup devices" 
[  314.920930] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/hugetlb cgroup hugetlb" 
[  314.923462] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/perf_event cgroup perf_event" 
[  314.926295] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/cpuset cgroup cpuset" 
[  314.928710] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/blkio cgroup blkio" 
[  314.931167] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/freezer cgroup freezer" 
[  314.942615] time="2017-06-15T13:27:42Z" level=debug msg="Mounting none /sys/fs/cgroup/net_cls,net_prio cgroup net_cls,net_prio" 
[  314.948177] time="2017-06-15T13:27:42Z" level=debug msg="Done mouting cgroupfs" 
[  314.961100] time="2017-06-15T13:27:42Z" level=debug msg="Creating /root/.ssh" 
[  314.964032] time="2017-06-15T13:27:42Z" level=debug msg="Not copying /usr/etc/ssl/certs/ca-certificates.crt, does not exists" 
[  314.964106] time="2017-06-15T13:27:42Z" level=debug msg="Not copying /usr/etc/passwd, does not exists" 
[  314.964165] time="2017-06-15T13:27:42Z" level=debug msg="Not copying /usr/etc/group, does not exists" 
[  314.964330] time="2017-06-15T13:27:42Z" level=debug msg="Copying folder /etc/docker" 
[  314.964408] time="2017-06-15T13:27:42Z" level=debug msg="Copying folder /etc/selinux" 
[  314.964466] time="2017-06-15T13:27:42Z" level=debug msg="Copying folder /etc/selinux/ros" 
[  314.964516] time="2017-06-15T13:27:42Z" level=debug msg="Copying folder /etc/selinux/ros/policy" 
[  314.964595] time="2017-06-15T13:27:42Z" level=debug msg="Copying folder /etc/selinux/ros/contexts" 
[  314.964752] time="2017-06-15T13:27:42Z" level=debug msg="Copying folder /var/lib/cni" 
[  314.966084] time="2017-06-15T13:27:42Z" level=debug msg="Launching Docker /usr/bin/docker docker [daemon --group docker --storage-driver overlay --host unix:///var/run/docker.sock --log-opt max-file=2 --log-opt max-size=25m]" 
[  317.093284] Bridge firewalling registered
[  317.695964] Initializing XFRM netlink socket
[  317.933902] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready

rancher / os

RancherOS takes ages to boot after enabling kernel-extras service #1923