search

crc-org / crc

CRC is a tool to help you run containers. It manages a local OpenShift 4.x cluster, Microshift or a Podman VM optimized for testing and development purposes
https://crc.dev
Apache License 2.0
1.26k stars 239 forks source link

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

Open Manfred73 opened 3 months ago

Manfred73 commented 3 months ago

General information

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 installinglibvirt-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

  1. 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
  2. Checked if NetworkManager is installed and running on Ubuntu guest. This was the case.
  3. 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
  4. crc setup
  5. crc start
  6. crc config set cpus 6
  7. crc config set memory 12000
  8. 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

image

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:

praveenkumar commented 3 months ago

@Manfred73 Hi, If I understood correctly you are trying to run crc on a ubuntu VM which is running on windows machine. Why can't you directly use crc on that windows machine ? In past we also issue which raised by users are using nested virt (check the label) and in your case also it is same. We don't perform nested virtualization so not even sure why it is happen, Also we recently did 2.40.0 release try that and see if that works (it fixes one of the issue https://github.com/crc-org/machine-driver-libvirt/pull/122 if underlying hardware is AMD one)

Manfred73 commented 3 months ago

I want to use an Ubuntu/Linux image with crc and other tooling pre installed for training purposes, so I can easily share the image. Some users will have macOS, some Linux and some Windows. First I tried Virtual Box, but understood that doesn't work at all with nested virt and crc. I understood QEMU did supporr this.

Are there workarounds for this, or assigning IP manually. I will try the newer version also.

Update: I tried version 2.40.0. Unfortunately still the same issue.

praveenkumar commented 3 months ago

Check the logs under /var/log/libvirt/qemu/crc.log and see if there is any error, otherwise VM should able to get the IP automatic. Also you can try following if that help

$ crc delete
$ crc cleanup
$ crc config set network-mode user
$ crc setup
$ crc start
Manfred73 commented 3 months ago

I do see one error related to libvirtd in the crc.log (see log attached): crc.log

libvirt:  error : libvirtd quit during handshake: Input/output error
2024-08-08 22:07:04.951+0000: shutting down, reason=failed
2024-08-09 05:21:30.494+0000: Starting external device: virtiofsd

I also followed the steps you mentioned before, but without the crc config set network-mode user. I have tried them again, including this option which seems to do something.

I did crc delete followed by crc cleanup:

$ crc config set network-mode user
Network mode changed. Please run `crc cleanup` and `crc setup`.

It suggests I do crc cleanup again, which results in an error (unexpected AppArmor template file /etc/apparmor.d/libvirt/TEMPLATE.qemu, cannot configure it automatically):

$ crc cleanup
INFO Removing vsock configuration                 
INFO Removing 'crc' network from libvirt          
INFO Removing /etc/NetworkManager/dispatcher.d/99-crc.sh file 
INFO Cleaning up AppArmor configuration           
INFO Removing crc daemon systemd socket units     
INFO Removing crc daemon systemd service          
INFO Removing crc's virtual machine               
INFO Removing crc libvirt storage pool            
INFO Removing CRC Specific entries from user's known_hosts file 
INFO Removing hosts file records added by CRC     
INFO Removing pull secret from the keyring        
INFO Removing older logs                          
unexpected AppArmor template file /etc/apparmor.d/libvirt/TEMPLATE.qemu, cannot configure it automatically
Network mode changed. Please run `crc cleanup` and `crc setup`.

Then crc setup:

$ crc setup
INFO Using bundle path /home/itsme/.crc/cache/crc_libvirt_4.16.4_amd64.crcbundle 
INFO Checking if running as non-root              
INFO Checking if running inside WSL2              
INFO Checking if crc-admin-helper executable is cached 
INFO Checking if running on a supported CPU architecture 
INFO Checking if crc executable symlink exists    
INFO Creating symlink for crc executable          
INFO Checking minimum RAM requirements            
INFO Check if Podman binary exists in: /home/itsme/.crc/bin/oc 
INFO Checking if Virtualization is enabled        
INFO Checking if KVM is enabled                   
INFO Checking if libvirt is installed             
INFO Checking if user is part of libvirt group    
INFO Checking if active user/process is currently part of the libvirt group 
INFO Checking if libvirt daemon is running        
WARN No active (running) libvirtd systemd unit could be found - make sure one of libvirt systemd units is enabled so that it's autostarted at boot time. 
INFO Starting libvirt service                     
INFO Using root access: Executing systemctl daemon-reload command 
INFO Using root access: Executing systemctl start libvirtd 
INFO Checking if a supported libvirt version is installed 
INFO Checking if crc-driver-libvirt is installed  
INFO Checking crc daemon systemd service          
INFO Setting up crc daemon systemd service        
INFO Checking crc daemon systemd socket units     
INFO Setting up crc daemon systemd socket units   
INFO Checking if AppArmor is configured           
INFO Updating AppArmor configuration              
INFO Using root access: Updating AppArmor configuration 
INFO Using root access: Changing permissions for /etc/apparmor.d/libvirt/TEMPLATE.qemu to 644  
INFO Checking if vsock is correctly configured    
INFO Setting up vsock support                     
INFO Using root access: Setting CAP_NET_BIND_SERVICE capability for /home/itsme/bin/crc executable 
INFO Using root access: Creating udev rule for /dev/vsock 
INFO Using root access: Changing permissions for /etc/udev/rules.d/99-crc-vsock.rules to 644  
INFO Using root access: Reloading udev rules database 
INFO Using root access: Loading vhost_vsock kernel module 
INFO Using root access: Creating file /etc/modules-load.d/vhost_vsock.conf 
INFO Using root access: Changing permissions for /etc/modules-load.d/vhost_vsock.conf to 644  
INFO Checking if CRC bundle is extracted in '$HOME/.crc' 
INFO Checking if /home/itsme/.crc/cache/crc_libvirt_4.16.4_amd64.crcbundle exists 
Your system is correctly setup for using CRC. Use 'crc start' to start the instance

Now, doing a crc start gives the following error (failed to expose port 127.0.0.1:2222 -> 192.168.127.2:22: listen tcp 127.0.0.1:2222: bind: address already in use): I have github locally installed on Ubuntu guest as docker, using ports 2222:22. 

$ crc start -p ~/bin/pull-secret.txt --log-level debug
DEBU CRC version: 2.40.0+a14925                   
DEBU OpenShift version: 4.16.4                    
DEBU MicroShift version: 4.16.4                   
DEBU Running 'crc start'                          
DEBU Total memory of system is 33655652352 bytes  
DEBU No new version available. The latest version is 2.40.0 
DEBU Checking file: /home/itsme/.crc/machines/crc/.crc-exist 
INFO Using bundle path /home/itsme/.crc/cache/crc_libvirt_4.16.4_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 
DEBU Checking if libvirt version is >=8.0.0       
DEBU Running 'virsh -v'                           
INFO Checking if crc-driver-libvirt is installed  
DEBU Checking if crc-driver-libvirt-amd64 is installed 
DEBU Running '/home/itsme/.crc/bin/crc-driver-libvirt-amd64 version' 
DEBU Found crc-driver-libvirt-amd64 version 0.13.9 
DEBU crc-driver-libvirt-amd64 is already installed 
INFO Checking crc daemon systemd socket units     
DEBU Checking crc daemon systemd socket units     
DEBU Checking if crc-http.socket is running       
DEBU Running 'systemctl --user status crc-http.socket' 
DEBU crc-http.socket is running                   
DEBU Checking if crc-http.socket has the expected content 
DEBU Checking if crc-vsock.socket is running      
DEBU Running 'systemctl --user status crc-vsock.socket' 
DEBU crc-vsock.socket is running                  
DEBU Checking if crc-vsock.socket has the expected content 
INFO Checking if AppArmor is configured           
INFO Checking if vsock is correctly configured    
DEBU Running 'getcap /home/itsme/bin/crc'     
DEBU Checking file: /home/itsme/.crc/machines/crc/.crc-exist 
INFO Loading bundle: crc_libvirt_4.16.4_amd64...  
DEBU Using secret from configuration              
INFO Creating CRC VM for OpenShift 4.16.4...      
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:36177 
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-12T22:20:55+02:00" level=debug msg="About to check libvirt version" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Validating storage pool" 
DEBU (crc) Calling .GetConfigRaw                  
DEBU Creating machine...                          
DEBU (crc) Calling .Create                        
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Preparing /home/itsme/.crc/machines/crc/crc.qcow2 for machine use" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="image creation took 77.478378ms" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Verifying executable bit set on /home/itsme/.crc/machines/crc" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Verifying executable bit set on /home/itsme/.crc/machines" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Verifying executable bit set on /home/itsme/.crc" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Verifying executable bit set on /home/itsme" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Verifying executable bit set on /home" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Defining VM..." 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Found x86_64 hypervisor with 'hvm' capabilities" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Found q35 machine type" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Found x86_64 hypervisor with 'hvm' capabilities" 
DEBU (crc) DBG | time="2024-08-12T22:20:55+02:00" level=debug msg="Found q35 machine type" 
DEBU (crc) DBG | time="2024-08-12T22:20:56+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 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:46607 
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-12T22:20:56+02:00" level=debug msg="Getting current state..." 
DEBU (crc) DBG | time="2024-08-12T22:20:56+02:00" level=debug msg="Fetching VM..." 
INFO Starting CRC VM for openshift 4.16.4...      
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 
failed to expose port 127.0.0.1:2222 -> 192.168.127.2:22: listen tcp 127.0.0.1:2222: bind: address already in use

crc status shows:

$ crc status
CRC VM:          Stopped
OpenShift:       Stopped (v4.16.4)
RAM Usage:       0B of 0B
Disk Usage:      0B of 0B (Inside the CRC VM)
Cache Usage:     27.61GB
Cache Directory: /home/itsme/.crc/cache

When I stop gitlab and try crc start again, it fails on port 80 (I have another docker image running with also uses port 80):

failed to expose port :80 -> 192.168.127.2:80: listen tcp :80: bind: address already in use

Should I run these docker images on another port? Or can I configure crc to use others?

I have stopped both docker images and did another:

$ crc delete
$ crc cleanup
$ crc config set network-mode user
$ crc setup
$ crc start

This results in errors:

DEBU retry loop: attempt 61                       
DEBU Running SSH command: exit 0                  
DEBU Using ssh private keys: [/home/itsme/.crc/machines/crc/id_ecdsa /home/itsme/.crc/cache/crc_libvirt_4.16.4_amd64/id_ecdsa_crc] 
DEBU SSH command results: err: ssh: handshake failed: read tcp 127.0.0.1:56730->127.0.0.1:2222: read: connection reset by peer, output:  
DEBU error: Temporary error: ssh command error:
command : exit 0
err     : ssh: handshake failed: read tcp 127.0.0.1:56730->127.0.0.1:2222: read: connection reset by peer
 - sleeping 1s 
DEBU retry loop: attempt 62                       
DEBU Running SSH command: exit 0                  
DEBU Using ssh private keys: [/home/itsme/.crc/machines/crc/id_ecdsa /home/itsme/.crc/cache/crc_libvirt_4.16.4_amd64/id_ecdsa_crc] 
DEBU SSH command results: err: ssh: handshake failed: read tcp 127.0.0.1:56744->127.0.0.1:2222: read: connection reset by peer, output:  
DEBU error: Temporary error: ssh command error:
command : exit 0
err     : ssh: handshake failed: read tcp 127.0.0.1:56744->127.0.0.1:2222: read: connection reset by peer
 - sleeping 1s

On the Ubuntu guest I have a config file defined in the .ssh for the docker images I'm running which need ssh with identity file. Is this causing a problem for crc?

praveenkumar commented 3 months ago 
libvirt:  error : libvirtd quit during handshake: Input/output error
2024-08-08 22:07:04.951+0000: shutting down, reason=failed
2024-08-09 05:21:30.494+0000: Starting external device: virtiofsd

I think following explain it, looks like libvirt is not working at all properly and VM is not running, you can check status of the VM using sudo virsh list --all and might see the VM in stopped state. This might be the reason why ssh is failing.

Manfred73 commented 2 months ago

I create a complete new Ubuntu image and right after that installed prerequisites for crc (docker, libvirt):

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

Right after that installed crc:

crc config set network-mode user
crc setup
crc start

libvirt service is running:

libvirtd.service - libvirt legacy monolithic daemon
     Loaded: loaded (/usr/lib/systemd/system/libvirtd.service; enabled; preset: enabled)
     Active: active (running) since Tue 2024-08-13 23:41:18 CEST; 6min ago
TriggeredBy: libvirtd.socket
             libvirtd-admin.socket
             libvirtd-ro.socket
       Docs: man:libvirtd(8)
             https://libvirt.org/
   Main PID: 1070 (libvirtd)
      Tasks: 26 (limit: 32768)
     Memory: 36.3M (peak: 42.4M)
        CPU: 1.312s
     CGroup: /system.slice/libvirtd.service
             1070 /usr/sbin/libvirtd --timeout 120
             1244 /usr/sbin/dnsmasq --conf-file=/var/lib/libvirt/dnsmasq/default.conf --leasefile-ro --dhcp-script=/usr/lib/libvirt/libvirt_leaseshelper
             1245 /usr/sbin/dnsmasq --conf-file=/var/lib/libvirt/dnsmasq/default.conf --leasefile-ro --dhcp-script=/usr/lib/libvirt/libvirt_leaseshelper
             3224 /usr/libexec/virtiofsd --fd=34 -o source=/home/itsme

Aug 13 23:41:19 itsme dnsmasq[1244]: using nameserver 127.0.0.53#53
Aug 13 23:41:19 itsme dnsmasq[1244]: read /etc/hosts - 8 names
Aug 13 23:41:19 itsme dnsmasq[1244]: read /var/lib/libvirt/dnsmasq/default.addnhosts - 0 names
Aug 13 23:41:19 itsme dnsmasq-dhcp[1244]: read /var/lib/libvirt/dnsmasq/default.hostsfile
Aug 13 23:41:19 itsme libvirtd[1070]: libvirt version: 10.0.0, package: 10.0.0-2ubuntu8.3 (Ubuntu)
Aug 13 23:41:19 itsme libvirtd[1070]: hostname: itsme
Aug 13 23:41:19 itsme libvirtd[1070]: ignoring socket '/home/itsme/.crc/machines/crc/docker.sock'
Aug 13 23:41:51 itsme libvirtd[1070]: End of file while reading data: Input/output error
Aug 13 23:43:49 itsme libvirtd[1070]: End of file while reading data: Input/output error
Aug 13 23:46:58 itsme libvirtd[1070]: End of file while reading data: Input/output error

crc status shows:

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

sudo virsh list --all shows:

 Id   Name   State
----------------------
 1    crc    running

In the crc.log I still see ssh handshake errors:

2: read: connection reset by peer\n - sleeping 1s"
time="2024-08-13T23:46:54+02:00" level=debug msg="retry loop: attempt 75"
time="2024-08-13T23:46:54+02:00" level=debug msg="Running SSH command: exit 0"
time="2024-08-13T23:46:54+02:00" level=debug msg="Using ssh private keys: [/home/itsme/.crc/machines/crc/id_ecdsa /home/itsme/.crc/cache/crc_libvirt_4.16.4_amd64/id_ecdsa_crc]"
time="2024-08-13T23:46:57+02:00" level=debug msg="SSH command results: err: ssh: handshake failed: read tcp 127.0.0.1:48438->127.0.0.1:2222: read: connection reset by peer, output: "
time="2024-08-13T23:46:57+02:00" level=debug msg="error: Temporary error: ssh command error:\ncommand : exit 0\nerr     : ssh: handshake failed: read tcp 127.0.0.1:48438->127.0.0.1:2222: read: connection reset by peer\n - sleeping 1s"

and in /var/log/libvirt/qemu/crc.log still one handhake errors:

libvirt:  error : libvirtd quit during handshake: Input/output error
praveenkumar commented 2 months ago

We can only debug more around this if it can reproduce in our testing/dev environment and which is not the case :( . There is lot of things depend for failure like base/guest HyperVisor and also underlying hardware. As I told before nested-virt tests are not something we perform or encourage users to do it. If possible try on native hypervisor to see if it still fails instead nested-virt.