launch failed: Remote "" is unknown or unreachable — then `multipass launch` magically starts working 15min after boot!

[holta]

Describe the bug

Since December/January, several people have confirmed that the Edge channel version of multipass can no longer run multipass launch after every boot. multipass launch fails when run within 15min of boot. Several have confirmed this, and we each assumed the bug would go away. But 4+ months later it has not (hence this bug report!)

The error message is: launch failed: Remote "" is unknown or unreachable.

One workaround (annoying, but it works) is to run: snap restart multipass

Additional info

Host PC details:

# cat /etc/issue
Ubuntu 22.04.4 LTS \n \l

# multipass version
multipass   1.14.0-dev.1600+g2701b66b
multipassd  1.14.0-dev.1600+g2701b66b

# multipass get local.driver
lxd

# multipass get local.bridged-network
enp1s0

# lxd --version
5.20

# snap info lxd
...
installed:          5.20-f3dd836              (27049) 155MB -

# uname -a
Linux 126-u2204-desk 6.5.0-26-generic #26~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Tue Mar 12 10:22:43 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

Additional context

ASIDE: Will we be able test this on pre-release builds of Multipass on Windows in future, as hinted at... ?

• Cannot reboot instances on Windows 10 or 11 if /etc/hostname changes (within the instance) #3346 (comment)

Likely Related:

• launch failed: Remote "" is unknown or unreachable.  #1853
• launch failed: Remote "" is unknown or unreachable. #3074

[townsend2010]

Hi @holta!

We have not seen this issue. We occasionally get reports of this same symptom on releases versions of Multipass, but that is usually specific to the user's host system and/or network.

To help us better diagnose the issue, could you please provide a full journal from boot time to when you see this symptom? Thanks!

[holta]

full journal from boot time

multipass launch fails every time after booting:

# multipass launch
launch failed: Remote "" is unknown or unreachable.

# journalctl -b -u 'snap.multipass*'
Apr 05 16:16:37 126-u2204-desk systemd[1]: Started Service for snap application multipass.multipassd.
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Error getting https://codeload.github.com/canonical/multipass-blueprints/zip/refs/heads/main: Host codeload.github.com not found - trying cache.
Apr 05 16:16:39 126-u2204-desk multipassd[714]: gRPC listening on unix:/var/snap/multipass/common/multipass_socket
Apr 05 16:16:39 126-u2204-desk multipassd[714]: fetch manifest periodically
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Cannot retrieve headers for https://cdimage.ubuntu.com/ubuntu-core/16/stable/current/ubuntu-core-16-amd64.img.xz: Host cdimage.ubuntu.com not found
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Cannot retrieve headers for https://cdimage.ubuntu.com/ubuntu-core/20/stable/current/ubuntu-core-20-amd64.img.xz: Host cdimage.ubuntu.com not found
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Cannot retrieve headers for https://cdimage.ubuntu.com/ubuntu-core/22/stable/current/ubuntu-core-22-amd64.img.xz: Host cdimage.ubuntu.com not found
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Cannot retrieve headers for https://cdimage.ubuntu.com/ubuntu-core/18/stable/current/ubuntu-core-18-amd64.img.xz: Host cdimage.ubuntu.com not found
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Error getting https://cloud-images.ubuntu.com/buildd/daily/streams/v1/index.json: Host cloud-images.ubuntu.com not found - trying cache.
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Error getting https://cloud-images.ubuntu.com/releases/streams/v1/index.json: Host cloud-images.ubuntu.com not found - trying cache.
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Error getting https://cloud-images.ubuntu.com/daily/streams/v1/index.json: Host cloud-images.ubuntu.com not found - trying cache.
Apr 05 16:16:39 126-u2204-desk multipassd[714]: Could not update manifest: failed to download from 'https://cdimage.ubuntu.com/ubuntu-core/16/stable/current/ubuntu-core-16-amd64.img.xz': Host cdimage.ubuntu.com not found
Apr 05 16:16:46 126-u2204-desk multipassd[714]: Using the 'multipass' storage pool.
Apr 05 16:16:46 126-u2204-desk multipassd[714]: Starting Multipass 1.14.0-dev.1600+g2701b66b
Apr 05 16:16:46 126-u2204-desk multipassd[714]: Daemon arguments: /snap/multipass/12063/bin/multipassd --verbosity debug --logger platform
Apr 05 16:20:50 126-u2204-desk systemd[1]: Started snap.multipass.multipass-13d6fc67-581c-4732-8249-0189fd0a91b2.scope.
Apr 05 16:20:51 126-u2204-desk systemd[1]: snap.multipass.multipass-13d6fc67-581c-4732-8249-0189fd0a91b2.scope: Deactivated successfully.

Further logs show applying of the workaround:

# snap restart multipass
Restarted.

# multipass launch
Launched: humorous-poodle

# journalctl -b -u 'snap.multipass*'
...
Apr 05 16:31:40 126-u2204-desk multipassd[714]: fetch manifest periodically
Apr 05 16:38:05 126-u2204-desk multipassd[714]: Received signal 15 (Terminated)
Apr 05 16:38:05 126-u2204-desk multipassd[714]: Goodbye!
Apr 05 16:38:05 126-u2204-desk systemd[1]: Stopping Service for snap application multipass.multipassd...
Apr 05 16:38:06 126-u2204-desk systemd[1]: snap.multipass.multipassd.service: Deactivated successfully.
Apr 05 16:38:06 126-u2204-desk systemd[1]: Stopped Service for snap application multipass.multipassd.
Apr 05 16:38:06 126-u2204-desk systemd[1]: snap.multipass.multipassd.service: Consumed 2.567s CPU time.
Apr 05 16:38:06 126-u2204-desk systemd[1]: Started Service for snap application multipass.multipassd.
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Loading "anbox-cloud-appliance" v1
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Loading "charm-dev" v1
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Loading "docker" v1
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Loading "jellyfin" v1
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Loading "minikube" v1
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Loading "ros-noetic" v1
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Loading "ros2-humble" v1
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: gRPC listening on unix:/var/snap/multipass/common/multipass_socket
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: fetch manifest periodically
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Using the 'multipass' storage pool.
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Starting Multipass 1.14.0-dev.1600+g2701b66b
Apr 05 16:38:06 126-u2204-desk multipassd[1928]: Daemon arguments: /snap/multipass/12063/bin/multipassd --verbosity debug --logger platform
Apr 05 16:39:01 126-u2204-desk systemd[1]: Started snap.multipass.multipass-8d10f7fb-0ee1-4262-ba05-d262e920627a.scope.
Apr 05 16:39:01 126-u2204-desk multipassd[1928]: Using the 'multipass' storage pool.
Apr 05 16:39:01 126-u2204-desk multipassd[1928]: Creating instance with image id: da10d667adf5588f2540afcbbaf0bb91c529719003f53fdc1f4d589fb407d0aa
Apr 05 16:39:07 126-u2204-desk multipassd[1928]: Waiting for SSH to be up
Apr 05 16:39:29 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:32 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:33 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:34 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:36 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:37 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:38 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:39 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:40 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:42 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:43 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:44 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:45 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:46 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:47 126-u2204-desk multipassd[1928]: Executing '[ -e /var/lib/cloud/instance/boot-finished ]'
Apr 05 16:39:47 126-u2204-desk systemd[1]: snap.multipass.multipass-8d10f7fb-0ee1-4262-ba05-d262e920627a.scope: Deactivated successfully.

Just FYI: Multipass's "How to access logs" instructions at https://multipass.run/docs/accessing-logs say to run journalctl --unit 'snap.multipass*' but this turns out to be problematic and unhelpful in cases like this. That command is projected to take an hour-or-more to complete (any idea why it seems to be unpacking / unzipping old Multipass log files from the past ~12 months painfully slowly, in what appears to be a very inefficient manner?) On the bright side, people who happen to know about journalctl -b (i.e. journal from boot time) can avoid most of this nightmare. 🙏

[holta]

@townsend2010 are the above logs sufficient, to help you diagnose?

[townsend2010]

Hi @holta!

I have a hunch of what the problem is, but I really need to examine full logs of the boot including the multipass log entries. By full log, I mean everything that happens during the boot.

My suspicion is that there is a race between all of the host networking coming up and Multipass starting. It looks to me that at the very least, the host does not have DNS running yet when Multipass starts and the way Qt networking works is that it caches the networking info (such as DNS), so if DNS is not configured yet, then Qt won't be either.

[holta]

full logs of the boot including the multipass log entries. By full log, I mean everything that happens during the boot.

Got it, and thanks for explaining what may be happening. 💯

Here are 2344 lines from boot (journalctl -b) posted to a pastebin:

• http://sprunge.us/livybx
• http://sprunge.us/livybx?en (with line numbers)

Lines 2343 and 2344 are a result of multipass launch failing to run. (Just LMK if you need anything else!)

[townsend2010]

Hi @holta!

Thank you for the detailed logs. This is helpful. It does look like there is a potential race between the networking being fully up (such as DNS not configured yet) and Multipass starting.

Upon some initial investigation, it looks like Qt caches the current network settings and will use that for the duration of the QNetworkAccessManager's lifetime. We instantiate this when the daemon starts. We have not made any changes in this area in the time frame you began to see this problem, so it's possible something is causing your systems to take a little longer for networking to be completely up and fully configured.

Qt networking is not very robust when it comes to changes in networking after it has been instantiated. We will have to think about if there is anything we can do to help mitigate this problem, but I don't have an answer at this time.

[holta]

Qt networking is not very robust when it comes to changes in networking after it has been instantiated.

@townsend2010 any chance upgrading to the imminent Ubuntu 24.04 might help? Or reveal clues?

(Just FYI this not only occurs on this generic/vanilla Ubuntu 22.04 PC — but the same exact problem
also began in December/January on a very different brand / different manufacturer PC.)

[townsend2010]

Hi @holta,

I'm not sure if upgrading to 22.04 will help or not. Regarding a very different brand PC, is it running the same version of Ubuntu or something else?

In the meantime, as an experiment that hopefully will prove my theory, please try the following:
$ sudo systemctl edit snap.multipass.multipassd.service
Add the following to the override file:

[Unit]
After=
After=snap-multipass-12153.mount network.target snapd.apparmor.service systemd-resolved.service

Ensure the number contained in snap-multipass-xxxxx.mount matches what's list below in the file for the After= line.

Reboot the machine and see if this helps. This is supposed to ensure multipass starts after systemd-resolved is started which should help with making sure DNS is set up on the host first.

[zchem]

Doesn't work for me.

$ sudo systemctl edit snap.multipass.multipassd.service

### Editing /etc/systemd/system/snap.multipass.multipassd.service.d/override.conf
### Anything between here and the comment below will become the contents of the drop-in file

[Unit]
After=
After=snap-multipass-12146.mount network.target snapd.apparmor.service systemd-resolved.service

### Edits below this comment will be discarded

### /etc/systemd/system/snap.multipass.multipassd.service
# [Unit]
# # Auto-generated, DO NOT EDIT
# Description=Service for snap application multipass.multipassd
# Requires=snap-multipass-12146.mount
# Wants=network.target
# After=snap-multipass-12146.mount network.target snapd.apparmor.service
# X-Snappy=yes
# 
# [Service]
# EnvironmentFile=-/etc/environment
# ExecStart=/usr/bin/snap run multipass.multipassd
# SyslogIdentifier=multipass.multipassd
# Restart=on-failure
# WorkingDirectory=/var/snap/multipass/12146
# TimeoutStopSec=300
# Type=simple
# 
# [Install]
# WantedBy=multi-user.target

$ multipass launch -n vm1
launch failed: Remote "" is unknown or unreachable.

$ ping -c 1 cloud-images.ubuntu.com
PING cloud-images.ubuntu.com (185.125.190.40) 56(84) bytes of data.
64 bytes from https-services.aerodent.canonical.com (185.125.190.40): icmp_seq=1 ttl=53 time=240 ms

--- cloud-images.ubuntu.com ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 239.776/239.776/239.776/0.000 ms

$ ping -c 1 cdimage.ubuntu.com
PING cdimage.ubuntu.com (185.125.190.37) 56(84) bytes of data.
64 bytes from https-services.actiontoad.canonical.com (185.125.190.37): icmp_seq=1 ttl=49 time=205 ms

--- cdimage.ubuntu.com ping statistics ---
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 205.023/205.023/205.023/0.000 ms

$ cat /etc/os-release 
PRETTY_NAME="Ubuntu 23.10"
NAME="Ubuntu"
VERSION_ID="23.10"
VERSION="23.10 (Mantic Minotaur)"
VERSION_CODENAME=mantic
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=mantic
LOGO=ubuntu-logo

Attaching multipass logs.
multipass.txt

[zchem]

I'm trying to compare the strace output of when it's not working vs when it's working. Seems like multipass is writing some info to /run/user/1000/bus and trying it fails when it try to receive info from it later?

[holta]

Doesn't work for me.

1. Likewise 😿. Thanks @zchem for confirming!

2. Logs:

   • http://sprunge.us/UZ4Gfw
   • http://sprunge.us/UZ4Gfw?en (with line numbers)

3. Curiously multipass launch suddenly starts working "exactly ~15 min" after boot.

   It begins to work immediately after fetch manifest periodically appears in logs like journalctl -b -u snap.multipass.multipassd.service

   All of which reminds me I had the same problem prior to Dec 2023, and thought the problem was almost randomly intermittent, when I likely didn't realize that multipass launch magically comes to life 15min after boot (-:

   @townsend2010 probably already knew this (still, does confirmation provide any new hints?!)

4. Just FYI for @townsend2010, systemd's override.conf (not that it solved the problem ;) can in fact be made shorter:

   # cat /etc/systemd/system/snap.multipass.multipassd.service.d/override.conf
   [Unit]
   After=systemd-resolved.service
   
   # systemctl daemon-reload
   
   # systemctl show snap.multipass.multipassd.service | grep After=
   After=network.target systemd-journald.socket system.slice -.mount snap-multipass-12063.mount sysinit.target 
   snapd.apparmor.service systemd-resolved.service basic.target
   

   The reason is that After= is a systemd "dependency" — meaning that it cannot be reset to an empty list — only additional values can be added: https://unix.stackexchange.com/questions/398540/how-to-override-systemd-unit-file-settings/468067#468067