search

canonical / multipass

Multipass orchestrates virtual Ubuntu instances
https://multipass.run
GNU General Public License v3.0
7.71k stars 641 forks source link

`multipass launch charm-dev` times out, although machine is created #3310

Closed mmkay closed 9 months ago

mmkay commented 9 months ago

Describe the bug Launching multipass machine based on charm-dev blueprint times out. The created machine is however accessible and functional.

To Reproduce

$ multipass launch --cpus 4 --memory 8G --disk 30G --name charm-dev-vm charm-dev
launch failed: The following errors occurred:
timed out waiting for initialization to complete
$ multipass shell charm-dev-vm
Welcome to Ubuntu 22.04.3 LTS (GNU/Linux 5.15.0-87-generic x86_64)

Expected behavior Initialization should finish.

Logs

Nov 20 11:04:05 wanderer multipassd[995]: Loading "anbox-cloud-appliance" v1
Nov 20 11:04:05 wanderer multipassd[995]: Loading "charm-dev" v1
Nov 20 11:04:05 wanderer multipassd[995]: Loading "docker" v1
Nov 20 11:04:05 wanderer multipassd[995]: Loading "jellyfin" v1
Nov 20 11:04:05 wanderer multipassd[995]: Loading "minikube" v1
Nov 20 11:04:05 wanderer multipassd[995]: Loading "ros-noetic" v1
Nov 20 11:04:05 wanderer multipassd[995]: Loading "ros2-humble" v1
Nov 20 11:04:05 wanderer multipassd[995]: [18415] started: qemu-system-x86_64 --version
Nov 20 11:04:05 wanderer multipassd[995]: Loading Blueprint "charm-dev", version v1
Nov 20 11:04:12 wanderer multipassd[995]: Applied AppArmor policy: multipass.qemu-img
Nov 20 11:04:12 wanderer multipassd[995]: [18437] started: qemu-img info /var/snap/multipass/common/cache/multipassd/vault/images/jammy-20231026/ubuntu-22.04-server-cloudimg-amd64.img
Nov 20 11:04:12 wanderer multipassd[995]: Applied AppArmor policy: multipass.qemu-img
Nov 20 11:04:12 wanderer multipassd[995]: [18445] started: qemu-img resize /var/snap/multipass/common/data/multipassd/vault/instances/charm-dev-vm/ubuntu-22.04-server-cloudimg-amd64.img 32212254720
Nov 20 11:04:13 wanderer multipassd[995]: [18450] started: qemu-img snapshot -l /var/snap/multipass/common/data/multipassd/vault/instances/charm-dev-vm/ubuntu-22.04-server-cloudimg-amd64.img
Nov 20 11:04:13 wanderer multipassd[995]: process working dir '/snap/multipass/10899/qemu'
Nov 20 11:04:13 wanderer multipassd[995]: process program 'qemu-system-x86_64'
Nov 20 11:04:13 wanderer multipassd[995]: process arguments '-bios, OVMF.fd, --enable-kvm, -cpu, host, -nic, tap,ifname=tap-a5daa0d07d1,script=no,downscript=no,model=virtio-net-pci,mac=52:54:00:08:aa:86, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/charm-dev-vm/ubuntu-22.04-server-cloudimg-amd64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 4, -m, 8192M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/snap/multipass/common/data/multipassd/vault/instances/charm-dev-vm/cloud-init-config.iso'
Nov 20 11:04:13 wanderer multipassd[995]: [18467] started: qemu-system-x86_64 -nographic -dump-vmstate /tmp/multipassd.eYInqs
Nov 20 11:04:13 wanderer multipassd[995]: Applied AppArmor policy: multipass.charm-dev-vm.qemu-system-x86_64
Nov 20 11:04:13 wanderer multipassd[995]: process state changed to Starting
Nov 20 11:04:13 wanderer multipassd[995]: process state changed to Running
Nov 20 11:04:13 wanderer multipassd[995]: [18469] started: qemu-system-x86_64 -bios OVMF.fd --enable-kvm -cpu host -nic tap,ifname=tap-a5daa0d07d1,script=no,downscript=no,model=virtio-net-pci,mac=52:54:00:08:aa:86 -device virtio-scsi-pci,id=scsi0 -drive file=/var/snap/multipass/common/data/multipassd/vault/instances/charm-dev-vm/ubuntu-22.04-server-cloudimg-amd64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 4 -m 8192M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/snap/multipass/common/data/multipassd/vault/instances/charm-dev-vm/cloud-init-config.iso
Nov 20 11:04:13 wanderer multipassd[995]: process started
Nov 20 11:04:13 wanderer multipassd[995]: Waiting for SSH to be up
Nov 20 11:04:13 wanderer multipassd[995]: QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 0, "major": 8}, "package": ""}, "capabilities": ["oob"]}}
Nov 20 11:04:13 wanderer multipassd[995]: QMP: {"return": {}}
Nov 20 11:04:15 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700474655, "microseconds": 260680}, "event": "RTC_CHANGE", "data": {"offset": -1, "qom-path": "/machine/unattached/device[14]"}}
Nov 20 11:04:16 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700474655, "microseconds": 288351}, "event": "RTC_CHANGE", "data": {"offset": -1, "qom-path": "/machine/unattached/device[14]"}}
Nov 20 11:04:21 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700474661, "microseconds": 378927}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[25]/virtio-backend"}}
Nov 20 11:04:24 wanderer dnsmasq-dhcp[1406]: DHCPDISCOVER(mpqemubr0) 52:54:00:08:aa:86
Nov 20 11:04:24 wanderer dnsmasq-dhcp[1406]: DHCPOFFER(mpqemubr0) 10.54.224.95 52:54:00:08:aa:86
Nov 20 11:04:24 wanderer dnsmasq-dhcp[1406]: DHCPREQUEST(mpqemubr0) 10.54.224.95 52:54:00:08:aa:86
Nov 20 11:04:24 wanderer dnsmasq-dhcp[1406]: DHCPACK(mpqemubr0) 10.54.224.95 52:54:00:08:aa:86 charm-dev-vm
Nov 20 11:04:26 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:27 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:28 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:29 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:30 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:31 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:32 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:33 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:34 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:35 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:36 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:37 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:38 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:39 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:40 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:41 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:42 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:43 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:44 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:45 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:46 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:47 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:48 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:50 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:51 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:52 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:53 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:54 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:55 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:04:55 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700474695, "microseconds": 508623}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[14]"}}
Nov 20 11:04:56 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'

[5 MIN OF SAME LOG LINES OMITTED FOR CLARITY]

Nov 20 11:09:13 wanderer multipassd[995]: ssh failed to authenticate: 'Socket error: disconnected'
Nov 20 11:09:14 wanderer multipassd[995]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'

...

Nov 20 11:15:54 wanderer multipassd[995]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Nov 20 11:15:54 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700475354, "microseconds": 526240}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[14]"}}
Nov 20 11:15:55 wanderer multipassd[995]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Nov 20 11:15:56 wanderer multipassd[995]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'

...

Nov 20 11:24:25 wanderer multipassd[995]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Nov 20 11:24:26 wanderer multipassd[995]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Nov 20 11:26:53 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700476013, "microseconds": 514688}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[14]"}}
Nov 20 11:37:52 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700476672, "microseconds": 525515}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[14]"}}
Nov 20 11:48:51 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700477331, "microseconds": 472762}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[14]"}}
Nov 20 11:59:50 wanderer multipassd[995]: QMP: {"timestamp": {"seconds": 1700477990, "microseconds": 491018}, "event": "RTC_CHANGE", "data": {"offset": 0, "qom-path": "/machine/unattached/device[14]"}}

Additional info

Name: charm-dev State: Running IPv4: 10.54.224.17 10.1.157.64 Release: Ubuntu 22.04.3 LTS Image hash: 054db2d88c45 (Ubuntu 22.04 LTS) CPU(s): 4 Load: 0.31 0.15 0.05 Disk usage: 13.1GiB out of 48.4GiB Memory usage: 985.7MiB out of 11.7GiB Mounts: --

Name: charm-dev-vm State: Running IPv4: 10.54.224.95 10.42.163.1 10.1.64.128 Release: Ubuntu 22.04.3 LTS Image hash: 054db2d88c45 (Ubuntu 22.04 LTS) CPU(s): 4 Load: 0.53 0.42 0.43 Disk usage: 9.0GiB out of 29.0GiB Memory usage: 1.7GiB out of 7.7GiB Mounts: --

Name: deb-dev State: Stopped IPv4: -- Release: -- Image hash: 054db2d88c45 (Ubuntu 22.04 LTS) CPU(s): -- Load: -- Disk usage: -- Memory usage: -- Mounts: --

- `multipass get local.driver`

$ multipass get local.driver qemu


**Additional context**

@tmihoc also had the same issue.
luis4a0 commented 9 months ago

Hi @mmkay, thanks for reporting! One thing that might be happening here is that the default timeout for charm-dev is too small (it is currently 20 minutes). Can you please try adding the parameter --timeout 3600? This way, it will fail only after one hour.

mmkay commented 9 months ago

Hi @luis4a0 - longer timeout seems to do the trick. Based on the logs it looks like it took 21 minutes to start on my setup.

tmihoc commented 9 months ago

Hi @luis4a0 , is there any way to increase the timeout by default? If the issue is general, then the fix should be general too. (Note: I don't know if me experiencing this issue multiple times and now @mmkay encountering it too counts as general. I'll leave it up to you to decide.)

luis4a0 commented 9 months ago

Hi! Thanks for testing @mmkay! @tmihoc yes, one possibility is to increase the timeout. Slowness usually comes from slow download speeds (not only from Ubuntu repositories: also snaps, PPAs and third-party sites can be slow).

However, examining the charm-dev definition, I see that many things must be downloaded and installed on the instance. I think thus that increasing a bit the timeout would solve the timeout in some cases. In addition, we should be maybe more verbose in the failure message on Multipass.

tmihoc commented 9 months ago

Awesome, thanks, @luis4a0 !

tmihoc commented 9 months ago

@luis4a0 Not sure if related to this, but for the past few days I've also been getting this:

$ multipass shell test-vm
shell failed: ssh failed to authenticate: 'Socket error: disconnected'

If I try again just a moment later, it works. :shrug:

luis4a0 commented 9 months ago

Hey @tmihoc! It may be the same issue. You created the instance, it timed out, but it was finishing the initialization in the background. And It could'nt connect until it finished. That's one possibility, but we can't know exactly what did it happen.

ricab commented 9 months ago

Hi @tmihoc, I believe that is another manifestation of https://github.com/canonical/multipass/issues/3252. We've already fixed it, but we haven't released yet.

Depending on the environment, this can unfortunately happen repeatedly and get annoying. If that is the case, of if you just feel like it, you can get the fix in the "edge" snap channel.