[Solved (kinda)] Multipass Failing to Launch VM (core18, beta & edge)

snapcraft
1

I am attempting to build a Snap, however Multipass is failing to launch the VM to do so. I tried both via snapcraft and multipass launch, and sadly neither is working. It looks like the Multipass VM is attempting to make a network connection, but fails upon timeout.

Here are the logs from snap logs -f multipass:

2019-04-03T21:15:50Z dnsmasq-dhcp[22929]: DHCPOFFER(mpqemubr0) 10.64.37.90 52:54:00:5f:fa:50
2019-04-03T21:15:50Z dnsmasq-dhcp[22929]: DHCPDISCOVER(mpqemubr0) 52:54:00:5f:fa:50
2019-04-03T21:15:50Z dnsmasq-dhcp[22929]: DHCPOFFER(mpqemubr0) 10.64.37.90 52:54:00:5f:fa:50
2019-04-03T21:15:50Z dnsmasq-dhcp[22929]: DHCPREQUEST(mpqemubr0) 10.64.37.90 52:54:00:5f:fa:50
2019-04-03T21:15:50Z dnsmasq-dhcp[22929]: DHCPACK(mpqemubr0) 10.64.37.90 52:54:00:5f:fa:50 enjoyed-slug
2019-04-03T21:16:08Z multipassd[22586]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
2019-04-03T21:18:09Z multipassd[22586]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
2

Hi @easthighNerd,

The Metrics error is benign in this case and has no bearing on the instance running. It looks like you are getting an IP address for the instance named enjoyed-slug. What does multipass list show? Also, could you include more logs by doing journalctl -u snap.multipass.*?

Thanks,
Chris

3

multipass list:

Name                    State             IPv4             Release
enjoyed-slug            STOPPED           --               Ubuntu Snapcraft builder for Core 18
regular-troll           UNKNOWN           --               Ubuntu Snapcraft builder for Core 18
hearty-lobster          STOPPED           --               Ubuntu Snapcraft builder for Core 18
snapcraft-etcher        STOPPED           --               Ubuntu Snapcraft builder for Core 18

journalctl -u snap.multipass.multipassd.service:

-- Logs begin at Tue 2019-02-26 17:01:02 EST, end at Thu 2019-04-04 09:59:30 EDT. --
Apr 03 16:17:18 Lenovo-ThinkPad-T420s systemd[1]: Started Service for snap application multipass.multipassd.
Apr 03 16:17:20 Lenovo-ThinkPad-T420s multipassd[11178]: Unable to determine subnet for the mpqemubr0 subnet
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq[11560]: started, version 2.75 cachesize 150
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq[11560]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCP, IP range 10.64.37.2 -- 10.64.37.254, lease time infinite
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCP, sockets bound exclusively to interface mpqemubr0
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq[11560]: reading /etc/resolv.conf
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq[11560]: using nameserver 103.86.99.99#53
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq[11560]: using nameserver 103.86.96.96#53
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq[11560]: read /etc/hosts - 3 addresses
Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq[11560]: cannot read /var/snap/multipass/common/data/multipassd/network/dnsmasq.hosts: No such file or directory
Apr 03 16:17:22 Lenovo-ThinkPad-T420s multipassd[11178]: gRPC listening on unix:/run/multipass_socket, SSL:on
Apr 03 16:17:22 Lenovo-ThinkPad-T420s multipassd[11178]: QIODevice::write (QFile, "/var/snap/multipass/common/cache/multipassd/vault/multipassd-image-records.json"): device not open
Apr 03 16:40:52 Lenovo-ThinkPad-T420s multipassd[11178]: process working dir '/snap/multipass/716/qemu'
Apr 03 16:40:52 Lenovo-ThinkPad-T420s multipassd[11178]: process program 'qemu-system-x86_64'
Apr 03 16:40:52 Lenovo-ThinkPad-T420s multipassd[11178]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/snapcraft-etcher/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/snapcraft-etcher/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 2, -m, 2048M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:0c:19:d3, -netdev, tap,id=hostnet0,ifname=tap-da2f767773a,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 16:40:59 Lenovo-ThinkPad-T420s multipassd[11178]: process state changed to Starting
Apr 03 16:40:59 Lenovo-ThinkPad-T420s multipassd[11178]: process state changed to Running
Apr 03 16:40:59 Lenovo-ThinkPad-T420s multipassd[11178]: process started
Apr 03 16:41:10 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPDISCOVER(mpqemubr0) 52:54:00:0c:19:d3
Apr 03 16:41:10 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPOFFER(mpqemubr0) 10.64.37.151 52:54:00:0c:19:d3
Apr 03 16:41:10 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPDISCOVER(mpqemubr0) 52:54:00:0c:19:d3
Apr 03 16:41:10 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPOFFER(mpqemubr0) 10.64.37.151 52:54:00:0c:19:d3
Apr 03 16:41:10 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPREQUEST(mpqemubr0) 10.64.37.151 52:54:00:0c:19:d3
Apr 03 16:41:10 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPACK(mpqemubr0) 10.64.37.151 52:54:00:0c:19:d3 snapcraft-etcher
Apr 03 16:45:59 Lenovo-ThinkPad-T420s multipassd[11178]: [143B blob data]
Apr 03 16:45:59 Lenovo-ThinkPad-T420s multipassd[11178]: [21B blob data]
Apr 03 16:46:20 Lenovo-ThinkPad-T420s multipassd[11178]: Cannot open ssh session on "snapcraft-etcher" shutdown: ssh connection failed: 'Timeout connecting to 10.64.37.151'
Apr 03 16:46:20 Lenovo-ThinkPad-T420s multipassd[11178]: Shutdown request delayed for 10 minutes
Apr 03 16:50:08 Lenovo-ThinkPad-T420s multipassd[11178]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 16:50:40 Lenovo-ThinkPad-T420s multipassd[11178]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 16:51:45 Lenovo-ThinkPad-T420s multipassd[11178]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 16:52:07 Lenovo-ThinkPad-T420s multipassd[11178]: process working dir '/snap/multipass/716/qemu'
Apr 03 16:52:07 Lenovo-ThinkPad-T420s multipassd[11178]: process program 'qemu-system-x86_64'
Apr 03 16:52:07 Lenovo-ThinkPad-T420s multipassd[11178]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/hearty-lobster/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/hearty-lobster/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:90:ee:69, -netdev, tap,id=hostnet0,ifname=tap-578a7d7d665,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 16:52:08 Lenovo-ThinkPad-T420s multipassd[11178]: process state changed to Starting
Apr 03 16:52:08 Lenovo-ThinkPad-T420s multipassd[11178]: process state changed to Running
Apr 03 16:52:08 Lenovo-ThinkPad-T420s multipassd[11178]: process started
Apr 03 16:52:19 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPDISCOVER(mpqemubr0) 52:54:00:90:ee:69
Apr 03 16:52:19 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPOFFER(mpqemubr0) 10.64.37.102 52:54:00:90:ee:69
Apr 03 16:52:19 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPDISCOVER(mpqemubr0) 52:54:00:90:ee:69
Apr 03 16:52:19 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPOFFER(mpqemubr0) 10.64.37.102 52:54:00:90:ee:69
Apr 03 16:52:19 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPREQUEST(mpqemubr0) 10.64.37.102 52:54:00:90:ee:69
Apr 03 16:52:19 Lenovo-ThinkPad-T420s dnsmasq-dhcp[11560]: DHCPACK(mpqemubr0) 10.64.37.102 52:54:00:90:ee:69 hearty-lobster
Apr 03 16:53:46 Lenovo-ThinkPad-T420s multipassd[11178]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 16:57:08 Lenovo-ThinkPad-T420s multipassd[11178]: [143B blob data]
Apr 03 16:57:08 Lenovo-ThinkPad-T420s multipassd[11178]: [21B blob data]
Apr 03 16:57:49 Lenovo-ThinkPad-T420s multipassd[11178]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:01:08 Lenovo-ThinkPad-T420s multipassd[11178]: [21B blob data]
Apr 03 17:01:08 Lenovo-ThinkPad-T420s multipassd[11178]: [91B blob data]
Apr 03 17:01:08 Lenovo-ThinkPad-T420s multipassd[11178]: VM powering down
Apr 03 17:01:09 Lenovo-ThinkPad-T420s multipassd[11178]: [90B blob data]
Apr 03 17:01:09 Lenovo-ThinkPad-T420s multipassd[11178]: VM shut down
Apr 03 17:01:09 Lenovo-ThinkPad-T420s multipassd[11178]: process state changed to NotRunning
Apr 03 17:01:09 Lenovo-ThinkPad-T420s multipassd[11178]: process finished with exit code 0
Apr 03 17:05:50 Lenovo-ThinkPad-T420s multipassd[11178]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:13:45 Lenovo-ThinkPad-T420s systemd[1]: Stopping Service for snap application multipass.multipassd...
Apr 03 17:13:45 Lenovo-ThinkPad-T420s multipassd[11178]: Received signal 15 (Terminated)
Apr 03 17:13:45 Lenovo-ThinkPad-T420s multipassd[11178]: Goodbye!
Apr 03 17:14:15 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: State 'stop-sigterm' timed out. Killing.
Apr 03 17:14:15 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Killing process 11178 (multipassd) with signal SIGKILL.
Apr 03 17:14:15 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Killing process 11560 (dnsmasq) with signal SIGKILL.
Apr 03 17:14:15 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Killing process 19553 (qemu-system-x86) with signal SIGKILL.
Apr 03 17:14:15 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Main process exited, code=killed, status=9/KILL
Apr 03 17:14:15 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Failed with result 'timeout'.
Apr 03 17:14:15 Lenovo-ThinkPad-T420s systemd[1]: Stopped Service for snap application multipass.multipassd.
Apr 03 17:14:28 Lenovo-ThinkPad-T420s systemd[1]: Started Service for snap application multipass.multipassd.
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq[22929]: started, version 2.75 cachesize 150
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq[22929]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq-dhcp[22929]: DHCP, IP range 10.64.37.2 -- 10.64.37.254, lease time infinite
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq-dhcp[22929]: DHCP, sockets bound exclusively to interface mpqemubr0
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq[22929]: reading /etc/resolv.conf
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq[22929]: using nameserver 103.86.99.99#53
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq[22929]: using nameserver 103.86.96.96#53
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq[22929]: read /etc/hosts - 3 addresses
Apr 03 17:14:32 Lenovo-ThinkPad-T420s dnsmasq[22929]: cannot read /var/snap/multipass/common/data/multipassd/network/dnsmasq.hosts: No such file or directory
Apr 03 17:14:32 Lenovo-ThinkPad-T420s multipassd[22586]: gRPC listening on unix:/run/multipass_socket, SSL:on
Apr 03 17:14:32 Lenovo-ThinkPad-T420s multipassd[22586]: process working dir '/snap/multipass/719/qemu'
Apr 03 17:14:32 Lenovo-ThinkPad-T420s multipassd[22586]: process program 'qemu-system-x86_64'
Apr 03 17:14:32 Lenovo-ThinkPad-T420s multipassd[22586]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/snapcraft-etcher/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/snapcraft-etcher/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 2, -m, 2048M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:0c:19:d3, -netdev, tap,id=hostnet0,ifname=tap-da2f767773a,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 17:14:32 Lenovo-ThinkPad-T420s multipassd[22586]: process working dir '/snap/multipass/719/qemu'
Apr 03 17:14:32 Lenovo-ThinkPad-T420s multipassd[22586]: process program 'qemu-system-x86_64'
Apr 03 17:14:32 Lenovo-ThinkPad-T420s multipassd[22586]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/hearty-lobster/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/hearty-lobster/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:90:ee:69, -netdev, tap,id=hostnet0,ifname=tap-578a7d7d665,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 17:14:34 Lenovo-ThinkPad-T420s multipassd[22586]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:15:06 Lenovo-ThinkPad-T420s multipassd[22586]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:15:37 Lenovo-ThinkPad-T420s multipassd[22586]: process working dir '/snap/multipass/719/qemu'
Apr 03 17:15:37 Lenovo-ThinkPad-T420s multipassd[22586]: process program 'qemu-system-x86_64'
Apr 03 17:15:37 Lenovo-ThinkPad-T420s multipassd[22586]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/enjoyed-slug/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/enjoyed-slug/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:5f:fa:50, -netdev, tap,id=hostnet0,ifname=tap-c757b31ed9f,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 17:15:37 Lenovo-ThinkPad-T420s multipassd[22586]: process state changed to Starting
Apr 03 17:15:37 Lenovo-ThinkPad-T420s multipassd[22586]: process state changed to Running
Apr 03 17:15:37 Lenovo-ThinkPad-T420s multipassd[22586]: process started
Apr 03 17:15:50 Lenovo-ThinkPad-T420s dnsmasq-dhcp[22929]: DHCPDISCOVER(mpqemubr0) 52:54:00:5f:fa:50
Apr 03 17:15:50 Lenovo-ThinkPad-T420s dnsmasq-dhcp[22929]: DHCPOFFER(mpqemubr0) 10.64.37.90 52:54:00:5f:fa:50
Apr 03 17:15:50 Lenovo-ThinkPad-T420s dnsmasq-dhcp[22929]: DHCPDISCOVER(mpqemubr0) 52:54:00:5f:fa:50
Apr 03 17:15:50 Lenovo-ThinkPad-T420s dnsmasq-dhcp[22929]: DHCPOFFER(mpqemubr0) 10.64.37.90 52:54:00:5f:fa:50
Apr 03 17:15:50 Lenovo-ThinkPad-T420s dnsmasq-dhcp[22929]: DHCPREQUEST(mpqemubr0) 10.64.37.90 52:54:00:5f:fa:50
Apr 03 17:15:50 Lenovo-ThinkPad-T420s dnsmasq-dhcp[22929]: DHCPACK(mpqemubr0) 10.64.37.90 52:54:00:5f:fa:50 enjoyed-slug
Apr 03 17:16:08 Lenovo-ThinkPad-T420s multipassd[22586]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:18:09 Lenovo-ThinkPad-T420s multipassd[22586]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:20:38 Lenovo-ThinkPad-T420s multipassd[22586]: [143B blob data]
Apr 03 17:20:38 Lenovo-ThinkPad-T420s multipassd[22586]: [21B blob data]
Apr 03 17:22:11 Lenovo-ThinkPad-T420s multipassd[22586]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:30:12 Lenovo-ThinkPad-T420s multipassd[22586]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:38:05 Lenovo-ThinkPad-T420s multipassd[22586]: Received signal 15 (Terminated)
Apr 03 17:38:05 Lenovo-ThinkPad-T420s multipassd[22586]: Goodbye!
Apr 03 17:38:05 Lenovo-ThinkPad-T420s systemd[1]: Stopping Service for snap application multipass.multipassd...
Apr 03 17:38:35 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: State 'stop-sigterm' timed out. Killing.
Apr 03 17:38:35 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Killing process 22586 (multipassd) with signal SIGKILL.
Apr 03 17:38:35 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Killing process 22929 (dnsmasq) with signal SIGKILL.
Apr 03 17:38:35 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Killing process 26405 (qemu-system-x86) with signal SIGKILL.
Apr 03 17:38:35 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Main process exited, code=killed, status=9/KILL
Apr 03 17:38:35 Lenovo-ThinkPad-T420s systemd[1]: snap.multipass.multipassd.service: Failed with result 'timeout'.
Apr 03 17:38:35 Lenovo-ThinkPad-T420s systemd[1]: Stopped Service for snap application multipass.multipassd.
Apr 03 17:38:44 Lenovo-ThinkPad-T420s systemd[1]: Started Service for snap application multipass.multipassd.
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq[31550]: started, version 2.75 cachesize 150
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq[31550]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq-dhcp[31550]: DHCP, IP range 10.64.37.2 -- 10.64.37.254, lease time infinite
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq-dhcp[31550]: DHCP, sockets bound exclusively to interface mpqemubr0
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq[31550]: reading /etc/resolv.conf
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 103.86.99.99#53
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 103.86.96.96#53
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq[31550]: read /etc/hosts - 3 addresses
Apr 03 17:38:50 Lenovo-ThinkPad-T420s dnsmasq[31550]: cannot read /var/snap/multipass/common/data/multipassd/network/dnsmasq.hosts: No such file or directory
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: gRPC listening on unix:/run/multipass_socket, SSL:on
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process working dir '/snap/multipass/716/qemu'
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process program 'qemu-system-x86_64'
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/snapcraft-etcher/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/snapcraft-etcher/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 2, -m, 2048M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:0c:19:d3, -netdev, tap,id=hostnet0,ifname=tap-da2f767773a,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process working dir '/snap/multipass/716/qemu'
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process program 'qemu-system-x86_64'
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/hearty-lobster/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/hearty-lobster/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:90:ee:69, -netdev, tap,id=hostnet0,ifname=tap-578a7d7d665,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process working dir '/snap/multipass/716/qemu'
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process program 'qemu-system-x86_64'
Apr 03 17:38:51 Lenovo-ThinkPad-T420s multipassd[31088]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/enjoyed-slug/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/enjoyed-slug/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:5f:fa:50, -netdev, tap,id=hostnet0,ifname=tap-c757b31ed9f,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 17:38:52 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:39:17 Lenovo-ThinkPad-T420s multipassd[31088]: process working dir '/snap/multipass/716/qemu'
Apr 03 17:39:17 Lenovo-ThinkPad-T420s multipassd[31088]: process program 'qemu-system-x86_64'
Apr 03 17:39:17 Lenovo-ThinkPad-T420s multipassd[31088]: process arguments '--enable-kvm, -hda, /var/snap/multipass/common/data/multipassd/vault/instances/regular-troll/ubuntu-18.04-minimal-cloudimg-amd64.img, -drive, file=/var/snap/multipass/common/data/multipassd/vault/instances/regular-troll/cloud-init-config.iso,if=virtio,format=raw,snapshot=off,read-only, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:b2:2e:fc, -netdev, tap,id=hostnet0,ifname=tap-8a1d7435480,script=no,downscript=no, -qmp, stdio, -cpu, host, -chardev, null,id=char0, -serial, chardev:char0, -nographic'
Apr 03 17:39:18 Lenovo-ThinkPad-T420s multipassd[31088]: process state changed to Starting
Apr 03 17:39:18 Lenovo-ThinkPad-T420s multipassd[31088]: process state changed to Running
Apr 03 17:39:18 Lenovo-ThinkPad-T420s multipassd[31088]: process started
Apr 03 17:39:24 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:39:28 Lenovo-ThinkPad-T420s dnsmasq-dhcp[31550]: DHCPDISCOVER(mpqemubr0) 52:54:00:b2:2e:fc
Apr 03 17:39:28 Lenovo-ThinkPad-T420s dnsmasq-dhcp[31550]: DHCPOFFER(mpqemubr0) 10.64.37.215 52:54:00:b2:2e:fc
Apr 03 17:39:28 Lenovo-ThinkPad-T420s dnsmasq-dhcp[31550]: DHCPREQUEST(mpqemubr0) 10.64.37.215 52:54:00:b2:2e:fc
Apr 03 17:39:28 Lenovo-ThinkPad-T420s dnsmasq-dhcp[31550]: DHCPACK(mpqemubr0) 10.64.37.215 52:54:00:b2:2e:fc regular-troll
Apr 03 17:40:25 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:42:27 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:44:18 Lenovo-ThinkPad-T420s multipassd[31088]: [143B blob data]
Apr 03 17:44:18 Lenovo-ThinkPad-T420s multipassd[31088]: [21B blob data]
Apr 03 17:46:29 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 17:54:30 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 18:10:33 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 18:42:34 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 19:14:36 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 03 19:46:38 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Error transferring https://api.staging.jujucharms.com/omnibus/v4/multipass/metrics - server replied: Internal Server Error - Attempting to resend
Apr 04 09:49:38 Lenovo-ThinkPad-T420s dnsmasq[31550]: no servers found in /etc/resolv.conf, will retry
Apr 04 09:49:50 Lenovo-ThinkPad-T420s multipassd[31088]: Metrics error: Network session error. - Attempting to resend
Apr 04 09:50:28 Lenovo-ThinkPad-T420s dnsmasq[31550]: reading /etc/resolv.conf
Apr 04 09:50:28 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 192.168.1.1#53
Apr 04 09:50:29 Lenovo-ThinkPad-T420s dnsmasq[31550]: reading /etc/resolv.conf
Apr 04 09:50:29 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 192.168.1.1#53
Apr 04 09:50:29 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 2001:4888:14:ff00:196:d::#53
Apr 04 09:50:29 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 2001:4888:15:ff00:194:d::#53
Apr 04 09:50:30 Lenovo-ThinkPad-T420s dnsmasq[31550]: reading /etc/resolv.conf
Apr 04 09:50:30 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 192.168.0.1#53
Apr 04 09:50:44 Lenovo-ThinkPad-T420s multipassd[31088]: "No such interface “org.freedesktop.DBus.Properties” on object at path /org/freedesktop/NetworkManager/ActiveConnection/17"
Apr 04 09:50:44 Lenovo-ThinkPad-T420s multipassd[31088]: "No such interface “org.freedesktop.DBus.Properties” on object at path /org/freedesktop/NetworkManager/ActiveConnection/17"
Apr 04 09:50:49 Lenovo-ThinkPad-T420s dnsmasq[31550]: reading /etc/resolv.conf
Apr 04 09:50:49 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 103.86.99.99#53
Apr 04 09:50:49 Lenovo-ThinkPad-T420s dnsmasq[31550]: using nameserver 103.86.96.96#53
4

I’m thinking it may be somewhat linked to this line here:

Apr 03 16:17:22 Lenovo-ThinkPad-T420s dnsmasq[11560]: cannot read /var/snap/multipass/common/data/multipassd/network/dnsmasq.hosts: No such file or directory
5

@easthighNerd,

This is really strange…the Multipass snap’s dnsmasq server is fine handing out an IP address, but the ssh connection to the instance is failing. Are you by chance running any sort of firewall that may be blocking port 23?

6

@townsend
Not as far as I know. I have not configured any firewall, and with the OS being Arch, I do not believe that one is installed and configured by default.

Is there an easy way for me to check?

7

Hmm, ok, I’m a little stumped right now…BTW, that cannot read... line is benign.

I’ll give it some more thought, but I must admit I don’t have any experience with Multipass on Arch, but it should work.

8

Thank you very much for your help @townsend

9

@easthighNerd,

Also, just in case the blob data in the journalctl output has anything important , could you please do journalctl -au snap.multipass.* and we’ll get the expanded blob data that way.

10

Also, another thing that seems fishy to me, but I’m not able to explain is why multipassd is unable to reach the metrics url. Really seems like something network related is going on…

11

One last thing, which version of multipass are you using? multipass version and the snap version please?

12

@townsend
Strangely enough, a reboot and installing squashfuse fixed the issues I was having. I am now working on Snapping away!

13

@easthighNerd,

Glad to hear you got it working! Do you mean you had to install squashfuse on your Arch machine?

14

Yes, I did have to install squashfuse on my Arch machine

15

@easthighNerd,

Hmm, ok, I’m not sure how squashfuse plays into this since nothing with Multipass should depend on that. I don’t even have squashfuse installed on my system…