search

canonical / multipass

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

Apple M1 / Hypervisor.framework support #1857

Closed flying-sausages closed 2 years ago

flying-sausages commented 3 years ago

What are you trying to do? Run Multipass to launch instances on top of Apple Silicon devices

What's your proposed solution? Restrict multipass on AS to use the Virtualisation API intrdouced in Big Sur only and ensure ARM builds of ubuntu are being installed

Additional context I have 0 experience in any of the underlying technologies that are used here. I know 1.5.0 has Big Sur support on Intel through the API above, and so I'm wondering what are the extra steps that need to be taken care in order to allow users to have ARM-based VMs.

ED: Latest build

1.8.0 build 787

Saviq commented 3 years ago

Is virtualizing macOS in scope, now that multipass is using Virtualization.framework?

No, sorry. We ended up with Hypervisor.framework after all, as we need to control the boot process, which V.fwork doesn't currently allow.

Just ran a benchmark comparing a Multipass VM to a Dell Poweredge server... The results speak for themselves.

It's crazy, isn't it... You should try with more --cpus, too ;)

shawnanastasio commented 3 years ago

the macOS support is only present in the proprietary builds by Canonical?

Correct, we've decided to keep it proprietary for the moment.

That is unfortunate to hear, especially considering how multipass seems (at least to me) to be marketed as an open source tool. I wasn't even aware that there was a proprietary variant until downloading the macOS installer package from the multipass homepage and carefully checking the license. Frankly, the decision to keep the Linux platform support code open and the macOS code closed seems rather arbitrary. I hope the team will reconsider this decision in the future.

flying-sausages commented 3 years ago

Frankly, the decision to keep the Linux platform support code open and the macOS code closed seems rather arbitrary

Sounds like entitlements?

jamal commented 3 years ago

It looks like multipass.gui is crashing with this build:

-------------------------------------
Translated Report (Full Report Below)
-------------------------------------

Process:               multipass.gui [1106]
Path:                  /Library/Application Support/com.canonical.multipass/*/multipass.gui.app/Contents/MacOS/multipass.gui
Identifier:            
Version:                ()
Code Type:             ARM-64 (Native)
Parent Process:        launchd [1]
User ID:               501

Date/Time:             2021-08-12 07:33:01.8344 -0700
OS Version:            macOS 12.0 (21A5294g)
Report Version:        12
Anonymous UUID:        C9042466-4C70-EAF5-EC37-976231412F96

Time Awake Since Boot: 560 seconds

System Integrity Protection: enabled

Crashed Thread:        0

Exception Type:        EXC_CRASH (SIGABRT)
Exception Codes:       0x0000000000000000, 0x0000000000000000
Exception Note:        EXC_CORPSE_NOTIFY

Termination Reason:    Namespace DYLD, Code 1 Library missing
Library not loaded: @rpath/QtWidgets.framework/Versions/5/QtWidgets
Referenced from: /Library/Application Support/com.canonical.multipass/bin/multipass.gui.app/Contents/MacOS/multipass.gui
Reason: tried: '/Library/Application Support/com.canonical.multipass/bin/multipass.gui.app/Contents/MacOS/../../../../lib/QtWidgets.framework/Versions/5/QtWidgets' (code signature in <FBEE3A40-5F29-3055-B420-CAB3B14C90AA> '/Library/Application Support/com.canonical.multipass/lib/QtWidgets.framework/Versions/5/QtWidgets' not valid for use in process: mapped file has no Team ID and is not a platform binary (signed with custom identity or adhoc?)), '/Library/Application Support/com.canonical.multipass/bin/multipass.gui.app/Contents/MacOS/../../../../lib/QtWidgets.framework/Versions/5/QtWidgets' (code signature in <FBEE3A40-5F29-3055-B420-CAB3B14C90AA> '/Library/Application Support/com.canonical.multipass/lib/QtWidgets.framework/Versions/5/QtWidgets' not valid for use in process: mapped file has no Team ID and is not a pla

Application Specific Information:
Library not loaded: @rpath/QtWidgets.framework/Versions/5/QtWidgets
Referenced from: /Library/Application Support/com.canonical.multipass/bin/multipass.gui.app/Contents/MacOS/multipass.gui
Reason: tried: '/Library/Application Support/com.canonical.multipass/bin/multipass.gui.app/Contents/MacOS/../../../../lib/QtWidgets.framework/Versions/5/QtWidgets' (code signature in <FBEE3A40-5F29-3055-B420-CAB3B14C90AA> '/Library/Application Support/com.canonical.multipass/lib/QtWidgets.framework/Versions/5/QtWidgets' not valid for use in process: mapped file has no Team ID and is not a platform binary (signed with custom identity or adhoc?)), '/Library/Application Support/com.canonical.multipass/bin/multipass.gui.app/Contents/MacOS/../../../../lib/QtWidgets.framework/Versions/5/QtWidgets' (code signature in <FBEE3A40-5F29-3055-B420-CAB3B14C90AA> '/Library/Application Support/com.canonical.multipass/lib/QtWidgets.framework/Versions/5/QtWidgets' not valid for use in process: mapped file has no Team ID and is not a pla

Thread 0 Crashed:
0   dyld                                   0x1047f2834 0x1047a8000 + 305204
1   dyld                                   0x1047f97cc 0x1047a8000 + 333772
2   dyld                                   0x1047f9800 0x1047a8000 + 333824
3   dyld                                   0x1047b2588 0x1047a8000 + 42376
4   dyld                                   0x1047adf0c 0x1047a8000 + 24332
5   dyld                                   0x1047ad0dc 0x1047a8000 + 20700

Thread 0 crashed with ARM Thread State (64-bit):
    x0: 0x0000000000000006   x1: 0x0000000000000001   x2: 0x000000016da32b10   x3: 0x00000000000000ac
    x4: 0x000000016da32710   x5: 0x0000000000000000   x6: 0x0073746567646957   x7: 0x0000000000000830
    x8: 0x0000000000000020   x9: 0x0000000000000009  x10: 0x0000000000000001  x11: 0x000000000000000a
   x12: 0x0000000000000000  x13: 0x0000000000000031  x14: 0x000000024b85d3d6  x15: 0x0000000000000000
   x16: 0x0000000000000209  x17: 0x00000001047ab170  x18: 0x0000000000000000  x19: 0x0000000000000000
   x20: 0x000000016da32710  x21: 0x00000000000000ac  x22: 0x000000016da32b10  x23: 0x0000000000000001
   x24: 0x0000000000000006  x25: 0x000000016da33458  x26: 0x0000000000000000  x27: 0x000000001f070004
   x28: 0x0000000000000000   fp: 0x000000016da326e0   lr: 0x00000001047f97cc
    sp: 0x000000016da326a0   pc: 0x00000001047f2834 cpsr: 0x00000000
   far: 0x0000000104658000  esr: 0x56000080  Address size fault

Binary Images:
       0x1047a8000 -        0x104803fff dyld (*) <19cc8ea0-15a6-3229-b7e7-e3ba70a607a2> /usr/lib/dyld

External Modification Summary:
  Calls made by other processes targeting this process:
    task_for_pid: 0
    thread_create: 0
    thread_set_state: 0
  Calls made by this process:
    task_for_pid: 0
    thread_create: 0
    thread_set_state: 0
  Calls made by all processes on this machine:
    task_for_pid: 0
    thread_create: 0
    thread_set_state: 0

VM Region Summary:
ReadOnly portion of Libraries: Total=33.7M resident=0K(0%) swapped_out_or_unallocated=33.7M(100%)
Writable regions: Total=9312K written=0K(0%) resident=0K(0%) swapped_out=0K(0%) unallocated=9312K(100%)

                                VIRTUAL   REGION 
REGION TYPE                        SIZE    COUNT (non-coalesced) 
===========                     =======  ======= 
STACK GUARD                       56.0M        1 
Stack                             8176K        1 
VM_ALLOCATE                        1.0G        2 
__DATA                             272K        3 
__DATA_CONST                       256K        2 
__LINKEDIT                        19.8M        3 
__TEXT                            13.8M        2 
dyld private memory               1024K        1 
shared memory                       16K        1 
===========                     =======  ======= 
TOTAL                              1.1G       16 

-----------
Full Report
-----------

{"app_name":"multipass.gui","timestamp":"2021-08-12 07:33:01.00 -0700","app_version":"","slice_uuid":"5dbabefa-8c60-3cec-a5ea-e65e6d31c682","build_version":"","platform":1,"bundleID":"","share_with_app_devs":0,"is_first_party":0,"etl_key":"3","bug_type":"309","os_version":"macOS 12.0 (21A5294g)","incident_id":"CDFFD909-C24D-408E-A6A4-6B2BFDC8673F","name":"multipass.gui"}
{
  "uptime" : 560,
  "procLaunch" : "2021-08-12 07:33:01.8135 -0700",
  "procRole" : "Unspecified",
  "version" : 2,
  "userID" : 501,
  "deployVersion" : 209,
  "modelCode" : "MacBookAir10,1",
  "procStartAbsTime" : 13558532978,
  "coalitionID" : 766,
  "osVersion" : {
    "train" : "macOS 12.0",
    "build" : "21A5294g",
    "releaseType" : "User"
  },
  "captureTime" : "2021-08-12 07:33:01.8344 -0700",
  "incident" : "CDFFD909-C24D-408E-A6A4-6B2BFDC8673F",
  "bug_type" : "309",
  "pid" : 1106,
  "procExitAbsTime" : 13559020482,
  "translated" : false,
  "cpuType" : "ARM-64",
  "procName" : "multipass.gui",
  "procPath" : "\/Library\/Application Support\/com.canonical.multipass\/*\/multipass.gui.app\/Contents\/MacOS\/multipass.gui",
  "bundleInfo" : {"CFBundleShortVersionString":"","CFBundleVersion":"","CFBundleIdentifier":""},
  "storeInfo" : {"deviceIdentifierForVendor":"7B1B9E53-FBD5-561B-9CB8-5E026108C9AC","thirdParty":true},
  "parentProc" : "launchd",
  "parentPid" : 1,
  "coalitionName" : "com.canonical.multipass.gui.autostart",
  "crashReporterKey" : "C9042466-4C70-EAF5-EC37-976231412F96",
  "sip" : "enabled",
  "isCorpse" : 1,
  "exception" : {"codes":"0x0000000000000000, 0x0000000000000000","rawCodes":[0,0],"type":"EXC_CRASH","signal":"SIGABRT"},
  "termination" : {"flags":518,"code":1,"namespace":"DYLD","indicator":"Library missing","reasons":["Library not loaded: @rpath\/QtWidgets.framework\/Versions\/5\/QtWidgets","Referenced from: \/Library\/Application Support\/com.canonical.multipass\/bin\/multipass.gui.app\/Contents\/MacOS\/multipass.gui","Reason: tried: '\/Library\/Application Support\/com.canonical.multipass\/bin\/multipass.gui.app\/Contents\/MacOS\/..\/..\/..\/..\/lib\/QtWidgets.framework\/Versions\/5\/QtWidgets' (code signature in <FBEE3A40-5F29-3055-B420-CAB3B14C90AA> '\/Library\/Application Support\/com.canonical.multipass\/lib\/QtWidgets.framework\/Versions\/5\/QtWidgets' not valid for use in process: mapped file has no Team ID and is not a platform binary (signed with custom identity or adhoc?)), '\/Library\/Application Support\/com.canonical.multipass\/bin\/multipass.gui.app\/Contents\/MacOS\/..\/..\/..\/..\/lib\/QtWidgets.framework\/Versions\/5\/QtWidgets' (code signature in <FBEE3A40-5F29-3055-B420-CAB3B14C90AA> '\/Library\/Application Support\/com.canonical.multipass\/lib\/QtWidgets.framework\/Versions\/5\/QtWidgets' not valid for use in process: mapped file has no Team ID and is not a pla"]},
  "asi" : {"dyld":["Library not loaded: @rpath\/QtWidgets.framework\/Versions\/5\/QtWidgets","Referenced from: \/Library\/Application Support\/com.canonical.multipass\/bin\/multipass.gui.app\/Contents\/MacOS\/multipass.gui","Reason: tried: '\/Library\/Application Support\/com.canonical.multipass\/bin\/multipass.gui.app\/Contents\/MacOS\/..\/..\/..\/..\/lib\/QtWidgets.framework\/Versions\/5\/QtWidgets' (code signature in <FBEE3A40-5F29-3055-B420-CAB3B14C90AA> '\/Library\/Application Support\/com.canonical.multipass\/lib\/QtWidgets.framework\/Versions\/5\/QtWidgets' not valid for use in process: mapped file has no Team ID and is not a platform binary (signed with custom identity or adhoc?)), '\/Library\/Application Support\/com.canonical.multipass\/bin\/multipass.gui.app\/Contents\/MacOS\/..\/..\/..\/..\/lib\/QtWidgets.framework\/Versions\/5\/QtWidgets' (code signature in <FBEE3A40-5F29-3055-B420-CAB3B14C90AA> '\/Library\/Application Support\/com.canonical.multipass\/lib\/QtWidgets.framework\/Versions\/5\/QtWidgets' not valid for use in process: mapped file has no Team ID and is not a pla"]},
  "extMods" : {"caller":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"system":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"targeted":{"thread_create":0,"thread_set_state":0,"task_for_pid":0},"warnings":0},
  "faultingThread" : 0,
  "threads" : [{"triggered":true,"id":10601,"threadState":{"x":[{"value":6},{"value":1},{"value":6134377232},{"value":172},{"value":6134376208},{"value":0},{"value":32497601196878167},{"value":2096},{"value":32},{"value":9},{"value":1},{"value":10},{"value":0},{"value":49},{"value":9856996310},{"value":0},{"value":521},{"value":4370116976},{"value":0},{"value":0},{"value":6134376208},{"value":172},{"value":6134377232},{"value":1},{"value":6},{"value":6134379608},{"value":0},{"value":520552452},{"value":0}],"flavor":"ARM_THREAD_STATE64","lr":{"value":4370438092},"cpsr":{"value":0},"fp":{"value":6134376160},"sp":{"value":6134376096},"esr":{"value":1442840704,"description":" Address size fault"},"pc":{"value":4370409524,"matchesCrashFrame":1},"far":{"value":4368728064}},"frames":[{"imageOffset":305204,"imageIndex":0},{"imageOffset":333772,"imageIndex":0},{"imageOffset":333824,"imageIndex":0},{"imageOffset":42376,"imageIndex":0},{"imageOffset":24332,"imageIndex":0},{"imageOffset":20700,"imageIndex":0}]}],
  "usedImages" : [
  {
    "source" : "P",
    "arch" : "arm64e",
    "base" : 4370104320,
    "size" : 376832,
    "uuid" : "19cc8ea0-15a6-3229-b7e7-e3ba70a607a2",
    "path" : "\/usr\/lib\/dyld",
    "name" : "dyld"
  }
],
  "sharedCache" : {
  "base" : 6870335488,
  "size" : 3042279424,
  "uuid" : "83ca2993-4a8c-3fde-a65f-ba9577abf71d"
},
  "vmSummary" : "ReadOnly portion of Libraries: Total=33.7M resident=0K(0%) swapped_out_or_unallocated=33.7M(100%)\nWritable regions: Total=9312K written=0K(0%) resident=0K(0%) swapped_out=0K(0%) unallocated=9312K(100%)\n\n                                VIRTUAL   REGION \nREGION TYPE                        SIZE    COUNT (non-coalesced) \n===========                     =======  ======= \nSTACK GUARD                       56.0M        1 \nStack                             8176K        1 \nVM_ALLOCATE                        1.0G        2 \n__DATA                             272K        3 \n__DATA_CONST                       256K        2 \n__LINKEDIT                        19.8M        3 \n__TEXT                            13.8M        2 \ndyld private memory               1024K        1 \nshared memory                       16K        1 \n===========                     =======  ======= \nTOTAL                              1.1G       16 \n",
  "legacyInfo" : {
  "threadTriggered" : {

  }
},
  "trialInfo" : {
  "rollouts" : [
    {
      "rolloutId" : "607844aa04477260f58a8077",
      "factorPackIds" : {
        "SIRI_MORPHUN_ASSETS" : "60ef663fea07ad5dba6c903e"
      },
      "deploymentId" : 250000055
    },
    {
      "rolloutId" : "5fc94383418129005b4e9ae0",
      "factorPackIds" : {

      },
      "deploymentId" : 250000110
    },
    {
      "rolloutId" : "60356660bbe37970735c5624",
      "factorPackIds" : {

      },
      "deploymentId" : 250000016
    },
    {
      "rolloutId" : "60da5e84ab0ca017dace9abf",
      "factorPackIds" : {

      },
      "deploymentId" : 250000006
    },
    {
      "rolloutId" : "602ad4dac86151000cf27e46",
      "factorPackIds" : {
        "SIRI_DICTATION_ASSETS" : "610c869037f5d11121dcd113"
      },
      "deploymentId" : 250000156
    },
    {
      "rolloutId" : "601d9415f79519000ccd4b69",
      "factorPackIds" : {
        "SIRI_TEXT_TO_SPEECH" : "610c7e7b37f5d11121dcd0fa"
      },
      "deploymentId" : 250000147
    }
  ],
  "experiments" : [

  ]
}
}

Model: MacBookAir10,1, BootROM 7429.0.207.141.1, proc 8:4:4 processors, 16 GB, SMC 
Graphics: kHW_AppleM1Item, Apple M1, spdisplays_builtin
Memory Module: LPDDR4
AirPort: spairport_wireless_card_type_wifi, wl0: Jul 12 2021 19:14:33 version 18.20.307.0.7.8.114 FWID 01-5c3877f0
Bluetooth: Version (null), 0 services, 0 devices, 0 incoming serial ports
Network Service: Wi-Fi, AirPort, en0
USB Device: USB 3.1 Bus
USB Device: USB 3.1 Bus
Thunderbolt Bus: MacBook Air, Apple Inc.
Thunderbolt Bus: MacBook Air, Apple Inc.
Saviq commented 3 years ago

@jamal are you using the last package I posted?

https://multipass-ci.s3.amazonaws.com/pr403/multipass-1.8.0-dev.403.pr403%2Bg843f3ca3.mac%2Barm64-Darwin.pkg

$ multipass version
multipass   1.8.0-dev.403.pr403+g843f3ca3.mac
multipassd  1.8.0-dev.403.pr403+g843f3ca3.mac

That one was meant to fix the issue you're seeing and I confirmed on two different machines that it works fine...

jamal commented 3 years ago

Ah, no. I was on build 397. Will try this now, thanks!

techmore commented 3 years ago

Thank you all so much, works well and makes the M1 so much better!

Successfully installed and ran current Ruby on Rails Rails version: 6.1.4 Ruby version: ruby 3.0.1p64 (2021-04-05 revision 0fb782ee38) [aarch64-linux]

I was also able to launch and use a second instance which I didn't expect to work. No bridged networking yet for Mac OS? That's okay I can wait a little longer :D

jajcayn commented 3 years ago

Thanks so much for this! It works like a charm! Additional question: is there an option (or plan to add it) to emulate the x86 architecture?

flying-sausages commented 3 years ago

@Saviq I added the link to the latest build to the OP, might be nice to keep that updated as they keep coming

Saviq commented 3 years ago

No bridged networking yet for Mac OS? That's okay I can wait a little longer :D

Not just yet, we'll get there :)

Additional question: is there an option (or plan to add it) to emulate the x86 architecture?

We plan to look into this for feasibility. Need to benchmark if it's going to be acceptable performance-wise.

@Saviq I added the link to the latest build to the OP, might be nice to keep that updated as they keep coming

Will do!

jajcayn commented 3 years ago

funnily enough, after an hour I wrote here that everything works like a charm, I start having problems... I did clean install of build 403:

multipass launch -vvv

gives timeout...

[2021-08-16T23:07:22.867] [debug] [qemu-system-aarch64] [8024] started: qemu-system-aarch64 --version
[2021-08-16T23:08:48.138] [debug] [qemu-img] [8040] started: qemu-img info --output=json /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210812/ubuntu-20.04-server-cloudimg-arm64.img
[2021-08-16T23:08:48.397] [debug] [qemu-img] [8041] started: qemu-img info /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210812/ubuntu-20.04-server-cloudimg-arm64.img
[2021-08-16T23:08:48.412] [debug] [qemu-img] [8042] started: qemu-img resize /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img 5368709120
[2021-08-16T23:08:48.423] [debug] [qemu-img] [8043] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img
[2021-08-16T23:08:48.429] [debug] [expressive-nyala] process working dir ''
[2021-08-16T23:08:48.429] [info] [expressive-nyala] process program 'qemu-system-aarch64'
[2021-08-16T23:08:48.429] [info] [expressive-nyala] process arguments '-accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -cpu, cortex-a72, -machine, virt,highmem=off, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:35:d1:5d, -netdev, vmnet-macos,mode=shared,id=hostnet0, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/cloud-init-config.iso'
[2021-08-16T23:08:48.432] [debug] [qemu-system-aarch64] [8044] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.OoRpCe
[2021-08-16T23:08:48.595] [info] [expressive-nyala] process state changed to Starting
[2021-08-16T23:08:48.596] [info] [expressive-nyala] process state changed to Running
[2021-08-16T23:08:48.597] [debug] [qemu-system-aarch64] [8045] started: qemu-system-aarch64 -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -cpu cortex-a72 -machine virt,highmem=off -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:35:d1:5d -netdev vmnet-macos,mode=shared,id=hostnet0 -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/cloud-init-config.iso
[2021-08-16T23:08:48.597] [info] [expressive-nyala] process started
launch failed: The following errors occurred:
expressive-nyala: timed out waiting for response

the log is also not very informative:

cat /Library/Logs/Multipass/multipassd.log

gives

[2021-08-16T23:07:11.696] [debug] [update] Latest Multipass release available is version 1.7.0
[2021-08-16T23:07:14.107] [info] [VMImageHost] Did not find any supported products in "appliance"
[2021-08-16T23:07:18.242] [info] [rpc] gRPC listening on unix:/var/run/multipass_socket, SSL:on
[2021-08-16T23:07:18.243] [warning] [Qt] QIODevice::write (QFile, "/var/root/Library/Caches/multipassd/qemu/vault/multipassd-image-records.json"): device not open
[2021-08-16T23:07:18.246] [info] [daemon] Starting Multipass 1.8.0-dev.403.pr403+g843f3ca3.mac
[2021-08-16T23:07:18.246] [info] [daemon] Daemon arguments: /Library/Application Support/com.canonical.multipass/bin/multipassd --verbosity debug
[2021-08-16T23:07:22.867] [debug] [qemu-system-aarch64] [8024] started: qemu-system-aarch64 --version
[2021-08-16T23:08:48.138] [debug] [qemu-img] [8040] started: qemu-img info --output=json /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210812/ubuntu-20.04-server-cloudimg-arm64.img
[2021-08-16T23:08:48.397] [debug] [qemu-img] [8041] started: qemu-img info /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210812/ubuntu-20.04-server-cloudimg-arm64.img
[2021-08-16T23:08:48.412] [debug] [qemu-img] [8042] started: qemu-img resize /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img 5368709120
[2021-08-16T23:08:48.423] [debug] [qemu-img] [8043] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img
[2021-08-16T23:08:48.429] [debug] [expressive-nyala] process working dir ''
[2021-08-16T23:08:48.429] [info] [expressive-nyala] process program 'qemu-system-aarch64'
[2021-08-16T23:08:48.429] [info] [expressive-nyala] process arguments '-accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -cpu, cortex-a72, -machine, virt,highmem=off, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:35:d1:5d, -netdev, vmnet-macos,mode=shared,id=hostnet0, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/cloud-init-config.iso'
[2021-08-16T23:08:48.431] [debug] [qemu-system-aarch64] [8044] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.OoRpCe
[2021-08-16T23:08:48.595] [info] [expressive-nyala] process state changed to Starting
[2021-08-16T23:08:48.596] [info] [expressive-nyala] process state changed to Running
[2021-08-16T23:08:48.596] [debug] [qemu-system-aarch64] [8045] started: qemu-system-aarch64 -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -cpu cortex-a72 -machine virt,highmem=off -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:35:d1:5d -netdev vmnet-macos,mode=shared,id=hostnet0 -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/cloud-init-config.iso
[2021-08-16T23:08:48.597] [info] [expressive-nyala] process started
[2021-08-16T23:08:48.597] [debug] [expressive-nyala] Waiting for SSH to be up
[2021-08-16T23:08:48.953] [warning] [expressive-nyala] qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: Started vmnet interface with configuration:
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: MTU:              1500
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: Max packet size:  1514
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: MAC:              ca:0b:db:c2:83:ca
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: UUID:             78912709-6324-419C-9681-13523BF7DEF2

[2021-08-16T23:08:48.954] [warning] [qemu-system-aarch64]
[2021-08-16T23:08:48.954] [debug] [expressive-nyala] QMP: {"QMP": {"version": {"qemu": {"micro": 92, "minor": 0, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2021-08-16T23:08:49.049] [debug] [expressive-nyala] QMP: {"return": {}}

[2021-08-16T23:09:02.565] [debug] [expressive-nyala] QMP: {"timestamp": {"seconds": 1629148142, "microseconds": 564923}, "event": "NIC_RX_FILTER_CHANGED", "data": {"name": "net0", "path": "/machine/peripheral/net0/virtio-backend"}}

when I check list of instances I get:

multipass list
Name                    State             IPv4             Image
expressive-nyala        Unknown           --               Ubuntu 20.04 LTS

and when I try to start the expressive-nyala this happens:

[2021-08-16T23:19:16.484] [error] [expressive-nyala] process error occurred Crashed program: qemu-system-aarch64; error: Process crashed
[2021-08-16T23:19:16.484] [error] [expressive-nyala] error: program: qemu-system-aarch64; error: Process crashed
start failed: cannot connect to the multipass socket
Please ensure multipassd is running and '/var/run/multipass_socket' is accessible

and these few lines are new in the log

[2021-08-16T23:19:16.472] [debug] [expressive-nyala] process working dir ''
[2021-08-16T23:19:16.473] [info] [expressive-nyala] process program 'qemu-system-aarch64'
[2021-08-16T23:19:16.473] [info] [expressive-nyala] process arguments '-accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -cpu, cortex-a72, -machine, virt,highmem=off, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -device, virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:35:d1:5d, -netdev, vmnet-macos,mode=shared,id=hostnet0, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/cloud-init-config.iso'
[2021-08-16T23:19:16.473] [warning] [Qt] QProcess: Destroyed while process ("qemu-system-aarch64") is still running.
[2021-08-16T23:19:16.484] [error] [expressive-nyala] process error occurred Crashed program: qemu-system-aarch64; error: Process crashed
[2021-08-16T23:19:16.484] [info] [expressive-nyala] process state changed to NotRunning
[2021-08-16T23:19:16.484] [error] [expressive-nyala] error: program: qemu-system-aarch64; error: Process crashed
[2021-08-16T23:19:16.485] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2021-08-16T23:19:16.485] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2021-08-16T23:19:16.485] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2021-08-16T23:19:16.485] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2021-08-16T23:19:16.485] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2021-08-16T23:19:16.485] [warning] [Qt] QObject::connect(multipass::Process, Unknown): invalid nullptr parameter
[2021-08-16T23:19:17.151] [debug] [update] Latest Multipass release available is version 1.7.0
[2021-08-16T23:19:17.590] [info] [VMImageHost] Did not find any supported products in "appliance"
[2021-08-16T23:19:19.459] [info] [rpc] gRPC listening on unix:/var/run/multipass_socket, SSL:on
[2021-08-16T23:19:19.466] [debug] [qemu-img] [8146] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img
[2021-08-16T23:19:19.492] [info] [daemon] Starting Multipass 1.8.0-dev.403.pr403+g843f3ca3.mac
[2021-08-16T23:19:19.492] [info] [daemon] Daemon arguments: /Library/Application Support/com.canonical.multipass/bin/multipassd --verbosity debug

I also tried older version (build 397) with the same result... I always completely uninstall multipass (using sudo sh /Library/Application\ Support/com.canonical.multipass/uninstall.sh and Y to both) and do fresh install, I also tried to restart a computer, to no avail... any idea what I am doing wrong?

Much appreciated! Thanks!

townsend2010 commented 3 years ago

Hey @jajcayn,

The logs look like everything worked as far as the instance booting. The problem looks like multipass just can't figure out the IP address. Could you please output what is contained in /var/db/dhcpd_leases?

jajcayn commented 3 years ago

hey @townsend2010 thanks for a comment! /var/db/dhcpd_leases gives me:

{
    name=dora
    ip_address=192.168.64.4
    hw_address=1,52:54:0:2a:dd:f9
    identifier=1,52:54:0:2a:dd:f9
    lease=0x611bcb50
}
{
    name=foo
    ip_address=192.168.64.3
    hw_address=1,52:54:0:d:6c:fb
    identifier=1,52:54:0:d:6c:fb
    lease=0x6112c1a7
}
{
    ip_address=192.168.64.2
    hw_address=1,e:44:5f:af:c8:fd
    identifier=1,e:44:5f:af:c8:fd
    lease=0x60778020
}

P.S. dora was the name of multipass VM back in the days when it worked:)

townsend2010 commented 3 years ago

Hey @jajcayn,

Ok, so Mac bootp didn't assign an IP address for some reason. Are there any stale running qemu-system-aarch64 processes? If so, kill those and let's see if it will start up.

jajcayn commented 3 years ago

no stale processes, at least ps aux didn't show any...

townsend2010 commented 3 years ago

Hey @jajcayn,

If you still have the expressive-nyala instance, could you please try the following from the command line and see what it outputs:

$ sudo /Library/Application\ Support/com.canonical.multipass/bin/qemu-system-aarch64 -accel hvf -drive file=/Library/Application\ Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -cpu cortex-a72 -machine virt,highmem=off -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application\ Support/multipassd/qemu/vault/instances/expressive-nyala/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -device virtio-net-pci,netdev=hostnet0,id=net0,mac=52:54:00:35:d1:5d -netdev vmnet-macos,mode=shared,id=hostnet0 -qmp stdio -chardev null,id=char0 -serial chardev:char0 -cdrom /var/root/Library/Application\ Support/multipassd/qemu/vault/instances/expressive-nyala/cloud-init-config.iso

You may have to escape some path spaces, etc. to get it to work, but that is the gist.

jajcayn commented 3 years ago

hmm, I removed it.. but I can reinstall multipass, (try to) create an instance, if nothing changed, it'll fail, I'll just check whether logs are the same as I posted here and then I'd run the command:) thanks!

jajcayn commented 3 years ago

so did that with a different instance (changed in the paths and changed its MAC address) and got

qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: Started vmnet interface with configuration:
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: MTU:              1500
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: Max packet size:  1514
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: MAC:              7e:24:44:99:1f:ca
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: UUID:             1D4A9B4E-942F-465C-B76B-A87F20907B3C
{"QMP": {"version": {"qemu": {"micro": 92, "minor": 0, "major": 6}, "package": ""}, "capabilities": ["oob"]}}
townsend2010 commented 3 years ago

Hey @jajcayn,

You should have seen a console window open when running the command I posted. If so, did you see if the instance actually booted?

jajcayn commented 3 years ago

oh, nothing like that happened... immediately after the command, I got the log above, but then nothing happened.. I've got a stale session...

Screenshot 2021-08-18 at 17 51 57
townsend2010 commented 3 years ago

Hey @jajcayn,

Ok, a window should have still popped up, but I did give the wrong command. Just Ctrl-C out of that qemu-system-aarch64 command and then try the command with the following removed: -chardev null,id=char0 -serial chardev:char0

This should open a QEMU console and you should see the boot process.

jajcayn commented 3 years ago

ok, now I am getting an error:

qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: Started vmnet interface with configuration:
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: MTU:              1500
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: Max packet size:  1514
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: MAC:              ae:c5:20:31:28:8b
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -netdev vmnet-macos,mode=shared,id=hostnet0: info: UUID:             16B5B9BB-1447-459E-A870-E4D585A893CA
qemu-system-aarch64: cannot use stdio by multiple character devices
qemu-system-aarch64: could not connect serial device to character backend 'stdio'
flying-sausages commented 3 years ago

Anyone else noticing that at some point, the shell of an instance can become unresponsive? When it happens, it mainfests through all shells whenever a new command is sent.

I've got the following in dmesg as well as in journalctl.

Let me know if I should start a separate issue for this.

[    7.102273] random: 7 urandom warning(s) missed due to ratelimiting
[   12.399669] kauditd_printk_skb: 20 callbacks suppressed
[   12.399671] audit: type=1400 audit(1629486434.720:32): apparmor="DENIED" operation="capable" profile="/snap/snapd/12707/usr/lib/snapd/snap-confine" pid=934 comm="snap-confine" capability=4  capname="fsetid"
[89045.713552] INFO: task git:26637 blocked for more than 120 seconds.
[89045.714126]       Not tainted 5.4.0-81-generic #91-Ubuntu
[89045.714549] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[89045.715110] git             D    0 26637      1 0x00000009
[89045.715117] Call trace:
[89045.715288]  __switch_to+0x134/0x190
[89045.715352]  __schedule+0x31c/0x7e0
[89045.715354]  schedule+0x40/0xb8
[89045.715396]  request_wait_answer+0x14c/0x288
[89045.715398]  fuse_simple_request+0x1a8/0x2c0
[89045.715401]  fuse_lookup_name+0xe4/0x1d0
[89045.715404]  fuse_lookup+0x64/0x170
[89045.715423]  __lookup_slow+0x98/0x1b0
[89045.715426]  lookup_slow+0x48/0x70
[89045.715430]  walk_component+0x204/0x388
[89045.715433]  path_lookupat.isra.0+0xa4/0x210
[89045.715435]  filename_lookup+0x9c/0x170
[89045.715437]  user_path_at_empty+0x5c/0x70
[89045.715439]  vfs_statx+0x90/0x110
[89045.715442]  __do_sys_newfstatat+0x30/0x70
[89045.715445]  __arm64_sys_newfstatat+0x2c/0x38
[89045.715448]  el0_svc_common.constprop.0+0xe4/0x1f0
[89045.715450]  el0_svc_handler+0x38/0xa8
[89045.715453]  el0_svc+0x10/0x2c8

It might or might not be related, but something seems to stop some multipass process on the host, as I always notice that the GUI is not running even though it's supposed to autostart. When I try to restart the aforementioned instance, it takes forever for it to go down, and that's when I notice the GUI is not running.

djettah commented 3 years ago

How can I download the latest beta? Gives me AccessDenied for now.

Saviq commented 3 years ago

@djettah here's a fresh link:

https://multipass-ci.s3.amazonaws.com/pr403/multipass-1.8.0-dev.787.pr403%2Bg9c2fa6ea.mac%2Barm64-Darwin.pkg

sxueck commented 3 years ago

@djettah here's a fresh link:

https://multipass-ci.s3.amazonaws.com/pr403/multipass-1.8.0-dev.787.pr403%2Bg9c2fa6ea.mac%2Barm64-Darwin.pkg

This version of the network io has problems often timeout

townsend2010 commented 3 years ago

Hi @sxueck,

Could you please provide some more details? I haven't seen issues and I'd like to know if I need to dig into a problem. Thanks!

ashmckenzie commented 3 years ago

Tested 1.8.0-dev.787.pr403+g9c2fa6ea.mac on my M1 mac and it works, thanks! 👍 

$ uname -a
Darwin machine.local 20.6.0 Darwin Kernel Version 20.6.0: Mon Aug 30 06:12:20 PDT 2021; root:xnu-7195.141.6~3/RELEASE_ARM64_T8101 arm64

$ multipass version
multipass   1.8.0-dev.787.pr403+g9c2fa6ea.mac
multipassd  1.8.0-dev.787.pr403+g9c2fa6ea.mac

$ multipass list
Name                    State             IPv4             Image
primary                 Running           192.168.64.12    Ubuntu 20.04 LTS

$ multipass exec primary -- uname -a
Linux primary 5.4.0-84-generic #94-Ubuntu SMP Thu Aug 26 19:28:28 UTC 2021 aarch64 aarch64 aarch64 GNU/Linux
mattou78400 commented 3 years ago

I can't seem to get it started myself

 ~ % multipass launch ubuntu
launch failed: The following errors occurred:                                   
sustained-monster: timed out waiting for response

~ % multipass version
multipass   1.8.0-dev.787.pr403+g9c2fa6ea.mac
multipassd  1.8.0-dev.787.pr403+g9c2fa6ea.mac
Saviq commented 3 years ago

Hi @mattou78400, any VPN in play or firewall maybe? Can you post the output of multipass launch -vvvv ubuntu please?

mattou78400 commented 3 years ago

Here you go sir

~ % multipass launch -vvvv ubuntu
[2021-09-16T13:53:24.042] [trace] [url downloader] Found https://codeload.github.com/canonical/multipass-workflows/zip/refs/heads/main in cache: true
[2021-09-16T13:53:24.712] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/16/stable/current/SHA256SUMS in cache: true
[2021-09-16T13:53:25.303] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/18/stable/current/SHA256SUMS in cache: true
[2021-09-16T13:53:26.030] [trace] [url downloader] Found https://cloud-images.ubuntu.com/buildd/releases/bionic/release/SHA256SUMS in cache: true
[2021-09-16T13:53:26.614] [trace] [url downloader] Found https://cloud-images.ubuntu.com/buildd/releases/focal/release/SHA256SUMS in cache: true
[2021-09-16T13:53:27.219] [trace] [url downloader] Found https://cloud-images.ubuntu.com/minimal/releases/xenial/release/SHA256SUMS in cache: true
[2021-09-16T13:53:27.815] [trace] [url downloader] Found https://cloud-images.ubuntu.com/releases/streams/v1/index.json in cache: false
[2021-09-16T13:53:29.080] [trace] [url downloader] Found https://cloud-images.ubuntu.com/releases/streams/v1/com.ubuntu.cloud:released:download.json in cache: false
[2021-09-16T13:53:29.171] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/appliances/streams/v1/index.json in cache: true
[2021-09-16T13:53:29.172] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/appliances/streams/v1/com.ubuntu.appliances:released:download.json in cache: true
[2021-09-16T13:53:29.172] [info] [VMImageHost] Did not find any supported products in "appliance"
[2021-09-16T13:53:29.174] [debug] [qemu-system-aarch64] [20566] started: qemu-system-aarch64 --version
[2021-09-16T13:53:29.210] [debug] [qemu-img] [20567] started: qemu-img info /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210907/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-16T13:53:29.223] [debug] [qemu-img] [20568] started: qemu-img resize /var/root/Library/Application Support/multipassd/qemu/vault/instances/lusty-vireo/ubuntu-20.04-server-cloudimg-arm64.img 5368709120
[2021-09-16T13:53:29.248] [debug] [qemu-img] [20569] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/lusty-vireo/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-16T13:53:29.251] [debug] [lusty-vireo] process working dir ''          
[2021-09-16T13:53:29.251] [info] [lusty-vireo] process program 'qemu-system-aarch64'
[2021-09-16T13:53:29.251] [info] [lusty-vireo] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:c1:56:b1, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/lusty-vireo/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/lusty-vireo/cloud-init-config.iso'
[2021-09-16T13:53:29.252] [debug] [qemu-system-aarch64] [20570] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.xBcFUN
[2021-09-16T13:53:29.290] [info] [lusty-vireo] process state changed to Starting
[2021-09-16T13:53:29.291] [info] [lusty-vireo] process state changed to Running 
[2021-09-16T13:53:29.291] [debug] [qemu-system-aarch64] [20571] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:c1:56:b1 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/lusty-vireo/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/lusty-vireo/cloud-init-config.iso
[2021-09-16T13:53:29.291] [info] [lusty-vireo] process started                  
launch failed: The following errors occurred:                                   
lusty-vireo: timed out waiting for response

Thanks a lot!

adamcstephens commented 3 years ago

I was able to create and use a single VM, but then deleted it. Now I'm having the same issue as @mattou78400. The qemu process is launched and continues to run, but multipass times out.

─❯ multipass launch -c 4 -d 20G -vvvv           
[2021-09-23T16:01:26.620] [trace] [url downloader] Found https://codeload.github.com/canonical/multipass-workflows/zip/refs/heads/main in cache: true
[2021-09-23T16:01:26.904] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/16/stable/current/SHA256SUMS in cache: true
[2021-09-23T16:01:27.082] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/18/stable/current/SHA256SUMS in cache: true
[2021-09-23T16:01:27.261] [trace] [url downloader] Found https://cloud-images.ubuntu.com/buildd/releases/bionic/release/SHA256SUMS in cache: true
[2021-09-23T16:01:27.441] [trace] [url downloader] Found https://cloud-images.ubuntu.com/buildd/releases/focal/release/SHA256SUMS in cache: true
[2021-09-23T16:01:27.617] [trace] [url downloader] Found https://cloud-images.ubuntu.com/minimal/releases/xenial/release/SHA256SUMS in cache: true
[2021-09-23T16:01:27.813] [trace] [url downloader] Found https://cloud-images.ubuntu.com/releases/streams/v1/index.json in cache: false
[2021-09-23T16:01:27.848] [trace] [url downloader] Found https://cloud-images.ubuntu.com/releases/streams/v1/com.ubuntu.cloud:released:download.json in cache: true
[2021-09-23T16:01:27.925] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/appliances/streams/v1/index.json in cache: true
[2021-09-23T16:01:27.926] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/appliances/streams/v1/com.ubuntu.appliances:released:download.json in cache: true
[2021-09-23T16:01:27.927] [info] [VMImageHost] Did not find any supported products in "appliance"
[2021-09-23T16:01:27.929] [debug] [qemu-system-aarch64] [92380] started: qemu-system-aarch64 --version
[2021-09-23T16:01:27.960] [debug] [qemu-img] [92381] started: qemu-img info /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210921/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-23T16:01:27.982] [debug] [qemu-img] [92382] started: qemu-img resize /var/root/Library/Application Support/multipassd/qemu/vault/instances/vivacious-razorbill/ubuntu-20.04-server-cloudimg-arm64.img 21474836480
[2021-09-23T16:01:27.994] [debug] [qemu-img] [92383] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/vivacious-razorbill/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-23T16:01:28.001] [debug] [vivacious-razorbill] process working dir ''  
[2021-09-23T16:01:28.001] [info] [vivacious-razorbill] process program 'qemu-system-aarch64'
[2021-09-23T16:01:28.001] [info] [vivacious-razorbill] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:ca:a8:22, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/vivacious-razorbill/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 4, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/vivacious-razorbill/cloud-init-config.iso'
[2021-09-23T16:01:28.003] [debug] [qemu-system-aarch64] [92384] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.wTZYXe
[2021-09-23T16:01:28.042] [info] [vivacious-razorbill] process state changed to Starting
[2021-09-23T16:01:28.044] [info] [vivacious-razorbill] process state changed to Running
[2021-09-23T16:01:28.045] [debug] [qemu-system-aarch64] [92385] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:ca:a8:22 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/vivacious-razorbill/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 4 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/vivacious-razorbill/cloud-init-config.iso
[2021-09-23T16:01:28.045] [info] [vivacious-razorbill] process started          
launch failed: The following errors occurred:                                   
vivacious-razorbill: timed out waiting for response

─❯ ps -ef | grep vivacious
    0 92385 11388   0  4:01PM ??         0:23.18 /Library/Application Support/com.canonical.multipass/bin/qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:ca:a8:22 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/vivacious-razorbill/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 4 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/vivacious-razorbill/cloud-init-config.iso
lethargosapatheia commented 3 years ago

In my case, it stopped working after restarting the laptop (macbook pro m1, big sur 11.6) But the error looks slightly differently:

multipass launch -vvvv ubuntu
[2021-09-27T12:23:04.940] [trace] [url downloader] Found https://codeload.github.com/canonical/multipass-workflows/zip/refs/heads/main in cache: true
[2021-09-27T12:23:05.546] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/16/stable/current/SHA256SUMS in cache: true
[2021-09-27T12:23:06.100] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/18/stable/current/SHA256SUMS in cache: true
[2021-09-27T12:23:06.695] [trace] [url downloader] Found https://cloud-images.ubuntu.com/buildd/releases/bionic/release/SHA256SUMS in cache: true
[2021-09-27T12:23:07.244] [trace] [url downloader] Found https://cloud-images.ubuntu.com/buildd/releases/focal/release/SHA256SUMS in cache: true
[2021-09-27T12:23:07.798] [trace] [url downloader] Found https://cloud-images.ubuntu.com/minimal/releases/xenial/release/SHA256SUMS in cache: true
[2021-09-27T12:23:08.364] [trace] [url downloader] Found https://cloud-images.ubuntu.com/releases/streams/v1/index.json in cache: false
[2021-09-27T12:23:09.933] [trace] [url downloader] Found https://cloud-images.ubuntu.com/releases/streams/v1/com.ubuntu.cloud:released:download.json in cache: false
[2021-09-27T12:23:10.022] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/appliances/streams/v1/index.json in cache: true
[2021-09-27T12:23:10.022] [trace] [url downloader] Found https://cdimage.ubuntu.com/ubuntu-core/appliances/streams/v1/com.ubuntu.appliances:released:download.json in cache: true
[2021-09-27T12:23:10.023] [info] [VMImageHost] Did not find any supported products in "appliance"
[2021-09-27T12:23:10.025] [debug] [qemu-system-aarch64] [5057] started: qemu-system-aarch64 --version
[2021-09-27T12:23:10.104] [debug] [qemu-img] [5058] started: qemu-img info /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210921/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-27T12:23:10.116] [debug] [qemu-img] [5059] started: qemu-img resize /var/root/Library/Application Support/multipassd/qemu/vault/instances/polite-octopus/ubuntu-20.04-server-cloudimg-arm64.img 5368709120
[2021-09-27T12:23:10.122] [debug] [qemu-img] [5060] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/polite-octopus/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-27T12:23:10.126] [debug] [polite-octopus] process working dir ''
[2021-09-27T12:23:10.126] [info] [polite-octopus] process program 'qemu-system-aarch64'
[2021-09-27T12:23:10.126] [info] [polite-octopus] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e9:70:db, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/polite-octopus/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/polite-octopus/cloud-init-config.iso'
[2021-09-27T12:23:10.127] [debug] [qemu-system-aarch64] [5061] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.MeWcXB
[2021-09-27T12:23:10.160] [info] [polite-octopus] process state changed to Starting
[2021-09-27T12:23:10.161] [info] [polite-octopus] process state changed to Running
[2021-09-27T12:23:10.162] [debug] [qemu-system-aarch64] [5062] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e9:70:db -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/polite-octopus/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/polite-octopus/cloud-init-config.iso
[2021-09-27T12:23:10.162] [info] [polite-octopus] process started
launch failed: The following errors occurred:
polite-octopus: timed out waiting for response

And the process is still running:

ps aux | grep polite
root              5062   0.0  0.7 410513808 116672   ??  S    12:23PM   0:20.58 /Library/Application Support/com.canonical.multipass/bin/qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e9:70:db -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/polite-octopus/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/polite-octopus/cloud-init-config.iso
townsend2010 commented 3 years ago

@mattou78400, @adamcstephens, @lethargosapatheia, or any else getting timed out waiting for response issues,

Could you also please post the relevant part (meaning the part of where the instance is being launched) in the log found at /Library/Logs/Multipass/multipassd.log?

Thanks!

adamcstephens commented 3 years ago

@townsend2010

Could you also please post the relevant part (meaning the part of where the instance is being launched) in the log found at /Library/Logs/Multipass/multipassd.log?

[2021-09-27T15:13:13.017] [info] [VMImageHost] Did not find any supported products in "appliance"
[2021-09-27T15:13:13.149] [debug] [qemu-system-aarch64] [88148] started: qemu-system-aarch64 --version
[2021-09-27T15:13:13.515] [debug] [qemu-img] [88149] started: qemu-img info /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210921/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-27T15:13:13.566] [debug] [qemu-img] [88150] started: qemu-img resize /var/root/Library/Application Support/multipassd/qemu/vault/instances/amazing-jerboa/ubuntu-20.04-server-cloudimg-arm64.img 21474836480
[2021-09-27T15:13:13.577] [debug] [qemu-img] [88151] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/amazing-jerboa/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-27T15:13:13.584] [debug] [amazing-jerboa] process working dir ''
[2021-09-27T15:13:13.584] [info] [amazing-jerboa] process program 'qemu-system-aarch64'
[2021-09-27T15:13:13.584] [info] [amazing-jerboa] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/amazing-jerboa/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 4, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/amazing-jerboa/cloud-init-config.iso'
[2021-09-27T15:13:13.586] [debug] [qemu-system-aarch64] [88152] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.aDuINg
[2021-09-27T15:13:13.642] [info] [amazing-jerboa] process state changed to Starting
[2021-09-27T15:13:13.643] [info] [amazing-jerboa] process state changed to Running
[2021-09-27T15:13:13.644] [debug] [qemu-system-aarch64] [88153] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/amazing-jerboa/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 4 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/amazing-jerboa/cloud-init-config.iso
[2021-09-27T15:13:13.644] [info] [amazing-jerboa] process started
[2021-09-27T15:13:13.644] [debug] [amazing-jerboa] Waiting for SSH to be up
[2021-09-27T15:13:14.340] [warning] [amazing-jerboa] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: MAC:              ca:5e:03:51:a5:84
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:44:a0:8d: info: UUID:             B7B80AF9-7FCC-4EFB-BBCE-C0B734029EA9

[2021-09-27T15:13:14.340] [warning] [qemu-system-aarch64] 
[2021-09-27T15:13:14.340] [debug] [amazing-jerboa] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2021-09-27T15:13:14.389] [debug] [amazing-jerboa] QMP: {"return": {}}

[2021-09-27T15:13:28.398] [debug] [amazing-jerboa] QMP: {"timestamp": {"seconds": 1632770008, "microseconds": 398476}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[9]/virtio-backend"}}

And then when I killed the process


[2021-09-27T15:22:45.647] [error] [amazing-jerboa] process error occurred Crashed program: qemu-system-aarch64; error: Process crashed
[2021-09-27T15:22:45.650] [info] [amazing-jerboa] process state changed to NotRunning
[2021-09-27T15:22:45.650] [error] [amazing-jerboa] error: program: qemu-system-aarch64; error: Process crashed
townsend2010 commented 3 years ago

Hi @adamcstephens,

Ok, the log looks mostly sane in that the instances network adapter looks ready. Could you also post what is in /var/db/dhcpd_leases?

Also, doing tail -f /var/log/system.log while starting an instance and posting the output may provide some info as well.

adamcstephens commented 3 years ago

Hi @townsend2010

Not much in the system log, but the dhcpd leases seems to be missing the newer VMs. Latest was named wanted-frog.

Sep 27 15:34:16 mycomputer pfd[11080]: DEPRECATED USE in libdispatch client: Setting timer interval to 0 requests a 1ns timer, did you mean FOREVER (a one-shot timer)?; set a breakpoint on _dispatch_bug_deprecated to debug
Sep 27 15:34:16 mycomputer com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.system): entering bootstrap mode
Sep 27 15:34:16 mycomputer com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.system): exiting bootstrap mode
Sep 27 15:34:16 mycomputer InternetSharing[11079]: DEPRECATED USE in libdispatch client: Setting timer interval to 0 requests a 1ns timer, did you mean FOREVER (a one-shot timer)?; set a breakpoint on _dispatch_bug_deprecated to debug
Sep 27 15:34:16 mycomputer com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.system): entering bootstrap mode
Sep 27 15:34:16 mycomputer com.apple.xpc.launchd[1] (com.apple.xpc.launchd.domain.system): exiting bootstrap mode
Sep 27 15:34:16 mycomputer com.apple.xpc.launchd[1] (com.apple.dhcp6d): This service is defined to be constantly running and is inherently inefficient.
Sep 27 15:34:44 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.04000000-0400-0000-0000-000000000000[10297]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:34:48 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0D000000-0000-0000-0000-000000000000[10885]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:34:48 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.03000000-0200-0000-0000-000000000000[10130]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:35:11 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.03000000-0300-0000-0000-000000000000[11591]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:35:11 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0D000000-0100-0000-0000-000000000000[11592]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:35:53 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.04000000-0500-0000-0000-000000000000[11750]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:35:53 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.08000000-0300-0000-0000-000000000000[12085]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:35:54 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.03000000-0400-0000-0000-000000000000[12090]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:36:15 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.05000000-0400-0000-0000-000000000000[12086]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:36:16 mycomputer systemstats[308]: assertion failed: 20G95: systemstats + 413748 [F3867909-0B62-389F-8F1D-33E6671E7A01]: 0x0
Sep 27 15:36:16 mycomputer systemstats[308]: assertion failed: 20G95: systemstats + 615252 [F3867909-0B62-389F-8F1D-33E6671E7A01]: 0x2
Sep 27 15:36:48 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.04000000-0600-0000-0000-000000000000[12340]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:37:01 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0D000000-0200-0000-0000-000000000000[12091]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:37:30 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.05000000-0500-0000-0000-000000000000[12334]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:38:06 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.04000000-0700-0000-0000-000000000000[12365]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:38:08 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0B000000-0200-0000-0000-000000000000[10880]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:38:25 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.08000000-0400-0000-0000-000000000000[12341]): Service exited due to SIGKILL | sent by mds[330]
Sep 27 15:38:25 mycomputer com.apple.xpc.launchd[1] (com.apple.mdworker.shared.0D000000-0300-0000-0000-000000000000[12390]): Service exited due to SIGKILL | sent by mds[330]
^C

~ took 5m13s 
─❯ cat /var/db/dhcpd_leases       
{
        name=primary
        ip_address=192.168.64.4
        hw_address=1,52:54:0:81:4c:12
        identifier=1,52:54:0:81:4c:12
        lease=0x614c9b0a
}
{
        name=sassy-amoeba
        ip_address=192.168.64.3
        hw_address=1,52:54:0:fe:43:f9
        identifier=1,52:54:0:fe:43:f9
        lease=0x614c99a2
}
{
        name=divine-porcupine
        ip_address=192.168.64.2
        hw_address=1,52:54:0:aa:d9:9a
        identifier=1,52:54:0:aa:d9:9a
        lease=0x612449c1
}
lethargosapatheia commented 3 years ago

In case it helps, this is my /Library/Logs/Multipass/multipassd.log:

[2021-09-28T15:40:11.464] [info] [VMImageHost] Did not find any supported products in "appliance"
[2021-09-28T15:40:11.467] [debug] [qemu-system-aarch64] [29453] started: qemu-system-aarch64 --version
[2021-09-28T15:40:11.549] [debug] [qemu-img] [29454] started: qemu-img info /var/root/Library/Caches/multipassd/qemu/vault/images/focal-20210927/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-28T15:40:11.562] [debug] [qemu-img] [29455] started: qemu-img resize /var/root/Library/Application Support/multipassd/qemu/vault/instances/u2004/ubuntu-20.04-server-cloudimg-arm64.img 5368709120
[2021-09-28T15:40:11.567] [debug] [qemu-img] [29456] started: qemu-img snapshot -l /var/root/Library/Application Support/multipassd/qemu/vault/instances/u2004/ubuntu-20.04-server-cloudimg-arm64.img
[2021-09-28T15:40:11.571] [debug] [u2004] process working dir ''
[2021-09-28T15:40:11.571] [info] [u2004] process program 'qemu-system-aarch64'
[2021-09-28T15:40:11.571] [info] [u2004] process arguments '-machine, virt,highmem=off, -accel, hvf, -drive, file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on, -nic, vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63, -cpu, cortex-a72, -device, virtio-scsi-pci,id=scsi0, -drive, file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/u2004/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda, -device, scsi-hd,drive=hda,bus=scsi0.0, -smp, 1, -m, 1024M, -qmp, stdio, -chardev, null,id=char0, -serial, chardev:char0, -nographic, -cdrom, /var/root/Library/Application Support/multipassd/qemu/vault/instances/u2004/cloud-init-config.iso'
[2021-09-28T15:40:11.573] [debug] [qemu-system-aarch64] [29457] started: qemu-system-aarch64 -machine virt,highmem=off -nographic -dump-vmstate /private/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/multipassd.bHrkMH
[2021-09-28T15:40:11.606] [info] [u2004] process state changed to Starting
[2021-09-28T15:40:11.607] [info] [u2004] process state changed to Running
[2021-09-28T15:40:11.607] [debug] [qemu-system-aarch64] [29458] started: qemu-system-aarch64 -machine virt,highmem=off -accel hvf -drive file=/Library/Application Support/com.canonical.multipass/bin/../Resources/qemu/edk2-aarch64-code.fd,if=pflash,format=raw,readonly=on -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63 -cpu cortex-a72 -device virtio-scsi-pci,id=scsi0 -drive file=/var/root/Library/Application Support/multipassd/qemu/vault/instances/u2004/ubuntu-20.04-server-cloudimg-arm64.img,if=none,format=qcow2,discard=unmap,id=hda -device scsi-hd,drive=hda,bus=scsi0.0 -smp 1 -m 1024M -qmp stdio -chardev null,id=char0 -serial chardev:char0 -nographic -cdrom /var/root/Library/Application Support/multipassd/qemu/vault/instances/u2004/cloud-init-config.iso
[2021-09-28T15:40:11.607] [info] [u2004] process started
[2021-09-28T15:40:11.607] [debug] [u2004] Waiting for SSH to be up
[2021-09-28T15:40:12.056] [warning] [u2004] qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63: info: Started vmnet interface with configuration:
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63: info: MTU:              1500
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63: info: Max packet size:  1514
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63: info: MAC:              5a:76:01:cf:c2:9d
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63: info: DHCP IPv4 start:  192.168.64.1
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63: info: DHCP IPv4 end:    192.168.64.254
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63: info: IPv4 subnet mask: 255.255.255.0
qemu-system-aarch64: -nic vmnet-macos,mode=shared,model=virtio-net-pci,mac=52:54:00:e2:69:63: info: UUID:             4E552E97-16AD-4411-AC4A-37EFFCEB1B7B

[2021-09-28T15:40:12.056] [warning] [qemu-system-aarch64]
[2021-09-28T15:40:12.059] [debug] [u2004] QMP: {"QMP": {"version": {"qemu": {"micro": 0, "minor": 1, "major": 6}, "package": ""}, "capabilities": ["oob"]}}

[2021-09-28T15:40:12.112] [debug] [u2004] QMP: {"return": {}}

[2021-09-28T15:40:25.688] [debug] [u2004] QMP: {"timestamp": {"seconds": 1632832825, "microseconds": 688330}, "event": "NIC_RX_FILTER_CHANGED", "data": {"path": "/machine/unattached/device[6]/virtio-backend"}}

/var/db/dhcpd_leases:

{
    name=k8s-single-node-1
    ip_address=192.168.64.3
    hw_address=1,52:54:0:eb:f9:82
    identifier=1,52:54:0:eb:f9:82
    lease=0x61502e7a
}
{
    name=primary
    ip_address=192.168.64.2
    hw_address=1,52:54:0:bf:4f:50
    identifier=1,52:54:0:bf:4f:50
    lease=0x614e5467
}

I have several now deleted VMs, but the IPs only for the first two (primary and k8s-single-node-1):

 multipass list
Name                    State             IPv4             Image
primary                 Deleted           --               Not Available
k8s-single-node-1       Deleted           --               Not Available
polite-octopus          Stopped           --               Ubuntu 20.04 LTS
u20                     Deleted           --               Not Available

It was a little bit hard for me to get the relevant logs from /var/log/system.log, as teamviewer (which I haven't uninstalled completely) kept spamming the logs :D (launchd), but here's part of it:

Sep 28 15:43:57 hostname syslogd[278]: ASL Sender Statistics
Sep 28 15:44:01 hostname VTDecoderXPCService[8626]: DEPRECATED USE in libdispatch client: Changing the target of a source after it has been activated; set a breakpoint on _dispatch_bug_deprecated to debug
Sep 28 15:44:01 hostname VTDecoderXPCService[8626]: DEPRECATED USE in libdispatch client: Changing target queue hierarchy after xpc connection was activated; set a breakpoint on _dispatch_bug_deprecated to debug
Sep 28 15:44:02 hostname com.apple.xpc.launchd[1] (com.apple.mdworker.shared.06000000-0700-0000-0000-000000000000[29611]): Service exited due to SIGKILL | sent by mds[310]
townsend2010 commented 3 years ago

@adamcstephens & @lethargosapatheia,

With an instance started, could you run ps -aef | grep InternetSharing and see if the InternetSharing process is running? If it's not, it might be worth a try of toggling Internet Sharing on and then back off again. To do this go to System Preferences->Sharing and then select Internet Sharing and then unselect it.

lethargosapatheia commented 3 years ago

@townsend2010 I cannot start any instance anymore. I would need to create a new one and creating a new one leads to our problem - timeout.

townsend2010 commented 3 years ago

@lethargosapatheia,

Right, what I mean is when the launch is occurring, do you see that InternetSharing process running? I'm suspecting there is some issue on your host where the process responsible for handling DHCP requests from virtual machines is not working properly, but it's not clear why.

lethargosapatheia commented 3 years ago

Yes, the process is there, also before trying to run a new vm instance:

$ ps aux | grep -i internet
root             29459   0.0  0.0 408641808   4880   ??  Ss    3:40PM   0:14.76 /usr/libexec/InternetSharing

But before this I activated and deactivated internet sharing. Didn't check the process then.

adamcstephens commented 3 years ago

@townsend2010 yes InternetSharing is running. I killed it, ran another launch, and InternetSharing was started again.

townsend2010 commented 3 years ago

@lethargosapatheia & @adamcstephens,

Just curious if you are running any other type of virtualization software such as Docker, etc?

lethargosapatheia commented 3 years ago

Yes, I have docker desktop installed, latest version (20.10.8) and Parallels (17.0.1), but I'm not running any of them at the same time with multipass.

townsend2010 commented 3 years ago

Ok, well, I'm running out of ideas. Does Docker/Parallels still work as expected? Does vftool and/or vmcli work as expected?

lethargosapatheia commented 3 years ago

Paralells worked just fine until the trial expired some 2 weeks ago :) Docker Desktop works as expected, yes, I haven't seen anything weird. I don't know what vftool or vmcli are :) I don't have the commands in the cli.

townsend2010 commented 3 years ago

@lethargosapatheia,

The names of the tools in my previous reply are links to the projects, but for clarity, they are: https://github.com/evansm7/vftool https://github.com/gyf304/vmcli

It's up to you if you want to try them. I'm just trying to find some data points on what the issue could possibly be :slightly_smiling_face:

lethargosapatheia commented 3 years ago

Yes, I want to try them. I'm starting with vftool. I just don't understand why I need to give the kernel path and where I'm supposed to get it from. Directly from kernel org? Seems strange, the image should contain the kernel also, I expect.

Saviq commented 3 years ago

Yes, I want to try them. I'm starting with vftool. I just don't understand why I need to give the kernel path and where I'm supposed to get it from. Directly from kernel org? Seems strange, the image should contain the kernel also, I expect.

That's because the vftool does not include a bootloader, so the kernel needs to be executed directly.

You can grab the Ubuntu kernel and initrd from https://cloud-images.ubuntu.com/releases/focal/release/unpacked/ (for 20.04, other releases can also be found there).