search

ContainerCraft / kmi

KubeVirt Virtual Machine Disk Image Library
Apache License 2.0
10 stars 1 forks source link

FreeBSD: cloud-init fails to configure ssh keys and user #22

Closed jbpratt closed 2 years ago

jbpratt commented 2 years ago

Since the user doesn't exist, qemu-guest-agent fails to synchronize the ssh key secret as well Error encountered writing ssh pub key access credentials for user [kc2user]: Unable to detect home directory of user kc2user: exited with error code:2

The manifest below differs from the one tested in CI slightly, it was replicated from the cloud-init-bsd-testing repo.

It also looks like the VM is not getting an IP address either.

VM described ``` ❯ k describe vmi -A Name: testvm Namespace: default Labels: kubevirt.io/nodeName=kmi-test-worker test=kmi Annotations: kubevirt.io/latest-observed-api-version: v1 kubevirt.io/storage-observed-api-version: v1alpha3 API Version: kubevirt.io/v1 Kind: VirtualMachineInstance Metadata: Creation Timestamp: 2021-12-15T10:49:26Z Finalizers: kubevirt.io/virtualMachineControllerFinalize foregroundDeleteVirtualMachine Generation: 13 Managed Fields: API Version: kubevirt.io/v1alpha3 Fields Type: FieldsV1 fieldsV1: f:metadata: f:annotations: .: f:kubevirt.io/latest-observed-api-version: f:kubevirt.io/storage-observed-api-version: f:finalizers: .: v:"kubevirt.io/virtualMachineControllerFinalize": f:labels: .: f:kubevirt.io/nodeName: f:test: f:ownerReferences: .: k:{"uid":"0f03580d-6fab-4e27-8e1a-3ff774bd495f"}: f:spec: .: f:accessCredentials: f:domain: .: f:devices: .: f:autoattachGraphicsDevice: f:autoattachPodInterface: f:autoattachSerialConsole: f:disks: f:networkInterfaceMultiqueue: f:firmware: .: f:uuid: f:machine: .: f:type: f:resources: .: f:limits: .: f:memory: f:requests: .: f:memory: f:hostname: f:nodeSelector: .: f:test: f:terminationGracePeriodSeconds: f:volumes: f:status: .: f:activePods: .: f:462bb7bc-4e72-4eae-bf8a-e13d8b5b9fba: f:conditions: f:guestOSInfo: f:interfaces: f:launcherContainerImageVersion: f:migrationMethod: f:migrationTransport: f:nodeName: f:phase: f:phaseTransitionTimestamps: f:qosClass: f:virtualMachineRevisionName: f:volumeStatus: Manager: Go-http-client Operation: Update Time: 2021-12-15T10:49:31Z Owner References: API Version: kubevirt.io/v1 Block Owner Deletion: true Controller: true Kind: VirtualMachine Name: testvm UID: 0f03580d-6fab-4e27-8e1a-3ff774bd495f Resource Version: 2304 UID: 89459ef8-1ac5-4edf-a517-f5c0ab749bc7 Spec: Access Credentials: Ssh Public Key: Propagation Method: Qemu Guest Agent: Users: kc2user Source: Secret: Secret Name: kargo-sshpubkey-kc2user Domain: Cpu: Cores: 1 Sockets: 1 Threads: 1 Devices: Autoattach Graphics Device: true Autoattach Pod Interface: true Autoattach Serial Console: true Disks: Boot Order: 1 Disk: Bus: virtio Name: containerdisk Disk: Bus: virtio Name: cloudinitdisk Interfaces: Bridge: Name: default Network Interface Multiqueue: false Features: Acpi: Enabled: true Firmware: Uuid: 5a9fc181-957e-5c32-9e5a-2de5e9673531 Machine: Type: q35 Resources: Limits: Memory: 4G Requests: Memory: 4G Hostname: testvm Networks: Name: default Pod: Node Selector: Test: kmi Termination Grace Period Seconds: 0 Volumes: Container Disk: Image: docker.io/containercraft/freebsd:13-dev Image Pull Policy: Always Name: containerdisk Cloud Init No Cloud: Network Data: version: 2 ethernets: eth0: match: mac_address: "...." dhcp4: true User Data: #cloud-config users: - default - name: kc2user sudo: ALL=(ALL) NOPASSWD:ALL groups: sudo,wheel ssh-authorized-keys: - ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAACAQCqii+2B/KMkBtJOr0ku4wgbMrnuj5iVo5BmJGNzjdPmkLxQsOhZ3es0Gxb/1HJgOg1DptKPIxrMpWb1QCJf56zxUIcWKTHUIXzXY4KW0sT4bKSsE43AQQ0J2Ao3fQz8vdccWDPwpgrTaV6t1ZaFhb9sJJkzfplrBo2v0xVMSBieIpt4Znpi6HrIgXt6aqd5JpYuYv4SjYs/n+V2j62gAKKl7lt3ie+Nz50nrx9SPJ2+VrwCSQvidpGv1VY/tbG9j8VNff4fuxFl37au2TCfRYC7ANhTZjZWQOG3Yo920jziD+EY6lVv6G3GeMpVCny9lqcc+hUI+wP2Rd4Kw0RShwX1NrW7NyG+u8hjluIEubj4PWwwArMp6MQgdQKGhurOtBWBhdaFFrooiC4/DmAHUuPZAOK5vO0F1KEOUVVOz4VDsrU5Kw3X0NhBVcLDqrC9dwBMrqVBY5gnuboDb4Cq+RuW0cT9CIz2b7iwZZU8sg82O1Z2iu7qvER8TYJH4y8U2sE7OpkAfbOVqMlxW2x+O4ci6f9m8M/C7WRwGRoKvx422aaBihEJ7eQ5JXxlEwSWErbU+oXwdMRxJ6aMlWfXUCBhGfrTEa8sbyhThh9EsGvk+JV58EjfgqNqidDqSgzTh3Zfve0frj5rsS55CKK700pm8k/v/+sSl8tMC6oxGDdmw== jbpratt78@gmail.com Name: cloudinitdisk Status: Active Pods: 462bb7bc-4e72-4eae-bf8a-e13d8b5b9fba: kmi-test-worker Conditions: Last Probe Time: Last Transition Time: 2021-12-15T10:49:31Z Status: True Type: Ready Last Probe Time: Last Transition Time: Message: cannot migrate VMI which does not use masquerade to connect to the pod network Reason: InterfaceNotLiveMigratable Status: False Type: LiveMigratable Last Probe Time: 2021-12-15T10:50:29Z Last Transition Time: Status: True Type: AgentConnected Last Probe Time: Last Transition Time: 2021-12-15T10:55:39Z Message: Error encountered writing ssh pub key access credentials for user [kc2user]: Unable to detect home directory of user kc2user: exited with error code:2 Status: False Type: AccessCredentialsSynchronized Guest OS Info: Interfaces: Interface Name: vtnet0 Mac: ee:82:d0:65:b7:c1 Name: default Interface Name: lo0 Ip Address: 127.0.0.1 Ip Addresses: ::1 fe80::1 127.0.0.1 Mac: 00:00:00:00:00:00 Launcher Container Image Version: quay.io/kubevirt/virt-launcher:v0.47.1 Migration Method: BlockMigration Migration Transport: Unix Node Name: kmi-test-worker Phase: Running Phase Transition Timestamps: Phase: Pending Phase Transition Timestamp: 2021-12-15T10:49:26Z Phase: Scheduling Phase Transition Timestamp: 2021-12-15T10:49:26Z Phase: Scheduled Phase Transition Timestamp: 2021-12-15T10:49:31Z Phase: Running Phase Transition Timestamp: 2021-12-15T10:49:31Z Qos Class: Burstable Virtual Machine Revision Name: revision-start-vm-0f03580d-6fab-4e27-8e1a-3ff774bd495f-1 Volume Status: Name: cloudinitdisk Size: 1048576 Target: vdb Name: containerdisk Target: vda Events: Type Reason Age From Message ---- ------ ---- ---- ------- Normal SuccessfulCreate 10m virtualmachine-controller Created virtual machine pod virt-launcher-testvm-xzbq4 Normal Created 10m virt-handler VirtualMachineInstance defined. Normal Started 10m virt-handler VirtualMachineInstance started. Warning AccessCredentialsSyncFailed 10m virt-handler Guest agent is offline Warning AccessCredentialsSyncFailed 4m27s virt-handler Error encountered writing ssh pub key access credentials for user [kc2user]: Unable to detect home directory of user kc2user: exited with error code:2 ```
VM manifest file ``` cat <
Serial console output attempt 1 ``` - ______ ____ _____ _____ | ____| | _ \ / ____| __ \ | |___ _ __ ___ ___ | |_) | (___ | | | | | ___| '__/ _ \/ _ \| _ < \___ \| | | | | | | | | __/ __/| |_) |____) | |__| | | | | | | | || | | | |_| |_| \___|\___||____/|_____/|_____/ console efi is invalid! ` Available consoles: s` `.....---.......--.``` -/ +-----------Welcome to FreeBSDconsole efi is invalid!--` /y:` +. Available consoles: | yo`:. :o `+- 1. Boot Multi user [Enter] | y/ -/` -o/ 2. Boot Single user | .- ::/sy+:. 3. Escape to loader prompt | / `-- / 4. Rebootle | `: :` | 5. Cons: Dual (Serial primary) | `: :` | | / / | Options: | .- -. | 6. Kernel: default/kernel (1 of 1) | -- -. | 7. Boot Options | `:` `:` | | .-- `--. | | .---.....----.console efi is invalid! A+-----------------------------------------+ Autoboot in 0 seconds, hit [Enter] to boot or any other key to stop comconsole Loading kernel... /boot/kernel/kernel text=0x17b9e0 text=0xdd6d30 text=0x65b9ac data=0x140 data=0x1b9348+0x445cb8 syms=[0x8+0x178e90+0x8+0x199058] Loading configured modules... can't find '/boot/entropy' can't find '/etc/hostid' /boot/kernel/zfs.ko size 0x67feb0 at 0x2112000 ---<>--- Copyright (c) 1992-2021 The FreeBSD Project. Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 The Regents of the University of California. All rights reserved. FreeBSD is a registered trademark of The FreeBSD Foundation. FreeBSD 13.0-RELEASE #0 releng/13.0-n244733-ea31abc261f: Fri Apr 9 04:24:09 UTC 2021 root@releng1.nyi.freebsd.org:/usr/obj/usr/src/amd64.amd64/sys/GENERIC amd64 FreeBSD clang version 11.0.1 (git@github.com:llvm/llvm-project.git llvmorg-11.0.1-0-g43ff75f2c3fe) VT(vga): text 80x25 CPU: AMD EPYC Processor (3800.48-MHz K8-class CPU) Origin="AuthenticAMD" Id=0x800f12 Family=0x17 Model=0x1 Stepping=2 Features=0xfc3fbfd Features2=0xced8220b AMD Features=0xec500800 AMD Features2=0x75 Structured Extended Features=0x1d84389,CLFLUSHOPT,CLWB> Structured Extended Features2=0x10008 XSAVE Features=0x5 SVM: NP,NAsids=16 Hypervisor: Origin = "TCGTCGTCGTCG" real memory = 4000317440 (3815 MB) avail memory = 3785117696 (3609 MB) Event timer "LAPIC" quality 600 ACPI APIC Table: random: registering fast source Intel Secure Key RNG random: fast provider: "Intel Secure Key RNG" arc4random: WARNING: initial seeding bypassed the cryptographic random device because it was not yet seeded and the knob 'bypass_before_seeding' was enabled. ioapic0 irqs 0-23 Timecounter "TSC-low" frequency 1900242117 Hz quality 800 KTLS: Initialized 1 threads random: entropy device external interface [ath_hal] loaded WARNING: Device "kbd" is Giant locked and may be deleted before FreeBSD 14.0. kbd1 at kbdmux0 000.000054 [4354] netmap_init netmap: loaded module mlx5en: Mellanox Ethernet driver 3.6.0 (December 2020) nexus0 vtvga0: cryptosoft0: aesni0: acpi0: acpi0: Power Button (fixed) cpu0: on acpi0 atrtc0: port 0x70-0x77 irq 8 on acpi0 atrtc0: registered as a time-of-day clock, resolution 1.000000s Event timer "RTC" frequency 32768 Hz quality 0 Timecounter "ACPI-fast" frequency 3579545 Hz quality 900 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x608-0x60b on acpi0 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 vgapci0: mem 0xfb000000-0xfbffffff,0xfea10000-0xfea10fff at device 1.0 on pci0 vgapci0: Boot video device pcib1: mem 0xfea11000-0xfea11fff irq 22 at device 2.0 on pci0 pci1: on pcib1 virtio_pci0: mem 0xfe800000-0xfe800fff,0xfcc00000-0xfcc03fff irq 22 at device 0.0 on pci1 vtnet0: on virtio_pci0 vtnet0: Ethernet address: fa:1c:34:2f:57:d5 vtnet0: netmap queues/slots: TX 1/256, RX 1/128 000.000074 [ 450] vtnet_netmap_attach vtnet attached txq=1, txd=256 rxq=1, rxd=128 pcib2: mem 0xfea12000-0xfea12fff irq 22 at device 2.1 on pci0 pci2: on pcib2 virtio_pci1: mem 0xfe600000-0xfe600fff,0xfca00000-0xfca03fff irq 22 at device 0.0 on pci2 vtscsi0: on virtio_pci1 pcib3: mem 0xfea13000-0xfea13fff irq 22 at device 2.2 on pci0 pci3: on pcib3 virtio_pci2: mem 0xfe400000-0xfe400fff,0xfc800000-0xfc803fff irq 22 at device 0.0 on pci3 pcib4: mem 0xfea14000-0xfea14fff irq 22 at device 2.3 on pci0 pci4: on pcib4 virtio_pci3: mem 0xfe200000-0xfe200fff,0xfc600000-0xfc603fff irq 22 at device 0.0 on pci4 vtblk0: on virtio_pci3 vtblk0: 3072MB (6291456 512 byte sectors) pcib5: mem 0xfea15000-0xfea15fff irq 22 at device 2.4 on pci0 pci5: on pcib5 virtio_pci4: mem 0xfe000000-0xfe000fff,0xfc400000-0xfc403fff irq 22 at device 0.0 on pci5 vtblk1: on virtio_pci4 vtblk1: 1MB (2048 512 byte sectors) pcib6: mem 0xfea16000-0xfea16fff irq 22 at device 2.5 on pci0 pci6: on pcib6 virtio_pci5: mem 0xfc200000-0xfc203fff irq 22 at device 0.0 on pci6 vtballoon0: on virtio_pci5 pcib7: mem 0xfea17000-0xfea17fff irq 22 at device 2.6 on pci0 isab0: at device 31.0 on pci0 isa0: on isab0 ahci0: port 0xc040-0xc05f mem 0xfea18000-0xfea18fff irq 16 at device 31.2 on pci0 ahci0: AHCI v1.00 with 6 1.5Gbps ports, Port Multiplier not supported ahcich0: at channel 0 on ahci0 ahcich1: at channel 1 on ahci0 ahcich2: at channel 2 on ahci0 ahcich3: at channel 3 on ahci0 ahcich4: at channel 4 on ahci0 ahcich5: at channel 5 on ahci0 acpi_syscontainer0: on acpi0 acpi_syscontainer1: port 0xcd8-0xce3 on acpi0 acpi_syscontainer2: port 0x620-0x62f on acpi0 uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 uart0: console (115200,n,8,1) atkbdc0: port 0x60,0x64 irq 1 on acpi0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] psm0: irq 12 on atkbdc0 psm0: [GIANT-LOCKED] WARNING: Device "psm" is Giant locked and may be deleted before FreeBSD 14.0. psm0: model IntelliMouse Explorer, device ID 4 orm0: at iomem 0xe9000-0xeffff pnpid ORM0000 on isa0 vga0: at port 0x3c0-0x3df iomem 0xa0000-0xbffff pnpid PNP0900 on isa0 attimer0: at port 0x40 on isa0 Timecounter "i8254" frequency 1193182 Hz quality 0 Event timer "i8254" frequency 1193182 Hz quality 100 attimer0: non-PNP ISA device will be removed from GENERIC in FreeBSD 14. Timecounters tick every 10.000 msec ZFS filesystem version: 5 ZFS storage pool version: features support (5000) usb_needs_explore_all: no devclass Trying to mount root from zfs:zroot/ROOT/default []... Dual Console: Serial Primary, Video Secondary Setting hostuuid: 5a9fc181-957e-5c32-9e5a-2de5e9673531. Setting hostid: 0x2455456c. Starting file system checks: Mounting local filesystems:. random: unblocking device. ELF ldconfig path: /lib /usr/lib /usr/lib/compat /usr/local/lib /usr/local/lib/compat/pkg /usr/local/lib/compat/pkg /usr/local/lib/e2fsprogs 32-bit compatibility ldconfig path: /usr/lib32 /etc/rc: WARNING: $hostname is not set -- see rc.conf(5). Setting up harvesting: PURE_RDRAND,[UMA],[FS_ATIME],SWI,INTERRUPT,NET_NG,[NET_ETHER],NET_TUN,MOUSE,KEYBOARD,ATTACH,CACHED Feeding entropy: . /usr/local/bin/cloud-init startingCloud-init v. 21.4 running 'init-local' at Wed, 15 Dec 2021 10:42:30 +0000. Up 13.2301766872406 seconds. lo0: link state changed to DOWN lo0: link state changed to UP Autoloading module: ichsmb.ko Autoloading module: virtio_console.ko ichsmb0: port 0x700-0x73f irq 16 at device 31.3 on pci0 smbus0: on ichsmb0 vtcon0: on virtio_pci2 Starting Network: lo0 vtnet0. lo0: flags=8049 metric 0 mtu 16384 options=680003 inet6 ::1 prefixlen 128 inet6 fe80::1%lo0 prefixlen 64 scopeid 0x2 inet 127.0.0.1 netmask 0xff000000 groups: lo nd6 options=21 vtnet0: flags=8822 metric 0 mtu 1500 options=4c079b ether fa:1c:34:2f:57:d5 media: Ethernet autoselect (10Gbase-T ) status: active nd6 options=29 Starting devd. Starting Network: vtnet0. vtnet0: flags=8822 metric 0 mtu 1500 options=4c079b ether fa:1c:34:2f:57:d5 media: Ethernet autoselect (10Gbase-T ) status: active nd6 options=29 Autoloading module: virtio_console.ko Autoloading module: ichsmb.ko add host 127.0.0.1: gateway lo0 fib 0: route already in table add host ::1: gateway lo0 fib 0: route already in table add net fe80::: gateway ::1 fib 0: route already in table add net ff02::: gateway ::1 fib 0: route already in table add net ::ffff:0.0.0.0: gateway ::1 fib 0: route already in table add net ::0.0.0.0: gateway ::1 fib 0: route already in table /usr/local/bin/cloud-init startingCloud-init v. 21.4 running 'init' at Wed, 15 Dec 2021 10:42:47 +0000. Up 30.345906972885132 seconds. ci-info: ++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++ ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: | lo0 | True | 127.0.0.1 | 0xff000000 | . | . | ci-info: | lo0 | True | ::1/128 | . | . | . | ci-info: | lo0 | True | fe80::1%lo0/64 | . | 0x2 | . | ci-info: | vtnet0 | False | . | . | . | fa:1c:34:2f:57:d5 | ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: 2021-12-15 10:42:50,273 - util.py[WARNING]: Failed to create user kc2user 2021-12-15 10:42:50,289 - util.py[WARNING]: Running module users-groups () failed Generating public/private rsa key pair. Your identification has been saved in /etc/ssh/ssh_host_rsa_key. Your public key has been saved in /etc/ssh/ssh_host_rsa_key.pub. The key fingerprint is: SHA256:rcXaHyqipu8XIrWMPVmAtMV1cH9BPhYzBver3gQciBU root@testvm The key's randomart image is: +---[RSA 2048]----+ | ..o..o.o E+O | | .oo o + = * | | . . . o * . | | . . o + o . | | = + S + o . | | o B . = o | | . o .o . o . | | . o . + + | | .=+o . .. o . | +----[SHA256]-----+ Generating public/private dsa key pair. Your identification has been saved in /etc/ssh/ssh_host_dsa_key. Your public key has been saved in /etc/ssh/ssh_host_dsa_key.pub. The key fingerprint is: SHA256:bCyX4g5v5Z27GJwRv5Gl68dV7/MVfoTCkMo5sBH7+sI root@testvm The key's randomart image is: +---[DSA 1024]----+ | . | | o . | | + . o . | | O * * ..| | + S = o .oo| | . B.+ + .o.o| | ..oo+.oo . oo| | +E..+o o .+| | .o.o ++ +| +----[SHA256]-----+ Generating public/private ecdsa key pair. Your identification has been saved in /etc/ssh/ssh_host_ecdsa_key. Your public key has been saved in /etc/ssh/ssh_host_ecdsa_key.pub. The key fingerprint is: SHA256:FxMT8TSS8tYSXLBAYJ5DF/InIeiY3YzuVGdranSbR2Y root@testvm The key's randomart image is: +---[ECDSA 256]---+ | .*o*oB*+ | | .+ *.o+B . | | = ++ oo=o. | | o + +.oo+o. | | . . oSo.. | | o . +.E | | o . + * | | . o o . | | . . | +----[SHA256]-----+ Generating public/private ed25519 key pair. Your identification has been saved in /etc/ssh/ssh_host_ed25519_key. Your public key has been saved in /etc/ssh/ssh_host_ed25519_key.pub. The key fingerprint is: SHA256:u5P6aDOdY5xlaTTZ4xNtWfDQxKMj8ePbSyB+m0QD4dM root@testvm The key's randomart image is: +--[ED25519 256]--+ | . o=.| | ..o ++| | *oE.oo| | +.*=+ | | S. =oBo | | .* =.o | | o.B . +o. | | +.X. o.+. | | .o*oo o ..| +----[SHA256]-----+ /usr/local/bin/cloud-init starting Cloud-init v. 21.4 running 'modules:config' at Wed, 15 Dec 2021 10:42:55 +0000. Up 38.55824422836304 seconds. Updating /var/run/os-release done. Clearing /tmp (X related). Creating and/or trimming log files. Updating motd:. Starting syslogd. Starting qemu_guest_agent. Mounting late filesystems:. Performing sanity check on sshd configuration. Starting sshd. Configuring vt: blanktime. Starting cron. /usr/local/bin/cloud-init startingCloud-init v. 21.4 running 'modules:final' at Wed, 15 Dec 2021 10:43:03 +0000. Up 46.66900062561035 seconds. 2021-12-15 10:43:05,053 - util.py[WARNING]: Running module ssh-authkey-fingerprints () failed cloud-init 1073 - - ############################################################# cloud-init 1077 - - -----BEGIN SSH HOST KEY FINGERPRINTS----- cloud-init 1082 - - 1024 SHA256:bCyX4g5v5Z27GJwRv5Gl68dV7/MVfoTCkMo5sBH7+sI root@testvm (DSA) cloud-init 1087 - - 256 SHA256:FxMT8TSS8tYSXLBAYJ5DF/InIeiY3YzuVGdranSbR2Y root@testvm (ECDSA) cloud-init 1092 - - 256 SHA256:u5P6aDOdY5xlaTTZ4xNtWfDQxKMj8ePbSyB+m0QD4dM root@testvm (ED25519) cloud-init 1097 - - 2048 SHA256:rcXaHyqipu8XIrWMPVmAtMV1cH9BPhYzBver3gQciBU root@testvm (RSA) cloud-init 1101 - - -----END SSH HOST KEY FINGERPRINTS----- cloud-init 1105 - - ############################################################# -----BEGIN SSH HOST KEY KEYS----- ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBHYvXfqXPGSH2jiANp7lFpRXaPfd+UbPPF6A6KhVgf+tfrEa1RSDxuLioeqIa/XtasOB+YfcMQJT4TUpP0C3KSI= root@testvm ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIE47DrqHXf26qwz54+CnhWEr03ub3mE/p5RsyQrQWP63 root@testvm ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQD61lOm0hytEnJYDUo9an00dVUB9nokkdqZYNBGWFkCUhA7T7saGIQr/Xxp6D/Kc8EeFFYwVRaV4NVgYnjY7Rxrs4QFeg8vXfqXP2Y5Nl6fjQ1UZ5bB6hp4+nA/33fRoc+8ni2O3FOs6YUCfZNhcUMnwlC/EogfJYJD06kbBEWrFUZ+pex+thhzfondt0cZ9gSYE8Bzb+dFzj0BL01GFqjqMHhD/KW7Yw/P6Rv1/MiifzRyh+q/miOwrUVDBc3eRjO9Hv+VwNvAOVwmi+vo21i+1urGhzou4y3SfpgDaNXSsZExeHd9Dkwme0WvTdIjp6U/XddjuU0eHohCAk8YJtST root@testvm -----END SSH HOST KEY KEYS----- Cloud-init v. 21.4 finished at Wed, 15 Dec 2021 10:43:05 +0000. Datasource DataSourceNoCloud [seed=/dev/iso9660/cidata][dsmode=net]. Up 48.59985971450806 seconds Starting background file system checks in 60 seconds. Wed Dec 15 10:43:06 UTC 2021 FreeBSD/amd64 (testvm) (ttyu0) login: You were disconnected from the console. This has one of the following reasons: - another user connected to the console of the target vm - network issues websocket: close 1006 (abnormal closure): unexpected EOF ```
Serial console attempt 2 ``` - ______ ____ _____ _____ | ____| | _ \ / ____| __ \ | |___ _ __ ___ ___ | |_) | (___ | | | | | ___| '__/ _ \/ _ \| _ < \___ \| | | | | | | | | __/ __/| |_) |____) | |__| | | | | | | | || | | | |_| |_| \___|\___||____/|_____/|_____/ console efi is invalid! ` Available consoles: s` `.....---.......--.``` -/ +-----------Welcome to FreeBSDconsole efi is invalid!--` /y:` +. Available consoles: | yo`:. :o `+- 1. Boot Multi user [Enter] | y/ -/` -o/ 2. Boot Single user | .- ::/sy+:. 3. Escape to loader prompt | / `-- / 4. Rebootle | `: :` | 5. Cons: Dual (Serial primary) | `: :` | | / / | Options: | .- -. | 6. Kernel: default/kernel (1 of 1) | -- -. | 7. Boot Options | `:` `:` | | .-- `--. | | .---.....----.console efi is invalid! A+-----------------------------------------+ Autoboot in 0 seconds, hit [Enter] to boot or any other key to stop comconsole Loading kernel... /boot/kernel/kernel text=0x17b9e0 text=0xdd6d30 text=0x65b9ac data=0x140 data=0x1b9348+0x445cb8 syms=[0x8+0x178e90+0x8+0x199058] Loading configured modules... /boot/kernel/zfs.ko size 0x67feb0 at 0x2112000 can't find '/boot/entropy' can't find '/etc/hostid' ---<>--- Copyright (c) 1992-2021 The FreeBSD Project. Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 The Regents of the University of California. All rights reserved. FreeBSD is a registered trademark of The FreeBSD Foundation. FreeBSD 13.0-RELEASE #0 releng/13.0-n244733-ea31abc261f: Fri Apr 9 04:24:09 UTC 2021 root@releng1.nyi.freebsd.org:/usr/obj/usr/src/amd64.amd64/sys/GENERIC amd64 FreeBSD clang version 11.0.1 (git@github.com:llvm/llvm-project.git llvmorg-11.0.1-0-g43ff75f2c3fe) VT(vga): text 80x25 CPU: AMD EPYC Processor (3800.52-MHz K8-class CPU) Origin="AuthenticAMD" Id=0x800f12 Family=0x17 Model=0x1 Stepping=2 Features=0xfc3fbfd Features2=0xced8220b AMD Features=0xec500800 AMD Features2=0x75 Structured Extended Features=0x1d84389,CLFLUSHOPT,CLWB> Structured Extended Features2=0x10008 XSAVE Features=0x5 SVM: NP,NAsids=16 Hypervisor: Origin = "TCGTCGTCGTCG" real memory = 4000317440 (3815 MB) avail memory = 3785117696 (3609 MB) Event timer "LAPIC" quality 600 ACPI APIC Table: random: registering fast source Intel Secure Key RNG random: fast provider: "Intel Secure Key RNG" arc4random: WARNING: initial seeding bypassed the cryptographic random device because it was not yet seeded and the knob 'bypass_before_seeding' was enabled. ioapic0 irqs 0-23 Timecounter "TSC-low" frequency 1900262371 Hz quality 800 KTLS: Initialized 1 threads random: entropy device external interface [ath_hal] loaded WARNING: Device "kbd" is Giant locked and may be deleted before FreeBSD 14.0. kbd1 at kbdmux0 000.000054 [4354] netmap_init netmap: loaded module mlx5en: Mellanox Ethernet driver 3.6.0 (December 2020) nexus0 vtvga0: cryptosoft0: aesni0: acpi0: acpi0: Power Button (fixed) cpu0: on acpi0 atrtc0: port 0x70-0x77 irq 8 on acpi0 atrtc0: registered as a time-of-day clock, resolution 1.000000s Event timer "RTC" frequency 32768 Hz quality 0 Timecounter "ACPI-fast" frequency 3579545 Hz quality 900 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x608-0x60b on acpi0 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 vgapci0: mem 0xfb000000-0xfbffffff,0xfea10000-0xfea10fff at device 1.0 on pci0 vgapci0: Boot video device pcib1: mem 0xfea11000-0xfea11fff irq 22 at device 2.0 on pci0 pci1: on pcib1 virtio_pci0: mem 0xfe800000-0xfe800fff,0xfcc00000-0xfcc03fff irq 22 at device 0.0 on pci1 vtnet0: on virtio_pci0 vtnet0: Ethernet address: ee:82:d0:65:b7:c1 vtnet0: netmap queues/slots: TX 1/256, RX 1/128 000.000074 [ 450] vtnet_netmap_attach vtnet attached txq=1, txd=256 rxq=1, rxd=128 pcib2: mem 0xfea12000-0xfea12fff irq 22 at device 2.1 on pci0 pci2: on pcib2 virtio_pci1: mem 0xfe600000-0xfe600fff,0xfca00000-0xfca03fff irq 22 at device 0.0 on pci2 vtscsi0: on virtio_pci1 pcib3: mem 0xfea13000-0xfea13fff irq 22 at device 2.2 on pci0 pci3: on pcib3 virtio_pci2: mem 0xfe400000-0xfe400fff,0xfc800000-0xfc803fff irq 22 at device 0.0 on pci3 pcib4: mem 0xfea14000-0xfea14fff irq 22 at device 2.3 on pci0 pci4: on pcib4 virtio_pci3: mem 0xfe200000-0xfe200fff,0xfc600000-0xfc603fff irq 22 at device 0.0 on pci4 vtblk0: on virtio_pci3 vtblk0: 3072MB (6291456 512 byte sectors) pcib5: mem 0xfea15000-0xfea15fff irq 22 at device 2.4 on pci0 pci5: on pcib5 virtio_pci4: mem 0xfe000000-0xfe000fff,0xfc400000-0xfc403fff irq 22 at device 0.0 on pci5 vtblk1: on virtio_pci4 vtblk1: 1MB (2048 512 byte sectors) pcib6: mem 0xfea16000-0xfea16fff irq 22 at device 2.5 on pci0 pci6: on pcib6 virtio_pci5: mem 0xfc200000-0xfc203fff irq 22 at device 0.0 on pci6 vtballoon0: on virtio_pci5 pcib7: mem 0xfea17000-0xfea17fff irq 22 at device 2.6 on pci0 isab0: at device 31.0 on pci0 isa0: on isab0 ahci0: port 0xc040-0xc05f mem 0xfea18000-0xfea18fff irq 16 at device 31.2 on pci0 ahci0: AHCI v1.00 with 6 1.5Gbps ports, Port Multiplier not supported ahcich0: at channel 0 on ahci0 ahcich1: at channel 1 on ahci0 ahcich2: at channel 2 on ahci0 ahcich3: at channel 3 on ahci0 ahcich4: at channel 4 on ahci0 ahcich5: at channel 5 on ahci0 acpi_syscontainer0: on acpi0 acpi_syscontainer1: port 0xcd8-0xce3 on acpi0 acpi_syscontainer2: port 0x620-0x62f on acpi0 uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 uart0: console (115200,n,8,1) atkbdc0: port 0x60,0x64 irq 1 on acpi0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] psm0: irq 12 on atkbdc0 psm0: [GIANT-LOCKED] WARNING: Device "psm" is Giant locked and may be deleted before FreeBSD 14.0. psm0: model IntelliMouse Explorer, device ID 4 orm0: at iomem 0xe9000-0xeffff pnpid ORM0000 on isa0 vga0: at port 0x3c0-0x3df iomem 0xa0000-0xbffff pnpid PNP0900 on isa0 attimer0: at port 0x40 on isa0 Timecounter "i8254" frequency 1193182 Hz quality 0 Event timer "i8254" frequency 1193182 Hz quality 100 attimer0: non-PNP ISA device will be removed from GENERIC in FreeBSD 14. Timecounters tick every 10.000 msec ZFS filesystem version: 5 ZFS storage pool version: features support (5000) usb_needs_explore_all: no devclass Trying to mount root from zfs:zroot/ROOT/default []... Dual Console: Serial Primary, Video Secondary Setting hostuuid: 5a9fc181-957e-5c32-9e5a-2de5e9673531. Setting hostid: 0x2455456c. Starting file system checks: Mounting local filesystems:. random: unblocking device. ELF ldconfig path: /lib /usr/lib /usr/lib/compat /usr/local/lib /usr/local/lib/compat/pkg /usr/local/lib/compat/pkg /usr/local/lib/e2fsprogs 32-bit compatibility ldconfig path: /usr/lib32 /etc/rc: WARNING: $hostname is not set -- see rc.conf(5). Setting up harvesting: PURE_RDRAND,[UMA],[FS_ATIME],SWI,INTERRUPT,NET_NG,[NET_ETHER],NET_TUN,MOUSE,KEYBOARD,ATTACH,CACHED Feeding entropy: . /usr/local/bin/cloud-init startingCloud-init v. 21.4 running 'init-local' at Wed, 15 Dec 2021 10:50:00 +0000. Up 13.211192846298218 seconds. lo0: link state changed to DOWN lo0: link state changed to UP Autoloading module: ichsmb.ko Autoloading module: virtio_console.ko ichsmb0: port 0x700-0x73f irq 16 at device 31.3 on pci0 smbus0: on ichsmb0 vtcon0: on virtio_pci2 Starting Network: lo0 vtnet0. lo0: flags=8049 metric 0 mtu 16384 options=680003 inet6 ::1 prefixlen 128 inet6 fe80::1%lo0 prefixlen 64 scopeid 0x2 inet 127.0.0.1 netmask 0xff000000 groups: lo nd6 options=21 vtnet0: flags=8822 metric 0 mtu 1500 options=4c079b ether ee:82:d0:65:b7:c1 media: Ethernet autoselect (10Gbase-T ) status: active nd6 options=29 Starting devd. Starting Network: vtnet0. vtnet0: flags=8822 metric 0 mtu 1500 options=4c079b ether ee:82:d0:65:b7:c1 media: Ethernet autoselect (10Gbase-T ) status: active nd6 options=29 Autoloading module: virtio_console.ko Autoloading module: ichsmb.ko add host 127.0.0.1: gateway lo0 fib 0: route already in table add host ::1: gateway lo0 fib 0: route already in table add net fe80::: gateway ::1 fib 0: route already in table add net ff02::: gateway ::1 fib 0: route already in table add net ::ffff:0.0.0.0: gateway ::1 fib 0: route already in table add net ::0.0.0.0: gateway ::1 fib 0: route already in table /usr/local/bin/cloud-init startingCloud-init v. 21.4 running 'init' at Wed, 15 Dec 2021 10:50:17 +0000. Up 30.31445813179016 seconds. ci-info: ++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++ ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: | lo0 | True | 127.0.0.1 | 0xff000000 | . | . | ci-info: | lo0 | True | ::1/128 | . | . | . | ci-info: | lo0 | True | fe80::1%lo0/64 | . | 0x2 | . | ci-info: | vtnet0 | False | . | . | . | ee:82:d0:65:b7:c1 | ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: 2021-12-15 10:50:20,090 - util.py[WARNING]: Failed to create user kc2user 2021-12-15 10:50:20,108 - util.py[WARNING]: Running module users-groups () failed Generating public/private rsa key pair. Your identification has been saved in /etc/ssh/ssh_host_rsa_key. Your public key has been saved in /etc/ssh/ssh_host_rsa_key.pub. The key fingerprint is: SHA256:hIqU0ZFpHMyh5Saxm2lqgzp9ZvQeO6heQYPEth7Zyd0 root@testvm The key's randomart image is: +---[RSA 2048]----+ | .+==* | | .oXO . | | .B*=o... | | .+O+o..E | | .*.o S | |.o. .. | |o+ ..o. | |+ o.= oo | |.oo= .o. | +----[SHA256]-----+ Generating public/private dsa key pair. Your identification has been saved in /etc/ssh/ssh_host_dsa_key. Your public key has been saved in /etc/ssh/ssh_host_dsa_key.pub. The key fingerprint is: SHA256:UwDik78TUYlnwF5jq89V8NkebZX4xraz66exUfXo1kQ root@testvm The key's randomart image is: +---[DSA 1024]----+ | ..o+o. . .| | . oo.B.. . ..| | +..= o.o oo.E| | o.... + oB=| | o.S . .+o=| | .o .. ..* | | oo . = +| | .o . =.| | ++o| +----[SHA256]-----+ Generating public/private ecdsa key pair. Your identification has been saved in /etc/ssh/ssh_host_ecdsa_key. Your public key has been saved in /etc/ssh/ssh_host_ecdsa_key.pub. The key fingerprint is: SHA256:0keb8Sgm2N9L9JwCPKBdlaPkJB1qhIpW72r9VTuD0eA root@testvm The key's randomart image is: +---[ECDSA 256]---+ | ....... | | .....+.o | | .... +=.oo. | |... B =+.o* | |. + = SE*o. | | . = B+o.. | | o .o+++ | | o . .. oo | | . .. . | +----[SHA256]-----+ Generating public/private ed25519 key pair. Your identification has been saved in /etc/ssh/ssh_host_ed25519_key. Your public key has been saved in /etc/ssh/ssh_host_ed25519_key.pub. The key fingerprint is: SHA256:rxXlaXjAWIJTZ8ZLXB+BcGQM/+H0N4W18K65onkm2hY root@testvm The key's randomart image is: +--[ED25519 256]--+ | oooB*=oo..| | o O++o.o+.| | ...o.o =o.| | .= =.o.| | S o = ooo| | E + o o| | + o | | .=.+ . | | .++= .. | +----[SHA256]-----+ 2021-12-15 10:50:21,507 - util.py[WARNING]: Applying SSH credentials failed! /usr/local/bin/cloud-init starting Cloud-init v. 21.4 running 'modules:config' at Wed, 15 Dec 2021 10:50:25 +0000. Up 38.66350340843201 seconds. Updating /var/run/os-release done. Clearing /tmp (X related). Creating and/or trimming log files. Updating motd:. Starting syslogd. Starting qemu_guest_agent. Mounting late filesystems:. Performing sanity check on sshd configuration. Starting sshd. Configuring vt: blanktime. Starting cron. /usr/local/bin/cloud-init startingCloud-init v. 21.4 running 'modules:final' at Wed, 15 Dec 2021 10:50:33 +0000. Up 46.4662184715271 seconds. 2021-12-15 10:50:34,734 - util.py[WARNING]: Running module ssh-authkey-fingerprints () failed cloud-init 1073 - - ############################################################# cloud-init 1077 - - -----BEGIN SSH HOST KEY FINGERPRINTS----- cloud-init 1082 - - 1024 SHA256:UwDik78TUYlnwF5jq89V8NkebZX4xraz66exUfXo1kQ root@testvm (DSA) cloud-init 1087 - - 256 SHA256:0keb8Sgm2N9L9JwCPKBdlaPkJB1qhIpW72r9VTuD0eA root@testvm (ECDSA) cloud-init 1092 - - 256 SHA256:rxXlaXjAWIJTZ8ZLXB+BcGQM/+H0N4W18K65onkm2hY root@testvm (ED25519) cloud-init 1097 - - 2048 SHA256:hIqU0ZFpHMyh5Saxm2lqgzp9ZvQeO6heQYPEth7Zyd0 root@testvm (RSA) cloud-init 1101 - - -----END SSH HOST KEY FINGERPRINTS----- cloud-init 1105 - - ############################################################# -----BEGIN SSH HOST KEY KEYS----- ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBMIC107y8CWQSbUER3BWgXmN9yv3wDL8Q1TIV9kSCMUtzW46WLUA/GoFr0NRI3SiiUbod0zbWMC5CdPY2m9WeTU= root@testvm ssh-ed25519 AAAAC3NzaC1lZDI1NTE5AAAAIIJz/nhT04Xw0wmGWZlz7BUP/DG7CYH5LblReqxU9+tr root@testvm ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC/GuVTTAxOvBN7Pm/WLeLPQNdVihnKY28yASr/x5Dhetrbf2dcr4J05p+aCmYwk4CJn29oRBadmk9SsDl2AK2PuAMdXsEw1YBHQrOaJB9xeVeSflecWJQsN7/Y3d06CBxLh+x6+9orOv8lggVwa0ugXukVcrGlNbs4RI5X1n1IV4GCVO3+JuQVXaRCsPNcNYRfVeNp5/pF756pTxK+E8XLJPlIBOhlXY/1cIianyCDnGDfyDS/xCPUr7wzP6jJNYIN8c1SgKabnx6pa5SggxU9FCyv7LvQgneHqtBbx7OS0ztuhjz+NUg8XLy3vATCf85caDoMIJ58PWMOfr/F1H0/ root@testvm -----END SSH HOST KEY KEYS----- Cloud-init v. 21.4 finished at Wed, 15 Dec 2021 10:50:35 +0000. Datasource DataSourceNoCloud [seed=/dev/iso9660/cidata][dsmode=net]. Up 48.321099519729614 seconds Starting background file system checks in 60 seconds. Wed Dec 15 10:50:35 UTC 2021 FreeBSD/amd64 (testvm) (ttyu0) login: ```
jbpratt commented 2 years ago

adding cloud-init logs.

Looking through the logs, I think the issues are going to be related and may be worked around easily.

2021-12-15 17:44:23,953 - util.py[DEBUG]: Running module ssh-authkey-fingerprints (<module 'cloudinit.config.cc_ssh_authkey_fingerprints' from '/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/config/cc_ssh_authkey_fingerprints.py'>) failed
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/stages.py", line 976, in _run_modules
    ran, _r = cc.run(run_name, mod.handle, func_args,
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/cloud.py", line 54, in run
    return self._runners.run(name, functor, args, freq, clear_on_fail)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/helpers.py", line 186, in run
    results = functor(*args)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/config/cc_ssh_authkey_fingerprints.py", line 107, in handle
    (key_fn, key_entries) = ssh_util.extract_authorized_keys(user_name)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 385, in extract_authorized_keys
    (ssh_dir, pw_ent) = users_ssh_info(username)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 226, in users_ssh_info
    pw_ent = pwd.getpwnam(username)
KeyError: "getpwnam(): name not found: 'kc2user'"
2021-12-15 17:44:10,688 - util.py[DEBUG]: Applying SSH credentials failed!
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/config/cc_ssh.py", line 301, in handle
    apply_credentials(keys, user, disable_root, disable_root_opts)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/config/cc_ssh.py", line 310, in apply_credentials
    ssh_util.setup_user_keys(keys, user)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 437, in setup_user_keys
    (auth_key_fn, auth_key_entries) = extract_authorized_keys(username)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 385, in extract_authorized_keys
    (ssh_dir, pw_ent) = users_ssh_info(username)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 226, in users_ssh_info
    pw_ent = pwd.getpwnam(username)
KeyError: "getpwnam(): name not found: 'freebsd'"
2021-12-15 17:44:09,321 - util.py[WARNING]: Failed to create user kc2user
2021-12-15 17:44:09,324 - util.py[DEBUG]: Failed to create user kc2user
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/distros/freebsd.py", line 87, in add_user
    subp.subp(pw_useradd_cmd, logstring=log_pw_useradd_cmd)
  File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/subp.py", line 293, in subp
    raise ProcessExecutionError(stdout=out, stderr=err,
cloudinit.subp.ProcessExecutionError: Unexpected error while running command.
Command: ['pw', 'useradd', '-n', 'kc2user', '-G', 'sudo,wheel', '-d/usr/home/kc2user', '-m']
Exit code: 67
Reason: -
Stdout:
Stderr: pw: group `sudo' does not exist
cloud-init-output.log ``` root@testvm:~ # cat /var/log/cloud-init-output.log Cloud-init v. 21.4 running 'init-local' at Wed, 15 Dec 2021 17:43:49 +0000. Up 12.600369930267334 seconds. Cloud-init v. 21.4 running 'init' at Wed, 15 Dec 2021 17:44:06 +0000. Up 29.48997211456299 seconds. ci-info: ++++++++++++++++++++++++++++++Net device info+++++++++++++++++++++++++++++++ ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: | Device | Up | Address | Mask | Scope | Hw-Address | ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: | lo0 | True | 127.0.0.1 | 0xff000000 | . | . | ci-info: | lo0 | True | ::1/128 | . | . | . | ci-info: | lo0 | True | fe80::1%lo0/64 | . | 0x2 | . | ci-info: | vtnet0 | False | . | . | . | 1e:6c:ad:bd:28:28 | ci-info: +--------+-------+----------------+------------+-------+-------------------+ ci-info: 2021-12-15 17:44:09,321 - util.py[WARNING]: Failed to create user kc2user 2021-12-15 17:44:09,337 - util.py[WARNING]: Running module users-groups () failed Generating public/private rsa key pair. Your identification has been saved in /etc/ssh/ssh_host_rsa_key. Your public key has been saved in /etc/ssh/ssh_host_rsa_key.pub. The key fingerprint is: SHA256:R5kAuZhFFWhEbai1vlhpM60H6ARcINUzo4KWWjSYS84 root@testvm The key's randomart image is: +---[RSA 2048]----+ |.+oo +=B+. | |ooo * B o. o | |=+.+ @ + + | |+E= + o . | |oo . o oS . | |. o O .. | | o + * | | o o . | | . | +----[SHA256]-----+ Generating public/private dsa key pair. Your identification has been saved in /etc/ssh/ssh_host_dsa_key. Your public key has been saved in /etc/ssh/ssh_host_dsa_key.pub. The key fingerprint is: SHA256:mHobenZ2bv20ORWwSFIJwUJBMLnB0gBhsUNQ45f4qLE root@testvm The key's randomart image is: +---[DSA 1024]----+ |oB*.+o=+oo+.. | |o..+ *.. o o . | | oo + o . o . o | | .+ . o . . . | |. . . o S .| | + . .| |E . o . .. | | oooo o ...o | | .o.o +. .+. | +----[SHA256]-----+ Generating public/private ecdsa key pair. Your identification has been saved in /etc/ssh/ssh_host_ecdsa_key. Your public key has been saved in /etc/ssh/ssh_host_ecdsa_key.pub. The key fingerprint is: SHA256:h9YBvezh28D8wiTD7KUJkbN9sZwUhpG2YYPEWfVAIU4 root@testvm The key's randomart image is: +---[ECDSA 256]---+ | o.+EB=. | | +oBo+o | | +.*.o. | | + .o*. | | BSBo= | | o.*.& | | o X = | | + + o | | . | +----[SHA256]-----+ Generating public/private ed25519 key pair. Your identification has been saved in /etc/ssh/ssh_host_ed25519_key. Your public key has been saved in /etc/ssh/ssh_host_ed25519_key.pub. The key fingerprint is: SHA256:8zGG1EVzP8bwFLeMW0YFoOyDwmtLjwrJyMb70M70Vyw root@testvm The key's randomart image is: +--[ED25519 256]--+ | .=oo==| | o o oO.o| | . + . X.| | . . + = .| | o S * . | |oo.. E * + | |.=+o + o . | |. *..o = | | ..+.o+ . | +----[SHA256]-----+ 2021-12-15 17:44:10,686 - util.py[WARNING]: Applying SSH credentials failed! Cloud-init v. 21.4 running 'modules:config' at Wed, 15 Dec 2021 17:44:14 +0000. Up 37.7137713432312 seconds. Cloud-init v. 21.4 running 'modules:final' at Wed, 15 Dec 2021 17:44:22 +0000. Up 45.56748056411743 seconds. 2021-12-15 17:44:23,950 - util.py[WARNING]: Running module ssh-authkey-fingerprints () failed Cloud-init v. 21.4 finished at Wed, 15 Dec 2021 17:44:24 +0000. Datasource DataSourceNoCloud [seed=/dev/iso9660/cidata][dsmode=net]. Up 47.48525404930115 seconds ```
cloud-init.log ``` root@testvm:~ # cat /var/log/cloud-init.log 2021-12-15 17:43:49,983 - util.py[DEBUG]: Cloud-init v. 21.4 running 'init-local' at Wed, 15 Dec 2021 17:43:49 +0000. Up 12.600369930267334 seconds. 2021-12-15 17:43:49,984 - main.py[DEBUG]: No kernel command line url found. 2021-12-15 17:43:49,985 - main.py[DEBUG]: Closing stdin. 2021-12-15 17:43:50,022 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes 2021-12-15 17:43:50,048 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:0 2021-12-15 17:43:50,051 - util.py[DEBUG]: Writing to /var/lib/cloud/data/python-version - wb: [644] 3 bytes 2021-12-15 17:43:50,057 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance/boot-finished 2021-12-15 17:43:50,057 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/data/no-net 2021-12-15 17:43:50,060 - handlers.py[DEBUG]: start: init-local/check-cache: attempting to read from cache [check] 2021-12-15 17:43:50,060 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2021-12-15 17:43:50,061 - stages.py[DEBUG]: no cache found 2021-12-15 17:43:50,062 - handlers.py[DEBUG]: finish: init-local/check-cache: SUCCESS: no cache found 2021-12-15 17:43:50,062 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2021-12-15 17:43:50,088 - stages.py[DEBUG]: Using distro class 2021-12-15 17:43:50,090 - __init__.py[DEBUG]: Looking for data source in: ['NoCloud', 'ConfigDrive', 'Azure', 'OpenStack', 'Ec2'], via packages ['', 'cloudinit.sources'] that matches dependencies ['FILESYSTEM'] 2021-12-15 17:43:50,380 - subp.py[DEBUG]: Running command ['sysctl', 'dev.storvsc'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:50,409 - DataSourceAzure.py[DEBUG]: Failed to execute: sysctl dev.storvsc 2021-12-15 17:43:50,411 - DataSourceAzure.py[DEBUG]: Fail to find storvsc id from sysctl 2021-12-15 17:43:50,411 - DataSourceAzure.py[DEBUG]: resource disk is None 2021-12-15 17:43:50,444 - __init__.py[DEBUG]: Searching for local data source in: ['DataSourceNoCloud', 'DataSourceConfigDrive', 'DataSourceAzure', 'DataSourceOpenStackLocal', 'DataSourceEc2Local'] 2021-12-15 17:43:50,446 - handlers.py[DEBUG]: start: init-local/search-NoCloud: searching for local data from DataSourceNoCloud 2021-12-15 17:43:50,446 - __init__.py[DEBUG]: Seeing if we can get any data from 2021-12-15 17:43:50,449 - __init__.py[DEBUG]: Update datasource metadata and network config due to events: boot-new-instance 2021-12-15 17:43:50,450 - dmi.py[DEBUG]: querying dmi data smbios.system.serial 2021-12-15 17:43:50,451 - subp.py[DEBUG]: Running command ['kenv', '-q', 'smbios.system.serial'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:50,476 - dmi.py[DEBUG]: failed kenv cmd: ['kenv', '-q', 'smbios.system.serial'] Unexpected error while running command. Command: ['kenv', '-q', 'smbios.system.serial'] Exit code: 255 Reason: - Stdout: Stderr: 2021-12-15 17:43:50,478 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/user-data (quiet=False) 2021-12-15 17:43:50,479 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/meta-data (quiet=False) 2021-12-15 17:43:50,479 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/vendor-data (quiet=False) 2021-12-15 17:43:50,480 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud/network-config (quiet=False) 2021-12-15 17:43:50,481 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/user-data (quiet=False) 2021-12-15 17:43:50,481 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/meta-data (quiet=False) 2021-12-15 17:43:50,482 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/vendor-data (quiet=False) 2021-12-15 17:43:50,482 - util.py[DEBUG]: Reading from /var/lib/cloud/seed/nocloud-net/network-config (quiet=False) 2021-12-15 17:43:50,487 - DataSourceNoCloud.py[DEBUG]: Attempting to use data from /dev/iso9660/cidata 2021-12-15 17:43:50,489 - subp.py[DEBUG]: Running command mount with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:50,519 - util.py[DEBUG]: Fetched {} mounts from mount 2021-12-15 17:43:50,523 - subp.py[DEBUG]: Running command ['mount', '-o', 'ro', '-t', 'ufs', '/dev/iso9660/cidata', '/run/cloud-init/tmp/tmppuzxnnrk'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:50,568 - util.py[DEBUG]: Failed to mount device: '/dev/iso9660/cidata' with type: 'ufs' using mount command: 'mount -o ro -t ufs /dev/iso9660/cidata /run/cloud-init/tmp/tmppuzxnnrk', which caused exception: Unexpected error while running command. Command: ['mount', '-o', 'ro', '-t', 'ufs', '/dev/iso9660/cidata', '/run/cloud-init/tmp/tmppuzxnnrk'] Exit code: 1 Reason: - Stdout: Stderr: mount: /dev/iso9660/cidata: No such file or directory 2021-12-15 17:43:50,570 - subp.py[DEBUG]: Running command ['mount', '-o', 'ro', '-t', 'cd9660', '/dev/iso9660/cidata', '/run/cloud-init/tmp/tmppuzxnnrk'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:50,632 - util.py[DEBUG]: Reading from /run/cloud-init/tmp/tmppuzxnnrk//user-data (quiet=False) 2021-12-15 17:43:50,638 - util.py[DEBUG]: Read 885 bytes from /run/cloud-init/tmp/tmppuzxnnrk//user-data 2021-12-15 17:43:50,639 - util.py[DEBUG]: Reading from /run/cloud-init/tmp/tmppuzxnnrk//meta-data (quiet=False) 2021-12-15 17:43:50,641 - util.py[DEBUG]: Read 58 bytes from /run/cloud-init/tmp/tmppuzxnnrk//meta-data 2021-12-15 17:43:50,641 - util.py[DEBUG]: Reading from /run/cloud-init/tmp/tmppuzxnnrk//vendor-data (quiet=False) 2021-12-15 17:43:50,642 - util.py[DEBUG]: Reading from /run/cloud-init/tmp/tmppuzxnnrk//network-config (quiet=False) 2021-12-15 17:43:50,643 - util.py[DEBUG]: Read 98 bytes from /run/cloud-init/tmp/tmppuzxnnrk//network-config 2021-12-15 17:43:50,644 - subp.py[DEBUG]: Running command ['umount', '/run/cloud-init/tmp/tmppuzxnnrk'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:50,679 - util.py[DEBUG]: Attempting to load yaml from string of length 58 with allowed root types (,) 2021-12-15 17:43:50,686 - util.py[DEBUG]: Attempting to load yaml from string of length 98 with allowed root types (,) 2021-12-15 17:43:50,697 - DataSourceNoCloud.py[DEBUG]: Using data from /dev/iso9660/cidata 2021-12-15 17:43:50,713 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data-sensitive.json (via temporary file /run/cloud-init/tmp_1oklyke) - w: [600] 4629 bytes/chars 2021-12-15 17:43:50,720 - atomic_helper.py[DEBUG]: Atomically writing to file /run/cloud-init/instance-data.json (via temporary file /run/cloud-init/tmpe0doxr3e) - w: [644] 1519 bytes/chars 2021-12-15 17:43:50,722 - handlers.py[DEBUG]: finish: init-local/search-NoCloud: SUCCESS: found local data from DataSourceNoCloud 2021-12-15 17:43:50,723 - stages.py[INFO]: Loaded datasource DataSourceNoCloud - DataSourceNoCloud [seed=/dev/iso9660/cidata][dsmode=net] 2021-12-15 17:43:50,725 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2021-12-15 17:43:50,726 - util.py[DEBUG]: Read 2410 bytes from /etc/cloud/cloud.cfg 2021-12-15 17:43:50,726 - util.py[DEBUG]: Attempting to load yaml from string of length 2410 with allowed root types (,) 2021-12-15 17:43:50,827 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2021-12-15 17:43:50,829 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2021-12-15 17:43:50,829 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2021-12-15 17:43:50,878 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2021-12-15 17:43:50,879 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2021-12-15 17:43:50,880 - util.py[DEBUG]: loaded blob returned None, returning default. 2021-12-15 17:43:50,886 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2021-12-15 17:43:50,887 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/testvm.default' 2021-12-15 17:43:50,900 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/testvm.default/datasource (quiet=False) 2021-12-15 17:43:50,902 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/datasource - wb: [644] 76 bytes 2021-12-15 17:43:50,906 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 76 bytes 2021-12-15 17:43:50,911 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2021-12-15 17:43:50,911 - stages.py[DEBUG]: previous iid found to be NO_PREVIOUS_INSTANCE_ID 2021-12-15 17:43:50,913 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 15 bytes 2021-12-15 17:43:50,917 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 15 bytes 2021-12-15 17:43:50,921 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 24 bytes 2021-12-15 17:43:50,931 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 4913 bytes 2021-12-15 17:43:50,936 - main.py[DEBUG]: [local] init will now be targeting instance id: testvm.default. new=True 2021-12-15 17:43:50,939 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2021-12-15 17:43:50,940 - util.py[DEBUG]: Read 2410 bytes from /etc/cloud/cloud.cfg 2021-12-15 17:43:50,941 - util.py[DEBUG]: Attempting to load yaml from string of length 2410 with allowed root types (,) 2021-12-15 17:43:51,039 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2021-12-15 17:43:51,041 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2021-12-15 17:43:51,041 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2021-12-15 17:43:51,086 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2021-12-15 17:43:51,087 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2021-12-15 17:43:51,088 - util.py[DEBUG]: loaded blob returned None, returning default. 2021-12-15 17:43:51,096 - stages.py[DEBUG]: Using distro class 2021-12-15 17:43:51,101 - cc_set_hostname.py[DEBUG]: Setting the hostname to testvm (testvm) 2021-12-15 17:43:51,102 - util.py[DEBUG]: Reading from /etc/rc.conf (quiet=False) 2021-12-15 17:43:51,103 - util.py[DEBUG]: Read 166 bytes from /etc/rc.conf 2021-12-15 17:43:51,104 - util.py[DEBUG]: Writing to /etc/rc.conf - wb: [644] 182 bytes 2021-12-15 17:43:51,108 - __init__.py[DEBUG]: Non-persistently setting the system hostname to testvm 2021-12-15 17:43:51,109 - subp.py[DEBUG]: Running command ['hostname', 'testvm'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:51,138 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/set-hostname (via temporary file /var/lib/cloud/data/tmp1mpcf5kb) - w: [644] 45 bytes/chars 2021-12-15 17:43:51,146 - subp.py[DEBUG]: Running command ['ifconfig', '-a', 'ether'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:51,186 - util.py[DEBUG]: Reading from /sys/class/net/vtnet0/address (quiet=False) 2021-12-15 17:43:51,192 - subp.py[DEBUG]: Running command ['ifconfig', '-a', 'ether'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:51,222 - util.py[DEBUG]: Reading from /sys/class/net/vtnet0/address (quiet=False) 2021-12-15 17:43:51,226 - subp.py[DEBUG]: Running command ['ifconfig', '-a', 'ether'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:51,257 - networking.py[DEBUG]: net: all expected physical devices present 2021-12-15 17:43:51,259 - stages.py[DEBUG]: applying net config names for {'version': 2, 'ethernets': {'eth0': {'match': {'mac_address': 'a8:a1:59:02:0d:0e', 'dhcp4': True}}}} 2021-12-15 17:43:51,260 - stages.py[INFO]: Applying network configuration from ds bringup=False: {'version': 2, 'ethernets': {'eth0': {'match': {'mac_address': 'a8:a1:59:02:0d:0e', 'dhcp4': True}}}} 2021-12-15 17:43:51,263 - util.py[DEBUG]: Writing to /run/cloud-init/sem/apply_network_config.once - wb: [644] 24 bytes 2021-12-15 17:43:51,270 - network_state.py[DEBUG]: NetworkState Version2: missing "macaddress" info in config entry: eth0: {'match': {'mac_address': 'a8:a1:59:02:0d:0e', 'dhcp4': True}} 2021-12-15 17:43:51,270 - network_state.py[DEBUG]: v2(ethernets) -> v1(physical): {'type': 'physical', 'name': 'eth0', 'mac_address': None, 'match': {'mac_address': 'a8:a1:59:02:0d:0e', 'dhcp4': True}} 2021-12-15 17:43:51,292 - network_state.py[DEBUG]: v2_common: handling config: {'eth0': {'match': {'mac_address': 'a8:a1:59:02:0d:0e', 'dhcp4': True}}} 2021-12-15 17:43:51,294 - __init__.py[DEBUG]: Selected renderer 'freebsd' from priority list: ['freebsd'] 2021-12-15 17:43:51,295 - subp.py[DEBUG]: Running command ['ifconfig', '-a', 'ether'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:51,328 - bsd.py[INFO]: Cannot find any device with MAC None 2021-12-15 17:43:51,330 - bsd.py[INFO]: Configuring interface eth0 2021-12-15 17:43:51,331 - util.py[DEBUG]: Reading from /etc/resolv.conf (quiet=False) 2021-12-15 17:43:51,333 - util.py[DEBUG]: Read 1 bytes from /etc/resolv.conf 2021-12-15 17:43:51,334 - util.py[DEBUG]: Writing to /etc/resolv.conf - wb: [644] 1 bytes 2021-12-15 17:43:51,340 - util.py[DEBUG]: Reading from /etc/rc.conf (quiet=False) 2021-12-15 17:43:51,340 - util.py[DEBUG]: Read 182 bytes from /etc/rc.conf 2021-12-15 17:43:51,341 - util.py[DEBUG]: Writing to /etc/rc.conf - wb: [644] 201 bytes 2021-12-15 17:43:51,344 - subp.py[DEBUG]: Running command ['service', 'dhclient', 'stop', 'eth0'] with allowed return codes [0, 1] (shell=False, capture=True) 2021-12-15 17:43:51,480 - subp.py[DEBUG]: Running command ['service', 'netif', 'restart'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:43:55,015 - subp.py[DEBUG]: Running command ['service', 'routing', 'restart'] with allowed return codes [0, 1] (shell=False, capture=True) 2021-12-15 17:43:55,642 - subp.py[DEBUG]: Running command ['service', 'dhclient', 'start', 'eth0'] with allowed return codes [0, 1] (shell=False, capture=True) 2021-12-15 17:43:55,976 - __init__.py[DEBUG]: Not bringing up newly configured network interfaces 2021-12-15 17:43:55,978 - main.py[DEBUG]: [local] Exiting. datasource DataSourceNoCloud [seed=/dev/iso9660/cidata][dsmode=net] not in local mode. 2021-12-15 17:43:55,983 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpwzq3jxgd) - w: [644] 527 bytes/chars 2021-12-15 17:43:55,987 - util.py[DEBUG]: cloud-init mode 'init' took 6.540 seconds (6.54) 2021-12-15 17:43:55,989 - handlers.py[DEBUG]: finish: init-local: SUCCESS: searching for local datasources 2021-12-15 17:44:06,848 - util.py[DEBUG]: Cloud-init v. 21.4 running 'init' at Wed, 15 Dec 2021 17:44:06 +0000. Up 29.48997211456299 seconds. 2021-12-15 17:44:06,850 - main.py[DEBUG]: No kernel command line url found. 2021-12-15 17:44:06,850 - main.py[DEBUG]: Closing stdin. 2021-12-15 17:44:06,889 - util.py[DEBUG]: Writing to /var/log/cloud-init.log - ab: [644] 0 bytes 2021-12-15 17:44:06,896 - util.py[DEBUG]: Changing the ownership of /var/log/cloud-init.log to 0:0 2021-12-15 17:44:06,908 - subp.py[DEBUG]: Running command ['ifconfig', '-a'] with allowed return codes [0, 1] (shell=False, capture=True) 2021-12-15 17:44:06,948 - subp.py[DEBUG]: Running command ['netstat', '--route', '--numeric', '--extend'] with allowed return codes [0, 1] (shell=False, capture=True) 2021-12-15 17:44:07,036 - subp.py[DEBUG]: Running command ['netstat', '-A', 'inet6', '--route', '--numeric'] with allowed return codes [0, 1] (shell=False, capture=True) 2021-12-15 17:44:07,078 - main.py[DEBUG]: Checking to see if files that we need already exist from a previous run that would allow us to stop early. 2021-12-15 17:44:07,080 - main.py[DEBUG]: Execution continuing, no previous run detected that would allow us to stop early. 2021-12-15 17:44:07,083 - handlers.py[DEBUG]: start: init-network/check-cache: attempting to read from cache [trust] 2021-12-15 17:44:07,085 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/obj.pkl (quiet=False) 2021-12-15 17:44:07,086 - util.py[DEBUG]: Read 4913 bytes from /var/lib/cloud/instance/obj.pkl 2021-12-15 17:44:07,104 - util.py[DEBUG]: Reading from /run/cloud-init/.instance-id (quiet=False) 2021-12-15 17:44:07,106 - util.py[DEBUG]: Read 15 bytes from /run/cloud-init/.instance-id 2021-12-15 17:44:07,106 - stages.py[DEBUG]: restored from cache with run check: DataSourceNoCloud [seed=/dev/iso9660/cidata][dsmode=net] 2021-12-15 17:44:07,108 - handlers.py[DEBUG]: finish: init-network/check-cache: SUCCESS: restored from cache with run check: DataSourceNoCloud [seed=/dev/iso9660/cidata][dsmode=net] 2021-12-15 17:44:07,109 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2021-12-15 17:44:07,110 - util.py[DEBUG]: Read 2410 bytes from /etc/cloud/cloud.cfg 2021-12-15 17:44:07,111 - util.py[DEBUG]: Attempting to load yaml from string of length 2410 with allowed root types (,) 2021-12-15 17:44:07,215 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2021-12-15 17:44:07,216 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2021-12-15 17:44:07,217 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2021-12-15 17:44:07,263 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2021-12-15 17:44:07,264 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2021-12-15 17:44:07,266 - util.py[DEBUG]: loaded blob returned None, returning default. 2021-12-15 17:44:07,270 - util.py[DEBUG]: Attempting to remove /var/lib/cloud/instance 2021-12-15 17:44:07,271 - util.py[DEBUG]: Creating symbolic link from '/var/lib/cloud/instance' => '/var/lib/cloud/instances/testvm.default' 2021-12-15 17:44:07,277 - util.py[DEBUG]: Reading from /var/lib/cloud/instances/testvm.default/datasource (quiet=False) 2021-12-15 17:44:07,278 - util.py[DEBUG]: Read 76 bytes from /var/lib/cloud/instances/testvm.default/datasource 2021-12-15 17:44:07,279 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/datasource - wb: [644] 76 bytes 2021-12-15 17:44:07,283 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-datasource - wb: [644] 76 bytes 2021-12-15 17:44:07,287 - util.py[DEBUG]: Reading from /var/lib/cloud/data/instance-id (quiet=False) 2021-12-15 17:44:07,288 - util.py[DEBUG]: Read 15 bytes from /var/lib/cloud/data/instance-id 2021-12-15 17:44:07,288 - stages.py[DEBUG]: previous iid found to be testvm.default 2021-12-15 17:44:07,289 - util.py[DEBUG]: Writing to /var/lib/cloud/data/instance-id - wb: [644] 15 bytes 2021-12-15 17:44:07,293 - util.py[DEBUG]: Writing to /run/cloud-init/.instance-id - wb: [644] 15 bytes 2021-12-15 17:44:07,296 - util.py[DEBUG]: Writing to /var/lib/cloud/data/previous-instance-id - wb: [644] 15 bytes 2021-12-15 17:44:07,303 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 4938 bytes 2021-12-15 17:44:07,306 - main.py[DEBUG]: [net] init will now be targeting instance id: testvm.default. new=False 2021-12-15 17:44:07,308 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2021-12-15 17:44:07,308 - util.py[DEBUG]: Read 2410 bytes from /etc/cloud/cloud.cfg 2021-12-15 17:44:07,309 - util.py[DEBUG]: Attempting to load yaml from string of length 2410 with allowed root types (,) 2021-12-15 17:44:07,406 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2021-12-15 17:44:07,408 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2021-12-15 17:44:07,408 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2021-12-15 17:44:07,455 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2021-12-15 17:44:07,456 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2021-12-15 17:44:07,457 - util.py[DEBUG]: loaded blob returned None, returning default. 2021-12-15 17:44:07,466 - subp.py[DEBUG]: Running command ['ifconfig', '-a', 'ether'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:07,501 - util.py[DEBUG]: Reading from /sys/class/net/vtnet0/address (quiet=False) 2021-12-15 17:44:07,510 - stages.py[DEBUG]: Allowed events: {: {}} 2021-12-15 17:44:07,511 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=boot-legacy 2021-12-15 17:44:07,512 - stages.py[DEBUG]: No network config applied. Neither a new instance nor datasource network update allowed 2021-12-15 17:44:07,513 - stages.py[DEBUG]: applying net config names for {'version': 2, 'ethernets': {'eth0': {'match': {'mac_address': 'a8:a1:59:02:0d:0e', 'dhcp4': True}}}} 2021-12-15 17:44:07,517 - stages.py[DEBUG]: Using distro class 2021-12-15 17:44:07,521 - handlers.py[DEBUG]: start: init-network/setup-datasource: setting up datasource 2021-12-15 17:44:07,522 - handlers.py[DEBUG]: finish: init-network/setup-datasource: SUCCESS: setting up datasource 2021-12-15 17:44:07,523 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/user-data.txt - wb: [600] 885 bytes 2021-12-15 17:44:07,535 - util.py[DEBUG]: Attempting to load yaml from string of length 885 with allowed root types (,) 2021-12-15 17:44:07,588 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/user-data.txt.i - wb: [600] 1190 bytes 2021-12-15 17:44:07,593 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/vendor-data.txt - wb: [600] 0 bytes 2021-12-15 17:44:07,603 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/vendor-data.txt.i - wb: [600] 308 bytes 2021-12-15 17:44:07,608 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/vendor-data2.txt - wb: [600] 0 bytes 2021-12-15 17:44:07,618 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/vendor-data2.txt.i - wb: [600] 308 bytes 2021-12-15 17:44:07,628 - util.py[DEBUG]: Reading from /var/lib/cloud/data/set-hostname (quiet=False) 2021-12-15 17:44:07,629 - util.py[DEBUG]: Read 45 bytes from /var/lib/cloud/data/set-hostname 2021-12-15 17:44:07,630 - cc_set_hostname.py[DEBUG]: No hostname changes. Skipping set-hostname 2021-12-15 17:44:07,633 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/consume_data - wb: [644] 23 bytes 2021-12-15 17:44:07,638 - helpers.py[DEBUG]: Running consume_data using lock () 2021-12-15 17:44:07,640 - handlers.py[DEBUG]: start: init-network/consume-user-data: reading and applying user-data 2021-12-15 17:44:07,644 - stages.py[DEBUG]: Added default handler for {'text/cloud-config-jsonp', 'text/cloud-config'} from CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] 2021-12-15 17:44:07,645 - stages.py[DEBUG]: Added default handler for {'text/x-shellscript'} from ShellScriptPartHandler: [['text/x-shellscript']] 2021-12-15 17:44:07,645 - stages.py[DEBUG]: Added default handler for {'text/cloud-boothook'} from BootHookPartHandler: [['text/cloud-boothook']] 2021-12-15 17:44:07,646 - stages.py[DEBUG]: Added default handler for {'text/upstart-job'} from UpstartJobPartHandler: [['text/upstart-job']] 2021-12-15 17:44:07,646 - stages.py[DEBUG]: Added default handler for {'text/jinja2'} from JinjaTemplatePartHandler: [['text/jinja2']] 2021-12-15 17:44:07,649 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__begin__, None, 3) with frequency once-per-instance 2021-12-15 17:44:07,649 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__begin__, None, 2) with frequency once-per-instance 2021-12-15 17:44:07,650 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__begin__, None, 2) with frequency once-per-instance 2021-12-15 17:44:07,650 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__begin__, None, 2) with frequency once-per-instance 2021-12-15 17:44:07,651 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__begin__, None, 3) with frequency once-per-instance 2021-12-15 17:44:07,652 - __init__.py[DEBUG]: {'MIME-Version': '1.0', 'Content-Type': 'text/cloud-config', 'Content-Disposition': 'attachment; filename="part-001"'} 2021-12-15 17:44:07,653 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (text/cloud-config, part-001, 3) with frequency once-per-instance 2021-12-15 17:44:07,654 - util.py[DEBUG]: Attempting to load yaml from string of length 885 with allowed root types (,) 2021-12-15 17:44:07,676 - cloud_config.py[DEBUG]: Merging by applying [('dict', ['replace']), ('list', []), ('str', [])] 2021-12-15 17:44:07,678 - __init__.py[DEBUG]: Calling handler CloudConfigPartHandler: [['text/cloud-config', 'text/cloud-config-jsonp']] (__end__, None, 3) with frequency once-per-instance 2021-12-15 17:44:07,696 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/cloud-config.txt - wb: [600] 925 bytes 2021-12-15 17:44:07,703 - __init__.py[DEBUG]: Calling handler ShellScriptPartHandler: [['text/x-shellscript']] (__end__, None, 2) with frequency once-per-instance 2021-12-15 17:44:07,703 - __init__.py[DEBUG]: Calling handler BootHookPartHandler: [['text/cloud-boothook']] (__end__, None, 2) with frequency once-per-instance 2021-12-15 17:44:07,704 - __init__.py[DEBUG]: Calling handler UpstartJobPartHandler: [['text/upstart-job']] (__end__, None, 2) with frequency once-per-instance 2021-12-15 17:44:07,705 - __init__.py[DEBUG]: Calling handler JinjaTemplatePartHandler: [['text/jinja2']] (__end__, None, 3) with frequency once-per-instance 2021-12-15 17:44:07,705 - handlers.py[DEBUG]: finish: init-network/consume-user-data: SUCCESS: reading and applying user-data 2021-12-15 17:44:07,706 - handlers.py[DEBUG]: start: init-network/consume-vendor-data: reading and applying vendor-data 2021-12-15 17:44:07,707 - stages.py[DEBUG]: no vendordata from datasource 2021-12-15 17:44:07,707 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data: SUCCESS: reading and applying vendor-data 2021-12-15 17:44:07,708 - handlers.py[DEBUG]: start: init-network/consume-vendor-data2: reading and applying vendor-data2 2021-12-15 17:44:07,709 - stages.py[DEBUG]: no vendordata2 from datasource 2021-12-15 17:44:07,709 - handlers.py[DEBUG]: finish: init-network/consume-vendor-data2: SUCCESS: reading and applying vendor-data2 2021-12-15 17:44:07,711 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg (quiet=False) 2021-12-15 17:44:07,712 - util.py[DEBUG]: Read 2410 bytes from /etc/cloud/cloud.cfg 2021-12-15 17:44:07,712 - util.py[DEBUG]: Attempting to load yaml from string of length 2410 with allowed root types (,) 2021-12-15 17:44:07,808 - util.py[DEBUG]: Reading from /etc/cloud/cloud.cfg.d/05_logging.cfg (quiet=False) 2021-12-15 17:44:07,809 - util.py[DEBUG]: Read 2070 bytes from /etc/cloud/cloud.cfg.d/05_logging.cfg 2021-12-15 17:44:07,810 - util.py[DEBUG]: Attempting to load yaml from string of length 2070 with allowed root types (,) 2021-12-15 17:44:07,856 - util.py[DEBUG]: Reading from /run/cloud-init/cloud.cfg (quiet=False) 2021-12-15 17:44:07,857 - util.py[DEBUG]: Attempting to load yaml from string of length 0 with allowed root types (,) 2021-12-15 17:44:07,858 - util.py[DEBUG]: loaded blob returned None, returning default. 2021-12-15 17:44:07,860 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2021-12-15 17:44:07,862 - util.py[DEBUG]: Read 925 bytes from /var/lib/cloud/instance/cloud-config.txt 2021-12-15 17:44:07,862 - util.py[DEBUG]: Attempting to load yaml from string of length 925 with allowed root types (,) 2021-12-15 17:44:07,891 - util.py[DEBUG]: Reading from /var/lib/cloud/instance/cloud-config.txt (quiet=False) 2021-12-15 17:44:07,894 - util.py[DEBUG]: Read 925 bytes from /var/lib/cloud/instance/cloud-config.txt 2021-12-15 17:44:07,894 - util.py[DEBUG]: Attempting to load yaml from string of length 925 with allowed root types (,) 2021-12-15 17:44:07,940 - handlers.py[DEBUG]: start: init-network/activate-datasource: activating datasource 2021-12-15 17:44:07,947 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/obj.pkl - wb: [400] 7819 bytes 2021-12-15 17:44:07,952 - handlers.py[DEBUG]: finish: init-network/activate-datasource: SUCCESS: activating datasource 2021-12-15 17:44:07,955 - main.py[DEBUG]: no di_report found in config. 2021-12-15 17:44:08,065 - stages.py[DEBUG]: Using distro class 2021-12-15 17:44:08,070 - stages.py[DEBUG]: Running module migrator () with frequency always 2021-12-15 17:44:08,072 - handlers.py[DEBUG]: start: init-network/config-migrator: running config-migrator with frequency always 2021-12-15 17:44:08,073 - helpers.py[DEBUG]: Running config-migrator using lock () 2021-12-15 17:44:08,075 - cc_migrator.py[DEBUG]: Migrated 0 semaphore files to there canonicalized names 2021-12-15 17:44:08,077 - handlers.py[DEBUG]: finish: init-network/config-migrator: SUCCESS: config-migrator ran successfully 2021-12-15 17:44:08,078 - stages.py[DEBUG]: Running module seed_random () with frequency once-per-instance 2021-12-15 17:44:08,080 - handlers.py[DEBUG]: start: init-network/config-seed_random: running config-seed_random with frequency once-per-instance 2021-12-15 17:44:08,081 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_seed_random - wb: [644] 23 bytes 2021-12-15 17:44:08,087 - helpers.py[DEBUG]: Running config-seed_random using lock () 2021-12-15 17:44:08,088 - cc_seed_random.py[DEBUG]: no command provided 2021-12-15 17:44:08,088 - handlers.py[DEBUG]: finish: init-network/config-seed_random: SUCCESS: config-seed_random ran successfully 2021-12-15 17:44:08,089 - stages.py[DEBUG]: Running module bootcmd () with frequency always 2021-12-15 17:44:08,091 - handlers.py[DEBUG]: start: init-network/config-bootcmd: running config-bootcmd with frequency always 2021-12-15 17:44:08,092 - helpers.py[DEBUG]: Running config-bootcmd using lock () 2021-12-15 17:44:08,092 - cc_bootcmd.py[DEBUG]: Skipping module named bootcmd, no 'bootcmd' key in configuration 2021-12-15 17:44:08,093 - handlers.py[DEBUG]: finish: init-network/config-bootcmd: SUCCESS: config-bootcmd ran successfully 2021-12-15 17:44:08,094 - stages.py[DEBUG]: Running module write-files () with frequency once-per-instance 2021-12-15 17:44:08,096 - handlers.py[DEBUG]: start: init-network/config-write-files: running config-write-files with frequency once-per-instance 2021-12-15 17:44:08,097 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_write_files - wb: [644] 23 bytes 2021-12-15 17:44:08,102 - helpers.py[DEBUG]: Running config-write-files using lock () 2021-12-15 17:44:08,592 - cc_write_files.py[DEBUG]: Skipping module named write-files, no/empty 'write_files' key in configuration 2021-12-15 17:44:08,594 - handlers.py[DEBUG]: finish: init-network/config-write-files: SUCCESS: config-write-files ran successfully 2021-12-15 17:44:08,595 - stages.py[DEBUG]: Running module growpart () with frequency always 2021-12-15 17:44:08,597 - handlers.py[DEBUG]: start: init-network/config-growpart: running config-growpart with frequency always 2021-12-15 17:44:08,598 - helpers.py[DEBUG]: Running config-growpart using lock () 2021-12-15 17:44:08,599 - subp.py[DEBUG]: Running command ['growpart', '--help'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:08,622 - subp.py[DEBUG]: Running command ['gpart', 'help'] with allowed return codes [0, 1] (shell=False, capture=True) 2021-12-15 17:44:08,724 - subp.py[DEBUG]: Running command ['gpart', 'recover', '/dev/vtbd0'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:08,781 - subp.py[DEBUG]: Running command ['gpart', 'resize', '-i', '4', '/dev/vtbd0'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:08,829 - subp.py[DEBUG]: Running command ['mount'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:08,862 - util.py[DEBUG]: found line in mount -> devpth: zroot/ROOT/default, mount_point: /, fs_type: zfs 2021-12-15 17:44:08,864 - util.py[DEBUG]: resize_devices took 0.143 seconds 2021-12-15 17:44:08,865 - cc_growpart.py[DEBUG]: '/dev/vtbd0p4' NOCHANGE: no change necessary (/dev/vtbd0, 4) 2021-12-15 17:44:08,866 - cc_growpart.py[DEBUG]: '/' SKIPPED: stat of 'zroot/ROOT/default' failed: [Errno 2] No such file or directory: 'zroot/ROOT/default' 2021-12-15 17:44:08,867 - handlers.py[DEBUG]: finish: init-network/config-growpart: SUCCESS: config-growpart ran successfully 2021-12-15 17:44:08,868 - stages.py[DEBUG]: Running module resizefs () with frequency always 2021-12-15 17:44:08,870 - handlers.py[DEBUG]: start: init-network/config-resizefs: running config-resizefs with frequency always 2021-12-15 17:44:08,871 - helpers.py[DEBUG]: Running config-resizefs using lock () 2021-12-15 17:44:08,878 - subp.py[DEBUG]: Running command ['mount'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:08,907 - util.py[DEBUG]: found line in mount -> devpth: zroot/ROOT/default, mount_point: /, fs_type: zfs 2021-12-15 17:44:08,909 - subp.py[DEBUG]: Running command ['zpool', 'status', 'zroot'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:09,014 - util.py[DEBUG]: found zpool "zroot" on disk vtbd0p4 2021-12-15 17:44:09,016 - cc_resizefs.py[DEBUG]: resize_info: dev=vtbd0p4 mnt_point=/ path=zroot 2021-12-15 17:44:09,017 - cc_resizefs.py[DEBUG]: 'vtbd0p4' doesn't appear to be a valid device path. Trying '/dev/vtbd0p4' 2021-12-15 17:44:09,018 - cc_resizefs.py[DEBUG]: Resizing zroot (zfs) using zpool online -e zroot /dev/vtbd0p4 2021-12-15 17:44:09,019 - subp.py[DEBUG]: Running command ('zpool', 'online', '-e', 'zroot', '/dev/vtbd0p4') with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:09,196 - util.py[DEBUG]: Resizing took 0.176 seconds 2021-12-15 17:44:09,197 - cc_resizefs.py[DEBUG]: Resized root filesystem (type=zfs, val=True) 2021-12-15 17:44:09,199 - handlers.py[DEBUG]: finish: init-network/config-resizefs: SUCCESS: config-resizefs ran successfully 2021-12-15 17:44:09,200 - stages.py[DEBUG]: Running module set_hostname () with frequency once-per-instance 2021-12-15 17:44:09,203 - handlers.py[DEBUG]: start: init-network/config-set_hostname: running config-set_hostname with frequency once-per-instance 2021-12-15 17:44:09,204 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_set_hostname - wb: [644] 23 bytes 2021-12-15 17:44:09,211 - helpers.py[DEBUG]: Running config-set_hostname using lock () 2021-12-15 17:44:09,212 - util.py[DEBUG]: Reading from /var/lib/cloud/data/set-hostname (quiet=False) 2021-12-15 17:44:09,213 - util.py[DEBUG]: Read 45 bytes from /var/lib/cloud/data/set-hostname 2021-12-15 17:44:09,213 - cc_set_hostname.py[DEBUG]: No hostname changes. Skipping set-hostname 2021-12-15 17:44:09,215 - handlers.py[DEBUG]: finish: init-network/config-set_hostname: SUCCESS: config-set_hostname ran successfully 2021-12-15 17:44:09,215 - stages.py[DEBUG]: Running module update_hostname () with frequency always 2021-12-15 17:44:09,218 - handlers.py[DEBUG]: start: init-network/config-update_hostname: running config-update_hostname with frequency always 2021-12-15 17:44:09,219 - helpers.py[DEBUG]: Running config-update_hostname using lock () 2021-12-15 17:44:09,220 - cc_update_hostname.py[DEBUG]: Updating hostname to testvm (testvm) 2021-12-15 17:44:09,221 - util.py[DEBUG]: Reading from /etc/rc.conf (quiet=False) 2021-12-15 17:44:09,222 - util.py[DEBUG]: Read 201 bytes from /etc/rc.conf 2021-12-15 17:44:09,223 - __init__.py[DEBUG]: Attempting to update hostname to testvm in 1 files 2021-12-15 17:44:09,223 - util.py[DEBUG]: Reading from /etc/rc.conf (quiet=False) 2021-12-15 17:44:09,224 - util.py[DEBUG]: Read 201 bytes from /etc/rc.conf 2021-12-15 17:44:09,225 - handlers.py[DEBUG]: finish: init-network/config-update_hostname: SUCCESS: config-update_hostname ran successfully 2021-12-15 17:44:09,225 - stages.py[DEBUG]: Running module update_etc_hosts () with frequency always 2021-12-15 17:44:09,228 - handlers.py[DEBUG]: start: init-network/config-update_etc_hosts: running config-update_etc_hosts with frequency always 2021-12-15 17:44:09,228 - helpers.py[DEBUG]: Running config-update_etc_hosts using lock () 2021-12-15 17:44:09,229 - cc_update_etc_hosts.py[DEBUG]: Configuration option 'manage_etc_hosts' is not set, not managing /etc/hosts in module update_etc_hosts 2021-12-15 17:44:09,229 - handlers.py[DEBUG]: finish: init-network/config-update_etc_hosts: SUCCESS: config-update_etc_hosts ran successfully 2021-12-15 17:44:09,230 - stages.py[DEBUG]: Running module users-groups () with frequency once-per-instance 2021-12-15 17:44:09,232 - handlers.py[DEBUG]: start: init-network/config-users-groups: running config-users-groups with frequency once-per-instance 2021-12-15 17:44:09,234 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_users_groups - wb: [644] 24 bytes 2021-12-15 17:44:09,241 - helpers.py[DEBUG]: Running config-users-groups using lock () 2021-12-15 17:44:09,246 - freebsd.py[INFO]: Adding user kc2user 2021-12-15 17:44:09,246 - subp.py[DEBUG]: Running hidden command to protect sensitive input/output logstring: ['pw', 'useradd', '-n', 'kc2user', '-d/usr/home/kc2user', '-m'] 2021-12-15 17:44:09,321 - util.py[WARNING]: Failed to create user kc2user 2021-12-15 17:44:09,324 - util.py[DEBUG]: Failed to create user kc2user Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/distros/freebsd.py", line 87, in add_user subp.subp(pw_useradd_cmd, logstring=log_pw_useradd_cmd) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/subp.py", line 293, in subp raise ProcessExecutionError(stdout=out, stderr=err, cloudinit.subp.ProcessExecutionError: Unexpected error while running command. Command: ['pw', 'useradd', '-n', 'kc2user', '-G', 'sudo,wheel', '-d/usr/home/kc2user', '-m'] Exit code: 67 Reason: - Stdout: Stderr: pw: group `sudo' does not exist 2021-12-15 17:44:09,337 - handlers.py[DEBUG]: finish: init-network/config-users-groups: FAIL: running config-users-groups with frequency once-per-instance 2021-12-15 17:44:09,337 - util.py[WARNING]: Running module users-groups () failed 2021-12-15 17:44:09,340 - util.py[DEBUG]: Running module users-groups () failed Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/stages.py", line 976, in _run_modules ran, _r = cc.run(run_name, mod.handle, func_args, File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/cloud.py", line 54, in run return self._runners.run(name, functor, args, freq, clear_on_fail) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/helpers.py", line 186, in run results = functor(*args) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/config/cc_users_groups.py", line 172, in handle cloud.distro.create_user(user, **config) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/distros/__init__.py", line 589, in create_user self.add_user(name, **kwargs) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/distros/freebsd.py", line 87, in add_user subp.subp(pw_useradd_cmd, logstring=log_pw_useradd_cmd) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/subp.py", line 293, in subp raise ProcessExecutionError(stdout=out, stderr=err, cloudinit.subp.ProcessExecutionError: Unexpected error while running command. Command: ['pw', 'useradd', '-n', 'kc2user', '-G', 'sudo,wheel', '-d/usr/home/kc2user', '-m'] Exit code: 67 Reason: - Stdout: Stderr: pw: group `sudo' does not exist 2021-12-15 17:44:09,363 - stages.py[DEBUG]: Running module ssh () with frequency once-per-instance 2021-12-15 17:44:09,366 - handlers.py[DEBUG]: start: init-network/config-ssh: running config-ssh with frequency once-per-instance 2021-12-15 17:44:09,369 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_ssh - wb: [644] 24 bytes 2021-12-15 17:44:09,374 - helpers.py[DEBUG]: Running config-ssh using lock () 2021-12-15 17:44:09,381 - subp.py[DEBUG]: Running command ['ssh-keygen', '-t', 'rsa', '-N', '', '-f', '/etc/ssh/ssh_host_rsa_key'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:10,185 - util.py[DEBUG]: Group ssh_keys is not a valid group name 2021-12-15 17:44:10,190 - subp.py[DEBUG]: Running command ['ssh-keygen', '-t', 'dsa', '-N', '', '-f', '/etc/ssh/ssh_host_dsa_key'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:10,503 - util.py[DEBUG]: Group ssh_keys is not a valid group name 2021-12-15 17:44:10,509 - subp.py[DEBUG]: Running command ['ssh-keygen', '-t', 'ecdsa', '-N', '', '-f', '/etc/ssh/ssh_host_ecdsa_key'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:10,597 - util.py[DEBUG]: Group ssh_keys is not a valid group name 2021-12-15 17:44:10,602 - subp.py[DEBUG]: Running command ['ssh-keygen', '-t', 'ed25519', '-N', '', '-f', '/etc/ssh/ssh_host_ed25519_key'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:10,672 - util.py[DEBUG]: Group ssh_keys is not a valid group name 2021-12-15 17:44:10,677 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_ed25519_key.pub (quiet=False) 2021-12-15 17:44:10,678 - util.py[DEBUG]: Read 93 bytes from /etc/ssh/ssh_host_ed25519_key.pub 2021-12-15 17:44:10,679 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_rsa_key.pub (quiet=False) 2021-12-15 17:44:10,680 - util.py[DEBUG]: Read 393 bytes from /etc/ssh/ssh_host_rsa_key.pub 2021-12-15 17:44:10,680 - util.py[DEBUG]: Reading from /etc/ssh/ssh_host_ecdsa_key.pub (quiet=False) 2021-12-15 17:44:10,681 - util.py[DEBUG]: Read 173 bytes from /etc/ssh/ssh_host_ecdsa_key.pub 2021-12-15 17:44:10,686 - util.py[WARNING]: Applying SSH credentials failed! 2021-12-15 17:44:10,688 - util.py[DEBUG]: Applying SSH credentials failed! Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/config/cc_ssh.py", line 301, in handle apply_credentials(keys, user, disable_root, disable_root_opts) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/config/cc_ssh.py", line 310, in apply_credentials ssh_util.setup_user_keys(keys, user) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 437, in setup_user_keys (auth_key_fn, auth_key_entries) = extract_authorized_keys(username) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 385, in extract_authorized_keys (ssh_dir, pw_ent) = users_ssh_info(username) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 226, in users_ssh_info pw_ent = pwd.getpwnam(username) KeyError: "getpwnam(): name not found: 'freebsd'" 2021-12-15 17:44:10,701 - handlers.py[DEBUG]: finish: init-network/config-ssh: SUCCESS: config-ssh ran successfully 2021-12-15 17:44:10,701 - main.py[DEBUG]: Ran 11 modules with 1 failures 2021-12-15 17:44:10,706 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmp3rq68yu4) - w: [644] 825 bytes/chars 2021-12-15 17:44:10,709 - util.py[DEBUG]: cloud-init mode 'init' took 4.237 seconds (4.24) 2021-12-15 17:44:10,710 - handlers.py[DEBUG]: finish: init-network: FAIL: searching for network datasources 2021-12-15 17:44:15,402 - util.py[DEBUG]: Cloud-init v. 21.4 running 'modules:config' at Wed, 15 Dec 2021 17:44:14 +0000. Up 37.7137713432312 seconds. 2021-12-15 17:44:15,475 - stages.py[DEBUG]: Using distro class 2021-12-15 17:44:15,479 - stages.py[INFO]: Skipping modules 'ssh-import-id' because they are not verified on distro 'freebsd'. To run anyway, add them to 'unverified_modules' in config. 2021-12-15 17:44:15,481 - stages.py[DEBUG]: Running module locale () with frequency once-per-instance 2021-12-15 17:44:15,483 - handlers.py[DEBUG]: start: modules-config/config-locale: running config-locale with frequency once-per-instance 2021-12-15 17:44:15,485 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_locale - wb: [644] 24 bytes 2021-12-15 17:44:15,489 - helpers.py[DEBUG]: Running config-locale using lock () 2021-12-15 17:44:15,741 - cc_locale.py[DEBUG]: Setting locale to en_US.UTF-8 2021-12-15 17:44:15,742 - util.py[DEBUG]: Reading from /etc/login.conf (quiet=False) 2021-12-15 17:44:15,746 - util.py[DEBUG]: Read 7106 bytes from /etc/login.conf 2021-12-15 17:44:15,755 - util.py[DEBUG]: Copying /etc/login.conf to /etc/login.conf.orig 2021-12-15 17:44:15,759 - util.py[DEBUG]: Writing to /etc/login.conf - wb: [644] 7123 bytes 2021-12-15 17:44:15,763 - freebsd.py[DEBUG]: Running cap_mkdb for en_US.UTF-8 2021-12-15 17:44:15,764 - subp.py[DEBUG]: Running command ['cap_mkdb', '/etc/login.conf'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:15,813 - handlers.py[DEBUG]: finish: modules-config/config-locale: SUCCESS: config-locale ran successfully 2021-12-15 17:44:15,814 - stages.py[DEBUG]: Running module set-passwords () with frequency once-per-instance 2021-12-15 17:44:15,816 - handlers.py[DEBUG]: start: modules-config/config-set-passwords: running config-set-passwords with frequency once-per-instance 2021-12-15 17:44:15,819 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_set_passwords - wb: [644] 24 bytes 2021-12-15 17:44:15,824 - helpers.py[DEBUG]: Running config-set-passwords using lock () 2021-12-15 17:44:15,824 - cc_set_passwords.py[DEBUG]: Leaving SSH config 'PasswordAuthentication' unchanged. ssh_pwauth=None 2021-12-15 17:44:15,825 - handlers.py[DEBUG]: finish: modules-config/config-set-passwords: SUCCESS: config-set-passwords ran successfully 2021-12-15 17:44:15,826 - stages.py[DEBUG]: Running module timezone () with frequency once-per-instance 2021-12-15 17:44:15,828 - handlers.py[DEBUG]: start: modules-config/config-timezone: running config-timezone with frequency once-per-instance 2021-12-15 17:44:15,829 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_timezone - wb: [644] 24 bytes 2021-12-15 17:44:15,832 - helpers.py[DEBUG]: Running config-timezone using lock () 2021-12-15 17:44:15,833 - cc_timezone.py[DEBUG]: Skipping module named timezone, no 'timezone' specified 2021-12-15 17:44:15,834 - handlers.py[DEBUG]: finish: modules-config/config-timezone: SUCCESS: config-timezone ran successfully 2021-12-15 17:44:15,834 - stages.py[DEBUG]: Running module disable-ec2-metadata () with frequency always 2021-12-15 17:44:15,836 - handlers.py[DEBUG]: start: modules-config/config-disable-ec2-metadata: running config-disable-ec2-metadata with frequency always 2021-12-15 17:44:15,837 - helpers.py[DEBUG]: Running config-disable-ec2-metadata using lock () 2021-12-15 17:44:15,838 - cc_disable_ec2_metadata.py[DEBUG]: Skipping module named disable-ec2-metadata, disabling the ec2 route not enabled 2021-12-15 17:44:15,838 - handlers.py[DEBUG]: finish: modules-config/config-disable-ec2-metadata: SUCCESS: config-disable-ec2-metadata ran successfully 2021-12-15 17:44:15,839 - stages.py[DEBUG]: Running module runcmd () with frequency once-per-instance 2021-12-15 17:44:15,841 - handlers.py[DEBUG]: start: modules-config/config-runcmd: running config-runcmd with frequency once-per-instance 2021-12-15 17:44:15,842 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_runcmd - wb: [644] 24 bytes 2021-12-15 17:44:15,846 - helpers.py[DEBUG]: Running config-runcmd using lock () 2021-12-15 17:44:15,848 - cc_runcmd.py[DEBUG]: Skipping module named runcmd, no 'runcmd' key in configuration 2021-12-15 17:44:15,848 - handlers.py[DEBUG]: finish: modules-config/config-runcmd: SUCCESS: config-runcmd ran successfully 2021-12-15 17:44:15,849 - main.py[DEBUG]: Ran 5 modules with 0 failures 2021-12-15 17:44:15,852 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpcgsh0vyv) - w: [644] 853 bytes/chars 2021-12-15 17:44:15,855 - util.py[DEBUG]: cloud-init mode 'modules' took 1.077 seconds (1.08) 2021-12-15 17:44:15,856 - handlers.py[DEBUG]: finish: modules-config: SUCCESS: running modules for config 2021-12-15 17:44:23,280 - util.py[DEBUG]: Cloud-init v. 21.4 running 'modules:final' at Wed, 15 Dec 2021 17:44:22 +0000. Up 45.56748056411743 seconds. 2021-12-15 17:44:23,508 - stages.py[DEBUG]: Using distro class 2021-12-15 17:44:23,514 - stages.py[DEBUG]: Running module package-update-upgrade-install () with frequency once-per-instance 2021-12-15 17:44:23,518 - handlers.py[DEBUG]: start: modules-final/config-package-update-upgrade-install: running config-package-update-upgrade-install with frequency once-per-instance 2021-12-15 17:44:23,521 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_package_update_upgrade_install - wb: [644] 25 bytes 2021-12-15 17:44:23,526 - helpers.py[DEBUG]: Running config-package-update-upgrade-install using lock () 2021-12-15 17:44:23,528 - handlers.py[DEBUG]: finish: modules-final/config-package-update-upgrade-install: SUCCESS: config-package-update-upgrade-install ran successfully 2021-12-15 17:44:23,528 - stages.py[DEBUG]: Running module write-files-deferred () with frequency once-per-instance 2021-12-15 17:44:23,531 - handlers.py[DEBUG]: start: modules-final/config-write-files-deferred: running config-write-files-deferred with frequency once-per-instance 2021-12-15 17:44:23,532 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_write_files_deferred - wb: [644] 25 bytes 2021-12-15 17:44:23,537 - helpers.py[DEBUG]: Running config-write-files-deferred using lock () 2021-12-15 17:44:23,817 - cc_write_files_deferred.py[DEBUG]: Skipping module named write-files-deferred, no deferred file defined in configuration 2021-12-15 17:44:23,819 - handlers.py[DEBUG]: finish: modules-final/config-write-files-deferred: SUCCESS: config-write-files-deferred ran successfully 2021-12-15 17:44:23,820 - stages.py[DEBUG]: Running module puppet () with frequency once-per-instance 2021-12-15 17:44:23,822 - handlers.py[DEBUG]: start: modules-final/config-puppet: running config-puppet with frequency once-per-instance 2021-12-15 17:44:23,824 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_puppet - wb: [644] 25 bytes 2021-12-15 17:44:23,829 - helpers.py[DEBUG]: Running config-puppet using lock () 2021-12-15 17:44:23,830 - cc_puppet.py[DEBUG]: Skipping module named puppet, no 'puppet' configuration found 2021-12-15 17:44:23,830 - handlers.py[DEBUG]: finish: modules-final/config-puppet: SUCCESS: config-puppet ran successfully 2021-12-15 17:44:23,831 - stages.py[DEBUG]: Running module chef () with frequency always 2021-12-15 17:44:23,833 - handlers.py[DEBUG]: start: modules-final/config-chef: running config-chef with frequency always 2021-12-15 17:44:23,834 - helpers.py[DEBUG]: Running config-chef using lock () 2021-12-15 17:44:23,834 - cc_chef.py[DEBUG]: Skipping module named chef, no 'chef' key in configuration 2021-12-15 17:44:23,835 - handlers.py[DEBUG]: finish: modules-final/config-chef: SUCCESS: config-chef ran successfully 2021-12-15 17:44:23,836 - stages.py[DEBUG]: Running module mcollective () with frequency once-per-instance 2021-12-15 17:44:23,838 - handlers.py[DEBUG]: start: modules-final/config-mcollective: running config-mcollective with frequency once-per-instance 2021-12-15 17:44:23,839 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_mcollective - wb: [644] 25 bytes 2021-12-15 17:44:23,844 - helpers.py[DEBUG]: Running config-mcollective using lock () 2021-12-15 17:44:23,845 - cc_mcollective.py[DEBUG]: Skipping module named mcollective, no 'mcollective' key in configuration 2021-12-15 17:44:23,846 - handlers.py[DEBUG]: finish: modules-final/config-mcollective: SUCCESS: config-mcollective ran successfully 2021-12-15 17:44:23,847 - stages.py[DEBUG]: Running module salt-minion () with frequency once-per-instance 2021-12-15 17:44:23,849 - handlers.py[DEBUG]: start: modules-final/config-salt-minion: running config-salt-minion with frequency once-per-instance 2021-12-15 17:44:23,850 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_salt_minion - wb: [644] 24 bytes 2021-12-15 17:44:23,854 - helpers.py[DEBUG]: Running config-salt-minion using lock () 2021-12-15 17:44:23,855 - cc_salt_minion.py[DEBUG]: Skipping module named salt-minion, no 'salt_minion' key in configuration 2021-12-15 17:44:23,856 - handlers.py[DEBUG]: finish: modules-final/config-salt-minion: SUCCESS: config-salt-minion ran successfully 2021-12-15 17:44:23,856 - stages.py[DEBUG]: Running module reset_rmc () with frequency once-per-instance 2021-12-15 17:44:23,859 - handlers.py[DEBUG]: start: modules-final/config-reset_rmc: running config-reset_rmc with frequency once-per-instance 2021-12-15 17:44:23,860 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_reset_rmc - wb: [644] 25 bytes 2021-12-15 17:44:23,864 - helpers.py[DEBUG]: Running config-reset_rmc using lock () 2021-12-15 17:44:23,865 - cc_reset_rmc.py[DEBUG]: module disabled, RSCT_PATH not present 2021-12-15 17:44:23,866 - handlers.py[DEBUG]: finish: modules-final/config-reset_rmc: SUCCESS: config-reset_rmc ran successfully 2021-12-15 17:44:23,872 - stages.py[DEBUG]: Running module refresh_rmc_and_interface () with frequency always 2021-12-15 17:44:23,874 - handlers.py[DEBUG]: start: modules-final/config-refresh_rmc_and_interface: running config-refresh_rmc_and_interface with frequency always 2021-12-15 17:44:23,875 - helpers.py[DEBUG]: Running config-refresh_rmc_and_interface using lock () 2021-12-15 17:44:23,877 - cc_refresh_rmc_and_interface.py[DEBUG]: No 'rmcctrl' in path, disabled 2021-12-15 17:44:23,879 - handlers.py[DEBUG]: finish: modules-final/config-refresh_rmc_and_interface: SUCCESS: config-refresh_rmc_and_interface ran successfully 2021-12-15 17:44:23,879 - stages.py[DEBUG]: Running module rightscale_userdata () with frequency once-per-instance 2021-12-15 17:44:23,881 - handlers.py[DEBUG]: start: modules-final/config-rightscale_userdata: running config-rightscale_userdata with frequency once-per-instance 2021-12-15 17:44:23,883 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_rightscale_userdata - wb: [644] 25 bytes 2021-12-15 17:44:23,887 - helpers.py[DEBUG]: Running config-rightscale_userdata using lock () 2021-12-15 17:44:23,888 - cc_rightscale_userdata.py[DEBUG]: Failed to get raw userdata in module rightscale_userdata 2021-12-15 17:44:23,889 - handlers.py[DEBUG]: finish: modules-final/config-rightscale_userdata: SUCCESS: config-rightscale_userdata ran successfully 2021-12-15 17:44:23,890 - stages.py[DEBUG]: Running module scripts-vendor () with frequency once-per-instance 2021-12-15 17:44:23,892 - handlers.py[DEBUG]: start: modules-final/config-scripts-vendor: running config-scripts-vendor with frequency once-per-instance 2021-12-15 17:44:23,893 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_scripts_vendor - wb: [644] 24 bytes 2021-12-15 17:44:23,897 - helpers.py[DEBUG]: Running config-scripts-vendor using lock () 2021-12-15 17:44:23,899 - handlers.py[DEBUG]: finish: modules-final/config-scripts-vendor: SUCCESS: config-scripts-vendor ran successfully 2021-12-15 17:44:23,900 - stages.py[DEBUG]: Running module scripts-per-once () with frequency once 2021-12-15 17:44:23,902 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-once: running config-scripts-per-once with frequency once 2021-12-15 17:44:23,903 - util.py[DEBUG]: Writing to /var/lib/cloud/sem/config_scripts_per_once.once - wb: [644] 23 bytes 2021-12-15 17:44:23,908 - helpers.py[DEBUG]: Running config-scripts-per-once using lock () 2021-12-15 17:44:23,909 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-once: SUCCESS: config-scripts-per-once ran successfully 2021-12-15 17:44:23,910 - stages.py[DEBUG]: Running module scripts-per-boot () with frequency always 2021-12-15 17:44:23,912 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-boot: running config-scripts-per-boot with frequency always 2021-12-15 17:44:23,912 - helpers.py[DEBUG]: Running config-scripts-per-boot using lock () 2021-12-15 17:44:23,914 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-boot: SUCCESS: config-scripts-per-boot ran successfully 2021-12-15 17:44:23,915 - stages.py[DEBUG]: Running module scripts-per-instance () with frequency once-per-instance 2021-12-15 17:44:23,917 - handlers.py[DEBUG]: start: modules-final/config-scripts-per-instance: running config-scripts-per-instance with frequency once-per-instance 2021-12-15 17:44:23,919 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_scripts_per_instance - wb: [644] 23 bytes 2021-12-15 17:44:23,924 - helpers.py[DEBUG]: Running config-scripts-per-instance using lock () 2021-12-15 17:44:23,925 - handlers.py[DEBUG]: finish: modules-final/config-scripts-per-instance: SUCCESS: config-scripts-per-instance ran successfully 2021-12-15 17:44:23,926 - stages.py[DEBUG]: Running module scripts-user () with frequency once-per-instance 2021-12-15 17:44:23,928 - handlers.py[DEBUG]: start: modules-final/config-scripts-user: running config-scripts-user with frequency once-per-instance 2021-12-15 17:44:23,929 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_scripts_user - wb: [644] 25 bytes 2021-12-15 17:44:23,934 - helpers.py[DEBUG]: Running config-scripts-user using lock () 2021-12-15 17:44:23,935 - handlers.py[DEBUG]: finish: modules-final/config-scripts-user: SUCCESS: config-scripts-user ran successfully 2021-12-15 17:44:23,936 - stages.py[DEBUG]: Running module ssh-authkey-fingerprints () with frequency once-per-instance 2021-12-15 17:44:23,938 - handlers.py[DEBUG]: start: modules-final/config-ssh-authkey-fingerprints: running config-ssh-authkey-fingerprints with frequency once-per-instance 2021-12-15 17:44:23,939 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_ssh_authkey_fingerprints - wb: [644] 25 bytes 2021-12-15 17:44:23,943 - helpers.py[DEBUG]: Running config-ssh-authkey-fingerprints using lock () 2021-12-15 17:44:23,950 - handlers.py[DEBUG]: finish: modules-final/config-ssh-authkey-fingerprints: FAIL: running config-ssh-authkey-fingerprints with frequency once-per-instance 2021-12-15 17:44:23,950 - util.py[WARNING]: Running module ssh-authkey-fingerprints () failed 2021-12-15 17:44:23,953 - util.py[DEBUG]: Running module ssh-authkey-fingerprints () failed Traceback (most recent call last): File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/stages.py", line 976, in _run_modules ran, _r = cc.run(run_name, mod.handle, func_args, File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/cloud.py", line 54, in run return self._runners.run(name, functor, args, freq, clear_on_fail) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/helpers.py", line 186, in run results = functor(*args) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/config/cc_ssh_authkey_fingerprints.py", line 107, in handle (key_fn, key_entries) = ssh_util.extract_authorized_keys(user_name) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 385, in extract_authorized_keys (ssh_dir, pw_ent) = users_ssh_info(username) File "/usr/local/lib/python3.8/site-packages/cloud_init-21.4-py3.8.egg/cloudinit/ssh_util.py", line 226, in users_ssh_info pw_ent = pwd.getpwnam(username) KeyError: "getpwnam(): name not found: 'kc2user'" 2021-12-15 17:44:23,969 - stages.py[DEBUG]: Running module keys-to-console () with frequency once-per-instance 2021-12-15 17:44:23,972 - handlers.py[DEBUG]: start: modules-final/config-keys-to-console: running config-keys-to-console with frequency once-per-instance 2021-12-15 17:44:23,973 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_keys_to_console - wb: [644] 25 bytes 2021-12-15 17:44:23,979 - helpers.py[DEBUG]: Running config-keys-to-console using lock () 2021-12-15 17:44:23,982 - subp.py[DEBUG]: Running command ['/usr/local/lib/cloud-init/write-ssh-key-fingerprints', '', 'ssh-dss'] with allowed return codes [0] (shell=False, capture=True) 2021-12-15 17:44:24,571 - handlers.py[DEBUG]: finish: modules-final/config-keys-to-console: SUCCESS: config-keys-to-console ran successfully 2021-12-15 17:44:24,573 - stages.py[DEBUG]: Running module install-hotplug () with frequency once-per-instance 2021-12-15 17:44:24,576 - handlers.py[DEBUG]: start: modules-final/config-install-hotplug: running config-install-hotplug with frequency once-per-instance 2021-12-15 17:44:24,578 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_install_hotplug - wb: [644] 24 bytes 2021-12-15 17:44:24,586 - helpers.py[DEBUG]: Running config-install-hotplug using lock () 2021-12-15 17:44:24,596 - stages.py[DEBUG]: Allowed events: {: {}} 2021-12-15 17:44:24,597 - stages.py[DEBUG]: Event Denied: scopes=['network'] EventType=hotplug 2021-12-15 17:44:24,599 - cc_install_hotplug.py[DEBUG]: Skipping hotplug install, not enabled 2021-12-15 17:44:24,600 - handlers.py[DEBUG]: finish: modules-final/config-install-hotplug: SUCCESS: config-install-hotplug ran successfully 2021-12-15 17:44:24,601 - stages.py[DEBUG]: Running module phone-home () with frequency once-per-instance 2021-12-15 17:44:24,603 - handlers.py[DEBUG]: start: modules-final/config-phone-home: running config-phone-home with frequency once-per-instance 2021-12-15 17:44:24,605 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_phone_home - wb: [644] 25 bytes 2021-12-15 17:44:24,611 - helpers.py[DEBUG]: Running config-phone-home using lock () 2021-12-15 17:44:24,611 - cc_phone_home.py[DEBUG]: Skipping module named phone-home, no 'phone_home' configuration found 2021-12-15 17:44:24,613 - handlers.py[DEBUG]: finish: modules-final/config-phone-home: SUCCESS: config-phone-home ran successfully 2021-12-15 17:44:24,614 - stages.py[DEBUG]: Running module final-message () with frequency always 2021-12-15 17:44:24,616 - handlers.py[DEBUG]: start: modules-final/config-final-message: running config-final-message with frequency always 2021-12-15 17:44:24,617 - helpers.py[DEBUG]: Running config-final-message using lock () 2021-12-15 17:44:24,661 - util.py[DEBUG]: Cloud-init v. 21.4 finished at Wed, 15 Dec 2021 17:44:24 +0000. Datasource DataSourceNoCloud [seed=/dev/iso9660/cidata][dsmode=net]. Up 47.48525404930115 seconds 2021-12-15 17:44:24,662 - util.py[DEBUG]: Writing to /var/lib/cloud/instance/boot-finished - wb: [644] 62 bytes 2021-12-15 17:44:24,668 - handlers.py[DEBUG]: finish: modules-final/config-final-message: SUCCESS: config-final-message ran successfully 2021-12-15 17:44:24,669 - stages.py[DEBUG]: Running module power-state-change () with frequency once-per-instance 2021-12-15 17:44:24,671 - handlers.py[DEBUG]: start: modules-final/config-power-state-change: running config-power-state-change with frequency once-per-instance 2021-12-15 17:44:24,672 - util.py[DEBUG]: Writing to /var/lib/cloud/instances/testvm.default/sem/config_power_state_change - wb: [644] 25 bytes 2021-12-15 17:44:24,677 - helpers.py[DEBUG]: Running config-power-state-change using lock () 2021-12-15 17:44:24,678 - cc_power_state_change.py[DEBUG]: no power_state provided. doing nothing 2021-12-15 17:44:24,678 - handlers.py[DEBUG]: finish: modules-final/config-power-state-change: SUCCESS: config-power-state-change ran successfully 2021-12-15 17:44:24,679 - main.py[DEBUG]: Ran 20 modules with 1 failures 2021-12-15 17:44:24,684 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/status.json (via temporary file /var/lib/cloud/data/tmpaytuiorn) - w: [644] 973 bytes/chars 2021-12-15 17:44:24,689 - atomic_helper.py[DEBUG]: Atomically writing to file /var/lib/cloud/data/result.json (via temporary file /var/lib/cloud/data/tmptp1xywrk) - w: [644] 464 bytes/chars 2021-12-15 17:44:24,692 - util.py[DEBUG]: Creating symbolic link from '/run/cloud-init/result.json' => '../../var/lib/cloud/data/result.json' 2021-12-15 17:44:24,693 - util.py[DEBUG]: cloud-init mode 'modules' took 2.073 seconds (2.07) 2021-12-15 17:44:24,694 - handlers.py[DEBUG]: finish: modules-final: FAIL: running modules for final ```
jbpratt commented 2 years ago

Removing the group section allows kc2user to be created and the ssh key to be set. Currently the VM is not getting an IP address though

jbpratt commented 2 years ago

removing any network config works as expected now, marking this as closed.