multipassd.log

[2020-02-19T12:31:23.704] [info] [rpc] gRPC listening on unix:/var/run/multipass_socket, SSL:on
[2020-02-19T12:31:23.707] [info] [daemon] dev needs starting. Starting now...
[2020-02-19T12:31:23.717] [info] [dev] process program '/Library/Application Support/com.canonical.multipass/bin/hyperkit'
[2020-02-19T12:31:23.717] [info] [dev] process arguments '-c, 4, -m, 8192M, -u, -A, -H, -U, e77989ed-2175-3e78-b31b-20e477fc5582, -s, 0:0,hostbridge, -s, 2:0,virtio-net, -s, 5,virtio-rnd, -s, 31,lpc, -l, com1,autopty=/var/root/Library/Application Support/multipassd/vault/instances/dev/pty,log=/Library/Logs/Multipass/dev-hyperkit.log, -s, 1:0,ahci-hd,file:///var/root/Library/Application Support/multipassd/vault/instances/dev/ubuntu-18.04-server-cloudimg-amd64.img?sync=os&buffered=1,format=qcow,qcow-config=discard=true;compact_after_unmaps=262144;keep_erased=262144;runtime_asserts=false, -s, 1:1,ahci-cd,/var/root/Library/Application Support/multipassd/vault/instances/dev/cloud-init-config.iso, -f, kexec,/var/root/Library/Application Support/multipassd/vault/instances/dev/ubuntu-18.04-server-cloudimg-amd64-vmlinuz-generic,/var/root/Library/Application Support/multipassd/vault/instances/dev/ubuntu-18.04-server-cloudimg-amd64-initrd-generic,earlyprintk=serial console=ttyS0 root=/dev/sda1 rw panic=1 no_timer_check'
[2020-02-19T12:31:23.717] [info] [dev] process state changed to Starting
[2020-02-19T12:31:23.722] [info] [dev] process state changed to Running
[2020-02-19T12:31:23.723] [warning] [url downloader] Cannot retrieve last modified date for http://cloud-images.ubuntu.com/releases/streams/v1/index.json: Host cloud-images.ubuntu.com not found. Using cached data instead.
[2020-02-19T12:31:23.729] [warning] [url downloader] Cannot retrieve last modified date for http://cloud-images.ubuntu.com/releases/streams/v1/com.ubuntu.cloud:released:download.json: Host cloud-images.ubuntu.com not found. Using cached data instead.
[2020-02-19T12:31:23.753] [error] [dev] hv_vm_create unknown error -85377023
[2020-02-19T12:31:23.753] [error] [dev] process error occurred Crashed
[2020-02-19T12:31:23.753] [info] [dev] process state changed to NotRunning
[2020-02-19T12:31:23.753] [info] [dev] process finished with exit code 6
[2020-02-19T12:31:23.808] [warning] [url downloader] Cannot retrieve last modified date for http://cloud-images.ubuntu.com/daily/streams/v1/index.json: Host cloud-images.ubuntu.com not found. Using cached data instead.
[2020-02-19T12:31:23.818] [warning] [url downloader] Cannot retrieve last modified date for http://cloud-images.ubuntu.com/daily/streams/v1/com.ubuntu.cloud:daily:download.json: Host cloud-images.ubuntu.com not found. Using cached data instead.
[2020-02-19T12:31:23.821] [warning] [VMImageHost] Could not update manifest: failed to download from 'http://cdimage.ubuntu.com/ubuntu-core/16/stable/current/ubuntu-core-16-amd64.img.xz': Host cdimage.ubuntu.com not found
[2020-02-19T12:31:23.822] [warning] [VMImageHost] Could not update manifest: failed to download from 'http://cloud-images.ubuntu.com/minimal/releases/xenial/release/ubuntu-16.04-minimal-cloudimg-amd64-disk1.img': Host cloud-images.ubuntu.com not found
[2020-02-19T12:31:24.026] [info] [update] Failed to fetch update info: failed to download from 'https://multipass.run/static/latest-release.json': Host multipass.run not found
[2020-02-19T12:32:29.927] [info] [dev] process program '/Library/Application Support/com.canonical.multipass/bin/hyperkit'
[2020-02-19T12:32:29.927] [info] [dev] process arguments '-c, 4, -m, 8192M, -u, -A, -H, -U, e77989ed-2175-3e78-b31b-20e477fc5582, -s, 0:0,hostbridge, -s, 2:0,virtio-net, -s, 5,virtio-rnd, -s, 31,lpc, -l, com1,autopty=/var/root/Library/Application Support/multipassd/vault/instances/dev/pty,log=/Library/Logs/Multipass/dev-hyperkit.log, -s, 1:0,ahci-hd,file:///var/root/Library/Application Support/multipassd/vault/instances/dev/ubuntu-18.04-server-cloudimg-amd64.img?sync=os&buffered=1,format=qcow,qcow-config=discard=true;compact_after_unmaps=262144;keep_erased=262144;runtime_asserts=false, -s, 1:1,ahci-cd,/var/root/Library/Application Support/multipassd/vault/instances/dev/cloud-init-config.iso, -f, kexec,/var/root/Library/Application Support/multipassd/vault/instances/dev/ubuntu-18.04-server-cloudimg-amd64-vmlinuz-generic,/var/root/Library/Application Support/multipassd/vault/instances/dev/ubuntu-18.04-server-cloudimg-amd64-initrd-generic,earlyprintk=serial console=ttyS0 root=/dev/sda1 rw panic=1 no_timer_check'
[2020-02-19T12:32:29.928] [info] [dev] process state changed to Starting
[2020-02-19T12:32:29.929] [info] [dev] process state changed to Running
[2020-02-19T12:32:29.943] [info] [dev] mirage_block_open: block_config = file:///var/root/Library/Application Support/multipassd/vault/instances/dev/ubuntu-18.04-server-cloudimg-amd64.img?sync=os&buffered=1 and qcow_config = discard=true;compact_after_unmaps=262144;keep_erased=262144;runtime_asserts=false and stats_config = None

[2020-02-19T12:32:30.844] [info] [dev] hyperkit: [INFO] Resized file to 152337 clusters (19499136 sectors)
[2020-02-19T12:32:30.844] [info] [dev] hyperkit: [INFO] block recycler starting with keep_erased = 2048
[2020-02-19T12:32:30.846] [info] [dev] hyperkit: [INFO] image has 0 free sectors and 151509 used sectors
[2020-02-19T12:32:30.846] [info] [dev] mirage_block_open: block_config = file:///var/root/Library/Application Support/multipassd/vault/instances/dev/ubuntu-18.04-server-cloudimg-amd64.img?sync=os&buffered=1 and qcow_config = discard=true;compact_after_unmaps=262144;keep_erased=262144;runtime_asserts=false and stats_config = None returning 0
mirage_block_stat

[2020-02-19T12:32:30.846] [info] [dev] fcntl(F_PUNCHHOLE) failed: host filesystem does not support sparse files: Operation not permitted
[2020-02-19T12:32:31.698] [info] [dev] rdmsr to register 0x140 on vcpu 0
[2020-02-19T12:32:31.830] [info] [dev] rdmsr to register 0x140 on vcpu 1
[2020-02-19T12:32:32.108] [info] [dev] rdmsr to register 0x140 on vcpu 2
[2020-02-19T12:32:32.411] [info] [dev] rdmsr to register 0x140 on vcpu 3
[2020-02-19T12:32:33.337] [info] [dev] rdmsr to register 0x64e on vcpu 1
[2020-02-19T12:32:33.337] [info] [dev] rdmsr to register 0x34 on vcpu 1
[2020-02-19T12:32:35.920] [info] [dev] hyperkit: [INFO] block recycler: triggering background flush: 151509 used; 0 junk; 0 erased; 0 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 152336
[2020-02-19T12:32:41.634] [info] [dev] hyperkit: [INFO] Allocator: 151509 used; 0 junk; 0 erased; 0 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 152336
[2020-02-19T12:32:41.635] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 152336 will enlarge file to 0 .. 152848
[2020-02-19T12:32:41.635] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 152337) (y 152848) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:32:50.034] [info] [sshfs-mounts] mounting /Users/mark/src => src in dev
[2020-02-19T12:32:50.034] [info] [sshfs-mounts] process program '/Library/Application Support/com.canonical.multipass/bin/sshfs_server'
[2020-02-19T12:32:50.034] [info] [sshfs-mounts] process arguments '192.168.64.2, 22, ubuntu, /Users/mark/src, src, 501:-1,, 20:-1,'
[2020-02-19T12:33:01.694] [info] [dev] hyperkit: [INFO] Allocator: 151766 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 152593
[2020-02-19T12:33:01.694] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 152848 will enlarge file to 0 .. 153360
[2020-02-19T12:33:01.694] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 152849) (y 153360) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:02.838] [info] [dev] hyperkit: [INFO] Allocator: 152278 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 153105
[2020-02-19T12:33:02.838] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 153360 will enlarge file to 0 .. 153872
[2020-02-19T12:33:02.838] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 153361) (y 153872) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:07.290] [info] [dev] hyperkit: [INFO] Allocator: 152790 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 153617
[2020-02-19T12:33:07.290] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 153872 will enlarge file to 0 .. 154384
[2020-02-19T12:33:07.290] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 153873) (y 154384) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:09.092] [info] [dev] hyperkit: [INFO] Allocator: 153302 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 154129
[2020-02-19T12:33:09.092] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 154384 will enlarge file to 0 .. 154896
[2020-02-19T12:33:09.092] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 154385) (y 154896) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:16.796] [info] [dev] hyperkit: [INFO] Allocator: 153814 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 154641
[2020-02-19T12:33:16.796] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 154896 will enlarge file to 0 .. 155408
[2020-02-19T12:33:16.796] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 154897) (y 155408) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:16.962] [info] [dev] hyperkit: [INFO] Allocator: 154326 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 155153
[2020-02-19T12:33:16.963] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 155408 will enlarge file to 0 .. 155920
[2020-02-19T12:33:16.963] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 155409) (y 155920) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:17.486] [info] [dev] hyperkit: [INFO] Allocator: 154838 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 155665
[2020-02-19T12:33:17.486] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 155920 will enlarge file to 0 .. 156432
[2020-02-19T12:33:17.486] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 155921) (y 156432) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:20.334] [info] [dev] hyperkit: [INFO] Allocator: 155350 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 156177
[2020-02-19T12:33:20.334] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 156432 will enlarge file to 0 .. 156944
[2020-02-19T12:33:20.334] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 156433) (y 156944) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:22.438] [info] [dev] hyperkit: [INFO] Allocator: 155862 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 156689
[2020-02-19T12:33:22.438] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 156944 will enlarge file to 0 .. 157456
[2020-02-19T12:33:22.438] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 156945) (y 157456) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:23.058] [info] [dev] hyperkit: [INFO] Allocator: 156374 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 157201
[2020-02-19T12:33:23.059] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 157456 will enlarge file to 0 .. 157968
[2020-02-19T12:33:23.059] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 157457) (y 157968) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:24.835] [info] [dev] hyperkit: [INFO] Allocator: 156886 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 157713
[2020-02-19T12:33:24.836] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 157968 will enlarge file to 0 .. 158480
[2020-02-19T12:33:24.836] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 157969) (y 158480) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:25.688] [info] [dev] hyperkit: [INFO] Allocator: 157398 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 158225
[2020-02-19T12:33:25.688] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 158480 will enlarge file to 0 .. 158992
[2020-02-19T12:33:25.688] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 158481) (y 158992) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:26.339] [info] [dev] hyperkit: [INFO] Allocator: 157910 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 158737
[2020-02-19T12:33:26.339] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 158992 will enlarge file to 0 .. 159504
[2020-02-19T12:33:26.339] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 158993) (y 159504) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:27.119] [info] [dev] hyperkit: [INFO] Allocator: 158422 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 159249
[2020-02-19T12:33:27.119] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 159504 will enlarge file to 0 .. 160016
[2020-02-19T12:33:27.119] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 159505) (y 160016) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:27.764] [info] [dev] hyperkit: [INFO] Allocator: 158934 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 159761
[2020-02-19T12:33:27.764] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 160016 will enlarge file to 0 .. 160528
[2020-02-19T12:33:27.765] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 160017) (y 160528) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:32.149] [info] [dev] hyperkit: [INFO] Allocator: 159446 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 160273
[2020-02-19T12:33:32.149] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 160528 will enlarge file to 0 .. 161040
[2020-02-19T12:33:32.149] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 160529) (y 161040) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:44.515] [info] [dev] hyperkit: [INFO] Allocator: 159958 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 160785
[2020-02-19T12:33:44.515] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 161040 will enlarge file to 0 .. 161552
[2020-02-19T12:33:44.515] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 161041) (y 161552) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:33:44.622] [info] [dev] hyperkit: [INFO] Allocator: 160470 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 161297
[2020-02-19T12:33:44.622] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 161552 will enlarge file to 0 .. 162064
[2020-02-19T12:33:44.622] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 161553) (y 162064) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:34:18.688] [info] [dev] hyperkit: [INFO] Allocator: 160982 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 161809
[2020-02-19T12:34:18.688] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 162064 will enlarge file to 0 .. 162576
[2020-02-19T12:34:18.688] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 162065) (y 162576) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:34:35.157] [info] [dev] sending shutdown signal to hyperkit process, waiting for it to shutdown...
[2020-02-19T12:34:35.246] [info] [dev] hyperkit: [INFO] Allocator: 161494 used; 0 junk; 0 erased; 255 available; 0 copies; 0 roots; 0 Copying; 0 Copied; 0 Flushed; 0 Referenced; max_cluster = 162321
[2020-02-19T12:34:35.247] [info] [dev] hyperkit: [INFO] Allocator: file contains cluster 0 .. 162576 will enlarge file to 0 .. 163088
[2020-02-19T12:34:35.247] [info] [dev] hyperkit: [INFO] resize: adding available clusters (Node ((x 162577) (y 163088) (l Empty) (r Empty) (h 1) (cardinal 512)))
[2020-02-19T12:34:43.065] [info] [dev] linkname /var/root/Library/Application Support/multipassd/vault/instances/dev/pty
COM1 connected to /dev/ttys001
COM1 linked to /var/root/Library/Application Support/multipassd/vault/instances/dev/pty

[2020-02-19T12:34:43.108] [info] [dev] process state changed to NotRunning
[2020-02-19T12:34:43.108] [info] [dev] process finished with exit code 0
[2020-02-19T18:31:53.892] [info] [image vault] Updating default source image to latest
[2020-02-19T18:31:53.897] [warning] [Qt] QProcess: Destroyed while process ("/Library/Application Support/com.canonical.multipass/bin/sshfs_server") is still running.
[2020-02-19T18:31:53.897] [info] [sshfs-mounts] Mount 'src' in instance "dev" has stopped
[2020-02-19T18:31:55.487] [info] [daemon]   0%
[2020-02-19T18:33:08.418] [info] [daemon]   10%
[2020-02-19T18:33:40.070] [info] [daemon]   20%
[2020-02-19T18:34:09.200] [info] [daemon]   30%
[2020-02-19T18:34:37.073] [info] [daemon]   40%
[2020-02-19T18:35:00.363] [info] [daemon]   50%
[2020-02-19T18:35:29.346] [info] [daemon]   60%
[2020-02-19T18:36:04.202] [info] [daemon]   70%
[2020-02-19T18:36:29.935] [info] [daemon]   80%
[2020-02-19T18:37:00.300] [info] [daemon]   90%
[2020-02-19T18:37:30.095] [info] [daemon]   100%