Can't enter any toolbox containers

[larsks]

Describe the bug

I'm unable to toolbox enter any toolbox containers. After running toolbox create followed by toolbox enter, the command fails with:

Error: failed to initialize container fedora-toolbox-31

Looking at the logs for the failed toolbox container, I see:

level=debug msg="Running as real user ID 0"
level=debug msg="Resolved absolute path to the executable as /usr/bin/toolbox"
level=debug msg="TOOLBOX_PATH is /usr/bin/toolbox"
level=debug msg="XDG_RUNTIME_DIR is unset"
level=debug msg="XDG_RUNTIME_DIR set to /run/user/1000"
level=debug msg="Creating /run/.toolboxenv"
level=debug msg="Mounting tmpfs at /tmp"
level=debug msg="Monitoring host"
level=debug msg="Path /run/host/etc exists"
level=debug msg="Preparing to redirect /etc/host.conf to /run/host/etc/host.conf"
level=debug msg="/run/host/etc/host.conf isn't a symbolic link"
level=debug msg="Redirecting /etc/host.conf to /run/host/etc/host.conf"
level=debug msg="Preparing to redirect /etc/hosts to /run/host/etc/hosts"
level=debug msg="/run/host/etc/hosts isn't a symbolic link"
level=debug msg="Redirecting /etc/hosts to /run/host/etc/hosts"
level=debug msg="Preparing to redirect /etc/resolv.conf to /run/host/etc/resolv.conf"
level=debug msg="/run/host/etc/resolv.conf isn't a symbolic link"
level=debug msg="Redirecting /etc/resolv.conf to /run/host/etc/resolv.conf"
level=debug msg="Binding /etc/machine-id to /run/host/etc/machine-id"
level=debug msg="Creating /run/libvirt"
level=debug msg="Binding /run/libvirt to /run/host/run/libvirt"
level=debug msg="Creating /run/systemd/journal"
level=debug msg="Binding /run/systemd/journal to /run/host/run/systemd/journal"
level=debug msg="Creating /var/lib/flatpak"
level=debug msg="Binding /var/lib/flatpak to /run/host/var/lib/flatpak"
level=debug msg="Creating /var/log/journal"
level=debug msg="Binding /var/log/journal to /run/host/var/log/journal"
level=debug msg="Path /run/host/monitor exists"
level=debug msg="Preparing to redirect /etc/localtime to /run/host/monitor/localtime"
level=debug msg="/run/host/monitor/localtime isn't a symbolic link"
level=debug msg="Redirecting /etc/localtime to /run/host/monitor/localtime"
level=debug msg="Preparing to redirect /etc/timezone to /run/host/monitor/timezone"
level=debug msg="/run/host/monitor/timezone isn't a symbolic link"
level=debug msg="Redirecting /etc/timezone to /run/host/monitor/timezone"
level=debug msg="Looking up group for sudo"
level=debug msg="Group for sudo is wheel"
level=debug msg="Modifying user lars with UID 1000:"
level=debug msg=usermod
level=debug msg=--append
level=debug msg=--groups
level=debug msg=wheel
level=debug msg=--home
level=debug msg=/home/lars
level=debug msg=--shell
level=debug msg=/bin/bash
level=debug msg=--uid
level=debug msg=1000
level=debug msg=lars
usermod: failure while writing changes to /etc/passwd
Error: failed to modify user lars with UID 1000

Output of toolbox --version (v0.0.90+)

toolbox version 0.0.95

Toolbox package info (rpm -q toolbox)

(installed from source 40e7e60)

Output of podman version

Version:      2.1.0-dev
API Version:  1
Go Version:   go1.13.11
Git Commit:   712d9f7cab967fda23547f49a01b44dfbbd13d57
Built:        Fri Aug  3 20:00:00 2018
OS/Arch:      linux/amd64

Podman package info (rpm -q podman)

podman-2.1.0-1594142770.git54d16f3b.fc31.x86_64

Info about your OS

Fedora 31

[erazemk]

Similar issue, probably related, but I get the error: Error: failed to start container <name>.

Here's the log:

ekokot@t540p: ~ $ toolbox -vv enter games
DEBU Running as real user ID 1000                 
DEBU Resolved absolute path to the executable as /usr/bin/toolbox 
DEBU Running on a cgroups v2 host                 
DEBU Checking if /etc/subgid and /etc/subuid have entries for user ekokot 
DEBU TOOLBOX_PATH is /usr/bin/toolbox             
DEBU Toolbox config directory is /home/ekokot/.config/toolbox 
INFO[0000] podman filtering at log level debug          
DEBU[0000] Called version.PersistentPreRunE(podman --log-level debug version --format json) 
DEBU[0000] Reading configuration file "/usr/share/containers/containers.conf" 
DEBU[0000] Merged system config "/usr/share/containers/containers.conf": &{Containers:{Devices:[] Volumes:[] ApparmorProfile:containers-default-0.22.0 Annotations:[] CgroupNS:private Cgroups:enabled DefaultCapabilities:[AUDIT_WRITE CHOWN DAC_OVERRIDE FOWNER FSETID KILL NET_BIND_SERVICE SETGID SETPCAP SETUID SYS_CHROOT] DefaultSysctls:[net.ipv4.ping_group_range=0 1] DefaultUlimits:[] DefaultMountsFile: DNSServers:[] DNSOptions:[] DNSSearches:[] EnableLabeling:true Env:[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin TERM=xterm] EnvHost:false HTTPProxy:false Init:false InitPath: IPCNS:private LogDriver:k8s-file LogSizeMax:-1 NetNS:slirp4netns NoHosts:false PidsLimit:2048 PidNS:private SeccompProfile:/usr/share/containers/seccomp.json ShmSize:65536k TZ: Umask:0022 UTSNS:private UserNS:host UserNSSize:65536} Engine:{CgroupCheck:false CgroupManager:systemd ConmonEnvVars:[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] ConmonPath:[/usr/libexec/podman/conmon /usr/local/libexec/podman/conmon /usr/local/lib/podman/conmon /usr/bin/conmon /usr/sbin/conmon /usr/local/bin/conmon /usr/local/sbin/conmon /run/current-system/sw/bin/conmon] DetachKeys:ctrl-p,ctrl-q EnablePortReservation:true Env:[] EventsLogFilePath:/tmp/runtime-ekokot/libpod/tmp/events/events.log EventsLogger:journald HooksDir:[/usr/share/containers/oci/hooks.d] ImageDefaultTransport:docker:// InfraCommand:/pause InfraImage:k8s.gcr.io/pause:3.2 InitPath:/usr/libexec/podman/catatonit LockType:shm MultiImageArchive:false Namespace: NetworkCmdPath: NoPivotRoot:false NumLocks:2048 OCIRuntime:crun OCIRuntimes:map[crun:[/usr/bin/crun /usr/sbin/crun /usr/local/bin/crun /usr/local/sbin/crun /sbin/crun /bin/crun /run/current-system/sw/bin/crun] kata:[/usr/bin/kata-runtime /usr/sbin/kata-runtime /usr/local/bin/kata-runtime /usr/local/sbin/kata-runtime /sbin/kata-runtime /bin/kata-runtime /usr/bin/kata-qemu /usr/bin/kata-fc] runc:[/usr/bin/runc /usr/sbin/runc /usr/local/bin/runc /usr/local/sbin/runc /sbin/runc /bin/runc /usr/lib/cri-o-runc/sbin/runc /run/current-system/sw/bin/runc]] PullPolicy:missing Remote:false RemoteURI: RemoteIdentity: ActiveService: ServiceDestinations:map[] RuntimePath:[] RuntimeSupportsJSON:[crun runc] RuntimeSupportsNoCgroups:[crun] RuntimeSupportsKVM:[kata kata-runtime kata-qemu kata-fc] SetOptions:{StorageConfigRunRootSet:false StorageConfigGraphRootSet:false StorageConfigGraphDriverNameSet:false StaticDirSet:false VolumePathSet:false TmpDirSet:false} SignaturePolicyPath:/etc/containers/policy.json SDNotify:false StateType:3 StaticDir:/home/ekokot/.local/share/containers/storage/libpod StopTimeout:10 TmpDir:/tmp/runtime-ekokot/libpod/tmp VolumePath:/home/ekokot/.local/share/containers/storage/volumes} Network:{CNIPluginDirs:[/usr/libexec/cni /usr/lib/cni /usr/local/lib/cni /opt/cni/bin] DefaultNetwork:podman NetworkConfigDir:/home/ekokot/.config/cni/net.d}} 
DEBU[0000] Using conmon: "/usr/bin/conmon"              
DEBU[0000] Initializing boltdb state at /home/ekokot/.local/share/containers/storage/libpod/bolt_state.db 
DEBU[0000] Using graph driver overlay                   
DEBU[0000] Using graph root /home/ekokot/.local/share/containers/storage 
DEBU[0000] Using run root /tmp/runtime-ekokot/containers 
DEBU[0000] Using static dir /home/ekokot/.local/share/containers/storage/libpod 
DEBU[0000] Using tmp dir /tmp/runtime-ekokot/libpod/tmp 
DEBU[0000] Using volume path /home/ekokot/.local/share/containers/storage/volumes 
DEBU[0000] Set libpod namespace to ""                   
DEBU[0000] [graphdriver] trying provided driver "overlay" 
DEBU[0000] overlay: mount_program=/usr/bin/fuse-overlayfs 
DEBU[0000] backingFs=btrfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=false 
DEBU[0000] Initializing event backend journald          
DEBU[0000] using runtime "/usr/bin/runc"                
DEBU[0000] using runtime "/usr/bin/crun"                
WARN[0000] Error initializing configured OCI runtime kata: no valid executable found for OCI runtime kata: invalid argument 
INFO[0000] Setting parallel job count to 13             
DEBU[0000] Called version.PersistentPostRunE(podman --log-level debug version --format json) 
DEBU Current Podman version is 2.1.1              
DEBU Old Podman version is 2.1.1                  
DEBU Migration not needed: Podman version 2.1.1 is unchanged 
DEBU Resolving container and image names          
DEBU Container: 'games'                           
DEBU Image: ''                                    
DEBU Release: ''                                  
DEBU Resolved container and image names           
DEBU Container: 'games'                           
DEBU Image: 'fedora-toolbox:33'                   
DEBU Release: '33'                                
DEBU Checking if container games exists           
INFO[0000] podman filtering at log level debug          
DEBU[0000] Called exists.PersistentPreRunE(podman --log-level debug container exists games) 
DEBU[0000] Reading configuration file "/usr/share/containers/containers.conf" 
DEBU[0000] Merged system config "/usr/share/containers/containers.conf": &{Containers:{Devices:[] Volumes:[] ApparmorProfile:containers-default-0.22.0 Annotations:[] CgroupNS:private Cgroups:enabled DefaultCapabilities:[AUDIT_WRITE CHOWN DAC_OVERRIDE FOWNER FSETID KILL NET_BIND_SERVICE SETGID SETPCAP SETUID SYS_CHROOT] DefaultSysctls:[net.ipv4.ping_group_range=0 1] DefaultUlimits:[] DefaultMountsFile: DNSServers:[] DNSOptions:[] DNSSearches:[] EnableLabeling:true Env:[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin TERM=xterm] EnvHost:false HTTPProxy:false Init:false InitPath: IPCNS:private LogDriver:k8s-file LogSizeMax:-1 NetNS:slirp4netns NoHosts:false PidsLimit:2048 PidNS:private SeccompProfile:/usr/share/containers/seccomp.json ShmSize:65536k TZ: Umask:0022 UTSNS:private UserNS:host UserNSSize:65536} Engine:{CgroupCheck:false CgroupManager:systemd ConmonEnvVars:[PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] ConmonPath:[/usr/libexec/podman/conmon /usr/local/libexec/podman/conmon /usr/local/lib/podman/conmon /usr/bin/conmon /usr/sbin/conmon /usr/local/bin/conmon /usr/local/sbin/conmon /run/current-system/sw/bin/conmon] DetachKeys:ctrl-p,ctrl-q EnablePortReservation:true Env:[] EventsLogFilePath:/tmp/runtime-ekokot/libpod/tmp/events/events.log EventsLogger:journald HooksDir:[/usr/share/containers/oci/hooks.d] ImageDefaultTransport:docker:// InfraCommand:/pause InfraImage:k8s.gcr.io/pause:3.2 InitPath:/usr/libexec/podman/catatonit LockType:shm MultiImageArchive:false Namespace: NetworkCmdPath: NoPivotRoot:false NumLocks:2048 OCIRuntime:crun OCIRuntimes:map[crun:[/usr/bin/crun /usr/sbin/crun /usr/local/bin/crun /usr/local/sbin/crun /sbin/crun /bin/crun /run/current-system/sw/bin/crun] kata:[/usr/bin/kata-runtime /usr/sbin/kata-runtime /usr/local/bin/kata-runtime /usr/local/sbin/kata-runtime /sbin/kata-runtime /bin/kata-runtime /usr/bin/kata-qemu /usr/bin/kata-fc] runc:[/usr/bin/runc /usr/sbin/runc /usr/local/bin/runc /usr/local/sbin/runc /sbin/runc /bin/runc /usr/lib/cri-o-runc/sbin/runc /run/current-system/sw/bin/runc]] PullPolicy:missing Remote:false RemoteURI: RemoteIdentity: ActiveService: ServiceDestinations:map[] RuntimePath:[] RuntimeSupportsJSON:[crun runc] RuntimeSupportsNoCgroups:[crun] RuntimeSupportsKVM:[kata kata-runtime kata-qemu kata-fc] SetOptions:{StorageConfigRunRootSet:false StorageConfigGraphRootSet:false StorageConfigGraphDriverNameSet:false StaticDirSet:false VolumePathSet:false TmpDirSet:false} SignaturePolicyPath:/etc/containers/policy.json SDNotify:false StateType:3 StaticDir:/home/ekokot/.local/share/containers/storage/libpod StopTimeout:10 TmpDir:/tmp/runtime-ekokot/libpod/tmp VolumePath:/home/ekokot/.local/share/containers/storage/volumes} Network:{CNIPluginDirs:[/usr/libexec/cni /usr/lib/cni /usr/local/lib/cni /opt/cni/bin] DefaultNetwork:podman NetworkConfigDir:/home/ekokot/.config/cni/net.d}} 
DEBU[0000] Using conmon: "/usr/bin/conmon"              
DEBU[0000] Initializing boltdb state at /home/ekokot/.local/share/containers/storage/libpod/bolt_state.db 
DEBU[0000] Using graph driver overlay                   
DEBU[0000] Using graph root /home/ekokot/.local/share/containers/storage 
DEBU[0000] Using run root /tmp/runtime-ekokot/containers 
DEBU[0000] Using static dir /home/ekokot/.local/share/containers/storage/libpod 
DEBU[0000] Using tmp dir /tmp/runtime-ekokot/libpod/tmp 
DEBU[0000] Using volume path /home/ekokot/.local/share/containers/storage/volumes 
DEBU[0000] Set libpod namespace to ""                   
DEBU[0000] [graphdriver] trying provided driver "overlay" 
DEBU[0000] overlay: mount_program=/usr/bin/fuse-overlayfs 
DEBU[0000] backingFs=btrfs, projectQuotaSupported=false, useNativeDiff=false, usingMetacopy=false 
DEBU[0000] Initializing event backend journald          
DEBU[0000] using runtime "/usr/bin/runc"                
DEBU[0000] using runtime "/usr/bin/crun"                
WARN[0000] Error initializing configured OCI runtime kata: no valid executable found for OCI runtime kata: invalid argument 
INFO[0000] Setting parallel job count to 13             
DEBU[0000] Called exists.PersistentPostRunE(podman --log-level debug container exists games) 
DEBU Calling org.freedesktop.Flatpak.SessionHelper.RequestSession 
DEBU Starting container games                     
Error: failed to start container games

Additional info:

• OS: Fedora 33 beta
• toolbox version 0.0.95
• podman version 2.1.1

The issue also looks similar to #488

[philn]

and #557

[juhp]

podman logs <container> is my new friend.

[erazemk]

@juhp podman logs <container> sadly gives even less info than toolbox -vv:

ekokot@t540p: ~ $ toolbox create games
Image required to create toolbox container.
Download registry.fedoraproject.org/f32/fedora-toolbox:32 (500MB)? [y/N]: y
Created container: games
Enter with: toolbox enter games
ekokot@t540p: ~ $ toolbox enter games
Error: failed to start container games
ekokot@t540p: ~ [1] $ podman logs games
ekokot@t540p: ~ $

This is on Fedora 32 with toolbox 0.0.95 and podman 2.1.1.

[erazemk]

Same error on toolbox v0.0.96, the warn message is same as before:

WARN[0000] Error initializing configured OCI runtime kata: no valid executable found for OCI runtime kata: invalid argument 

[debarshiray]

This is strange:

level=debug msg="Running as real user ID 0"
...
usermod: failure while writing changes to /etc/passwd
Error: failed to modify user lars with UID 1000

The entry point of the container is clearly running as UID 0, as expected.

[debarshiray]

Are your containers still failing to start with a similar log message?

[larsks]

With Fedora 38 I am no longer seeing this error.