Issue pulling user_data in OpenStack

jstuever commented 6 years ago

Ignition fails to pull user_data due to what appears to be a networking issue. I'm using rhcos-openstack.qcow2.gz from http://aos-ostree.rhev-ci-vms.eng.rdu2.redhat.com/rhcos/images/cloud/latest/ dated some time last week. I can replicate this on both OpenStack v9 and v10. The console logs are as follows:

> [H[J[1;1H[?25l[m[H[J[1;1H[20;7H[mUse the ^ and v keys to change the selection. > Press 'e' to edit the selected item, or 'c' for a command prompt. [4;80H [7m[4;1H Red Hat CoreOS 3.10 4.0.3999 (ostree) [m[4;79H[m[m[5;1H [m[5;79H[m[m[6;1H [m[6;79H[m[m[7;1H [m[7;79H[m[m[8;1H [m[8;79H[m[m[9;1H [m[9;79H[m[m[10;1H [m[10;79H[m[m[11;1H [m[11;79H[m[m[12;1H [m[12;79H[m[m[13;1H [m[13;79H[m[m[14;1H [m[14;79H[m[m[15;1H [m[15;79H[m[m[16;1H [m[16;79H[m[m[17;1H [m[17;79H[m[m[18;1H [m[18;79H[m[18;80H [4;79H[22;1H The selected entry will be started automatically in 1s. [4;79H[22;1H The selected entry will be started automatically in 0s. [4;79H[?25h[H[J[1;1H[H[J[1;1H[ 0.000000] Initializing cgroup subsys cpuset > [ 0.000000] Initializing cgroup subsys cpu > [ 0.000000] Initializing cgroup subsys cpuacct > [ 0.000000] Linux version 3.10.0-862.2.3.el7.x86_64 (mockbuild@x86-041.build.eng.bos.redhat.com) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-28) (GCC) ) #1 SMP Mon Apr 30 12:37:51 EDT 2018 > [ 0.000000] Command line: BOOT_IMAGE=/ostree/rhcos-e7f7c60f676784d3592864ddc4ffde0b8e45656ab0e71cd32331dbcce9881534/vmlinuz-3.10.0-862.2.3.el7.x86_64 no_timer_check console=tty0 console=ttyS0,115200n8 net.ifnames=0 biosdevname=0 ip=dhcp rd.neednet=1 enforcing=0 rw coreos.firstboot=detected rd.lvm.lv=coreos/root root=/dev/mapper/coreos-root ostree=/ostree/boot.0/rhcos/e7f7c60f676784d3592864ddc4ffde0b8e45656ab0e71cd32331dbcce9881534/0 coreos.oem.id=openstack > [ 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-0x00000000bffd9fff] usable > [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved > [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved > [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved > [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000023fffffff] usable > [ 0.000000] NX (Execute Disable) protection: active > [ 0.000000] SMBIOS 2.8 present. > [ 0.000000] Hypervisor detected: KVM > [ 0.000000] e820: last_pfn = 0x240000 max_arch_pfn = 0x400000000 > [ 0.000000] PAT configuration [0-7]: WB WC UC- UC WB WP UC- UC > [ 0.000000] e820: last_pfn = 0xbffda max_arch_pfn = 0x400000000 > [ 0.000000] found SMP MP-table at [mem 0x000f72f0-0x000f72ff] mapped at [ffffffffff2002f0] > [ 0.000000] Using GB pages for direct mapping > [ 0.000000] RAMDISK: [mem 0x307ee000-0x343eefff] > [ 0.000000] Early table checksum verification disabled > [ 0.000000] ACPI: RSDP 00000000000f70a0 00014 (v00 BOCHS ) > [ 0.000000] ACPI: RSDT 00000000bffe14c9 0002C (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001) > [ 0.000000] ACPI: FACP 00000000bffe13dd 00074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001) > [ 0.000000] ACPI: DSDT 00000000bffe0040 0139D (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001) > [ 0.000000] ACPI: FACS 00000000bffe0000 00040 > [ 0.000000] ACPI: APIC 00000000bffe1451 00078 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001) > [ 0.000000] No NUMA configuration found > [ 0.000000] Faking a node at [mem 0x0000000000000000-0x000000023fffffff] > [ 0.000000] NODE_DATA(0) allocated [mem 0x23ffd9000-0x23fffffff] > [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 > [ 0.000000] kvm-clock: cpu 0, msr 2:3ff89001, primary cpu clock > [ 0.000000] kvm-clock: using sched offset of 4128179240 cycles > [ 0.000000] Zone ranges: > [ 0.000000] DMA [mem 0x00001000-0x00ffffff] > [ 0.000000] DMA32 [mem 0x01000000-0xffffffff] > [ 0.000000] Normal [mem 0x100000000-0x23fffffff] > [ 0.000000] Movable zone start for each node > [ 0.000000] Early memory node ranges > [ 0.000000] node 0: [mem 0x00001000-0x0009efff] > [ 0.000000] node 0: [mem 0x00100000-0xbffd9fff] > [ 0.000000] node 0: [mem 0x100000000-0x23fffffff] > [ 0.000000] Initmem setup node 0 [mem 0x00001000-0x23fffffff] > [ 0.000000] ACPI: PM-Timer IO Port: 0x608 > [ 0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled) > [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) > [ 0.000000] ACPI: IOAPIC (id[0x00] address[0xfec00000] gsi_base[0]) > [ 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] Using ACPI (MADT) for SMP configuration information > [ 0.000000] smpboot: Allowing 1 CPUs, 0 hotplug CPUs > [ 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] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] > [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] > [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] > [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] > [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] > [ 0.000000] e820: [mem 0xc0000000-0xfeffbfff] available for PCI devices > [ 0.000000] Booting paravirtualized kernel on KVM > [ 0.000000] setup_percpu: NR_CPUS:5120 nr_cpumask_bits:1 nr_cpu_ids:1 nr_node_ids:1 > [ 0.000000] PERCPU: Embedded 35 pages/cpu @ffffa0343fc00000 s104856 r8192 d30312 u2097152 > [ 0.000000] KVM setup async PF for cpu 0 > [ 0.000000] kvm-stealtime: cpu 0, msr 23fc134c0 > [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes) > [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 2064227 > [ 0.000000] Policy zone: Normal > [ 0.000000] Kernel command line: BOOT_IMAGE=/ostree/rhcos-e7f7c60f676784d3592864ddc4ffde0b8e45656ab0e71cd32331dbcce9881534/vmlinuz-3.10.0-862.2.3.el7.x86_64 no_timer_check console=tty0 console=ttyS0,115200n8 net.ifnames=0 biosdevname=0 ip=dhcp rd.neednet=1 enforcing=0 rw coreos.firstboot=detected rd.lvm.lv=coreos/root root=/dev/mapper/coreos-root ostree=/ostree/boot.0/rhcos/e7f7c60f676784d3592864ddc4ffde0b8e45656ab0e71cd32331dbcce9881534/0 coreos.oem.id=openstack > [ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes) > [ 0.000000] x86/fpu: xstate_offset[2]: 0240, xstate_sizes[2]: 0100 > [ 0.000000] xsave: enabled xstate_bv 0x7, cntxt size 0x340 using standard form > [ 0.000000] Memory: 5096576k/9437184k available (7324k kernel code, 1049120k absent, 278188k reserved, 6305k data, 1832k init) > [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 > [ 0.000000] x86/pti: Unmapping kernel while in userspace > [ 0.000000] Hierarchical RCU implementation. > [ 0.000000] RCU restricting CPUs from NR_CPUS=5120 to nr_cpu_ids=1. > [ 0.000000] NR_IRQS:327936 nr_irqs:256 0 > [ 0.000000] Console: colour VGA+ 80x25 > [ 0.000000] console [tty0] enabled > [ 0.000000] console [ttyS0] enabled > [ 0.000000] allocated 33554432 bytes of page_cgroup > [ 0.000000] please try 'cgroup_disable=memory' option if you don't want memory cgroups > [ 0.000000] tsc: Detected 1999.997 MHz processor > [ 0.450681] Calibrating delay loop (skipped) preset value.. 3999.99 BogoMIPS (lpj=1999997) > [ 0.452743] pid_max: default: 32768 minimum: 301 > [ 0.453799] Security Framework initialized > [ 0.454839] SELinux: Initializing. > [ 0.455855] Yama: becoming mindful. > [ 0.457490] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes) > [ 0.467409] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes) > [ 0.472372] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes) > [ 0.473705] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes) > [ 0.476271] Initializing cgroup subsys memory > [ 0.477283] Initializing cgroup subsys devices > [ 0.478256] Initializing cgroup subsys freezer > [ 0.479231] Initializing cgroup subsys net_cls > [ 0.480199] Initializing cgroup subsys blkio > [ 0.481227] Initializing cgroup subsys perf_event > [ 0.482283] Initializing cgroup subsys hugetlb > [ 0.483429] Initializing cgroup subsys pids > [ 0.484438] Initializing cgroup subsys net_prio > [ 0.485557] CPU: Physical Processor ID: 0 > [ 0.487331] mce: CPU supports 10 MCE banks > [ 0.488309] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 > [ 0.489403] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0 > [ 0.490738] tlb_flushall_shift: 6 > [ 0.491959] FEATURE SPEC_CTRL Not Present > [ 0.493387] FEATURE IBPB_SUPPORT Not Present > [ 0.495374] Spectre V2 : Vulnerable: Retpoline without IBPB > [ 0.525631] Freeing SMP alternatives: 24k freed > [ 0.532786] ACPI: Core revision 20130517 > [ 0.534701] ACPI: All ACPI Tables successfully acquired > [ 0.536213] ftrace: allocating 28047 entries in 110 pages > [ 0.583640] Enabling x2apic > [ 0.584502] Enabled x2apic > [ 0.585608] Switched APIC routing to physical x2apic. > [ 0.587659] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 > [ 0.588820] smpboot: CPU0: Intel Core Processor (Skylake) (fam: 06, model: 5e, stepping: 03) > [ 0.590889] Performance Events: unsupported p6 CPU model 94 no PMU driver, software events only. > [ 0.592963] KVM setup paravirtual spinlock > [ 0.595613] Brought up 1 CPUs > [ 0.596541] smpboot: Max logical packages: 1 > [ 0.597494] smpboot: Total of 1 processors activated (3999.99 BogoMIPS) > [ 0.614412] node 0 initialised, 753325 pages in 15ms > [ 0.615747] devtmpfs: initialized > [ 0.619113] EVM: security.selinux > [ 0.620013] EVM: security.ima > [ 0.620809] EVM: security.capability > [ 0.623177] atomic64 test passed for x86-64 platform with CX8 and with SSE > [ 0.624477] pinctrl core: initialized pinctrl subsystem > [ 0.625709] RTC time: 21:21:36, date: 08/10/18 > [ 0.626819] NET: Registered protocol family 16 > [ 0.628154] ACPI: bus type PCI registered > [ 0.629092] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 > [ 0.630439] PCI: Using configuration type 1 for base access > [ 0.632984] ACPI: Added _OSI(Module Device) > [ 0.633969] ACPI: Added _OSI(Processor Device) > [ 0.634992] ACPI: Added _OSI(3.0 _SCP Extensions) > [ 0.635977] ACPI: Added _OSI(Processor Aggregator Device) > [ 0.640844] ACPI: Interpreter enabled > [ 0.641772] ACPI: (supports S0 S5) > [ 0.642657] ACPI: Using IOAPIC for interrupt routing > [ 0.643771] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug > [ 0.645732] ACPI: Enabled 2 GPEs in block 00 to 0F > [ 0.649727] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) > [ 0.650928] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI] > [ 0.652181] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM > [ 0.653575] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. > [ 0.656232] acpiphp: Slot [3] registered > [ 0.657161] acpiphp: Slot [4] registered > [ 0.658081] acpiphp: Slot [5] registered > [ 0.659030] acpiphp: Slot [6] registered > [ 0.659945] acpiphp: Slot [7] registered > [ 0.660973] acpiphp: Slot [8] registered > [ 0.662106] acpiphp: Slot [9] registered > [ 0.663188] acpiphp: Slot [10] registered > [ 0.664216] acpiphp: Slot [11] registered > [ 0.665140] acpiphp: Slot [12] registered > [ 0.666068] acpiphp: Slot [13] registered > [ 0.666992] acpiphp: Slot [14] registered > [ 0.667925] acpiphp: Slot [15] registered > [ 0.668843] acpiphp: Slot [16] registered > [ 0.669773] acpiphp: Slot [17] registered > [ 0.670697] acpiphp: Slot [18] registered > [ 0.671646] acpiphp: Slot [19] registered > [ 0.672694] acpiphp: Slot [20] registered > [ 0.673618] acpiphp: Slot [21] registered > [ 0.674570] acpiphp: Slot [22] registered > [ 0.675699] acpiphp: Slot [23] registered > [ 0.676655] acpiphp: Slot [24] registered > [ 0.677650] acpiphp: Slot [25] registered > [ 0.678824] acpiphp: Slot [26] registered > [ 0.679800] acpiphp: Slot [27] registered > [ 0.680767] acpiphp: Slot [28] registered > [ 0.681800] acpiphp: Slot [29] registered > [ 0.682768] acpiphp: Slot [30] registered > [ 0.683712] acpiphp: Slot [31] registered > [ 0.684636] PCI host bridge to bus 0000:00 > [ 0.685563] pci_bus 0000:00: root bus resource [bus 00-ff] > [ 0.686625] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] > [ 0.687824] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] > [ 0.689153] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] > [ 0.690953] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] > [ 0.703410] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] > [ 0.706481] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] > [ 0.707656] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] > [ 0.709058] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] > [ 0.719838] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI > [ 0.721715] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB > [ 0.858660] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11) > [ 0.860418] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11) > [ 0.862104] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11) > [ 0.863761] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11) > [ 0.866286] ACPI: PCI Interrupt Link [LNKS] (IRQs *9) > [ 0.868169] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none > [ 0.869981] vgaarb: loaded > [ 0.870747] vgaarb: bridge control possible 0000:00:02.0 > [ 0.872228] SCSI subsystem initialized > [ 0.873185] ACPI: bus type USB registered > [ 0.874153] usbcore: registered new interface driver usbfs > [ 0.875284] usbcore: registered new interface driver hub > [ 0.876587] usbcore: registered new device driver usb > [ 0.877839] EDAC MC: Ver: 3.0.0 > [ 0.879054] PCI: Using ACPI for IRQ routing > [ 0.880417] NetLabel: Initializing > [ 0.881305] NetLabel: domain hash size = 128 > [ 0.882378] NetLabel: protocols = UNLABELED CIPSOv4 > [ 0.883481] NetLabel: unlabeled traffic allowed by default > [ 0.884734] amd_nb: Cannot enumerate AMD northbridges > [ 0.885816] Switched to clocksource kvm-clock > [ 0.897592] pnp: PnP ACPI init > [ 0.898482] ACPI: bus type PNP registered > [ 0.900005] pnp: PnP ACPI: found 6 devices > [ 0.900990] ACPI: bus type PNP unregistered > [ 0.908314] NET: Registered protocol family 2 > [ 0.909652] TCP established hash table entries: 65536 (order: 7, 524288 bytes) > [ 0.911916] TCP bind hash table entries: 65536 (order: 8, 1048576 bytes) > [ 0.914052] TCP: Hash tables configured (established 65536 bind 65536) > [ 0.915370] TCP: reno registered > [ 0.916340] UDP hash table entries: 4096 (order: 5, 131072 bytes) > [ 0.917644] UDP-Lite hash table entries: 4096 (order: 5, 131072 bytes) > [ 0.919134] NET: Registered protocol family 1 > [ 0.920250] pci 0000:00:00.0: Limiting direct PCI/PCI transfers > [ 0.921471] pci 0000:00:01.0: PIIX3: Enabling Passive Release > [ 0.922671] pci 0000:00:01.0: Activating ISA DMA hang workarounds > [ 0.951864] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11 > [ 0.981733] Unpacking initramfs... > [ 1.939483] Freeing initrd memory: 61444k freed > [ 1.961508] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) > [ 1.962772] software IO TLB [mem 0xbbfda000-0xbffda000] (64MB) mapped at [ffffa032bbfda000-ffffa032bffd9fff] > [ 1.985881] sha1_ssse3: Using AVX2 optimized SHA-1 implementation > [ 1.987363] sha256_ssse3: Using AVX2 optimized SHA-256 implementation > [ 1.989132] futex hash table entries: 256 (order: 2, 16384 bytes) > [ 1.990346] Initialise system trusted keyring > [ 1.991411] audit: initializing netlink socket (disabled) > [ 1.992855] type=2000 audit(1533936097.464:1): initialized > [ 2.030648] HugeTLB registered 1 GB page size, pre-allocated 0 pages > [ 2.031888] HugeTLB registered 2 MB page size, pre-allocated 0 pages > [ 2.034824] zpool: loaded > [ 2.035626] zbud: loaded > [ 2.036913] VFS: Disk quotas dquot_6.5.2 > [ 2.037896] Dquot-cache hash table entries: 512 (order 0, 4096 bytes) > [ 2.039542] msgmni has been set to 15959 > [ 2.040595] Key type big_key registered > [ 2.042473] NET: Registered protocol family 38 > [ 2.043474] Key type asymmetric registered > [ 2.044410] Asymmetric key parser 'x509' registered > [ 2.045482] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248) > [ 2.047350] io scheduler noop registered > [ 2.048276] io scheduler deadline registered (default) > [ 2.049361] io scheduler cfq registered > [ 2.050277] io scheduler mq-deadline registered > [ 2.051254] io scheduler kyber registered > [ 2.052445] pci_hotplug: PCI Hot Plug PCI Core version: 0.5 > [ 2.053539] pciehp: PCI Express Hot Plug Controller Driver version: 0.4 > [ 2.055365] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 > [ 2.057169] ACPI: Power Button [PWRF] > [ 2.058952] GHES: HEST is not enabled! > [ 2.060178] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled > [ 2.085975] 00:04: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A > [ 2.111197] 00:05: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A > [ 2.113001] Non-volatile memory driver v1.3 > [ 2.114013] Linux agpgart interface v0.103 > [ 2.115268] crash memory driver: version 1.1 > [ 2.116496] rdac: device handler registered > [ 2.117504] hp_sw: device handler registered > [ 2.118520] emc: device handler registered > [ 2.119493] alua: device handler registered > [ 2.120542] libphy: Fixed MDIO Bus: probed > [ 2.121597] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver > [ 2.122799] ehci-pci: EHCI PCI platform driver > [ 2.123822] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver > [ 2.124977] ohci-pci: OHCI PCI platform driver > [ 2.125997] uhci_hcd: USB Universal Host Controller Interface driver > [ 2.157619] uhci_hcd 0000:00:01.2: UHCI Host Controller > [ 2.159129] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1 > [ 2.161347] uhci_hcd 0000:00:01.2: detected 2 ports > [ 2.162720] uhci_hcd 0000:00:01.2: irq 11, io base 0x0000c080 > [ 2.164110] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001 > [ 2.165384] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 > [ 2.167726] usb usb1: Product: UHCI Host Controller > [ 2.169169] usb usb1: Manufacturer: Linux 3.10.0-862.2.3.el7.x86_64 uhci_hcd > [ 2.170577] usb usb1: SerialNumber: 0000:00:01.2 > [ 2.172217] hub 1-0:1.0: USB hub found > [ 2.173542] hub 1-0:1.0: 2 ports detected > [ 2.175000] usbcore: registered new interface driver usbserial > [ 2.176233] usbcore: registered new interface driver usbserial_generic > [ 2.177774] usbserial: USB Serial support registered for generic > [ 2.179265] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 > [ 2.182252] serio: i8042 KBD port at 0x60,0x64 irq 1 > [ 2.183659] serio: i8042 AUX port at 0x60,0x64 irq 12 > [ 2.185082] mousedev: PS/2 mouse device common for all mice > [ 2.187008] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 > [ 2.189705] rtc_cmos 00:00: RTC can wake from S4 > [ 2.192230] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input2 > [ 2.195135] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0 > [ 2.196969] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram > [ 2.198980] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 > [ 2.201330] cpuidle: using governor menu > [ 2.202782] hidraw: raw HID events driver (C) Jiri Kosina > [ 2.204097] usbcore: registered new interface driver usbhid > [ 2.205513] usbhid: USB HID core driver > [ 2.206791] drop_monitor: Initializing network drop monitor service > [ 2.208675] TCP: cubic registered > [ 2.209650] Initializing XFRM netlink socket > [ 2.210871] NET: Registered protocol family 10 > [ 2.212358] NET: Registered protocol family 17 > [ 2.213425] mpls_gso: MPLS GSO support > [ 2.214942] microcode: CPU0 sig=0x506e3, pf=0x1, revision=0x1 > [ 2.216359] microcode: Microcode Update Driver: v2.01 , Peter Oruba > [ 2.218701] Loading compiled-in X.509 certificates > [ 2.220596] Loaded X.509 cert 'Red Hat Enterprise Linux Driver Update Program (key 3): bf57f3e87362bc7229d9f465321773dfd1f77a80' > [ 2.223610] Loaded X.509 cert 'Red Hat Enterprise Linux kpatch signing key: 4d38fd864ebe18c5f0b72e3852e2014c3a676fc8' > [ 2.226438] Loaded X.509 cert 'Red Hat Enterprise Linux kernel signing key: f069858c32950cc1b2e7de8ce20e565a586495b1' > [ 2.228961] registered taskstats version 1 > [ 2.233839] Key type trusted registered > [ 2.236900] Key type encrypted registered > [ 2.238105] IMA: No TPM chip found, activating TPM-bypass! (rc=-19) > [ 2.239987] Magic number: 14:813:398 > [ 2.241126] rtc_cmos 00:00: setting system clock to 2018-08-10 21:21:37 UTC (1533936097) > [ 2.244609] Freeing unused kernel memory: 1832k freed > [ 2.246970] Write protecting the kernel read-only data: 12288k > [ 2.250475] Freeing unused kernel memory: 856k freed > [ 2.254648] Freeing unused kernel memory: 684k freed > [ 2.260821] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.262716] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.264441] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.267337] systemd[1]: systemd 219 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 -SECCOMP +BLKID +ELFUTILS +KMOD +IDN) > [ 2.271308] systemd[1]: Detected virtualization kvm. > [ 2.272690] systemd[1]: Detected architecture x86-64. > [ 2.274023] systemd[1]: Running in initial RAM disk. > > Welcome to [0;34mRed Hat CoreOS 3.10 dracut-033-535.el7 (Initramfs)[0m! > > [ 2.275982] systemd[1]: No hostname configured. > [ 2.277191] systemd[1]: Set hostname to . > [ 2.278620] systemd[1]: Initializing machine ID from KVM UUID. > [ 2.289880] random: systemd-cryptse: uninitialized urandom read (16 bytes read) > [ 2.339425] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.340889] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.342235] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.343537] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.345722] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.347245] random: systemd: uninitialized urandom read (16 bytes read) > [ 2.353709] systemd[1]: Cannot add dependency job for unit blk-availability.service, ignoring: Unit not found. > [[32m OK [0m] Created slice Root Slice. > [ 2.357239] systemd[1]: Created slice Root Slice. > [ 2.358318] systemd[1]: Starting Root Slice. > [[32m OK [0m] Reached target Local File Systems. > [ 2.359795] systemd[1]: Reached target Local File Systems. > [ 2.360933] systemd[1]: Starting Local File Systems. > [[32m OK [0m] Created slice System Slice. > [ 2.362511] systemd[1]: Created slice System Slice. > [ 2.363568] systemd[1]: Starting System Slice. > [[32m OK [0m] Listening on udev Kernel Socket. > [ 2.365101] systemd[1]: Listening on udev Kernel Socket. > [ 2.366203] systemd[1]: Starting udev Kernel Socket. > [[32m OK [0m] Reached target Slices. > [ 2.367631] systemd[1]: Reached target Slices. > [ 2.368630] systemd[1]: Starting Slices. > [[32m OK [0m] Listening on Journal Socket. > [ 2.370041] systemd[1]: Listening on Journal Socket. > [ 2.371099] systemd[1]: Starting Journal Socket. > [ 2.372762] systemd[1]: Starting Journal Service... > Starting Journal Service... > [[32m OK [0m] Reached target Swap. > [ 2.374647] systemd[1]: Reached target Swap. > [ 2.375855] systemd[1]: Starting Swap. > [[32m OK [0m] Reached target Timers. > [ 2.378424] systemd[1]: Reached target Timers. > [ 2.381899] systemd[1]: Starting Timers. > [[32m OK [0m] Listening on udev Control Socket. > [ 2.384530] systemd[1]: Listening on udev Control Socket. > [ 2.387894] systemd[1]: Starting udev Control Socket. > [ 2.391592] systemd[1]: Starting Apply Kernel Variables... > Starting Apply Kernel Variables... > [[32m OK [0m] Reached target Local Encrypted Volumes. > [ 2.397938] systemd[1]: Reached target Local Encrypted Volumes. > [ 2.402561] systemd[1]: Starting Local Encrypted Volumes. > [ 2.406758] systemd[1]: Starting Create list of required static device nodes for the current kernel... > Starting Create list of required st... nodes for the current kernel... > [ 2.415654] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. > [ 2.420700] systemd[1]: Starting Dispatch Password Requests to Console Directory Watch. > [[32m OK [0m] Reached target Paths. > [ 2.423431] systemd[1]: Reached target Paths. > [ 2.424569] systemd[1]: Starting Paths. > [ 2.426370] systemd[1]: Starting dracut cmdline hook... > Starting dracut cmdline hook... > [[32m OK [0m] Started Journal Service. > [ 2.429140] systemd[1]: Started Journal Service. > [[32m OK [0m] Started Apply Kernel Variables. > [ 1.854627] systemd[1]: Started Apply Kernel Variables. > [[32m OK [0m] Started Create list of required sta...ce nodes for the current kernel. > [ 1.858068] systemd[1]: Started Create list of required static device nodes for the current kernel. > [ 1.860969] systemd[1]: Starting Create Static Device Nodes in /dev... > Starting Create Static Device Nodes in /dev... > [[32m OK [0m] Started Create Static Device Nodes in /dev. > [ 1.868949] systemd[1]: Started Create Static Device Nodes in /dev. > [ 2.475843] usb 1-1: new full-speed USB device number 2 using uhci_hcd > [ 2.604163] random: fast init done > [[32m OK [0m] Started dracut cmdline hook. > [ 2.032114] systemd[1]: Started dracut cmdline hook. > Starting dracut pre-udev hook... > [ 2.035076] systemd[1]: Starting dracut pre-udev hook... > [ 2.628688] usb 1-1: New USB device found, idVendor=0627, idProduct=0001 > [ 2.630048] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=5 > [ 2.631395] usb 1-1: Product: QEMU USB Tablet > [ 2.632420] usb 1-1: Manufacturer: QEMU > [ 2.633390] usb 1-1: SerialNumber: 42 > [ 2.642235] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-1/1-1:1.0/input/input4 > [ 2.644602] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Mouse [QEMU QEMU USB Tablet] on usb-0000:00:01.2-1/input0 > [ 2.655465] device-mapper: uevent: version 1.0.3 > [ 2.656640] device-mapper: ioctl: 4.37.0-ioctl (2017-09-20) initialised: dm-devel@redhat.com > [ 2.708310] RPC: Registered named UNIX socket transport module. > [ 2.709508] RPC: Registered udp transport module. > [ 2.710542] RPC: Registered tcp transport module. > [ 2.711556] RPC: Registered tcp NFSv4.1 backchannel transport module. > [ 2.723418] rpcbind[266]: cannot get uid of 'rpc': No such file or directory > [ 2.142931] rpcbind[266]: cannot get uid of 'rpc': No such file or directory > [ 2.730774] rpc.statd[270]: Version 1.3.0 starting > [ 2.150184] rpc.statd[270]: Version 1.3.0 starting > [ 2.736332] rpc.statd[270]: Initializing NSM state > [ 2.155583] rpc.statd[270]: Initializing NSM state > [ 2.738810] rpc.statd[270]: Running as root. chown /var/lib/nfs/statd to choose different user > [ 2.160018] rpc.statd[270]: Running as root. chown /var/lib/nfs/statd to choose different user > [ 2.744733] rpc.statd[270]: Failed to register (statd, 1, udp): svc_reg() err: RPC: Remote system error - Connection refused > [ 2.186586] rpc.statd[270]: Failed to register (statd, 1, udp): svc_reg() err: RPC: Remote system error - Connection refused > [ 2.769385] rpc.statd[270]: Failed to register (statd, 1, tcp): svc_reg() err: RPC: Remote system error - Connection refused > [ 2.191802] rpc.statd[270]: Failed to register (statd, 1, tcp): svc_reg() err: RPC: Remote system error - Connection refused > [ 2.774587] rpc.statd[270]: Failed to register (statd, 1, udp6): svc_reg() err: RPC: Remote system error - Connection refused > [ 2.196666] rpc.statd[270]: Failed to register (statd, 1, udp6): svc_reg() err: RPC: Remote system error - Connection refused > [ 2.779471] rpc.statd[270]: Failed to register (statd, 1, tcp6): svc_reg() err: RPC: Remote system error - Connection refused > [ 2.200447] rpc.statd[270]: Failed to register (statd, 1, tcp6): svc_reg() err: RPC: Remote system error - Connection refused > [ 2.201376] dracut-pre-udev[246]: rpc.idmapd: Could not find user "nobody" > [ 2.784579] rpc.statd[270]: failed to create RPC listeners, exiting > [ 2.203976] rpc.statd[270]: failed to create RPC listeners, exiting > [[32m OK [0m] Started dracut pre-udev hook. > Starting udev Kernel Device Manager...[ 2.227206] systemd[1]: Started dracut pre-udev hook. > [ 2.227936] systemd[1]: Starting udev Kernel Device Manager... > > [ 2.232217] systemd-udevd[296]: starting version 219 > [ 2.233251] systemd-udevd[296]: Network interface NamePolicy= disabled on kernel command line, ignoring. > [ 2.817057] systemd-udevd[296]: specified group 'tty' unknown > [ 2.236435] systemd-udevd[296]: specified group 'tty' unknown > [ 2.819868] systemd-udevd[296]: specified group 'kmem' unknown > [ 2.239225] systemd-udevd[296]: specified group 'kmem' unknown > [ 2.821752] systemd-udevd[296]: specified group 'input' unknown > [[32m OK [0m] Started udev Kernel Device Manager. > Starting dracut pre-trigger hook... > [ 2.245029] systemd-udevd[296]: specified group 'input' unknown > [ 2.834256] systemd-udevd[296]: specified group 'video' unknown > [ 2.255412] systemd-udevd[296]: specified group 'video' unknown > [ 2.840738] systemd-udevd[296]: specified group 'audio' unknown > [ 2.262024] systemd-udevd[296]: specified group 'audio' unknown > [ 2.844785] systemd-udevd[296]: specified group 'lp' unknown > [ 2.266022] systemd-udevd[296]: specified group 'lp' unknown > [ 2.848614] systemd-udevd[296]: specified group 'disk' unknown > [ 2.269228] systemd-udevd[296]: specified group 'disk' unknown > [ 2.269999] systemd[1]: Started udev Kernel Device Manager. > [ 2.270807] systemd[1]: Starting dracut pre-trigger hook... > [[32m OK [0m] Started dracut pre-trigger hook. > [ 2.321073] systemd[1]: Started dracut pre-trigger hook. > [ 2.322211] systemd[1]: Starting udev Coldplug all Devices... > Starting udev Coldplug all Devices... > [ 2.330064] systemd-udevd[296]: Network interface NamePolicy= disabled on kernel command line, ignoring. > [ 2.913013] systemd-udevd[296]: specified group 'tty' unknown > [ 2.333041] systemd-udevd[296]: specified group 'tty' unknown > [ 2.915709] systemd-udevd[296]: specified group 'kmem' unknown > [ 2.339025] systemd-udevd[296]: specified group 'kmem' unknown > [ 2.921632] systemd-udevd[296]: specified group 'input' unknown > [ 2.350878] systemd-udevd[296]: specified group 'input' unknown > [ 2.934608] systemd-udevd[296]: specified group 'video' unknown > [ 2.362069] systemd-udevd[296]: specified group 'video' unknown > Mounting Configuration File System... > [ 2.949447] systemd-udevd[296]: specified group 'audio' unknown > [ 2.376025] systemd-udevd[296]: specified group 'audio' unknown > [ 2.962348] systemd-udevd[296]: specified group 'lp' unknown > [[32m OK [0m] Mounted Configuration File System. > [ 2.386035] systemd-udevd[296]: specified group 'lp' unknown > [ 2.985206] systemd-udevd[296]: specified group 'disk' unknown > [ 2.986561] tsc: Refined TSC clocksource calibration: 1999.998 MHz > [ 2.414971] systemd-udevd[296]: specified group 'disk' unknown > [ 2.444214] systemd[1]: Mounting Configuration File System... > [ 2.444983] [[32m OK [0m] Started udev Coldplug all Devices. > [[32m OK [0m] Reached target System Initialization. > [[32m OK [0m] Listening on Open-iSCSI iscsiuio Socket. > [[32m OK [0m] Reached target Sockets. > [[32m OK [0m] Reached target Basic System. > Starting Open-iSCSI... > [ 3.036037] FDC 0 is a S82078B > systemd[1]: Mounted Configuration File System. > [ 2.461825] systemd[1]: Started udev Coldplug all Devices. > [ 2.473469] systemd[1]: Reached target System Initialization. > [ 3.059138] cryptd: max_cpu_qlen set to 100 > [ 3.064355] iscsid[353]: iSCSI logger with pid=355 started! > [ 2.496027] iscsid[353]: iSCSI logger with pid=355 started! > [ 2.496700] systemd[1]: Starting System Initialization. > [ 3.090134] iscsid[355]: iSCSI daemon with pid=356 started! > [ 2.518029] iscsid[355]: iSCSI daemon with pid=356 started! > [ 2.530163] systemd[1]: Listening on Open-iSCSI iscsiuio Socket. > [ 2.538039] systemd[1]: Starting Open-iSCSI iscsiuio Socket. > [ 2.538918] systemd[1]: Reached target Sockets. > [ 2.551035] systemd[1]: Starting Sockets. > [ 2.551643] systemd[1]: Reached target Basic System.[ 3.147926] Loading iSCSI transport class v2.0-870. > [ 3.152786] AVX2 version of gcm_enc/dec engaged. > [ 3.153841] AES CTR mode by8 optimization enabled > > [ 2.573770] systemd[1]: Starting Basic System. > [ 2.579531] systemd[1]: Starting Open-iSCSI... > [ 2.584483] systemd[1]: Failed to read PID from file /var/run/iscsid.pid: Invalid argument[[32m OK [0m] Started Open-iSCSI. > Starting dracut initqueue hook... > > [ 2.599206] systemd[1]: Started Open-iSCSI. > [ 2.599856] systemd[1]: Starting dracut initqueue hook... > [ 3.225859] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 10 > [ 3.232019] alg: No test for __gcm-aes-aesni (__driver-gcm-aes-aesni) > [ 3.233896] scsi host0: ata_piix > [ 3.236840] scsi host1: ata_piix > [ 3.237758] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0e0 irq 14 > [ 3.239340] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0e8 irq 15 > [ 3.244846] alg: No test for __generic-gcm-aes-aesni (__driver-generic-gcm-aes-aesni) > [ 2.716961] dracut-initqueue[367]: RTNETLINK answers: File exists > [ 3.337233] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10 > [ 3.367543] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 11 > [ 3.393544] vda: vda1 vda2 > [ 3.402849] vdb: > [ 3.018423] dracut-initqueue[367]: dhcp: PREINIT eth0 up > [ 3.035105] dhclient[494]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 4 (xid=0x77e7085b) > [ 3.037202] dhclient[494]: DHCPREQUEST on eth0 to 255.255.255.255 port 67 (xid=0x77e7085b) > [ 3.039275] dhclient[494]: DHCPOFFER from 10.74.148.53 > [ 3.040398] dhclient[494]: DHCPACK from 10.74.148.53 (xid=0x77e7085b) > [ 3.059577] dracut-initqueue[367]: dhcp: BOND setting eth0 > [ 4.066217] iscsid[355]: can't open InitiatorName configuration file /etc/iscsi/initiatorname.iscsi > [ 3.487351] iscsid[355]: can't open InitiatorName configuration file /etc/iscsi/initiatorname.iscsi > [ 4.070599] iscsid[355]: Warning: InitiatorName file /etc/iscsi/initiatorname.iscsi does not exist or does not contain a properly formatted InitiatorName. If using software iscsi (iscsi_tcp or ib_iser) or partial offload (bnx2i or cxgbi iscsi), you may not be able to log into or > [ 3.493346] iscsid[355]: Warning: InitiatorName file /etc/iscsi/initiatorname.iscsi does not exist or does not contain a properly formatted InitiatorName. If using software iscsi (iscsi_tcp or ib_iser) or partial offload (bnx2i or cxgbi iscsi), you may not be able to log into or > [ 4.077082] iscsid[355]: can't open InitiatorAlias configuration file /etc/iscsi/initiatorname.iscsi > [ 3.497267] iscsid[355]: can't open InitiatorAlias configuration file /etc/iscsi/initiatorname.iscsi > [ 4.080047] iscsid[355]: can't open iscsid.safe_logout configuration file /etc/iscsi/iscsid.conf > [ 3.500164] iscsid[355]: can't open iscsid.safe_logout configuration file /etc/iscsi/iscsid.conf > [ 5.072243] dhclient[494]: bound to 10.74.148.76 -- renewal in 36765 seconds. > [[32m OK [0m] Found device /dev/mapper/coreos-root. > [ 5.180485] systemd[1]: Found device /dev/mapper/coreos-root. > [ 5.182284] systemd[1]: Starting File System Check on /dev/mapper/coreos-root... > Starting File System Check on /dev/mapper/coreos-root... > [ 5.199392] systemd-fsck[579]: /sbin/fsck.xfs: XFS file system. > [[32m OK [0m] Started File System Check on /dev/mapper/coreos-root. > [ 5.201657] systemd[1]: Started File System Check on /dev/mapper/coreos-root. > [[32m OK [0m] Started dracut initqueue hook. > [ 5.748079] systemd[1]: Started dracut initqueue hook. > [ 5.749044] systemd[1]: Starting dracut pre-mount hook... > Starting dracut pre-mount hook... > [[32m OK [0m] Reached target Remote File Systems (Pre). > [ 5.750833] systemd[1]: Reached target Remote File Systems (Pre). > [ 5.751685] systemd[1]: Starting Remote File Systems (Pre). > [[32m OK [0m] Reached target Remote File Systems. > [ 5.753131] systemd[1]: Reached target Remote File Systems. > [ 5.754065] systemd[1]: Starting Remote File Systems. > [[32m OK [0m] Started dracut pre-mount hook. > [ 5.773069] systemd[1]: Started dracut pre-mount hook. > [ 5.773967] systemd[1]: Mounting /sysroot... > Mounting /sysroot... > [ 6.433917] SGI XFS with ACLs, security attributes, no debug enabled > [ 6.438078] XFS (dm-0): Mounting V5 Filesystem > [ 6.560819] XFS (dm-0): Ending clean mount > [[32m OK [0m] Mounted /sysroot. > [[32m OK [0m] Reached target Initrd Root File System. > [ 5.982152] systemd[1]: Mounted /sysroot. > [ 5.982867] systemd[1]: Reached target Initrd Root File System. > [ 5.983686] systemd[1]: Starting Initrd Root File System. Starting Reload Configuration from the Real Root... > [ 5.985414] systemd[1]: Starting Reload Configuration from the Real Root... > > [ 5.992051] systemd[1]: Reloading. > [[32m OK [0m] Started Reload Configuration from the Real Root. > [ 6.055420] systemd[1]: Started Reload Configuration from the Real Root. > [[32m OK [0m] Reached target Initrd File Systems. > [ 6.056928] systemd[1]: Reached target Initrd File Systems. > [ 6.057675] systemd[1]: Starting Initrd File Systems. > [[32m OK [0m] Reached target Initrd Default Target. > [ 6.059056] systemd[1]: Reached target Initrd Default Target. > [ 6.059756] systemd[1]: Starting Initrd Default Target. Starting dracut pre-pivot and cleanup hook... > > [ 6.061317] systemd[1]: Starting dracut pre-pivot and cleanup hook... > [[32m OK [0m] Started dracut pre-pivot and cleanup hook. > Starting Cleaning Up and Shutting Down Daemons... > [ 6.257076] systemd[1]: Started dracut pre-pivot and cleanup hook. > [ 6.258063] systemd[1]: Starting Cleaning Up and Shutting Down Daemons... > [[32m OK [0m] Stopped target Timers. > [ 6.265939] systemd[1]: Stopped target Timers. > [ 6.267136] systemd[1]: Stopping Timers. > [[32m OK [0m] Stopped Cleaning Up and Shutting Down Daemons. > [ 6.268748] systemd[1]: Stopped Cleaning Up and Shutting Down Daemons. > [[32m OK [0m] Stopped dracut pre-pivot and cleanup hook. > [ 6.271930] systemd[1]: Stopped dracut pre-pivot and cleanup hook. > [ 6.273041] systemd[1]: Stopping dracut pre-pivot and cleanup hook... > Stopping dracut pre-pivot and cleanup hook... > [[32m OK [0m] Stopped dracut pre-mount hook. > [ 6.275031] systemd[1]: Stopped dracut pre-mount hook. > [ 6.275906] systemd[1]: Stopping dracut pre-mount hook... > Stopping dracut pre-mount hook... > [[32m OK [0m] Stopped target Remote File Systems. > [ 6.277601] systemd[1]: Stopped target Remote File Systems. > [[32m OK [0m] Stopped target Remote File Systems (Pre). > [ 6.279076] systemd[1]: Stopping Remote File Systems. > [ 6.279776] systemd[1]: Stopped target Remote File Systems (Pre). > [ 6.280580] systemd[1]: Stopping Remote File Systems (Pre).[[32m OK [0m] Stopped dracut initqueue hook. > Stopping dracut initqueue hook... > [ 6.282560] systemd[1]: Stopped dracut initqueue hook. > Stopping Open-iSCSI... > [ 6.284486] systemd[1]: Stopping dracut initqueue hook... > [ 6.285197] systemd[1]: Stopping Open-iSCSI... > > [[32m OK [0m] Stopped target Initrd Default Target. > [[32m OK [0m] Stopped target Basic System. > [[32m OK [0m] Stopped target Sockets.[ 6.287227] systemd[1]: Stopped target Initrd Default Target. > [ 6.287916] > [[32m OK [0m] Closed Open-iSCSI iscsiuio Socket. > [[32m OK [0m] Stopped target Paths. > systemd[1]: Stopping Initrd Default Target. > [ 6.290643] systemd[1]: Stopped target Basic System.[[32m OK [0m] Stopped target Slices. > [[32m OK [0m] Stopped target System Initialization. > > [ 6.293414] systemd[1]: Stopping Basic System. > [[32m OK [0m] Stopped udev Coldplug all Devices.[ 6.878937] iscsid[355]: iscsid shutting down. > > Stopping udev Coldplug all Devices... > [[32m OK [0m[ 6.299107] iscsid[355]: iscsid shutting down. > [ 6.299745] systemd[1]: Stopped target Sockets.] Stopped dracut pre-trigger hook. > Stopping dracut pre-trigger hook... > > Stopping udev Kernel Device Manager... > [[32m OK [0m] Stopped Apply Kernel Variables.[ 6.307358] systemd[1]: Stopping Sockets. > [ 6.307990] systemd[1]: Closed Open-iSCSI iscsiuio Socket. > [ 6.308740] systemd[1]: Stopping Open-iSCSI iscsiuio Socket. > Stopping Apply Kernel Variables... > [[32m OK [0m] Stopped target Swap. > [[32m OK [0m > [ 6.311301] systemd[1]: Stopped target Paths. > [ 6.311921] ] Stopped target Local File Systems. > [[32m OK [0m] Stopped target Local Encrypted Volumes. > [[32m OK [0m] Stopped udev Kernel Device Manager. > systemd[1]: Stopping Paths. > [ 6.314506] systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch. > [ 6.315876] systemd[[32m OK [0m] Stopped Open-iSCSI. > [1]: Stopping Dispatch Password Requests to Console Directory Watch. > [ 6.317777] systemd[1]: [[32m OK [0m] Stopped target Slices. > [ 6.319458] systemd[1]: Stopping Slices. > Stopped Create Static Device Nodes in /dev.[ 6.321151] systemd[1]: Stopped target System Initialization. > [ 6.321865] systemd > Stopping Create Static Device Nodes in /dev... > [[32m OK [0m[1]: Stopping System Initialization. > [ 6.323528] systemd[1]: Stopped udev Coldplug all Devices. > ] Stopped Create list of required sta...ce nodes for the current kernel. > Stopping Create list of required st... nodes for the current kernel...[ 6.325319] systemd[1]: Stopping udev Coldplug all Devices... > > [[32m OK [0m] Stopped dracut pre-udev hook. > Stopping dracut pre-udev hook...[ 6.327199] systemd[1]: Stopped dracut pre-trigger hook. > [ 6.327863] systemd > [[32m OK [0m] Stopped dracut cmdline hook. > Stopping dracut cmdline hook...[1]: Stopping dracut pre-trigger hook... > [ 6.329607] systemd[1]: Stopping udev Kernel Device Manager... > [[32m OK [0m] Closed udev Control Socket. > [[32m OK [0m] Closed udev Kernel Socket. > [ 6.331313] systemd[1]: Stopped Apply Kernel Variables. > [ 6.331962] > Starting Cleanup udevd DB...systemd[1]: Stopping Apply Kernel Variables... > [ 6.333768] systemd[1]: > Stopped target Swap. > [ 6.334710] systemd[1]: Stopping Swap. > [ 6.336340] systemd[1]: Stopped target Local File Systems. > [ 6.338245] systemd[1]: Stopping Local File Systems. > [ 6.338895] systemd[1]: Stopped target Local Encrypted Volumes. > [ 6.340641] systemd[1]: Stopping Local Encrypted Volumes. > [ 6.342193] systemd[1]: Stopped udev Kernel Device Manager. > [ 6.342890] [[32m OK [0m] Started Cleanup udevd DB. > [[32m OK [0m] Reached target Switch Root. > Starting Ask OSTree to mount /var in initramfs... > systemd[1]: Stopped Open-iSCSI. > [ 6.347068] systemd[1]: Stopped Create Static Device Nodes in /dev. > [ 6.347837] systemd[1]: Stopping Create Static Device Nodes in /dev... > [ 6.349726] systemd[1]: Stopped Create list of required static device nodes for the current kernel. > [ 6.351911] systemd[1]: Stopping Create list of required static device nodes for the current kernel... > [ 6.354708] systemd[1]: Stopped dracut pre-udev hook.[[32m OK [0m] Started Ask OSTree to mount /var in initramfs. > Starting OSTree Prepare OS/... > > [ 6.357636] systemd[1]: Stopping dracut pre-udev hook... > [ 6.360243] systemd[1]: Stopped dracut cmdline hook. > [ 6.361453] systemd[1]: Stopping dracut cmdline hook... > [ 6.362288] systemd[1]: Closed udev Control Socket. > [ 6.362946] systemd[1]: Stopping udev Control Socket. > [ 6.363675] systemd[1]: Closed udev Kernel Socket. > [ 6.364339] systemd[1]: Stopping udev Kernel Socket. > [ 6.365177] systemd[1]: Starting Cleanup udevd DB... > [ 6.365824] systemd[1]: Started Cleanup udevd DB. > [ 6.366474] systemd[1]: Reached target Switch Root. > [ 6.367159] systemd[1]: Starting Switch Root. > [ 6.367774] systemd[1]: Starting Ask OSTree to mount /var in initramfs... > [ 6.368648] systemd[1]: Started Ask OSTree to mount /var in initramfs. > [ 6.369446] systemd[1]: Starting OSTree Prepare OS/... > [ 6.381114] ostree-prepare-root[725]: Resolved OSTree target to: /sysroot/ostree/deploy/rhcos/deploy/a6d9144d664945c4e6cd517a05d117497caf761ec242faf2e5ad7a3eb492db18.0[[32m OK [0m] Started OSTree Prepare OS/. > > [ 6.384266] systemd[1]: Started OSTree Prepare OS/. > Starting Ignition (files)... > [ 6.386827] systemd[1]: Starting Ignition (files)... > [ 6.394850] ignition[728]: INFO : Ignition 0.26.0 > [ 6.395708] ignition[728]: INFO : reading system config file "/usr/lib/ignition/base.ign" > [ 6.396787] ignition[728]: INFO : no config at "/usr/lib/ignition/base.ign" > [ 6.398048] ignition[728]: DEBUG : parsed url from cmdline: "" > [ 6.398804] ignition[728]: INFO : no config URL provided > [ 6.400741] ignition[728]: INFO : reading system config file "/usr/lib/ignition/user.ign" > [ 6.401961] ignition[728]: INFO : no config at "/usr/lib/ignition/user.ign" > [ 6.402980] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #1 > [ 6.403991] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 6.405054] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 7.402152] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 7.403304] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 8.402322] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 8.403431] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 9.402555] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 9.403716] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 10.402786] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 10.403910] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 11.403043] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 11.404206] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 12.403262] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 12.404721] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 13.403521] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 13.404893] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 13.417747] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 13.618205] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #2 > [ 13.619502] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 14.019558] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #3 > [ 14.020885] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 14.403752] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 14.404897] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 14.821037] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #4 > [ 14.822440] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 15.404033] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 15.405174] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 16.404259] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 16.405379] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 16.422405] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #5 > [ 16.423610] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 17.404517] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 17.406064] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 18.404763] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 18.405997] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 19.405072] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 19.406252] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 19.623830] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #6 > [ 19.625952] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 20.405332] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 20.406665] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 21.405584] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 21.406713] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 22.405834] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 22.407021] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 23.406244] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 23.407425] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 24.406460] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 24.407661] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 24.625044] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #7 > [ 24.626610] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 25.406705] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 25.408303] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 26.406947] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 26.408153] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 27.407209] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 27.408702] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 28.407457] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 28.408815] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 29.407656] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 29.408818] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 29.626570] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #8 > [ 29.628098] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 30.408059] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 30.409661] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 31.408277] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 31.409474] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 32.408477] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 32.409843] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 33.408710] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 33.409827] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 34.408893] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [ 34.410051] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 34.627916] ignition[728]: INFO : GET http://169.254.169.254/openstack/latest/user_data: attempt #9 > [ 34.629282] ignition[728]: INFO : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host > [ 35.409193] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting... > [ 35.410374] ignition[728]: DEBUG : config drive ("/dev/disk/by-label/config-2") not found. Waiting... > [[32m OK [0m] Started Ignition (files). > Starting Switch Root... > [ 36.401531] systemd[1]: Started Ignition (files). > [ 36.402365] ignition[728]: INFO : neither config drive nor metadata service were available in time. Continuing without a config... > [ 36.405180] ignition[728]: WARNING : failed to fetch config: not a config (empty) > [ 36.405820] ignition[728]: INFO : not a config (empty): ignoring user-provided config > [ 36.407588] ignition[728]: INFO : reading system config file "/usr/lib/ignition/default.ign" > [ 36.410312] ignition[728]: INFO : no config at "/usr/lib/ignition/default.ign" > [ 36.410948] systemd[1]: Starting Switch Root... > [ 37.005791] systemd[1]: Switching root. > [ 36.425115] systemd[1]: Switching root. > [ 37.007771] systemd-journald[95]: Received SIGTERM from PID 1 (systemd). > [ 37.581985] type=1403 audit(1533936132.840:2): policy loaded auid=4294967295 ses=4294967295 > [ 37.593664] systemd[1]: Successfully loaded SELinux policy in 190.553ms. > [ 37.685675] ip_tables: (C) 2000-2006 Netfilter Core Team > [ 37.686868] systemd[1]: Inserted module 'ip_tables' > [ 37.711071] systemd[1]: Relabelled /dev and /run in 20.399ms. > [ 37.745467] systemd[1]: [/etc/systemd/system.conf.d/origin-accounting.conf:5] Unknown lvalue 'DefaultIOAccounting' in section 'Manager' > > Welcome to [0;31mRed Hat CoreOS 3.10[0m! > > [[32m OK [0m] Stopped Switch Root. > [[32m OK [0m] Stopped Journal Service. > Starting Journal Service... > [[32m OK [0m] Listening on udev Kernel Socket. > [[32m OK [0m] Reached target Remote Encrypted Volumes. > [[32m OK [0m] Listening on udev Control Socket. > Starting Setup Virtual Console... > [[32m OK [0m] Listening on LVM2 metadata daemon socket. > [[32m OK [0m] Reached target Swap. > Mounting Huge Pages File System... > [[32m OK [0m] Created slice system-getty.slice. > [[32m OK [0m] Created slice system-serial\x2dgetty.slice. > [[32m OK [0m] Listening on Device-mapper event daemon FIFOs. > Mounting Temporary Directory... > Starting Create list of required st... nodes for the current kernel... > Mounting Debug File System... > [[32m OK [0m] Created slice User and Session Slice. > Mounting POSIX Message Queue File System... > [[32m OK [0m] Stopped target Switch Root. > [[32m OK [0m] Stopped target Initrd File Systems. > [[32m OK [0m] Stopped File System Check on Root Device. > Stopping File System Check on Root Device... > Starting Remount Root and Kernel File Systems... > [[32m OK [0m] Listening on LVM2 poll daemon socket. > [[32m OK [0m] Listening on /dev/initctl Compatibility Named Pipe. > [[32m OK [0m] Reached target Remote File Systems. > Starting Availability of block devices... > Starting Monitoring of LVM2 mirrors... dmeventd or progress polling... > [[32m OK [0m] Created slice system-selinux\x2dpol...grate\x2dlocal\x2dchanges.slice. > [[32m OK [0m] Stopped target Initrd Root File System. > [[32m OK [0m] Reached target Paths. > [[32m OK [0m] Reached target Slices. > [[32m OK [0m] Reached target Local Encrypted Volumes. > [[32m OK [0m] Set up automount Arbitrary Executab...ats File System Automount Point. > [[32m OK [0m] Listening on Delayed Shutdown Socket. > Starting Apply Kernel Variables... > [[32m OK [0m] Mounted Debug File System. > [[32m OK [0m] Mounted POSIX Message Queue File System. > [[32m OK [0m] Mounted Huge Pages File System. > [[32m OK [0m] Mounted Temporary Directory. > [[32m OK [0m] Started Journal Service. > [[32m OK [0m] Started Setup Virtual Console. > [[32m OK [0m] Started Create list of required sta...ce nodes for the current kernel. > [[32m OK [0m] Started Remount Root and Kernel File Systems. > [[32m OK [0m] Started Availability of block devices. > [[32m OK [0m] Started Apply Kernel Variables. > [[32m OK [0m] Started LVM2 metadata daemon. > Starting LVM2 metadata daemon... > Starting OSTree Remount OS/ bind mounts... > Starting First Boot Wizard... > Starting Rebuild Hardware Database... > [[32m OK [0m] Started Seed default bash profile for root. > Starting Seed default bash profile for root... > Starting Create Static Device Nodes in /dev... > [[32m OK [0m] Started OSTree Remount OS/ bind mounts. > Starting Load/Save Random Seed... > Starting Flush Journal to Persistent Storage... > [[32m OK [0m] Started Load/Save Random Seed. > [[32m OK [0m] Started First Boot Wizard. > [ 39.134182] systemd-journald[751]: Received request to flush runtime journal from PID 1 > [ 39.154375] random: crng init done > [[32m OK [0m] Started Create Static Device Nodes in /dev. > Starting udev Kernel Device Manager... > [[32m OK [0m] Started Flush Journal to Persistent Storage. > [[32m OK [0m] Started udev Kernel Device Manager. > [[32m OK [0m] Started Rebuild Hardware Database. > Starting udev Coldplug all Devices... > [[32m OK [0m] Started udev Coldplug all Devices. > [ 39.721768] input: PC Speaker as /devices/platform/pcspkr/input/input5 > [[32m OK [0m] Created slice system-lvm2\x2dpvscan.slice. > Starting LVM2 PV scan on device 252:2... > [ 39.786360] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 > [[32m OK [0m] Found device /dev/disk/by-uuid/e1ad011a-e12b-4bef-bda4-8ca506c3b52f. > [[32m OK [0m] Found device /dev/ttyS0. > [[32m OK [0m] Started Monitoring of LVM2 mirrors,...ng dmeventd or progress polling. > [[32m OK [0m] Reached target Local File Systems (Pre). > Mounting /boot... > [ 39.943270] XFS (vda1): Mounting V5 Filesystem > [ 40.007099] ppdev: user-space parallel port driver > [ 40.056110] Error: Driver 'pcspkr' is already registered, aborting... > [ 40.135175] [TTM] Zone kernel: Available graphics memory: 4087358 kiB > [ 40.136628] [TTM] Zone dma32: Available graphics memory: 2097152 kiB > [ 40.137855] [TTM] Initializing pool allocator > [ 40.140889] [TTM] Initializing DMA pool allocator > [ 40.143893] [drm] fb mappable at 0xFC000000 > [ 40.145029] [drm] vram aper at 0xFC000000 > [ 40.146099] [drm] size 33554432 > [ 40.146987] [drm] fb depth is 24 > [ 40.147907] [drm] pitch is 3072 > [ 40.153115] fbcon: cirrusdrmfb (fb0) is primary device > [ 40.197948] Console: switching to colour frame buffer device 128x48 > [ 40.202641] cirrus 0000:00:02.0: fb0: cirrusdrmfb frame buffer device > [ 40.206232] [drm] Initialized cirrus 1.0.0 20110418 for 0000:00:02.0 on minor 0 > [ 41.631067] XFS (vda1): Ending clean mount > [[32m OK [0m] Mounted /boot. > [[32m OK [0m] Reached target Local File Systems. > Starting Create Volatile Files and Directories... > Starting Rebuild Journal Catalog... > Starting Migrate local SELinux poli...tructure to the new structure... > [[32m OK [0m] Started Rebuild Journal Catalog. > Starting Update is Completed... > [[32m OK [0m] Started Update is Completed. > [[32m OK [0m] Started Migrate local SELinux polic... structure to the new structure. > [[32m OK [0m] Started Create Volatile Files and Directories. > Starting Update UTMP about System Boot/Shutdown... > [[32m OK [0m] Started Update UTMP about System Boot/Shutdown. > [[32m OK [0m] Reached target System Initialization. > [[32m OK [0m] Listening on RPCbind Server Activation Socket. > Starting RPC bind service... > [[32m OK [0m] Listening on Docker Block RHEL push plugin Socket for the API. > [[32m OK [0m] Listening on D-Bus System Message Bus Socket. > [[32m OK [0m] Reached target Sockets. > [[32m OK [0m] Reached target Basic System. > Starting Authorization Manager... > Starting Open Container Initiative Daemon... > Starting Docker Storage Setup... > Starting Permit User Sessions... > [[32m OK [0m] Started irqbalance daemon. > Starting irqbalance daemon... > Starting Login Service... > Starting Mark boot complete... > [[32m OK [0m] Reached target Containers. > Starting OpenSSH Server Key Generation... > Starting NTP client/server... > [[32m OK [0m] Started D-Bus System Message Bus. > Starting D-Bus System Message Bus... > Starting Network Manager... > [[32m OK [0m] Reached target Timers. > [[32m OK [0m] Started LVM2 PV scan on device 252:2. > [[32m OK [0m] Started RPC bind service. > [[32m OK [0m] Started Permit User Sessions. > [[32m OK [0m] Started Mark boot complete. > [[32m OK [0m] Started Getty on tty1. > Starting Getty on tty1... > [[32m OK [0m] Started Serial Getty on ttyS0. > Starting Serial Getty on ttyS0... > [[32m OK [0m] Reached target Login Prompts. > [[32m OK [0m] Started Login Service. > [[32m OK [0m] Started NTP client/server. > [[32m OK [0m] Started Authorization Manager. > Starting Hostname Service... > [[32m OK [0m] Started Hostname Service. > [[32m OK [0m] Started Network Manager. > [[32m OK [0m] Reached target Network. > Starting SystemWide Container Registries... > Starting Dynamic System Tuning Daemon... > Starting Network Manager Script Dispatcher Service... > [[32m OK [0m] Started Network Manager Script Dispatcher Service. > [ 43.279892] TECH PREVIEW: Overlay filesystem may not be fully supported. > [ 43.279892] Please review provided documentation for limitations. > [ 43.691020] nf_conntrack version 0.5.0 (65536 buckets, 262144 max) > [[32m OK [0m] Started Open Container Initiative Daemon. > [[32m OK [0m] Started Docker Storage Setup. > [[32m OK [0m] Started SystemWide Container Registries. > Starting Docker Application Container Engine... > [[32m OK [0m] Started OpenSSH Server Key Generation. > Starting OpenSSH server daemon... > [[32m OK [0m] Started OpenSSH server daemon. > [[32m OK [0m] Started Dynamic System Tuning Daemon. > [ 46.685947] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this. > [ 46.698930] Bridge firewalling registered > [ 46.981854] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready > [[32m OK [0m] Started Docker Block RHEL push plugin authZ Plugin. > Starting Docker Block RHEL push plugin authZ Plugin... > > Red Hat CoreOS 3.10 > Kernel 3.10.0-862.2.3.el7.x86_64 on an x86_64 > > host-10-74-148-76 login:

jlebon commented 6 years ago

Sounds like https://github.com/coreos/ignition/issues/597 -- can you try setting ignition.timeouts as mentioned there?

arithx commented 6 years ago

There's a lot of tcp errors trying to fetch from the metadata service: dial tcp 169.254.169.254:80: getsockopt: no route to host

jstuever commented 6 years ago

I should have added... this works using CoreOS container-Linux with the exact same provisioning parameters.

arithx commented 6 years ago

My initial guess would be that there's an issue with networking in the initramfs. @bgilbert or @ajeddeloh might be able to chime in a bit more but given we've had someone else also report issues with fetching userdata on RHCOS (without the TCP errors though notably), while it works on CL in the same OpenStack deployment that would be where I'd start digging.

jstuever commented 6 years ago

I changed the ignition.timeouts in the user_data to 60 seconds for each. That didn't appear to help... I didn't think it would considering network unreachable... and now we know.

sjenning commented 6 years ago

I also hit this issue, though my GET for the metadata just hangs forever

Starting Ignition (files)...
[    4.991984] systemd[1]: Starting Ignition (files)...
[    4.997905] ignition[752]: INFO     : Ignition 0.27.0
[    4.999040] ignition[752]: INFO     : reading system config file "/usr/lib/ignition/base.ign"
[    5.000415] ignition[752]: INFO     : no config at "/usr/lib/ignition/base.ign"
[    5.001404] ignition[752]: DEBUG    : parsed url from cmdline: ""
[    5.001611] ignition[752]: INFO     : no config URL provided
[    5.001809] ignition[752]: INFO     : reading system config file "/usr/lib/ignition/user.ign"
[    5.002040] ignition[752]: INFO     : no config at "/usr/lib/ignition/user.ign"
[    5.002236] ignition[752]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #1
[    5.002452] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    5.002650] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[    6.000612] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    6.001823] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[    7.000769] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    7.001934] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[    8.000922] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[    8.002086] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    9.001101] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    9.002432] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   10.001280] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   10.003077] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   11.001452] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   11.002663] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   12.001655] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   12.002682] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   13.001810] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   13.002952] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   14.001959] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   14.003077] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   15.002125] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   15.003447] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   16.002276] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   16.003623] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   17.002436] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   17.003601] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   18.002618] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   18.003839] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   19.002774] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   19.004022] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   20.002938] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   20.003951] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   21.003103] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   21.004199] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   22.003277] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   22.004629] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   23.003460] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   23.004545] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   24.003621] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   24.005022] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   25.003773] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   25.005108] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   26.003924] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   26.004952] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   27.004114] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   27.005508] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   28.004282] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   28.005772] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   29.004432] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   29.005661] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   30.004615] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   30.005800] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   31.004784] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   31.005934] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   32.004956] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   32.006174] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   33.005116] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   33.006162] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   34.005290] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   34.006516] ignition[752]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   34.998065] ignition[752]: INFO     : neither config drive nor metadata service were available in time. Continuing without a config...
[   34.998984] ignition[752]: ERROR    : timed out while fetching config from config drive (CONFIG-2)
[   34.999380] ignition[752]: ERROR    : timed out while fetching config from config drive (config-2)
[   34.999504] ignition[752]: WARNING  : failed to fetch config: not a config (empty)
[   34.999627] ignition[752]: INFO     : not a config (empty): ignoring user-provided config
[   34.999751] ignition[752]: INFO     : reading system config file "/usr/lib/ignition/default.ign"
[   34.999877] ignition[752]: INFO     : no config at "/usr/lib/ignition/default.ign"
[   35.006209] ignition[752]: INFO     : files: files passed
[[32m  OK  [0m] [   35.007252] Started Ignition (files).ignition

I've already tried via the config drive and that doesn't work either. It is possible that neither udev or networking is properly setup/running but this point in the boot process.

Using the Container Linux image from https://coreos.com/os/docs/latest/booting-on-openstack.html works fine on the same Openstack installation.

# journalctl | grep ignition | grep -v audit
Aug 15 21:16:10 localhost ignition[445]: Ignition v0.25.1
Aug 15 21:16:10 localhost ignition[445]: reading system config file "/usr/lib/ignition/base.ign"
Aug 15 21:16:10 localhost ignition[445]: no config at "/usr/lib/ignition/base.ign"
Aug 15 21:16:10 localhost ignition[445]: parsed url from cmdline: ""
Aug 15 21:16:10 localhost ignition[445]: no config URL provided
Aug 15 21:16:10 localhost ignition[445]: reading system config file "/usr/lib/ignition/user.ign"
Aug 15 21:16:10 localhost ignition[445]: no config at "/usr/lib/ignition/user.ign"
Aug 15 21:16:10 localhost ignition[445]: GET http://169.254.169.254/openstack/latest/user_data: attempt #1
Aug 15 21:16:10 localhost ignition[445]: config drive ("/dev/disk/by-label/config-2") not found. Waiting...
Aug 15 21:16:10 localhost ignition[445]: config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
Aug 15 21:16:10 localhost ignition[445]: GET result: OK
Aug 15 21:16:10 localhost ignition[445]: disks: op(1): [started]  waiting for udev to settle
Aug 15 21:16:10 localhost ignition[445]: disks: op(1): executing: "/usr/bin/udevadm" "settle"
Aug 15 21:16:10 localhost ignition[445]: disks: op(1): [finished] waiting for udev to settle
Aug 15 21:16:11 localhost ignition[502]: Ignition v0.25.1
Aug 15 21:16:11 localhost ignition[502]: reading system config file "/usr/lib/ignition/base.ign"
Aug 15 21:16:11 localhost ignition[502]: no config at "/usr/lib/ignition/base.ign"
Aug 15 21:16:11 localhost ignition[502]: files: createUsers: op(1): [started]  checking if user "sjennings" exists
Aug 15 21:16:11 localhost ignition[502]: files: createUsers: op(1): executing: "/usr/bin/chroot" "/sysroot" "/usr/bin/id" "sjennings"
Aug 15 21:16:11 localhost ignition[502]: files: createUsers: op(1): [failed]   checking if user "sjennings" exists: exit status 1: Cmd: "/usr/bin/chroot" "/sysroot" "/usr/bin/id" "sjennings" Stdout: "" Stderr: "/usr/bin/id: 'sjennings': no such user\n"
Aug 15 21:16:11 localhost ignition[502]: files: createUsers: op(2): [started]  creating or modifying user "sjennings"
Aug 15 21:16:11 localhost ignition[502]: files: createUsers: op(2): executing: "/usr/sbin/useradd" "--root" "/sysroot" "--create-home" "--password" "*" "--groups" "sudo" "sjennings"
Aug 15 21:16:11 localhost ignition[502]: files: createUsers: op(2): [finished] creating or modifying user "sjennings"
Aug 15 21:16:11 localhost ignition[502]: files: createUsers: op(3): [started]  adding ssh keys to user "sjennings"
Aug 15 21:16:11 localhost ignition[502]: files: createUsers: op(3): [finished] adding ssh keys to user "sjennings"

ajeddeloh commented 6 years ago

Can you add rd.break to the kernel command line and see if networking is up?

jstuever commented 6 years ago

I found that the same rhcos image pulls user_data in some situations. I found it working when passing an empty user_data and using a different network/subnet.

ashcrow commented 6 years ago

dustymabe commented 6 years ago

I tried this on 4.0.4707 and it seemed to work fine for me:

ignition[731]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #1 
ignition[731]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
ignition[731]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...

can we start sharing commands for how instances were started so we can try to come together on what the issue is? here is what I have for now:

openstack server create  \
 --key-name dusty-keypair \
 --network atomic-e2e-jenkins-test \
 --image rhcos/continuous \
 --flavor m1.small \
 --user-data /dev/stdin \
 dusty-server <<'EOF'
{
  "ignition": { "version": "2.2.0" },
  "passwd": {
    "users": [
      {
        "name": "core",
        "sshAuthorizedKeys": [
          "ssh-rsa AAAAB..."                                                                               
        ]
      }
    ]
  }
}
EOF

of course you need to update AAAAB with your pubkey.

rfairley commented 6 years ago

The same command on 4.0.4707 (with slightly different ignition config) gave the same messages as @dustymabe :

[    5.971531] ignition[731]: INFO     : Ignition 0.27.0
[    5.659792] ignition[731]: INFO     : Ignition 0.27.0
[    5.973417] ignition[731]: INFO     : reading system config file "/usr/lib/ignition/base.ign"
[    5.662565] ignition[731]: INFO     : reading system config file "/usr/lib/ignition/base.ign"
[    5.976419] ignition[731]: INFO     : no config at "/usr/lib/ignition/base.ign"
[    5.665395] ignition[731]: INFO     : no config at "/usr/lib/ignition/base.ign"
[    5.979164] ignition[731]: DEBUG    : parsed url from cmdline: ""
[    5.667504] ignition[731]: DEBUG    : parsed url from cmdline: ""
[    5.981188] ignition[731]: INFO     : no config URL provided
[    5.669491] ignition[731]: INFO     : no config URL provided
[    5.983122] ignition[731]: INFO     : reading system config file "/usr/lib/ignition/user.ign"
[    5.672223] ignition[731]: INFO     : reading system config file "/usr/lib/ignition/user.ign"
[    5.986043] ignition[731]: INFO     : no config at "/usr/lib/ignition/user.ign"
[    5.674995] ignition[731]: INFO     : no config at "/usr/lib/ignition/user.ign"
[    5.988755] ignition[731]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #1
[    5.677963] ignition[731]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #1
[    5.991840] ignition[731]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    5.681069] ignition[731]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    5.994963] ignition[731]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[    5.684191] ignition[731]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...

command:

openstack server create \
 --network atomic-e2e-jenkins-test \
 --config-drive True \
 --image rhcos/continuous \
 --flavor m1.small \
 --user-data /dev/stdin \
 rfairley-rhcos-test <<'EOF'
{"ignition":{"config":{},"security":{"tls":{}},"timeouts":{},"version":"2.2.0"},"networkd":{},"passwd":{"users":[{"groups":["sudo"],"name":"rfairley","sshAuthorizedKeys":["ssh-rsa AAAA..."]}]},"storage":{},"systemd":{}}
EOF

sjenning commented 6 years ago

Same here

[    6.143733] ignition[739]: INFO     : Ignition 0.27.0
[    6.145252] ignition[739]: INFO     : Ignition 0.27.0
[    6.146322] ignition[739]: INFO     : reading system config file "/usr/lib/ignition/base.ign"
[    6.148914] ignition[739]: INFO     : reading system config file "/usr/lib/ignition/base.ign"
[    6.150162] ignition[739]: INFO     : no config at "/usr/lib/ignition/base.ign"
[    6.152526] ignition[739]: INFO     : no config at "/usr/lib/ignition/base.ign"
[    6.153626] ignition[739]: DEBUG    : parsed url from cmdline: ""
[    6.155289] ignition[739]: DEBUG    : parsed url from cmdline: ""
[    6.156249] ignition[739]: INFO     : no config URL provided
[    6.157851] ignition[739]: INFO     : no config URL provided
[    6.158771] ignition[739]: INFO     : reading system config file "/usr/lib/ignition/user.ign"
[    6.173657] ignition[739]: INFO     : reading system config file "/usr/lib/ignition/user.ign"
[    6.175291] ignition[739]: INFO     : no config at "/usr/lib/ignition/user.ign"
[    6.177686] ignition[739]: INFO     : no config at "/usr/lib/ignition/user.ign"
[    6.179109] ignition[739]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #1
[    6.181930] ignition[739]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #1
[    6.183693] ignition[739]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    6.186473] ignition[739]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[    6.188277] ignition[739]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[    6.191048] ignition[739]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
...
[   35.145783] ignition[739]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   35.148855] ignition[739]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   35.150751] ignition[739]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   35.153536] ignition[739]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   36.134863] ignition[739]: INFO     : neither config drive nor metadata service were available in time. Continuing without a config...
[   36.139043] ignition[739]: INFO     : neither config drive nor metadata service were available in time. Continuing without a config...
[   36.141629] ignition[739]: WARNING  : failed to fetch config: not a config (empty)
[   36.144590] ignition[739]: WARNING  : failed to fetch config: not a config (empty)[[32m  OK  [0m] 
[   36.147731] ignition[739]: INFO     : not a config (empty): ignoring user-provided config
[   36.150795] ignition[739]: INFO     : not a config (empty): ignoring user-provided config
[   36.152355] ignition[739]: INFO     : reading system config file "/usr/lib/ignition/default.ign"
[   36.155506] ignition[739]: INFO     : reading system config file "/usr/lib/ignition/default.ign"
[   36.159828] ignition[739]: INFO     : no config at "/usr/lib/ignition/default.ign"
[   36.162627] ignition[739]: INFO     : no config at "/usr/lib/ignition/default.ign"
[   36.164047] ignition[739]: INFO     : files: GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: i/o timeout
[   36.168265] ignition[739]: ERROR    : files: timed out while fetching config from config drive (config-2)
[   36.171576] ignition[739]: ERROR    : files: timed out while fetching config from config drive (CONFIG-2)
[   36.174912] ignition[739]: INFO     : files: files passed
[   36.176819] ignition[739]: INFO     : Ignition finished successfully

dustymabe commented 6 years ago

can you share how you are starting your instance? a CLI command would be the most reproducible

jlebon commented 6 years ago

It might be worth sharing OpenStack versions as well. It's likely a subtle change in the interaction between the metadata server and Ignition.

For reference, AFAIK the internal OpenStack instance runs on RHOSP 10 (Newton).

jstuever commented 6 years ago

Command

$ openstack --version
openstack 3.14.1
openstack server create --image RHCOS --flavor ocp.master --network jstuever --user-data /dev/stdin jstuevertest << 'EOF'
{"ignition":{"config":{},"security":{"tls":{}},"timeouts":{},"version":"2.2.0"},"networkd":{},"passwd":{},"storage":{},"systemd":{}}
EOF

Result: no route to host

Starting Ignition (files)...
[   68.130434] ignition[743]: INFO     : Ignition 0.26.0
[   68.132085] ignition[743]: INFO     : reading system config file "/usr/lib/ignition/base.ign"
[   68.133366] ignition[743]: INFO     : no config at "/usr/lib/ignition/base.ign"
[   68.134760] ignition[743]: DEBUG    : parsed url from cmdline: ""
[   68.135987] ignition[743]: INFO     : no config URL provided
[   68.137254] ignition[743]: INFO     : reading system config file "/usr/lib/ignition/user.ign"
[   68.138635] ignition[743]: INFO     : no config at "/usr/lib/ignition/user.ign"
[   68.139924] ignition[743]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #1
[   68.141203] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   68.142715] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   69.137665] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   69.139156] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   70.138056] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   70.139820] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   71.140068] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   71.141461] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   71.145532] ignition[743]: INFO     : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host
[   71.345775] ignition[743]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #2
[   72.140239] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   72.142190] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   73.140542] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   73.142450] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   74.140857] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   74.142313] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   74.151384] ignition[743]: INFO     : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host
[   74.551656] ignition[743]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #3
[   75.141099] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   75.142982] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   76.141373] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   76.142840] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   77.141543] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   77.143435] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   77.157444] ignition[743]: INFO     : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host
[   77.957678] ignition[743]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #4
[   78.141798] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   78.143193] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   79.142233] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   79.144340] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   80.142463] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   80.143886] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   80.163531] ignition[743]: INFO     : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host
[   81.142720] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   81.144767] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   81.763781] ignition[743]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #5
[   82.143065] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   82.145056] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   83.143283] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   83.144842] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   83.169395] ignition[743]: INFO     : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host
[   84.143593] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   84.145050] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   85.143852] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   85.145802] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   86.144152] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   86.145764] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   86.369622] ignition[743]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #6
[   87.144525] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   87.145983] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   88.145663] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   88.147586] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   89.145938] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   89.147892] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   89.375421] ignition[743]: INFO     : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host
[   90.146342] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   90.147764] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   91.146558] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   91.147939] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   92.146825] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   92.148227] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   93.147061] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   93.148957] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   94.147349] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   94.148708] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   94.375655] ignition[743]: INFO     : GET http://169.254.169.254/openstack/latest/user_data: attempt #7
[   95.147512] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   95.149480] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   96.147811] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   96.149274] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   97.148140] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/config-2") not found. Waiting...
[   97.149699] ignition[743]: DEBUG    : config drive ("/dev/disk/by-label/CONFIG-2") not found. Waiting...
[   97.381395] ignition[743]: INFO     : GET error: Get http://169.254.169.254/openstack/latest/user_data: dial tcp 169.254.169.254:80: getsockopt: no route to host
[   98.135161] [ignition[743]: INFO     : neither config drive nor metadata service were available in time. Continuing without a config...
[   98.138278] ignition[743]: ERROR    : timed out while fetching config from config drive (CONFIG-2)
[   98.138874] ignition[743]: WARNING  : failed to fetch config: not a config (empty)
[   98.139556] ignition[743]: INFO     : not a config (empty): ignoring user-provided config
[   98.140114] ignition[743]: INFO     : reading system config file "/usr/lib/ignition/default.ign"
[   98.140649] ignition[743]: INFO     : no config at "/usr/lib/ignition/default.ign"
[   98.141204] ignition[743]: ERROR    : timed out while fetching config from config drive (config-2)
[32m  OK  [0m] Started Ignition (files).
[   98.146047] systemd[1]: Started Ignition (files).
         [   98.149142] systemd[1]: Starting Switch R

Subnet info (Freshly created with sanitized output)

openstack subnet show jstuever
+-------------------+--------------------------------------+
| Field             | Value                                |
+-------------------+--------------------------------------+
| allocation_pools  | 192.168.1.2-192.168.1.254
| cidr              | 192.168.1.0/24
| created_at        | 2018-08-24T19:30:14Z
| description       |
| dns_nameservers   |
| enable_dhcp       | True
| gateway_ip        | 192.168.1.1
| host_routes       |
| id                |
| ip_version        | 4
| ipv6_address_mode | None
| ipv6_ra_mode      | None
| name              | jstuever
| network_id        |
| project_id        |
| revision_number   | 2
| segment_id        | None
| service_types     |
| subnetpool_id     | None
| tags
| updated_at        | 2018-08-24T19:30:14Z
+-------------------+--------------------------------------+

jstuever commented 6 years ago

My issue may be specific to the OpenStack instance I'm using. When I root into the instance using rd.break init=/bin/sh I am able to ping 4.2.2.2. However, I continue to get "no route to host" when I curl http://169.254.169.254/openstack/latest/user_data.

sjenning commented 6 years ago

I am using

openstack server create --image rhcos-4.0.4760 --flavor m1.medium --network external --user-data ~/config.ign rhocs.lab.variantweb.net

~/config.ign

    "ignition": {
        "version": "2.2.0"
    },
    "passwd": {
        "users": [{
            "groups": ["sudo"],
            "name": "sjennings",
            "sshAuthorizedKeys": ["ssh-rsa AAAA..."]
        }]
    }
}

rfairley commented 6 years ago

How do we check the version of the OpenStack instance running? I agree it is likely something to do with this, not with the CLI used to access it.

I did try with the CLI version 3.14.1 on the same internal OpenStack instance I used before (https://github.com/openshift/os/issues/227#issuecomment-415783957), but this did not reproduce the issue. Also confirmed that curl http://169.254.169.254/openstack/latest/user_data worked on the internal OpenStack instance.

I'm not sure how to check what the version of the OpenStack instance is, will look into this. Anyone know already how to do it?

ashcrow commented 6 years ago

@rfairley easiest way is to find an admin and ask since Openstack has lots of different components :smiley:. Though you should be able to query the API of components directly for their versions. You could piece together a version from the following:

sjenning commented 6 years ago

My issue may be specific to the OpenStack instance I'm using. When I root into the instance using rd.break init=/bin/sh I am able to ping 4.2.2.2. However, I continue to get "no route to host" when I curl http://169.254.169.254/openstack/latest/user_data.

I did this as well and I think the difference might be that if your default gateway and metadata server are at the same IP, it will work.

The metadata route is not set up in the intird env

# ip r
default via 10.42.10.1. dev eth0
10.42.10.0/24 dev eth0 proto kernel scope link src 10.42.10.209

opposed to a fully booted VM on the same cluster with cloud-init

$ ip r
default via 10.42.10.1 dev eth0 proto dhcp metric 100 
10.42.10.0/24 dev eth0 proto kernel scope link src 10.42.10.203 metric 100 
169.254.169.254 via 10.42.10.200 dev eth0 proto dhcp metric 100 <---

In my case, my gateway is 10.42.10.1 (external network and the gateway is off-cluster) where my metadata server is 10.42.10.200. If I was running an internal network with a neutron router as the gateway, I think they would be the same and I wouldn't be seeing this issue. However, my setup is valid and the init env should install the metadata route before attempting to get the ignition config.

sjenning commented 6 years ago

I confirmed this. Though the gateway and metadata server don't have the be on the same IP. If the gateway is a neutron router, it has a route for the metdata server. I created an internal network and neutron router and started RHCOS image on this network and the neutron router (the default route in the initrd) properly routes to the metadata server.

However, having instances that attach directly to the external network (vs and internal network with floating ip) is a valid configuration and we should try to support it IMO.

rfairley commented 6 years ago

Confirmed on my end as well, using an internal OpenStack instance running RHCOS, the gateway and metadata server are on the same IP: 172.16.171.1. This is also the IP address of the neutron router configured in the network.

$ ip r
default via 172.16.171.1 dev eth0 
default via 172.16.171.1 dev eth0 proto dhcp metric 100 
169.254.169.254 via 172.16.171.1 dev eth0 proto dhcp metric 100 
172.16.171.0/24 dev eth0 proto kernel scope link src 172.16.171.9 
172.16.171.0/24 dev eth0 proto kernel scope link src 172.16.171.9 metric 100 
172.17.0.0/16 dev docker0 proto kernel scope link src 172.17.0.1

sjenning commented 6 years ago

Confirmed that the dhclient in the dracut initrd is not honoring option 121 (classless-static-routes) sent by the dhcp server. This prevents the creation of the route to the metadata server.

Could be this issue: https://bugzilla.redhat.com/show_bug.cgi?id=1453907

/tmp/dhclient.eth0.dhcpopts does have the new_classless_routes set correctly, but somewhere downstream from that point, the routes never get created.

dustymabe commented 6 years ago

seems possible. thanks for tracking that down. we are at an older version of dracut (dracut-033-535.el7.x86_64) than is mentioned as being fixed so maybe we can pull that in soon and re-test this.

sjenning commented 6 years ago

rebasing RHCOS composes on RHEL 7.5 fixed this. thanks! confirmed fixed on 5177.

openshift / os

Issue pulling user_data in OpenStack #227