crc CRC 2.39.0 fails to start VM - Unable to determine VM's IP address

CRC 2.39.0 fails to start VM - Unable to determine VM's IP address

Open Manfred73 opened this issue 6 months ago • 7 comments

General information

OS: Linux
Hypervisor: QEMU
Did you run crc setup before starting it (Yes/No)? Yes
Running CRC on: VM

CRC version

CRC version: 2.39.0+0849cb
OpenShift version: 4.16.0

CRC status

DEBU CRC version: 2.39.0+0849cb                   
DEBU OpenShift version: 4.16.0                    
DEBU Running 'crc start'                          
DEBU Total memory of system is 33655652352 bytes  
WARN A new version (2.40.0) has been published on https://developers.redhat.com/content-gateway/file/pub/openshift-v4/clients/crc/2.40.0/crc-linux-amd64.tar.xz 
DEBU Checking file: /home/itsme/.crc/machines/crc/.crc-exist 
INFO Using bundle path /home/itsme/.crc/cache/crc_libvirt_4.16.0_amd64.crcbundle 
DEBU resolv.conf file path: /run/systemd/resolve/stub-resolv.conf 
DEBU Checking if systemd-resolved.service is running 
DEBU Running 'systemctl status systemd-resolved.service' 
DEBU systemd-resolved.service is already running  
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/itsme/.crc/bin/crc-admin-helper-linux-amd64 --version' 
DEBU Found crc-admin-helper-linux-amd64 version 0.5.4 
DEBU crc-admin-helper executable already cached   
INFO Checking if running on a supported CPU architecture 
DEBU GOARCH is amd64 GOOS is linux                
INFO Checking if crc executable symlink exists    
INFO Checking minimum RAM requirements            
DEBU Total memory of system is 33655652352 bytes  
INFO Check if Podman binary exists in: /home/itsme/.crc/bin/oc 
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 
DEBU libvirt group is active for the current user/process 
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 libvirtd.socket is running                   
INFO Checking if a supported libvirt version is installed 
       Docs: man:systemd-networkd.service(8)
             man:org.freedesktop.network1(5)
   FD Store: 0 (limit: 512) 
DEBU stderr:                                      
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 dnsmasq configurations file exist for NetworkManager 
INFO Checking if the systemd-resolved service is running 
DEBU resolv.conf file path: /run/systemd/resolve/stub-resolv.conf 
DEBU Checking if systemd-resolved.service is running 
DEBU Running 'systemctl status systemd-resolved.service' 
DEBU systemd-resolved.service is already running  
INFO Checking if /etc/NetworkManager/dispatcher.d/99-crc.sh exists 
DEBU Checking NetworkManager dispatcher file for crc network 
DEBU Dispatcher file has the expected content     
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/itsme/.crc/machines/crc/.crc-exist 
INFO Loading bundle: crc_libvirt_4.16.0_amd64...  
DEBU Using secret from configuration              
INFO Creating CRC VM for OpenShift 4.16.0...      
DEBU Found binary path at /home/itsme/.crc/bin/crc-driver-libvirt-amd64 
DEBU Launching plugin server for driver libvirt   
DEBU Plugin server listening at address 127.0.0.1:43961 
DEBU () Calling .GetVersion                       
DEBU Using API Version 1                          
DEBU () Calling .SetConfigRaw                     
DEBU () Calling .GetMachineName                   
DEBU (crc) Calling .GetMachineName                
DEBU (crc) Calling .DriverName                    
DEBU Running pre-create checks...                 
DEBU (crc) Calling .PreCreateCheck                
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="About to check libvirt version" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Validating network" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Validating storage pool" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Could not find storage pool 'crc', trying to create it" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Creating storage pool" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=info msg="Creating storage pool with XML <pool type=\"dir\">\n  <name>crc</name>\n  <target>\n    <path>/home/itsme/.crc/machines/crc</path>\n  </target>\n</pool>" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Activating pool 'crc'" 
DEBU (crc) Calling .GetConfigRaw                  
DEBU Creating machine...                          
DEBU (crc) Calling .Create                        
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Preparing /home/itsme/.crc/machines/crc/crc.qcow2 for machine use" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="image creation took 140.6532ms" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Verifying executable bit set on /home/itsme/.crc/machines/crc" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Verifying executable bit set on /home/itsme/.crc/machines" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Verifying executable bit set on /home/itsme/.crc" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Verifying executable bit set on /home/itsme" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Verifying executable bit set on /home" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Defining VM..." 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Found x86_64 hypervisor with 'hvm' capabilities" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Found q35 machine type" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Found x86_64 hypervisor with 'hvm' capabilities" 
DEBU (crc) DBG | time="2024-08-08T20:41:52+02:00" level=debug msg="Found q35 machine type" 
DEBU (crc) DBG | time="2024-08-08T20:41:53+02:00" level=debug msg="disk image capacity is already 33285996544 bytes" 
INFO Generating new SSH key pair...               
INFO Generating new password for the kubeadmin user 
DEBU Created /home/itsme/.crc/machines/crc/.crc-exist 
DEBU Machine successfully created                 
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="2024-08-08T20:41:53+02:00" level=debug msg="Closing plugin on server side" 
DEBU Checking file: /home/itsme/.crc/machines/crc/.crc-exist 
DEBU Found binary path at /home/itsme/.crc/bin/crc-driver-libvirt-amd64 
DEBU Launching plugin server for driver libvirt   
DEBU Plugin server listening at address 127.0.0.1:44749 
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="2024-08-08T20:41:53+02:00" level=debug msg="Getting current state..." 
DEBU (crc) DBG | time="2024-08-08T20:41:53+02:00" level=debug msg="Fetching VM..." 
INFO Starting CRC VM for openshift 4.16.0...      
DEBU Updating CRC VM configuration                
DEBU (crc) Calling .GetConfigRaw                  
DEBU (crc) Calling .Start                         
DEBU (crc) DBG | time="2024-08-08T20:41:53+02:00" level=debug msg="Starting VM crc" 
DEBU (crc) DBG | time="2024-08-08T20:41:53+02:00" level=debug msg="Validating network" 
DEBU (crc) DBG | time="2024-08-08T20:41:53+02:00" level=debug msg="Validating storage pool" 
DEBU (crc) DBG | time="2024-08-08T20:41:59+02:00" level=debug msg="GetIP called for crc" 
DEBU (crc) DBG | time="2024-08-08T20:41:59+02:00" level=debug msg="Getting current state..." 
DEBU (crc) DBG | time="2024-08-08T20:41:59+02:00" level=debug msg="Waiting for machine to come up 0/60" 
DEBU (crc) DBG | time="2024-08-08T20:42:02+02:00" level=debug msg="GetIP called for crc" 
DEBU (crc) DBG | time="2024-08-08T20:42:02+02:00" level=debug msg="Getting current state..." 
DEBU (crc) DBG | time="2024-08-08T20:42:02+02:00" level=debug msg="Waiting for machine to come up 1/60" 
DEBU (crc) DBG | time="2024-08-08T20:42:05+02:00" level=debug msg="GetIP called for crc" 
DEBU (crc) DBG | time="2024-08-08T20:42:05+02:00" level=debug msg="Getting current state..." 
.
.
DEBU (crc) DBG | time="2024-08-08T20:44:57+02:00" level=debug msg="Waiting for machine to come up 59/60" 
DEBU Making call to close driver server           
DEBU (crc) Calling .Close                         
DEBU (crc) DBG | time="2024-08-08T20:45:00+02:00" level=warning msg="Unable to determine VM's IP address, did it fail to boot?" 
DEBU Successfully made call to close driver server 
DEBU Making call to close connection to plugin binary 
Error starting machine: Error in driver during machine start: Unable to determine VM's IP address, did it fail to boot?

The debug log shows DEBU systemd-networkd.service is not running, so I enabled and started it, but than crc start complains it cannot work with systemd-networkd.service, so I stopped and disabled it again.

I also see errors about systemctl status virtqemud.socket' which cannot be found (not running nor listening). It was my understanding that this should be available when installing libvirt-daemon-system`. I installed the following applications:

sudo apt install qemu-system qemu-kvm qemu-utils libvirt-daemon-system libvirt-clients bridge-utils virt-manager virtiofsd

Am I missing another library here? I understand libvirtd is moving away from monolith to modules. I didn't get the modular approach to work though.

CRC config

- consent-telemetry : no
- cpus : 6
- memory : 12000

Host Operating System

PRETTY_NAME="Ubuntu 24.04 LTS"
NAME="Ubuntu"
VERSION_ID="24.04"
VERSION="24.04 LTS (Noble Numbat)"
VERSION_CODENAME=noble
ID=ubuntu
ID_LIKE=debian
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
UBUNTU_CODENAME=noble
LOGO=ubuntu-logo

Steps to reproduce

Booting QEMU from Windows 11 host (with 64 GB RAM) using a batch file with the following options (using networking mode NAT). I noticed the crc network runs in bridge mode and thought that might be a problem. I tried to run QEMU in bridge, but didn't get that to work together with SPICE (the image won't boot if I use bridge mode).

@echo off

setlocal enabledelayedexpansion

:: Define the QEMU executable
set "QEMU_EXE=qemu-system-x86_64.exe"

:: Define the image name you want to check
set "IMAGENAME=ubuntu_24_04_openshift"

:: Define the image path and name
set "IMAGE=%QEMU_VMS%\ubuntu_24_04_openshift.img"

:: Check if the QEMU process is running with the specified image
tasklist /v /fi "IMAGENAME eq %QEMU_EXE%" | findstr /i "%IMAGENAME%" >nul

:: Check the exit code of findstr
if %ERRORLEVEL% == 0 (
    echo QEMU is already running image %IMAGENAME%. Exiting.
    exit /b 1
)

start "" cmd /c ^
  qemu ^
    -name "ubuntu_24_04_openshift" ^
    -m 32768 ^
    -smp 6 ^
    -hda %IMAGE% ^
    -accel whpx,kernel-irqchip=off ^
    -net nic ^
    -net user ^
    -vga virtio ^
    -usb ^
    -spice port=5900,disable-ticketing=on ^
    -chardev spicevmc,id=vdagent,name=vdagent,clipboard=on ^
    -device virtio-serial ^
    -device virtserialport,chardev=vdagent,name=com.redhat.spice.0 ^
    -device usb-tablet ^
    -display sdl,window-close=on ^
    -drive file=%IMAGE%,format=qcow2,cache=writeback

if defined VIRT_VIEWER_HOME (
  set "SEARCH_STRING=!VIRT_VIEWER_HOME!\bin"
  echo %PATH% | findstr /i /c:"!SEARCH_STRING!" >nul
  if !errorlevel!==0 (
    start "" cmd /c virt-view.bat
  )
)

endlocal

Checked if NetworkManager is installed and running on Ubuntu guest. This was the case.

Installed QEMU and related applications on Ubuntu guest, enabled and started libvirtd:

sudo apt update
sudo apt install qemu-system qemu-kvm qemu-utils libvirt-daemon-system libvirt-clients bridge-utils virt-manager virtiofsd
sudo systemctl enable libvirtd
sudo systemctl start libvirtd

crc setup
crc start
crc config set cpus 6
crc config set memory 12000

Added the following to /etc/hosts oh Ubuntu guest:

127.0.0.1 console-openshift-console.apps-crc.testing
127.0.0.1 api.crc.testing

Expected

CRC to start succesfully and

Actual

crc start takes a long time, and log shows 60 tries to GetIP for crc. Doing another start shows:

WARN A new version (2.40.0) has been published on https://developers.redhat.com/content-gateway/file/pub/openshift-v4/clients/crc/2.40.0/crc-linux-amd64.tar.xz 
INFO Loading bundle: crc_libvirt_4.16.0_amd64...  
INFO A CRC VM for OpenShift 4.16.0 is already running 
Started the OpenShift cluster.

The server is accessible via web console at:
  https://console-openshift-console.apps-crc.testing

Log in as administrator:
  Username: kubeadmin
  Password: 85ZcW-5NNFG-xrAG7-GrWN8

Log in as user:
  Username: developer
  Password: developer

Use the 'oc' command line interface:
  $ eval $(crc oc-env)
  $ oc login -u developer https://api.crc.testing:6443

But a crc status shows:

CRC VM:          Running
OpenShift:       Unreachable (v4.16.0)
Disk Usage:      0B of 0B (Inside the CRC VM)
Cache Usage:     29.05GB
Cache Directory: /home/itsme/.crc/cache

The CRC VM is running, but OpenShift is unreachable because it didn't get an IP assigned?

Logs

Before gather the logs try following if that fix your issue

$ 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.

output of crc start --log-level debug, see section 'CRC status' above.

virsh net-list --all

Name      State     Autostart   Persistent
--------------------------------------------
crc            active   yes            yes
default      active  yes            yes

nmcli connection

NAME                    UUID                                                                TYPE          DEVICE          
netplan-ens3         bec3d02a-c9e5-3283-92ab-ee43a4246c85     ethernet    ens3            
br-12289fa1b7f2   79dbbcf1-efb7-4917-86aa-ed554ce68698      bridge       br-12289fa1b7f2 
br-1320b7416fbc  7d79898d-6661-4cde-9057-e1961fa6e1ec      bridge       br-1320b7416fbc 
br-cea5fed94f89   5e19f443-e297-41d0-a1cc-a5553ac173d6       bridge      br-cea5fed94f89 
lo                           b7e6b12c-1c2f-4708-9166-5c9a18fd27cd       loopback  lo              
crc                         b266103a-b44d-4981-8707-ba982d53281b    bridge      crc             
docker0                 c5784d34-1ac6-49bf-910e-63ddd34c699d     bridge      docker0         
virbr0                     98714c75-c32e-4a6d-a7cd-c25ce7344ab8     bridge      virbr0

virsh net-dumpxml crc | grep -i dhcp

<dhcp>
</dhcp>

systemctl status libvirtd.service

systemctl status NetworkManager

     NetworkManager.service - Network Manager
     Loaded: loaded (/usr/lib/systemd/system/NetworkManager.service; enabled; preset: enabled)
     Active: active (running) since Thu 2024-08-08 20:19:18 CEST; 39min ago
       Docs: man:NetworkManager(8)
    Process: 11993 ExecReload=/usr/bin/busctl call org.freedesktop.NetworkManager /org/freedesktop/NetworkManager org.freedesktop.NetworkManager Reload u 0 (code=exit>
   Main PID: 920 (NetworkManager)
      Tasks: 4 (limit: 38418)
     Memory: 22.1M (peak: 125.2M)
        CPU: 2.876s
     CGroup: /system.slice/NetworkManager.service
             /usr/sbin/NetworkManager --no-daemon

Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8874] device (crc): state change: unmanaged -> unavailable (reason 'connection-assumed', sys-iface->
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8877] device (crc): state change: unavailable -> disconnected (reason 'connection-assumed', sys-ifa>
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8882] device (crc): Activation: starting connection 'crc' (b266103a-b44d-4981-8707-ba982d53281b)
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8885] device (crc): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'externa>
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8886] device (crc): state change: prepare -> config (reason 'none', sys-iface-state: 'external')
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8888] device (crc): state change: config -> ip-config (reason 'none', sys-iface-state: 'external')
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8890] device (crc): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'external')
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8982] device (crc): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'externa>
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8987] device (crc): state change: secondaries -> activated (reason 'none', sys-iface-state: 'extern>
Aug 08 20:51:58 itsme NetworkManager[920]: <info>  [1723143118.8990] device (crc): Activation: successful, device activated.

Older (related?) bugs/posts?

I have seen older other similar bugs around here:

https://github.com/crc-org/crc/issues/2732
- Eventually was solved by starting libvirtd if I understand correctly. In my case libvirtd is started.
https://github.com/crc-org/crc/issues/2397

Aug 09 '24 06:08 Manfred73

crc crc copied to clipboard

CRC 2.39.0 fails to start VM - Unable to determine VM's IP address

General information

CRC version

CRC status

CRC config

Host Operating System

Steps to reproduce

Expected

Actual

Logs

virsh net-list --all

nmcli connection

virsh net-dumpxml crc | grep -i dhcp

systemctl status libvirtd.service

systemctl status NetworkManager

Older (related?) bugs/posts?

crc
crc copied to clipboard