LXD VMs don't start

mikealloy · September 11, 2023, 2:53pm

I am having an issue with LXD installed via snap, version 5.17 latest/stable, revision 25505, and my host machine is running Rocky Linux 8.8.

Once I create a virtual machine of any operating system, either by lxc launch <img> <vm> or, lxc init <vm> and lxc start <vm>, it starts hanging up forever.

After I force cancel the lxc start <vm> command, i have the following information by doing the command lxc info --show-log <vm>

There is no log messages

Name: ubuntu-vm
Status: STOPPED
Type: virtual-machine
Architecture: x86_64
PID: 3259900
Created: 2023/09/11 16:20 CEST

Resources:
  Processes: 0
  Disk usage:
    root: 8.00KiB

Log:

Trying to dig a little deeper i check the process with htop, this is what i see:

The full command associated with the process:

/snap/lxd/25505/bin/qemu-system-x86_64 -S -name ubuntu-vm -uuid 45e86ae9-9963-4797-ab18-abea62d1c6f9 -daemonize -cpu host -nographic -serial chardev:console -nodefaults -no-user-config -sandbox on,obsolete=deny,elevateprivileges=allow,spawn=allow,resourcecontrol=deny -readconfig /var/snap/lxd/common/lxd/logs/<redacted>_ubuntu-vm/qemu.conf -spice unix=on,disable-ticketing=on,addr=/var/snap/lxd/common/lxd/logs/<redacted>_ubuntu-vm/qemu.spice -pidfile /var/snap/lxd/common/lxd/logs/<redacted>_ubuntu-vm/qemu.pid -D /var/snap/lxd/common/lxd/logs/<redacted>_ubuntu-vm/qemu.log -smbios type=2,manufacturer=Canonical Ltd.,product=LXD -runas lxd

ru-fu · September 11, 2023, 3:56pm

Is your storage pool big enough? I’ve had issues launching VMs where after downloading the image, there wasn’t enough space left to actually create the VM, and the unpacking of the image never completed.

mikealloy · September 12, 2023, 10:22am

It seems to have enough space

ru-fu · September 12, 2023, 11:46am

Maybe try running lxc monitor in another terminal while you start a VM - this might give some more information on where it is hanging.

mikealloy · September 12, 2023, 10:16pm

location: none
metadata:
  context:
    id: b986bce9-1124-458e-b87a-f6564c17d15f
    local: /var/snap/lxd/common/lxd/unix.socket
    remote: '@'
  level: debug
  message: Event listener server handler started
timestamp: "2023-09-13T00:08:14.924284462+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T00:08:26.16574366+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/instances/ubuntu-vm?project=<redacted>
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T00:08:26.166589849+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/events?project=<redacted>
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T00:08:26.167550293+02:00"
type: logging


location: none
metadata:
  context:
    id: 213f6ca8-95e7-432c-92b4-d7de70e6f6d3
    local: /var/snap/lxd/common/lxd/unix.socket
    remote: '@'
  level: debug
  message: Event listener server handler started
timestamp: "2023-09-13T00:08:26.167675158+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: PUT
    protocol: unix
    url: /1.0/instances/ubuntu-vm/state?project=<redacted>
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T00:08:26.167793169+02:00"
type: logging


location: none
metadata:
  context:
    class: task
    description: Starting instance
    operation: d201852a-5274-4a43-9f2c-860aa261f107
    project: <redacted>
  level: debug
  message: New operation
timestamp: "2023-09-13T00:08:26.169020374+02:00"
type: logging


location: none
metadata:
  class: task
  created_at: "2023-09-13T00:08:26.168273141+02:00"
  description: Starting instance
  err: ""
  id: d201852a-5274-4a43-9f2c-860aa261f107
  location: none
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/ubuntu-vm?project=<redacted>
  status: Running
  status_code: 103
  updated_at: "2023-09-13T00:08:26.168273141+02:00"
project: <redacted>
timestamp: "2023-09-13T00:08:26.169045742+02:00"
type: operation


location: none
metadata:
  class: task
  created_at: "2023-09-13T00:08:26.168273141+02:00"
  description: Starting instance
  err: ""
  id: d201852a-5274-4a43-9f2c-860aa261f107
  location: none
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/ubuntu-vm?project=<redacted>
  status: Pending
  status_code: 105
  updated_at: "2023-09-13T00:08:26.168273141+02:00"
project: <redacted>
timestamp: "2023-09-13T00:08:26.169034471+02:00"
type: operation


location: none
metadata:
  context:
    action: start
    instance: ubuntu-vm
    project: <redacted>
    reusable: "false"
  level: debug
  message: Instance operation lock created
timestamp: "2023-09-13T00:08:26.169141121+02:00"
type: logging


location: none
metadata:
  context:
    instance: ubuntu-vm
    instanceType: virtual-machine
    project: <redacted>
    stateful: "false"
  level: debug
  message: Start started
timestamp: "2023-09-13T00:08:26.169102148+02:00"
type: logging


location: none
metadata:
  context:
    class: task
    description: Starting instance
    operation: d201852a-5274-4a43-9f2c-860aa261f107
    project: <redacted>
  level: debug
  message: Started operation
timestamp: "2023-09-13T00:08:26.16903951+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/operations/d201852a-5274-4a43-9f2c-860aa261f107?project=<redacted>
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T00:08:26.169225409+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    instance: ubuntu-vm
    pool: <redacted>-project
    project: <redacted>
  level: debug
  message: MountInstance started
timestamp: "2023-09-13T00:08:26.169560409+02:00"
type: logging


location: none
metadata:
  context:
    dev: <redacted>-project/virtual-machines/<redacted>_ubuntu-vm.block
    driver: zfs
    pool: <redacted>-project
    volName: <redacted>_ubuntu-vm
  level: debug
  message: Activated ZFS volume
timestamp: "2023-09-13T00:08:26.752719576+02:00"
type: logging


location: none
metadata:
  context:
    dev: <redacted>-project/virtual-machines/<redacted>_ubuntu-vm
    driver: zfs
    path: /var/snap/lxd/common/lxd/storage-pools/<redacted>-project/virtual-machines/<redacted>_ubuntu-vm
    pool: <redacted>-project
    volName: <redacted>_ubuntu-vm
  level: debug
  message: Mounted ZFS dataset
timestamp: "2023-09-13T00:08:26.831177746+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    instance: ubuntu-vm
    pool: <redacted>-project
    project: <redacted>
  level: debug
  message: MountInstance finished
timestamp: "2023-09-13T00:08:26.831214725+02:00"
type: logging


location: none
metadata:
  context:
    installPath: /var/snap/lxd/common/lxd/virtual-machines/<redacted>_ubuntu-vm/config/lxd-agent
    instance: ubuntu-vm
    instanceType: virtual-machine
    project: <redacted>
    srcPath: /snap/lxd/25505/bin/lxd-agent
  level: debug
  message: Skipping lxd-agent install as unchanged
timestamp: "2023-09-13T00:08:26.83138249+02:00"
type: logging


location: none
metadata:
  context:
    device: eth0
    instance: ubuntu-vm
    instanceType: virtual-machine
    project: <redacted>
    type: nic
  level: debug
  message: Starting device
timestamp: "2023-09-13T00:08:26.833397715+02:00"
type: logging


location: none
metadata:
  context: {}
  level: debug
  message: 'Scheduler: network: tap36e8d42a has been added: updating network priorities'
timestamp: "2023-09-13T00:08:26.834527287+02:00"
type: logging


location: none
metadata:
  context:
    device: root
    instance: ubuntu-vm
    instanceType: virtual-machine
    project: <redacted>
    type: disk
  level: debug
  message: Starting device
timestamp: "2023-09-13T00:08:26.84027371+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    instance: ubuntu-vm
    pool: <redacted>-project
    project: <redacted>
  level: debug
  message: UpdateInstanceBackupFile started
timestamp: "2023-09-13T00:08:27.014049635+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    instance: ubuntu-vm
    pool: <redacted>-project
    project: <redacted>
  level: debug
  message: UpdateInstanceBackupFile finished
timestamp: "2023-09-13T00:08:27.015333085+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    pool: <redacted>-project
    refCount: "1"
    volName: <redacted>_ubuntu-vm
  level: debug
  message: Skipping unmount as in use
timestamp: "2023-09-13T00:08:27.015324429+02:00"
type: logging

I can’t really tell what is going wrong, it seems like it just decides to try unmount at some point and then skips it because of it being in use?

ru-fu · September 13, 2023, 7:26am

I just compared this to what I see when starting a VM, and I get the same, but then it continues …

...
location: none
metadata:
  context:
    driver: zfs
    pool: big
    refCount: "1"
    volName: ui-vm
  level: debug
  message: Skipping unmount as in use
timestamp: "2023-09-13T09:19:41.193471635+02:00"
type: logging


location: none
metadata:
  context:
    path: /var/snap/lxd/common/lxd/logs/ui-vm/qemu.monitor
  level: debug
  message: QMP monitor started
timestamp: "2023-09-13T09:19:42.123663143+02:00"
type: logging


location: none
metadata:
  action: instance-started
  requestor:
    address: '@'
    protocol: unix
    username: rufu
  source: /1.0/instances/ui-vm
project: default
timestamp: "2023-09-13T09:19:42.282679423+02:00"
type: lifecycle
...

So I guess your hunch that it’s something QEMU related is correct …

amikhalitsyn · September 13, 2023, 7:46am

Hi @mikealloy

Which distro you have inside the VM?
Couldn’t you check what you can see lxc start <vmname> --console=vga here?

mikealloy · September 13, 2023, 1:54pm

That command hangs, this is what I see from doing lxc monitor

  context:
    id: 45e25786-ce95-443d-9f35-a7d80f0e1474
    local: /var/snap/lxd/common/lxd/unix.socket
    remote: '@'
  level: debug
  message: Event listener server handler started
timestamp: "2023-09-13T15:51:32.162886576+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T15:51:36.026551292+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/instances/ubuntu-vm?project=<redacted>
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T15:51:36.027567893+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/events?project=<redacted>
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T15:51:36.028448208+02:00"
type: logging


location: none
metadata:
  context:
    id: 74331288-b286-41d7-82ab-750b65ec0141
    local: /var/snap/lxd/common/lxd/unix.socket
    remote: '@'
  level: debug
  message: Event listener server handler started
timestamp: "2023-09-13T15:51:36.028593972+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: PUT
    protocol: unix
    url: /1.0/instances/ubuntu-vm/state?project=<redacted>
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T15:51:36.028718045+02:00"
type: logging


location: none
metadata:
  context:
    class: task
    description: Starting instance
    operation: 99722c26-768c-432b-bc6a-a1e57e2b43e0
    project: <redacted>
  level: debug
  message: New operation
timestamp: "2023-09-13T15:51:36.030043035+02:00"
type: logging


location: none
metadata:
  class: task
  created_at: "2023-09-13T15:51:36.029266786+02:00"
  description: Starting instance
  err: ""
  id: 99722c26-768c-432b-bc6a-a1e57e2b43e0
  location: none
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/ubuntu-vm?project=<redacted>
  status: Pending
  status_code: 105
  updated_at: "2023-09-13T15:51:36.029266786+02:00"
project: <redacted>
timestamp: "2023-09-13T15:51:36.030057332+02:00"
type: operation


location: none
metadata:
  context:
    instance: ubuntu-vm
    instanceType: virtual-machine
    project: <redacted>
    stateful: "false"
  level: debug
  message: Start started
timestamp: "2023-09-13T15:51:36.030116053+02:00"
type: logging


location: none
metadata:
  context:
    class: task
    description: Starting instance
    operation: 99722c26-768c-432b-bc6a-a1e57e2b43e0
    project: <redacted>
  level: debug
  message: Started operation
timestamp: "2023-09-13T15:51:36.030063233+02:00"
type: logging


location: none
metadata:
  context:
    action: start
    instance: ubuntu-vm
    project: <redacted>
    reusable: "false"
  level: debug
  message: Instance operation lock created
timestamp: "2023-09-13T15:51:36.03015191+02:00"
type: logging


location: none
metadata:
  context:
    ip: '@'
    method: GET
    protocol: unix
    url: /1.0/operations/99722c26-768c-432b-bc6a-a1e57e2b43e0?project=<redacted>
    username: root
  level: debug
  message: Handling API request
timestamp: "2023-09-13T15:51:36.030300439+02:00"
type: logging


location: none
metadata:
  class: task
  created_at: "2023-09-13T15:51:36.029266786+02:00"
  description: Starting instance
  err: ""
  id: 99722c26-768c-432b-bc6a-a1e57e2b43e0
  location: none
  may_cancel: false
  metadata: null
  resources:
    instances:
    - /1.0/instances/ubuntu-vm?project=<redacted>
  status: Running
  status_code: 103
  updated_at: "2023-09-13T15:51:36.029266786+02:00"
project: <redacted>
timestamp: "2023-09-13T15:51:36.030068613+02:00"
type: operation


location: none
metadata:
  context:
    driver: zfs
    instance: ubuntu-vm
    pool: <redacted>-project
    project: <redacted>
  level: debug
  message: MountInstance started
timestamp: "2023-09-13T15:51:36.030537585+02:00"
type: logging


location: none
metadata:
  context:
    dev: <redacted>-project/virtual-machines/<redacted>_ubuntu-vm.block
    driver: zfs
    pool: <redacted>-project
    volName: <redacted>_ubuntu-vm
  level: debug
  message: Activated ZFS volume
timestamp: "2023-09-13T15:51:36.614762007+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    instance: ubuntu-vm
    pool: <redacted>-project
    project: <redacted>
  level: debug
  message: MountInstance finished
timestamp: "2023-09-13T15:51:36.701796414+02:00"
type: logging


location: none
metadata:
  context:
    dev: <redacted>-project/virtual-machines/<redacted>_ubuntu-vm
    driver: zfs
    path: /var/snap/lxd/common/lxd/storage-pools/<redacted>-project/virtual-machines/<redacted>_ubuntu-vm
    pool: <redacted>-project
    volName: <redacted>_ubuntu-vm
  level: debug
  message: Mounted ZFS dataset
timestamp: "2023-09-13T15:51:36.701754094+02:00"
type: logging


location: none
metadata:
  context:
    installPath: /var/snap/lxd/common/lxd/virtual-machines/<redacted>_ubuntu-vm/config/lxd-agent
    instance: ubuntu-vm
    instanceType: virtual-machine
    project: <redacted>
    srcPath: /snap/lxd/25505/bin/lxd-agent
  level: debug
  message: Skipping lxd-agent install as unchanged
timestamp: "2023-09-13T15:51:36.701942008+02:00"
type: logging


location: none
metadata:
  context:
    device: eth0
    instance: ubuntu-vm
    instanceType: virtual-machine
    project: <redacted>
    type: nic
  level: debug
  message: Starting device
timestamp: "2023-09-13T15:51:36.704035352+02:00"
type: logging


location: none
metadata:
  context: {}
  level: debug
  message: 'Scheduler: network: tap181ad4b0 has been added: updating network priorities'
timestamp: "2023-09-13T15:51:36.705020063+02:00"
type: logging


location: none
metadata:
  context:
    device: root
    instance: ubuntu-vm
    instanceType: virtual-machine
    project: <redacted>
    type: disk
  level: debug
  message: Starting device
timestamp: "2023-09-13T15:51:36.709958315+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    instance: ubuntu-vm
    pool: <redacted>-project
    project: <redacted>
  level: debug
  message: UpdateInstanceBackupFile started
timestamp: "2023-09-13T15:51:36.881189526+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    pool: <redacted>-project
    refCount: "1"
    volName: <redacted>_ubuntu-vm
  level: debug
  message: Skipping unmount as in use
timestamp: "2023-09-13T15:51:36.882591632+02:00"
type: logging


location: none
metadata:
  context:
    driver: zfs
    instance: ubuntu-vm
    pool: <redacted>-project
    project: <redacted>
  level: debug
  message: UpdateInstanceBackupFile finished
timestamp: "2023-09-13T15:51:36.882605047+02:00"
type: logging

mikealloy · September 13, 2023, 1:56pm

Is there anyway I can execute the same qemu command that i posted above from the process created for starting the VM so I can possibly see any output from it?

EDIT:
After running snap run --shell lxd and executing the following commands i get this output:

qemu-system-x86_64 -S -name ubuntu-vm -uuid 45e86ae9-9963-4797-ab18-abea62d1c6f9 -daemonize -cpu host -nographic -serial chardev:console -nodefaults -no-user-config -sandbox on,obsolete=deny,elevateprivileges=allow,spawn=allow,resourcecontrol=deny -readconfig /var/snap/lxd/common/lxd/logs/<redacted>_ubuntu-vm/qemu.conf -spice unix=on,disable-ticketing=on,addr=/var/snap/lxd/common/lxd/logs/<redacted>_ubuntu-vm/qemu.spice -pidfile /var/snap/lxd/common/lxd/logs/<redacted>_ubuntu-vm/qemu.pid -D /var/snap/lxd/common/lxd/logs/<redacted>_ubuntu-vm/qemu.log -smbios type=2,manufacturer=Canonical Ltd.,product=LXD -runas lxd
qemu-system-x86_64: error while loading shared libraries: libceph-common.so.2: cannot open shared object file: No such file or directory

The library seems to exist though

tomp · September 13, 2023, 2:09pm

Can you do:

lxc delete <broken vm> -f

Then run:

lxc monitor --pretty

Then in a separate window run:

lxc launch <img> <vm> --console

Then we are interested in seeing the console output and the lxc monitor window output.

mikealloy · September 13, 2023, 2:15pm

Here is the output of lxc monitor --pretty for lxc launch <img> <vm> --console

DEBUG  [2023-09-13T16:13:40+02:00] Event listener server handler started         id=85bac3c7-0b54-4c82-b9e3-fbe2db1c219e local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2023-09-13T16:13:46+02:00] Handling API request                          ip=@ method=GET protocol=unix url=/1.0 username=root
DEBUG  [2023-09-13T16:13:46+02:00] Handling API request                          ip=@ method=GET protocol=unix url="/1.0/images/aliases/c2d0202b5ff7?project=<redacted>" username=root
DEBUG  [2023-09-13T16:13:46+02:00] Handling API request                          ip=@ method=GET protocol=unix url="/1.0/images/c2d0202b5ff7?project=<redacted>" username=root
DEBUG  [2023-09-13T16:13:46+02:00] Handling API request                          ip=@ method=GET protocol=unix url="/1.0/events?project=<redacted>" username=root
DEBUG  [2023-09-13T16:13:46+02:00] Event listener server handler started         id=7d2a84fc-2efd-4f83-9060-ff0752119609 local=/var/snap/lxd/common/lxd/unix.socket remote=@
DEBUG  [2023-09-13T16:13:46+02:00] Handling API request                          ip=@ method=POST protocol=unix url="/1.0/instances?project=<redacted>" username=root
DEBUG  [2023-09-13T16:13:46+02:00] Responding to instance create
DEBUG  [2023-09-13T16:13:46+02:00] New operation                                 class=task description="Creating instance" operation=e52d6260-ca41-432d-a354-dfa5c73310c8 project=<redacted>
DEBUG  [2023-09-13T16:13:46+02:00] Acquiring lock for image                      fingerprint=c2d0202b5ff71a73ba8d44be79df5e9a50b6b5e7259ebf77128ef4496491159c
DEBUG  [2023-09-13T16:13:46+02:00] Lock acquired for image                       fingerprint=c2d0202b5ff71a73ba8d44be79df5e9a50b6b5e7259ebf77128ef4496491159c
INFO   [2023-09-13T16:13:46+02:00] ID: e52d6260-ca41-432d-a354-dfa5c73310c8, Class: task, Description: Creating instance  CreatedAt="2023-09-13 16:13:46.666911232 +0200 CEST" Err= Location=none MayCancel=false Metadata="map[]" Resources="map[instances:[/1.0/instances/ubuntu-vm?project=<redacted>]]" Status=Pending StatusCode=Pending UpdatedAt="2023-09-13 16:13:46.666911232 +0200 CEST"
INFO   [2023-09-13T16:13:46+02:00] ID: e52d6260-ca41-432d-a354-dfa5c73310c8, Class: task, Description: Creating instance  CreatedAt="2023-09-13 16:13:46.666911232 +0200 CEST" Err= Location=none MayCancel=false Metadata="map[]" Resources="map[instances:[/1.0/instances/ubuntu-vm?project=<redacted>]]" Status=Running StatusCode=Running UpdatedAt="2023-09-13 16:13:46.666911232 +0200 CEST"
DEBUG  [2023-09-13T16:13:46+02:00] Started operation                             class=task description="Creating instance" operation=e52d6260-ca41-432d-a354-dfa5c73310c8 project=<redacted>
DEBUG  [2023-09-13T16:13:46+02:00] Instance operation lock created               action=create instance=ubuntu-vm project=<redacted> reusable=false
DEBUG  [2023-09-13T16:13:46+02:00] Handling API request                          ip=@ method=GET protocol=unix url="/1.0/operations/e52d6260-ca41-432d-a354-dfa5c73310c8?project=<redacted>" username=root
INFO   [2023-09-13T16:13:46+02:00] Creating instance                             ephemeral=false instance=ubuntu-vm instanceType=virtual-machine project=<redacted>
INFO   [2023-09-13T16:13:46+02:00] Action: instance-created, Source: /1.0/instances/ubuntu-vm?project=<redacted>  location=none storage-pool=<redacted>-project type=virtual-machine
INFO   [2023-09-13T16:13:46+02:00] Created instance                              ephemeral=false instance=ubuntu-vm instanceType=virtual-machine project=<redacted>
DEBUG  [2023-09-13T16:13:46+02:00] Adding device                                 device=root instance=ubuntu-vm instanceType=virtual-machine project=<redacted> type=disk
DEBUG  [2023-09-13T16:13:46+02:00] CreateInstanceFromImage started               driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:46+02:00] EnsureImage started                           driver=zfs fingerprint=c2d0202b5ff71a73ba8d44be79df5e9a50b6b5e7259ebf77128ef4496491159c pool=<redacted>-project
DEBUG  [2023-09-13T16:13:46+02:00] Checking image volume size                    driver=zfs fingerprint=c2d0202b5ff71a73ba8d44be79df5e9a50b6b5e7259ebf77128ef4496491159c pool=<redacted>-project
DEBUG  [2023-09-13T16:13:46+02:00] Setting image volume size                     driver=zfs fingerprint=c2d0202b5ff71a73ba8d44be79df5e9a50b6b5e7259ebf77128ef4496491159c pool=<redacted>-project size=10GiB
DEBUG  [2023-09-13T16:13:46+02:00] EnsureImage finished                          driver=zfs fingerprint=c2d0202b5ff71a73ba8d44be79df5e9a50b6b5e7259ebf77128ef4496491159c pool=<redacted>-project
DEBUG  [2023-09-13T16:13:46+02:00] Checking volume size                          driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:46+02:00] Set new volume size                           driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted> size=10GiB
DEBUG  [2023-09-13T16:13:46+02:00] Mounted ZFS dataset                           dev=<redacted>-project/virtual-machines/<redacted>_ubuntu-vm driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/<redacted>-project/virtual-machines/<redacted>_ubuntu-vm pool=<redacted>-project volName=<redacted>_ubuntu-vm
DEBUG  [2023-09-13T16:13:47+02:00] Unmounted ZFS dataset                         dev=<redacted>-project/virtual-machines/<redacted>_ubuntu-vm driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/<redacted>-project/virtual-machines/<redacted>_ubuntu-vm pool=<redacted>-project volName=<redacted>_ubuntu-vm
DEBUG  [2023-09-13T16:13:47+02:00] UpdateInstanceBackupFile started              driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:47+02:00] CreateInstanceFromImage finished              driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:47+02:00] Mounted ZFS dataset                           dev=<redacted>-project/virtual-machines/<redacted>_ubuntu-vm driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/<redacted>-project/virtual-machines/<redacted>_ubuntu-vm pool=<redacted>-project volName=<redacted>_ubuntu-vm
DEBUG  [2023-09-13T16:13:47+02:00] Success for operation                         class=task description="Creating instance" operation=e52d6260-ca41-432d-a354-dfa5c73310c8 project=<redacted>
DEBUG  [2023-09-13T16:13:47+02:00] Unmounted ZFS dataset                         dev=<redacted>-project/virtual-machines/<redacted>_ubuntu-vm driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/<redacted>-project/virtual-machines/<redacted>_ubuntu-vm pool=<redacted>-project volName=<redacted>_ubuntu-vm
DEBUG  [2023-09-13T16:13:47+02:00] UpdateInstanceBackupFile finished             driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
INFO   [2023-09-13T16:13:47+02:00] ID: e52d6260-ca41-432d-a354-dfa5c73310c8, Class: task, Description: Creating instance  CreatedAt="2023-09-13 16:13:46.666911232 +0200 CEST" Err= Location=none MayCancel=false Metadata="map[]" Resources="map[instances:[/1.0/instances/ubuntu-vm?project=<redacted>]]" Status=Success StatusCode=Success UpdatedAt="2023-09-13 16:13:46.666911232 +0200 CEST"
DEBUG  [2023-09-13T16:13:47+02:00] Instance operation lock finished              action=create err="<nil>" instance=ubuntu-vm project=<redacted> reusable=false
DEBUG  [2023-09-13T16:13:47+02:00] Handling API request                          ip=@ method=GET protocol=unix url="/1.0/instances/ubuntu-vm?project=<redacted>" username=root
DEBUG  [2023-09-13T16:13:47+02:00] Handling API request                          ip=@ method=PUT protocol=unix url="/1.0/instances/ubuntu-vm/state?project=<redacted>" username=root
DEBUG  [2023-09-13T16:13:47+02:00] New operation                                 class=task description="Starting instance" operation=e64341c8-d776-414e-9981-fdcbc92cdc19 project=<redacted>
DEBUG  [2023-09-13T16:13:47+02:00] Started operation                             class=task description="Starting instance" operation=e64341c8-d776-414e-9981-fdcbc92cdc19 project=<redacted>
DEBUG  [2023-09-13T16:13:47+02:00] Start started                                 instance=ubuntu-vm instanceType=virtual-machine project=<redacted> stateful=false
DEBUG  [2023-09-13T16:13:47+02:00] Instance operation lock created               action=start instance=ubuntu-vm project=<redacted> reusable=false
INFO   [2023-09-13T16:13:47+02:00] ID: e64341c8-d776-414e-9981-fdcbc92cdc19, Class: task, Description: Starting instance  CreatedAt="2023-09-13 16:13:47.853624909 +0200 CEST" Err= Location=none MayCancel=false Metadata="map[]" Resources="map[instances:[/1.0/instances/ubuntu-vm?project=<redacted>]]" Status=Running StatusCode=Running UpdatedAt="2023-09-13 16:13:47.853624909 +0200 CEST"
INFO   [2023-09-13T16:13:47+02:00] ID: e64341c8-d776-414e-9981-fdcbc92cdc19, Class: task, Description: Starting instance  CreatedAt="2023-09-13 16:13:47.853624909 +0200 CEST" Err= Location=none MayCancel=false Metadata="map[]" Resources="map[instances:[/1.0/instances/ubuntu-vm?project=<redacted>]]" Status=Pending StatusCode=Pending UpdatedAt="2023-09-13 16:13:47.853624909 +0200 CEST"
DEBUG  [2023-09-13T16:13:47+02:00] Handling API request                          ip=@ method=GET protocol=unix url="/1.0/operations/e64341c8-d776-414e-9981-fdcbc92cdc19?project=<redacted>" username=root
DEBUG  [2023-09-13T16:13:47+02:00] MountInstance started                         driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:48+02:00] Activated ZFS volume                          dev=<redacted>-project/virtual-machines/<redacted>_ubuntu-vm.block driver=zfs pool=<redacted>-project volName=<redacted>_ubuntu-vm
DEBUG  [2023-09-13T16:13:48+02:00] Mounted ZFS dataset                           dev=<redacted>-project/virtual-machines/<redacted>_ubuntu-vm driver=zfs path=/var/snap/lxd/common/lxd/storage-pools/<redacted>-project/virtual-machines/<redacted>_ubuntu-vm pool=<redacted>-project volName=<redacted>_ubuntu-vm
DEBUG  [2023-09-13T16:13:48+02:00] MountInstance finished                        driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:48+02:00] Installing lxd-agent                          installPath=/var/snap/lxd/common/lxd/virtual-machines/<redacted>_ubuntu-vm/config/lxd-agent instance=ubuntu-vm instanceType=virtual-machine project=<redacted> srcPath=/snap/lxd/25505/bin/lxd-agent
DEBUG  [2023-09-13T16:13:48+02:00] Generating NVRAM                              instance=ubuntu-vm instanceType=virtual-machine project=<redacted>
DEBUG  [2023-09-13T16:13:48+02:00] MountInstance started                         driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:48+02:00] MountInstance finished                        driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:48+02:00] UnmountInstance started                       driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:48+02:00] Skipping unmount as in use                    driver=zfs pool=<redacted>-project refCount=1 volName=<redacted>_ubuntu-vm
DEBUG  [2023-09-13T16:13:48+02:00] UnmountInstance finished                      driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:48+02:00] Starting device                               device=root instance=ubuntu-vm instanceType=virtual-machine project=<redacted> type=disk
DEBUG  [2023-09-13T16:13:49+02:00] UpdateInstanceBackupFile started              driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:49+02:00] UpdateInstanceBackupFile finished             driver=zfs instance=ubuntu-vm pool=<redacted>-project project=<redacted>
DEBUG  [2023-09-13T16:13:49+02:00] Skipping unmount as in use                    driver=zfs pool=<redacted>-project refCount=1 volName=<redacted>_ubuntu-vm

tomp · September 13, 2023, 2:41pm

Have you tried VMs on a dir type storage pool?

tomp · September 13, 2023, 2:42pm

Please also can i see lxc config show <instance> --expanded?

tomp · September 13, 2023, 2:51pm

Compared to a running VM on my system you are missing these log lines:

DEBUG  [2023-09-13T15:46:21+01:00] QMP monitor started                           path=/var/log/lxd/v1/qemu.monitor
DEBUG  [2023-09-13T15:46:21+01:00] Instance operation lock finished              action=start err="<nil>" instance=v1 project=default reusable=false
DEBUG  [2023-09-13T15:46:21+01:00] Start finished                                instance=v1 instanceType=virtual-machine project=default stateful=false

Suggesting that there’s an issue with connecting to QEMU’s QMP socket.

mikealloy · September 13, 2023, 2:54pm

I have not yet, i will give it a try later

mikealloy · September 13, 2023, 2:55pm

Here is the VM config

architecture: x86_64
config:
  image.architecture: amd64
  image.description: Ubuntu mantic amd64 (20230911_07:42)
  image.os: Ubuntu
  image.release: mantic
  image.serial: "20230911_07:42"
  image.type: disk-kvm.img
  image.variant: default
  volatile.base_image: c2d0202b5ff71a73ba8d44be79df5e9a50b6b5e7259ebf77128ef4496491159c
  volatile.cloud-init.instance-id: 9385a222-3702-4cd2-98fd-6ebe88156321
  volatile.uuid: 964d8e31-f97a-455e-b5a0-129dc086e6e0
  volatile.uuid.generation: 964d8e31-f97a-455e-b5a0-129dc086e6e0
  volatile.vsock_id: "3587631750"
devices:
  root:
    path: /
    pool: <redacted>-project
    type: disk
ephemeral: false
profiles:
- default
stateful: false
description: ""

mikealloy · September 13, 2023, 2:58pm

I suppose that is all handled by the lxd’s snap package right? Or do I perhaps need any extra configuration on my host machine involving qemu.

tomp · September 13, 2023, 3:08pm

Yes, qemu is packaged, but we are dependent on certain kernel functionality.
So if qemu is hanging for some reason it maybe because of the host kernel.
We’ve seen various hangs related to io_uring in the past.

mikealloy · September 13, 2023, 3:28pm

Thanks for that information, I have just searched about that, and apparently there is people saying io_uring is available on linux kernel versions 5.1 and upwards, and I just checked my kernel version and i appear to be running 4.18.

I will try upgrading my host machine and see what happens

tomp · September 13, 2023, 3:47pm

Also check sudo dmesg for any signs of a kernel crash/hang issue.