crc: Podman images aren't usable (unavailable) when VM does not cleanly stop/restart

General information

  • OS: Linux / macOS / Windows
  • Hypervisor: KVM / Hyper-V / hyperkit
  • Did you run crc setup before starting it (Yes/No)?
  • Running CRC on: Laptop / Baremetal-Server / VM

CRC version

# Put `crc version` output here
[crc@eaas-crc ~]$ crc version
CodeReady Containers version: 1.33.1+3cfaa10f
OpenShift version: 4.8.12 (embedded in executable)
[crc@eaas-crc ~]$

  
## CRC status
```bash
# Put `crc status --log-level debug` output here
[crc@eaas-crc ~]$ crc status --log-level debug
DEBU CodeReady Containers version: 1.33.1+3cfaa10f
DEBU OpenShift version: 4.8.12 (embedded in executable)
DEBU Running 'crc status'
DEBU Checking file: /home/crc/.crc/machines/crc/.crc-exist
DEBU Checking file: /home/crc/.crc/machines/crc/.crc-exist
DEBU Found binary path at /home/crc/.crc/bin/crc-driver-libvirt
DEBU Launching plugin server for driver libvirt
DEBU Plugin server listening at address 127.0.0.1:45496
DEBU () Calling .GetVersion
DEBU Using API Version 1
DEBU () Calling .SetConfigRaw
DEBU () Calling .GetMachineName
DEBU (crc) Calling .GetState
DEBU (crc) DBG | time="2021-10-05T12:54:28+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:54:28+01:00" level=debug msg="Fetching VM..."
DEBU (crc) Calling .GetBundleName
DEBU (crc) Calling .GetIP
DEBU (crc) DBG | time="2021-10-05T12:54:28+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:54:28+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:54:28+01:00" level=debug msg="IP address: 192.168.130.11"
DEBU Running SSH command: df -B1 --output=size,used,target /sysroot | tail -1
DEBU Using ssh private keys: [/home/crc/.crc/machines/crc/id_ecdsa /home/crc/.crc/cache/crc_libvirt_4.8.12/id_ecdsa_crc]
DEBU SSH command results: err: <nil>, output: 354860118016 9323663360 /sysroot
DEBU cannot get OpenShift status: Get "https://api.crc.testing:6443/apis/config.openshift.io/v1/clusteroperators": net/http: request canceled (Client.Timeout exceeded while awaiting headers)
DEBU Making call to close driver server
DEBU (crc) Calling .Close
DEBU Successfully made call to close driver server
DEBU (crc) DBG | time="2021-10-05T12:54:33+01:00" level=debug msg="Closing plugin on server side"
DEBU Making call to close connection to plugin binary
CRC VM:          Running
OpenShift:       Unreachable (v4.8.12)
Disk Usage:      9.324GB of 354.9GB (Inside the CRC VM)
Cache Usage:     16.06GB
Cache Directory: /home/crc/.crc/cache


## CRC config
```bash
# Put `crc config view` output here
[crc@eaas-crc ~]$ crc config view
- consent-telemetry                     : yes
- http-proxy                            : http://10.232.233.70:8080
- https-proxy                           : http://10.232.233.70:8080
- no-proxy                              : .apps.ilocpfnd401.ocp.corp.amdocs.com,.cluster.local,.ilocpfnd401.ocp.corp.amdocs.com,.svc,10.0.0.0/16,10.254.0.0/16,127.0.0.1,172.30.0.0/16,api-int.ilocpfnd401.ocp.corp.amdocs.com,api.ilocpfnd401.ocp.corp.amdocs.com,etcd-0.ilocpfnd401.ocp.corp.amdocs.com,etcd-1.ilocpfnd401.ocp.corp.amdocs.com,etcd-2.ilocpfnd401.ocp.corp.amdocs.com,ilvcos01.corp.amdocs.com,localhost,.corp.amdocs.com,.apps-crc.testing,.crc.testing
- proxy-ca-file                         : /tmp/amdocs-certificat.crt


## Host Operating System
```bash
# Put the output of `cat /etc/os-release` in case of Linux
# put the output of `sw_vers` in case of Mac
# Put the output of `systeminfo` in case of Windows
[crc@eaas-crc ~]$ cat /etc/os-release
NAME="Red Hat Enterprise Linux Server"
VERSION="7.8 (Maipo)"
ID="rhel"
ID_LIKE="fedora"
VARIANT="Server"
VARIANT_ID="server"
VERSION_ID="7.8"
PRETTY_NAME="Red Hat Enterprise Linux"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:redhat:enterprise_linux:7.8:GA:server"
HOME_URL="https://www.redhat.com/"
BUG_REPORT_URL="https://bugzilla.redhat.com/"

REDHAT_BUGZILLA_PRODUCT="Red Hat Enterprise Linux 7"
REDHAT_BUGZILLA_PRODUCT_VERSION=7.8
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux"
REDHAT_SUPPORT_PRODUCT_VERSION="7.8"


### Steps to reproduce

  1. 
  2. 
  3. 
  4. 

### Expected


### Actual


### Logs

Before gather the logs try following if that fix your issue
```bash
$ crc delete -f
$ crc cleanup
$ crc setup
$ crc start --log-level debug

Please consider posting the output of crc start --log-level debug on http://gist.github.com/ and post the link in the issue.

After the crc successful installation , when we do crc stop and start , it get failed.

crc start --cpus 12 --memory 40000 --log-level debug
DEBU CodeReady Containers version: 1.33.1+3cfaa10f
DEBU OpenShift version: 4.8.12 (embedded in executable)
DEBU Running 'crc start'
DEBU Total memory of system is 42020716544 bytes
DEBU No new version available. The latest version is 1.33.1
DEBU Found binary path at /home/crc/.crc/bin/crc-driver-libvirt
DEBU Launching plugin server for driver libvirt
DEBU Plugin server listening at address 127.0.0.1:39196
DEBU () Calling .GetVersion
DEBU Using API Version 1
DEBU () Calling .SetConfigRaw
DEBU () Calling .GetMachineName
DEBU (crc) Calling .GetState
DEBU (crc) DBG | time="2021-10-05T12:49:25+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:25+01:00" level=debug msg="Fetching VM..."
DEBU Making call to close driver server
DEBU (crc) Calling .Close
DEBU Successfully made call to close driver server
DEBU Making call to close connection to plugin binary
DEBU (crc) DBG | time="2021-10-05T12:49:25+01:00" level=debug msg="Closing plugin on server side"
DEBU Checking if systemd-resolved.service is running
DEBU Running 'systemctl status systemd-resolved.service'
DEBU Command failed: exit status 4
DEBU stdout:
DEBU stderr: Unit systemd-resolved.service could not be found.
INFO Checking if running as non-root
INFO Checking if running inside WSL2
INFO Checking if crc-admin-helper executable is cached
DEBU Running '/home/crc/.crc/bin/crc-admin-helper-linux --version'
DEBU Found crc-admin-helper-linux version 0.0.6
DEBU crc-admin-helper executable already cached
INFO Checking for obsolete admin-helper executable
DEBU Checking if an older admin-helper executable is installed
DEBU No older admin-helper executable found
INFO Checking if running on a supported CPU architecture
INFO Checking minimum RAM requirements
DEBU Total memory of system is 42020716544 bytes
INFO Checking if crc executable symlink exists
INFO Checking if Virtualization is enabled
DEBU Checking if the vmx/svm flags are present in /proc/cpuinfo
DEBU CPU virtualization flags are good
INFO Checking if KVM is enabled
DEBU Checking if /dev/kvm exists
DEBU /dev/kvm was found
INFO Checking if libvirt is installed
DEBU Checking if 'virsh' is available
DEBU 'virsh' was found in /usr/bin/virsh
DEBU Checking 'virsh capabilities' for libvirtd/qemu availability
DEBU Running 'virsh --readonly --connect qemu:///system capabilities'
DEBU Found x86_64 hypervisor with 'hvm' capabilities
INFO Checking if user is part of libvirt group
DEBU Checking if current user is part of the libvirt group
DEBU Current user is already in the libvirt group
INFO Checking if active user/process is currently part of the libvirt group
INFO Checking if libvirt daemon is running
DEBU Checking if libvirtd service is running
DEBU Running 'systemctl status virtqemud.socket'
DEBU Command failed: exit status 4
DEBU stdout:
DEBU stderr: Unit virtqemud.socket could not be found.
DEBU virtqemud.socket is neither running nor listening
DEBU Running 'systemctl status libvirtd.socket'
DEBU Command failed: exit status 4
DEBU stdout:
DEBU stderr: Unit libvirtd.socket could not be found.
DEBU libvirtd.socket is neither running nor listening
DEBU Running 'systemctl status virtqemud.service'
DEBU Command failed: exit status 4
DEBU stdout:
DEBU stderr: Unit virtqemud.service could not be found.
DEBU virtqemud.service is neither running nor listening
DEBU Running 'systemctl status libvirtd.service'
DEBU libvirtd.service is running
INFO Checking if a supported libvirt version is installed
DEBU Checking if libvirt version is >=3.4.0
DEBU Running 'virsh -v'
INFO Checking if crc-driver-libvirt is installed
DEBU Checking if crc-driver-libvirt is installed
DEBU Running '/home/crc/.crc/bin/crc-driver-libvirt version'
DEBU Found crc-driver-libvirt version 0.13.1
DEBU crc-driver-libvirt is already installed
INFO Checking if systemd-networkd is running
DEBU Checking if systemd-networkd.service is running
DEBU Running 'systemctl status systemd-networkd.service'
DEBU Command failed: exit status 4
DEBU stdout:
DEBU stderr: Unit systemd-networkd.service could not be found.
DEBU systemd-networkd.service is not running
INFO Checking if NetworkManager is installed
DEBU Checking if 'nmcli' is available
DEBU 'nmcli' was found in /usr/bin/nmcli
INFO Checking if NetworkManager service is running
DEBU Checking if NetworkManager.service is running
DEBU Running 'systemctl status NetworkManager.service'
DEBU NetworkManager.service is already running
INFO Checking if /etc/NetworkManager/conf.d/crc-nm-dnsmasq.conf exists
DEBU Checking NetworkManager configuration
DEBU NetworkManager configuration is good
INFO Checking if /etc/NetworkManager/dnsmasq.d/crc.conf exists
DEBU Checking dnsmasq configuration
DEBU dnsmasq configuration is good
INFO Checking if libvirt 'crc' network is available
DEBU Checking if libvirt 'crc' network exists
DEBU Running 'virsh --connect qemu:///system net-info crc'
DEBU Checking if libvirt 'crc' definition is up to date
DEBU Running 'virsh --connect qemu:///system net-dumpxml --inactive crc'
DEBU libvirt 'crc' network has the expected value
INFO Checking if libvirt 'crc' network is active
DEBU Checking if libvirt 'crc' network is active
DEBU Running 'virsh --connect qemu:///system net-info crc'
DEBU libvirt 'crc' network is already active
DEBU Checking file: /home/crc/.crc/machines/crc/.crc-exist
DEBU Found binary path at /home/crc/.crc/bin/crc-driver-libvirt
DEBU Launching plugin server for driver libvirt
DEBU Plugin server listening at address 127.0.0.1:34995
DEBU () Calling .GetVersion
DEBU Using API Version 1
DEBU () Calling .SetConfigRaw
DEBU () Calling .GetMachineName
DEBU (crc) Calling .GetBundleName
DEBU (crc) Calling .GetState
DEBU (crc) DBG | time="2021-10-05T12:49:25+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:25+01:00" level=debug msg="Fetching VM..."
INFO Starting CodeReady Containers VM for OpenShift 4.8.12...
DEBU Updating CRC VM configuration
DEBU (crc) Calling .GetConfigRaw
DEBU (crc) Calling .Start
DEBU (crc) DBG | time="2021-10-05T12:49:25+01:00" level=debug msg="Starting VM crc"
DEBU (crc) DBG | time="2021-10-05T12:49:25+01:00" level=debug msg="Validating network"
DEBU (crc) DBG | time="2021-10-05T12:49:25+01:00" level=debug msg="Validating storage pool"
DEBU (crc) DBG | time="2021-10-05T12:49:32+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:32+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:32+01:00" level=debug msg="Waiting for machine to come up 0/60"
DEBU (crc) DBG | time="2021-10-05T12:49:35+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:35+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:35+01:00" level=debug msg="Waiting for machine to come up 1/60"
DEBU (crc) DBG | time="2021-10-05T12:49:38+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:38+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:38+01:00" level=debug msg="Waiting for machine to come up 2/60"
DEBU (crc) DBG | time="2021-10-05T12:49:41+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:41+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:41+01:00" level=debug msg="Waiting for machine to come up 3/60"
DEBU (crc) DBG | time="2021-10-05T12:49:44+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:44+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:44+01:00" level=debug msg="Waiting for machine to come up 4/60"
DEBU (crc) DBG | time="2021-10-05T12:49:47+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:47+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:47+01:00" level=debug msg="Waiting for machine to come up 5/60"
DEBU (crc) DBG | time="2021-10-05T12:49:50+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:50+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:50+01:00" level=debug msg="Waiting for machine to come up 6/60"
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=debug msg="IP address: 192.168.130.11"
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=info msg="Found IP for machine: 192.168.130.11"
DEBU (crc) Calling .GetConfigRaw
DEBU Waiting for machine to be running, this may take a few minutes...
DEBU retry loop: attempt 0
DEBU (crc) Calling .GetState
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=debug msg="Getting current state..."
DEBU Machine is up and running!
DEBU (crc) Calling .GetState
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=debug msg="Getting current state..."
DEBU (crc) Calling .GetIP
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=debug msg="GetIP called for crc"
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=debug msg="Getting current state..."
DEBU (crc) DBG | time="2021-10-05T12:49:53+01:00" level=debug msg="IP address: 192.168.130.11"
INFO CodeReady Containers instance is running with IP 192.168.130.11
DEBU Waiting until ssh is available
DEBU retry loop: attempt 0
DEBU Running SSH command: exit 0
DEBU Using ssh private keys: [/home/crc/.crc/cache/crc_libvirt_4.8.12/id_ecdsa_crc /home/crc/.crc/machines/crc/id_ecdsa]
DEBU SSH command results: err: <nil>, output:
INFO CodeReady Containers VM is running
DEBU Running SSH command: cat /home/core/.ssh/authorized_keys
DEBU SSH command results: err: <nil>, output: ecdsa-sha2-nistp521 AAAAE2VjZHNhLXNoYTItbmlzdHA1MjEAAAAIbmlzdHA1MjEAAACFBACBWAJWCXF38kJpADA+D5KvZP600TuT5F00Sv9Y8wc7Bu9aIfyRnNrvuyoqTkQXFnk7fxQd28o8tF+sJe0IaB3SdQD2DJ+CuzKfEt2xGhEHIw7c9UiWypQmHnmkVUFPv8gGfn0ndSJ+DxCHzK6InHPF4ZUHM+Zfq8NeJYUR/sAdFIKYCg==
DEBU Running SSH command: realpath /dev/disk/by-label/root
DEBU SSH command results: err: <nil>, output: /dev/vda4
DEBU Using root access: Growing /dev/vda4 partition
DEBU Running SSH command: sudo /usr/bin/growpart /dev/vda 4
DEBU SSH command results: err: Process exited with status 1, output: NOCHANGE: partition 4 is size 693106655. it cannot be grown
DEBU No free space after /dev/vda4, nothing to do
DEBU Using root access: make root Podman socket accessible
DEBU Running SSH command: sudo chmod 777 /run/podman/ /run/podman/podman.sock
DEBU SSH command results: err: <nil>, output:
DEBU Creating /var/srv/dnsmasq.conf with permissions 0644 in the CRC VM
DEBU Running SSH command: <hidden>
DEBU SSH command succeeded
DEBU Running SSH command: systemctl status crc-dnsmasq.service
DEBU SSH command results: err: Process exited with status 3, output: â crc-dnsmasq.service - Podman container-849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343.service
   Loaded: loaded (/etc/systemd/system/crc-dnsmasq.service; enabled; vendor preset: disabled)
   Active: activating (start) since Tue 2021-10-05 11:49:53 UTC; 1s ago
     Docs: man:podman-generate-systemd(1)
Cntrl PID: 1764 (podman)
    Tasks: 11 (limit: 250732)
   Memory: 50.6M
      CPU: 181ms
   CGroup: /system.slice/crc-dnsmasq.service
           ââ1764 /usr/bin/podman start 849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343

Oct 05 11:49:53 crc-scmfr-master-0 systemd[1]: Starting Podman container-849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343.service...
DEBU Using root access: Executing systemctl enable crc-dnsmasq.service
DEBU Running SSH command: sudo systemctl enable crc-dnsmasq.service
DEBU SSH command results: err: <nil>, output:
DEBU Using root access: Executing systemctl daemon-reload command
DEBU Running SSH command: sudo systemctl daemon-reload
DEBU SSH command results: err: <nil>, output:
DEBU Using root access: Executing systemctl start crc-dnsmasq.service
DEBU Running SSH command: sudo systemctl start crc-dnsmasq.service
DEBU SSH command results: err: Process exited with status 1, output:
DEBU Making call to close driver server
DEBU (crc) Calling .Close
DEBU Successfully made call to close driver server
DEBU Making call to close connection to plugin binary
Error running post start: Executing systemctl action failed:  ssh command error:
command : sudo systemctl start crc-dnsmasq.service
err     : Process exited with status 1
: Job for crc-dnsmasq.service failed because the control process exited with error code.
See "systemctl status crc-dnsmasq.service" and "journalctl -xe" for details.

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Reactions: 2
  • Comments: 39 (21 by maintainers)

Commits related to this issue

Most upvoted comments

We just faced the same issue.

Basically what is happening, podman containers state file /var/lib/containers/storage/libpod/bolt_state.db and in addition to that crc-dnsmasq and gvisor-tap-vsock images get vanished and 2 services cannot start.

[systemd]
Failed Units: 2
  crc-dnsmasq.service
  gvisor-tap-vsock.service

Basically instead of creation of crc-dnsmasq service by using podman generate systemd command, those systemd services should be created with real image names instead. Here is current service details:

# container-849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343.service
# autogenerated by Podman 3.2.3
# Fri Sep 24 07:55:08 UTC 2021
[Unit]
Description=Podman container-849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343.service
Documentation=man:podman-generate-systemd(1)
Wants=network.target
After=network-online.target
RequiresMountsFor=/var/run/containers/storage
[Service]
Environment=PODMAN_SYSTEMD_UNIT=%n
Restart=no
TimeoutStopSec=70
ExecStart=/usr/bin/podman start 849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343
ExecStop=/usr/bin/podman stop -t 10 849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343
ExecStopPost=/usr/bin/podman stop -t 10 849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343
PIDFile=/var/run/containers/storage/overlay-containers/849aa88cb5cd953dee534b75718babedc49dc017b74cf256c147272edb78f343/userdata/conmon.pid
Type=forking
[Install]
WantedBy=multi-user.target default.target

### gvisor service

# container-aa214a4633d94a6c41c963fb00b900dcf1368ba9d08e6c7617a452904f261894.service
# autogenerated by Podman 3.2.3
# Fri Sep 24 07:55:07 UTC 2021
[Unit]
Description=Podman container-aa214a4633d94a6c41c963fb00b900dcf1368ba9d08e6c7617a452904f261894.service
Documentation=man:podman-generate-systemd(1)
Wants=network.target
After=network-online.target
RequiresMountsFor=/var/run/containers/storage
[Service]
Environment=PODMAN_SYSTEMD_UNIT=%n
Restart=no
TimeoutStopSec=70
ExecStart=/usr/bin/podman start aa214a4633d94a6c41c963fb00b900dcf1368ba9d08e6c7617a452904f261894
ExecStop=/usr/bin/podman stop -t 10 aa214a4633d94a6c41c963fb00b900dcf1368ba9d08e6c7617a452904f261894
ExecStopPost=/usr/bin/podman stop -t 10 aa214a4633d94a6c41c963fb00b900dcf1368ba9d08e6c7617a452904f261894
PIDFile=/var/run/containers/storage/overlay-containers/aa214a4633d94a6c41c963fb00b900dcf1368ba9d08e6c7617a452904f261894/userdata/conmon.pid
Type=forking
[Install]
WantedBy=multi-user.target default.target

And startup should be something like with all needed options:

ExecStart=/usr/bin/podman run quay.io/crcont/dnsmasq:latest  

@rupeshad81 A new release has been made available: https://developers.redhat.com/content-gateway/rest/mirror/pub/openshift-v4/clients/crc/1.34.0 Do note, that although the fix is in, this also uses a new version of OpenShift 4.9. If you experience issues, please consider opening a new issue.

Once startup fails once with these errors, it will always happen until you run crc delete. If after crc delete; crc start you get this output for crc stop:

[crc@eaas-crc ~]$ crc stop
INFO Stopping kubelet and all containers...
INFO Stopping the OpenShift cluster, this may take a few minutes...
Stopped the OpenShift cluster

Then the VM should start properly the next run.

If you follow the conversations in this issue, and https://github.com/code-ready/snc/pull/471 , you will be able to follow the progress towards a resolution.

this happens only if underlying host is rebooted without properly stopping crc by crc stop command.

Your issue is only 4 hours old, and it’s not the only one which we have to look into, some patience is in order 😃