Cannot start container made from image created from lxd-p2c

LXD: 4.19 snap
Host: Ubuntu 20.04.3

I migrated a VM template over to lxd using lxd-p2c and then converted it into an image. I then deployed a container from that image. The container will not start. I am getting these messages in syslog:

Oct 11 09:16:16 hcpplcc1 systemd-udevd[3644335]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 11 09:16:16 hcpplcc1 systemd-udevd[3644335]: ethtool: could not get ethtool features for eth0
Oct 11 09:16:16 hcpplcc1 systemd-udevd[3644335]: Could not set offload features of eth0: No such device
Oct 11 09:16:16 hcpplcc1 systemd-udevd[3644335]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 11 09:16:16 hcpplcc1 systemd-udevd[3644335]: ethtool: could not get ethtool features for physD5tHtR
Oct 11 09:16:16 hcpplcc1 systemd-udevd[3644335]: Could not set offload features of physD5tHtR: No such device
Oct 11 09:16:16 hcpplcc1 systemd-udevd[3644335]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Oct 11 09:16:16 hcpplcc1 systemd-udevd[3644335]: Using default interface naming scheme 'v245'.
Oct 11 09:16:16 hcpplcc1 kernel: [341163.438523] device veth8952b06f left promiscuous mode
Oct 11 09:16:16 hcpplcc1 kernel: [341163.438585] br3500: port 2(veth8952b06f) entered disabled state
Oct 11 09:16:16 hcpplcc1 systemd-networkd[998534]: rtnl: received neighbor for link '34' we don't know about, ignoring.
Oct 11 09:16:16 hcpplcc1 systemd-networkd[998534]: rtnl: received neighbor for link '34' we don't know about, ignoring.
Oct 11 09:16:16 hcpplcc1 networkd-dispatcher[2775]: WARNING:Unknown index 34 seen, reloading interface list
Oct 11 09:16:17 hcpplcc1 systemd-networkd[998534]: veth8952b06f: Link DOWN
Oct 11 09:16:17 hcpplcc1 networkd-dispatcher[2775]: ERROR:Unknown interface index 34 seen even after reload
Oct 11 09:16:17 hcpplcc1 networkd-dispatcher[2775]: WARNING:Unknown index 34 seen, reloading interface list
Oct 11 09:16:17 hcpplcc1 networkd-dispatcher[2775]: ERROR:Unknown interface index 34 seen even after reload
Oct 11 09:16:17 hcpplcc1 networkd-dispatcher[2775]: WARNING:Unknown index 34 seen, reloading interface list
Oct 11 09:16:17 hcpplcc1 networkd-dispatcher[2775]: ERROR:Unknown interface index 34 seen even after reload
Oct 11 09:16:17 hcpplcc1 networkd-dispatcher[2775]: WARNING:Unknown index 34 seen, reloading interface list
Oct 11 09:16:17 hcpplcc1 networkd-dispatcher[2775]: ERROR:Unknown interface index 34 seen even after reload

Config of container:

architecture: x86_64
config:
  image.description: HT Build - Ubuntu 18.04 LTS Intel 64-Bit
  image.os: Ubuntu
  image.release: bionic 18.04
  volatile.base_image: 9fca6b90e2fe05eaea5359fa9a05af1900d44bd193b59b0dad1cfc5da3fde2a7
  volatile.eth0.hwaddr: 00:16:3e:29:06:82
  volatile.idmap.base: "0"
  volatile.idmap.current: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0
,"Maprange":1000000000}]'
  volatile.idmap.next: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"M
aprange":1000000000}]'
  volatile.last_state.idmap: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid
":0,"Maprange":1000000000}]'
  volatile.last_state.power: STOPPED
  volatile.uuid: 0b8d0391-a333-4530-bdda-eac2e13c3ccd
devices: {}
ephemeral: false
profiles:
- lxcVLAN3500
stateful: false
description: ""

Config of profile:

config: {}
description: LXD profile VLAN3500
devices:
  eth0:
    name: eth0
    nictype: bridged
    parent: br3500
    type: nic
  root:
    path: /
    pool: local
    type: disk
name: lxcVLAN3500
used_by:
- /1.0/instances/hcvplja8

What do you mean by not starting? Does lxc start get you an error or does the container immediately get stopped?

If the latter, what does lxc info --show-log NAME get you?

Hi stgraber! We can always count on you to help. So awesome! Thank you!

So, I watched closely and it does switch to RUNNING then back to STOPPED.

The log shows:

root@hcpplcc1:~# lxc info --show-log hcvplja8
Name: hcvplja8
Status: STOPPED
Type: container
Architecture: x86_64
Location: hcpplcc1
Created: 2021/10/11 09:01 EDT
Last Used: 2021/10/11 15:04 EDT

Log:

lxc hcvplja8 20211011190448.265 WARN     conf - conf.c:lxc_map_ids:3389 - newuidmap binary is missing
lxc hcvplja8 20211011190448.265 WARN     conf - conf.c:lxc_map_ids:3395 - newgidmap binary is missing
lxc hcvplja8 20211011190448.267 WARN     conf - conf.c:lxc_map_ids:3389 - newuidmap binary is missing
lxc hcvplja8 20211011190448.267 WARN     conf - conf.c:lxc_map_ids:3395 - newgidmap binary is missing
lxc hcvplja8 20211011190448.269 WARN     cgfsng - cgroups/cgfsng.c:fchowmodat:1293 - No such file or directory - Failed to fchownat(43, memory.oom.group, 1000000000, 0, AT_EMPTY_PATH | AT_SYMLINK_NOFOLLOW
 )
lxc hcvplja8 20211011190448.821 WARN     conf - conf.c:lxc_map_ids:3389 - newuidmap binary is missing
lxc hcvplja8 20211011190448.821 WARN     conf - conf.c:lxc_map_ids:3395 - newgidmap binary is missing
lxc 20211011190448.864 ERROR    af_unix - af_unix.c:lxc_abstract_unix_recv_fds_iov:220 - Connection reset by peer - Failed to receive response
lxc 20211011190448.864 ERROR    af_unix - af_unix.c:lxc_abstract_unix_recv_fds_iov:220 - Connection reset by peer - Failed to receive response
lxc 20211011190448.864 ERROR    commands - commands.c:lxc_cmd_rsp_recv_fds:129 - Failed to receive file descriptors
lxc 20211011190448.864 ERROR    commands - commands.c:lxc_cmd_rsp_recv_fds:129 - Failed to receive file descriptors

And before you ask for it:

root@hcpplcc1:~# lxc config show --expanded hcvplja8
architecture: x86_64
config:
  image.description: HT Build - Ubuntu 18.04 LTS Intel 64-Bit
  image.os: Ubuntu
  image.release: bionic 18.04
  volatile.base_image: 9fca6b90e2fe05eaea5359fa9a05af1900d44bd193b59b0dad1cfc5da3fde2a7
  volatile.eth0.hwaddr: 00:16:3e:29:06:82
  volatile.idmap.base: "0"
  volatile.idmap.current: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"Maprange":1000000000}]'
  volatile.idmap.next: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"Maprange":1000000000}]'
  volatile.last_state.idmap: '[{"Isuid":true,"Isgid":false,"Hostid":1000000,"Nsid":0,"Maprange":1000000000},{"Isuid":false,"Isgid":true,"Hostid":1000000,"Nsid":0,"Maprange":1000000000}]'
  volatile.last_state.power: STOPPED
  volatile.uuid: 0b8d0391-a333-4530-bdda-eac2e13c3ccd
devices:
  eth0:
    name: eth0
    nictype: bridged
    parent: br3500
    type: nic
  root:
    path: /
    pool: local
    type: disk
ephemeral: false
profiles:
- lxcVLAN3500
stateful: false
description: ""

And this is all that is new in the lxd.log file when starting:

t=2021-10-11T15:04:48-0400 lvl=info msg="Starting container" action=start created=2021-10-11T09:01:57-0400 ephemeral=false instance=hcvplja8 instanceType=container project=default stateful=false used=2021
-10-11T09:16:16-0400
t=2021-10-11T15:04:48-0400 lvl=info msg="Started container" action=start created=2021-10-11T09:01:57-0400 ephemeral=false instance=hcvplja8 instanceType=container project=default stateful=false used=2021-
10-11T09:16:16-0400

lxc console --show-log NAME may also be useful as this suggests the init system is almost immediately crashing/exiting.

Empty result:

root@hcpplcc1:/var/snap/lxd/common/lxd/logs# lxc console --show-log hcvplja8

Console log:


root@hcpplcc1:/var/snap/lxd/common/lxd/logs#

@stgraber Also seeing this in dmesg:

[363763.891569] device vethac0291ae entered promiscuous mode
[363764.146034] physRWhapc: renamed from veth2f4490c5
[363764.170853] eth0: renamed from physRWhapc
[363764.197807] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[363764.197899] br3500: port 2(vethac0291ae) entered blocking state
[363764.197902] br3500: port 2(vethac0291ae) entered forwarding state
[363764.349900] physRWhapc: renamed from eth0
[363764.393653] br3500: port 2(vethac0291ae) entered disabled state
[363764.399747] veth2f4490c5: renamed from physRWhapc
[363764.516288] device vethac0291ae left promiscuous mode

That’s consistent with a container starting and immediately exiting.

You may want to try lxc config set NAME raw.lxc=lxc.log.level=trace then start again and get lxc info --show-log NAME which should be VERY detailed then.

@stgraber Ok, did that and I meticulously went through the logs that came out. I think this might be the section where it fails, below. It looks like ‘init’ is not returning what is expected.

lxc hcvplja8 20211012111623.540 NOTICE   start - start.c:start:2139 - Exec'ing "/sbin/init"
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:243 - index: 0
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:244 - ifindex: 45
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:300 - type: phys
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:303 - host side ifindex for phys device: 45
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:318 - flags: up
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:322 - link: veth4f67d966
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:326 - l2proxy: false
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:329 - name: eth0
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:343 - ipv4 gateway auto: false
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:346 - ipv4 gateway dev: false
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:362 - ipv6 gateway auto: false
lxc hcvplja8 20211012111623.543 TRACE    confile_utils - confile_utils.c:lxc_log_configured_netdevs:365 - ipv6 gateway dev: false
lxc hcvplja8 20211012111623.543 NOTICE   start - start.c:post_start:2150 - Started "/sbin/init" with pid "253479"
lxc hcvplja8 20211012111623.543 TRACE    start - start.c:lxc_serve_state_socket_pair:546 - Sent container state "RUNNING" to 7
lxc hcvplja8 20211012111623.543 TRACE    start - start.c:lxc_serve_state_clients:482 - Set container state to RUNNING
lxc hcvplja8 20211012111623.543 TRACE    start - start.c:lxc_serve_state_clients:485 - No state clients registered
lxc hcvplja8 20211012111623.543 TRACE    lxccontainer - lxccontainer.c:wait_on_daemonized_start:873 - Container is in "RUNNING" state
lxc hcvplja8 20211012111623.543 TRACE    start - start.c:lxc_poll:636 - Mainloop is ready
lxc hcvplja8 20211012111623.543 NOTICE   start - start.c:signal_handler:448 - Received 17 from pid 253480 instead of container init 253479
lxc hcvplja8 20211012111623.543 TRACE    commands - commands.c:lxc_cmd_accept:2036 - Accepted new client as fd 27 on command server fd 9
lxc hcvplja8 20211012111623.543 TRACE    commands - commands.c:lxc_cmd_handler:2000 - Processed command get_state; cleaning up client fd 27
lxc hcvplja8 20211012111623.543 TRACE    commands - commands.c:lxc_cmd_fd_cleanup:1943 - Closing client fd 27 for command "get_state"
lxc hcvplja8 20211012111623.546 TRACE    commands - commands.c:lxc_cmd_accept:2036 - Accepted new client as fd 27 on command server fd 9
lxc hcvplja8 20211012111623.546 TRACE    commands - commands.c:lxc_cmd_handler:2000 - Processed command get_state; cleaning up client fd 27
lxc hcvplja8 20211012111623.546 TRACE    commands - commands.c:lxc_cmd_fd_cleanup:1943 - Closing client fd 27 for command "get_state"
lxc hcvplja8 20211012111623.550 DEBUG    start - start.c:signal_handler:466 - Container init process 253479 exited
lxc hcvplja8 20211012111623.550 TRACE    start - start.c:lxc_poll:649 - Closed console mainloop
lxc hcvplja8 20211012111623.550 TRACE    start - start.c:lxc_poll:654 - Closed mainloop
lxc hcvplja8 20211012111623.550 TRACE    start - start.c:lxc_poll:657 - Closed signal file descriptor 5
lxc hcvplja8 20211012111623.550 TRACE    network - network.c:lxc_restore_phys_nics_to_netns:3751 - Moving physical network devices back to parent network namespace
lxc hcvplja8 20211012111623.617 TRACE    network - network.c:lxc_restore_phys_nics_to_netns:3782 - Moved network device "eth0" back to network namespace
lxc hcvplja8 20211012111623.618 INFO     error - error.c:lxc_error_set_and_log:28 - Child <253479> ended on error (127)

Here is a link to the full log in case the previous section is not enough: lxc container failing to start - Pastebin.com

Yeah, you can see:

lxc hcvplja8 20211012111623.543 NOTICE   start - start.c:post_start:2150 - Started "/sbin/init" with pid "253479"

followed by:

lxc hcvplja8 20211012111623.550 DEBUG    start - start.c:signal_handler:466 - Container init process 253479 exited
lxc hcvplja8 20211012111623.618 INFO     error - error.c:lxc_error_set_and_log:28 - Child <253479> ended on error (127)

Errno 127 is “no such file or directory”, so this suggests your container doesn’t have a /sbin/init (or it’s a broken symlink or an architecture which isn’t supported on your system).

Can you show:

  • lxc query /1.0/instances/hcvplja8/files?path=/
  • lxc query /1.0/instances/hcvplja8/files?path=/sbin/

@stgraber Sure, see below. Thanks again for all of this help. This is an odd one…

root@hcpplcc1:~# lxc query /1.0/instances/hcvplja8/files?path=/
[
        "snap",
        "var",
        ".viminfo",
        "proc",
        "products",
        "root",
        "dev",
        "intrust",
        "srv",
        "lib64",
        "opt",
        "lib32",
        "media",
        "sys",
        "boot",
        "libx32",
        "nonexistent",
        "initrd.img",
        "tmp",
        "mnt",
        "sbin",
        "lib",
        "initrd.img.old",
        "run",
        "etc",
        "vmlinuz.old",
        "home",
        "bin",
        "usr",
        "vmlinuz"
]

root@hcpplcc1:~# lxc query /1.0/instances/hcvplja8/files?path=/sbin/
[
        "vgextend",
        "ntfslabel",
        "mkfs.bfs",
        "rpcbind",
        "rtmon",
        "fsck.fat",
        "iscsistart",
        "dhclient-script",
        "chcpu",
        "zhack",
        "lvmetad",
        "unix_update",
        "iscsi_discovery",
        "fstab-decode",
        "vgreduce",
        "devlink",
        "vgconvert",
        "lvcreate",
        "cryptdisks_start",
        "ebtables-save",
        "pam_extrausers_update",
        "dmsetup",
        "init",
        "mii-tool",
        "badblocks",
        "sm-notify",
        "pvck",
        "umount.nfs4",
        "getcap",
        "start-stop-daemon",
        "lvdisplay",
        "vgs",
        "slattach",
        "fsadm",
        "shutdown",
        "rpc.statd",
        "lvremove",
        "lvrename",
        "mount.fuse",
        "pvdisplay",
        "e2label",
        "lvchange",
        "ctrlaltdel",
        "on_ac_power",
        "mkfs.ntfs",
        "mount.lowntfs-3g",
        "fstrim",
        "mkfs.ext2",
        "dumpe2fs",
        "pvmove",
        "vgsplit",
        "cryptdisks_stop",
        "autrace",
        "fsck.xfs",
        "mkfs.vfat",
        "swapoff",
        "rtacct",
        "resolvconf",
        "iscsiadm",
        "pivot_root",
        "zramctl",
        "vgmerge",
        "mkdosfs",
        "route",
        "logsave",
        "cryptsetup-reencrypt",
        "lvmsar",
        "dmstats",
        "modprobe",
        "tipc",
        "ausearch",
        "iptables-restore",
        "iptables-save",
        "getty",
        "halt",
        "mke2fs",
        "blkdeactivate",
        "fsck.zfs",
        "hdparm",
        "setvtrgb",
        "osd_login",
        "losetup",
        "sulogin",
        "pvchange",
        "showmount",
        "sysctl",
        "plymouthd",
        "regdbdump",
        "udevadm",
        "setcap",
        "runuser",
        "key.dns_resolver",
        "pvremove",
        "installkernel",
        "zstreamdump",
        "depmod",
        "blockdev",
        "pam_tally",
        "fsck.nfs",
        "lvmconf",
        "ifenslave-2.6",
        "bridge",
        "unix_chkpwd",
        "veritysetup",
        "nameif",
        "isosize",
        "pvcreate",
        "fsck.vfat",
        "pam_extrausers_chkpwd",
        "mkntfs",
        "mount.ntfs-3g",
        "wipefs",
        "plipconfig",
        "fsck.ext2",
        "tc",
        "xfs_repair",
        "ifconfig",
        "mkswap",
        "mount.zfs",
        "vgchange",
        "swapon",
        "fsck.minix",
        "mkfs.ext3",
        "hwclock",
        "poweroff",
        "iptunnel",
        "zdb",
        "mount.vmhgfs",
        "vgremove",
        "mkfs.msdos",
        "runlevel",
        "telinit",
        "lvscan",
        "switch_root",
        "mdadm",
        "vgrename",
        "ip6tables",
        "augenrules",
        "debugfs",
        "dosfslabel",
        "auditd",
        "aureport",
        "lvmdiskscan",
        "lvm",
        "vgimportclone",
        "ifdown",
        "findfs",
        "lvs",
        "insmod",
        "ebtables",
        "vgdisplay",
        "fsck.cramfs",
        "resize2fs",
        "zpios",
        "killall5",
        "lvresize",
        "ntfsundelete",
        "lvmconfig",
        "iptables",
        "shadowconfig",
        "fatlabel",
        "cryptsetup",
        "kbdrate",
        "sfdisk",
        "e2image",
        "lvreduce",
        "lvconvert",
        "dmeventd",
        "pam_tally2",
        "mount.nfs",
        "lvmpolld",
        "zpool",
        "getpcaps",
        "ntfscp",
        "lvextend",
        "reboot",
        "ldconfig",
        "mount.ntfs",
        "crda",
        "mkfs",
        "lvmsadc",
        "ztest",
        "e2fsck",
        "ipmaddr",
        "mdmon",
        "agetty",
        "ip6tables-restore",
        "rmmod",
        "auditctl",
        "ureadahead",
        "vgcreate",
        "mkfs.ext4",
        "vgck",
        "fdisk",
        "vgscan",
        "vgimport",
        "ip6tables-save",
        "mkfs.xfs",
        "iscsid",
        "fsck.ext3",
        "dosfsck",
        "dhclient",
        "raw",
        "acpi_available",
        "ntfsresize",
        "capsh",
        "pvs",
        "fsck.msdos",
        "ntfsclone",
        "ifquery",
        "mkhomedir_helper",
        "tune2fs",
        "audispd",
        "MAKEDEV",
        "iw",
        "fsck",
        "mkfs.minix",
        "swaplabel",
        "apparmor_parser",
        "request-key",
        "blkid",
        "zfs",
        "iscsi-iname",
        "ip",
        "pvresize",
        "pvscan",
        "e2undo",
        "modinfo",
        "ifenslave",
        "vgmknodes",
        "ldconfig.real",
        "mkfs.cramfs",
        "apm_available",
        "vgexport",
        "vgcfgrestore",
        "cfdisk",
        "umount.nfs",
        "fsfreeze",
        "rarp",
        "zinject",
        "lsmod",
        "xtables-multi",
        "fsck.ext4",
        "ethtool",
        "mount.nfs4",
        "vgcfgbackup",
        "ifup",
        "mkfs.fat",
        "lvmdump",
        "parted",
        "blkdiscard",
        "integritysetup",
        "vconfig",
        "ebtables-restore",
        "partprobe"
]

Can you try lxc query /1.0/instances/hcvplja8/files?path=/sbin/init too?

@stgraber Here it is…

root@hcpplcc1:~# lxc query /1.0/instances/hcvplja8/files?path=/sbin/init
/lib/systemd/systemd

What’s your storage backend?

The storage backend is ZFS.

ok, can you show a zfs list? I think at this point the best way to figure out what’s going on is to mount that container and poke at the filesystem a bit :slight_smile:

Yep, I agree and was about to ask about the best way to do that. Here is the relevant line out of the ‘zfs list’:

local/containers/hcvplja8 5.81M 89.8G 1.52G /var/snap/lxd/common/lxd/storage-pools/local/containers/hcvplja8

Can you run mount -t zfs local/containers/hcvplja8 /mnt/ -o zfsutil and then ls -lh /mnt/rootfs/sbin/

Here it is: listing of files in LXD container - Pastebin.com