Runtime: cloud-hypervisor: Faild to create VM using latest virtiofsd (5.0 rease)
Description of problem
The PR #2840 upgrades qemu-virtiofs 5.0, on the upgrade kata fails to boot a container
looking to the logs.
error: 500 reason: VmBoot(VmBoot(DeviceManager(CreateVirtioFs(VhostUserGetProtocolFeatures(VhostUserProtocol(InvalidMessage)))))): unknown.
We should identify what version virtiofsd is recommended for cloud-hyervisor and manage from in a different place. Or make work both qemu and cloud-hypervisor with the same version.
\cc @sboeuf
jcvenegas
All 19 comments
Cloud hypervisor seems to be using a virtiofsd based in 4.0.94 https://github.com/sboeuf/qemu/blob/master/VERSION聽. The error mesasge is is not clear what is the message I got. I will try to add a few extra logs to cloud-hypervisor. I only see
Jul 24 13:38:04 clh-qemu-50 kata-hypervisor[7201]: cloud-hypervisor: 16.933191ms: INFO:vmm/src/memory_manager.rs:717 -- Created userspace mapping: 0 -> 7f0014000000 80000000
Jul 24 13:38:04 clh-qemu-50 kata-hypervisor[7201]: cloud-hypervisor: 23.083679ms: INFO:vmm/src/memory_manager.rs:717 -- Created userspace mapping: ffdffe00000 -> 7efe14000000 200000000
@dagrh could you point if there are additional changes that also requried changes on qemu to keep working with the new virtiofsd ?
jcvenegas
on 24 Jul 2020
@jcvenegas there are multiple issues with this new version of virtiofsd that I just identified while testing it with Cloud-Hypervisor.
First, we are missing the full list of supported protocol features, which is solved with this PR: https://github.com/cloud-hypervisor/vhost/pull/21
And second, after the VM is booted and the filesystem mounted, the daemon crashes while trying to read from a file in the shared directory.
Here is the end of the strace I got from the daemon, but this will need more investigation on the CH side too:
[pid 77701] write(10, "\1\0\0\0\0\0\0\0", 8 <unfinished ...>
[pid 77703] <... write resumed>) = 104
[pid 77701] <... write resumed>) = 8
[pid 77703] futex(0x7fb41bbc94b0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid 77701] futex(0x7fb398000bd0, FUTEX_WAIT_PRIVATE, 30, NULL <unfinished ...>
[pid 77703] <... futex resumed>) = 0
[pid 77643] <... ppoll resumed>) = 1 ([{fd=11, revents=POLLIN}])
[pid 77703] gettid( <unfinished ...>
[pid 77643] gettid( <unfinished ...>
[pid 77703] <... gettid resumed>) = 78
[pid 77643] <... gettid resumed>) = 18
[pid 77703] write(2, "[67800533413927] [ID: 00000078] "..., 111 <unfinished ...>
[67800533413927] [ID: 00000078] lo_setupmapping(ino=2, fi=0x(nil), foffset=0, len=2097152, moffset=0, flags=0)
[pid 77643] futex(0x7fb41bbc94b0, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 77703] <... write resumed>) = 111
[pid 77703] futex(0x7fb41bbc94b0, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 77643] <... futex resumed>) = 0
[pid 77703] openat(4, "14", O_RDONLY <unfinished ...>
[pid 77643] write(2, "[67800533417214] [ID: 00000018] "..., 76[67800533417214] [ID: 00000018] fv_queue_thread: Got queue event on Queue 1
<unfinished ...>
[pid 77703] <... openat resumed>) = 17
[pid 77643] <... write resumed>) = 76
[pid 77703] sendmsg(13, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\6\0\0\0\t\0\0\0\0\1\0\0", iov_len=12}], msg_iovlen=1, msg_control=[{cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, cmsg_data=[17]}], msg_controllen=24, msg_flags=0}, 0 <unfin
ished ...>
[pid 77643] futex(0x7fb41bbc94b0, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 77703] <... sendmsg resumed>) = 12
[pid 77643] read(11, <unfinished ...>
[pid 77703] write(13, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 256 <unfinished ...>
[pid 77643] <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8
[pid 77703] <... write resumed>) = 256
[pid 77643] gettid( <unfinished ...>
[pid 77703] recvmsg(13, <unfinished ...>
[pid 77643] <... gettid resumed>) = 18
[pid 77703] <... recvmsg resumed>{msg_namelen=0}, 0) = -1 ECONNRESET (Connection reset by peer)
[pid 77643] write(2, "[67800533609664] [ID: 00000018] "..., 99[67800533609664] [ID: 00000018] fv_queue_thread: Queue 1 gave evalue: 1 available: in: 120 out: 56
) = 99
[pid 77703] gettid( <unfinished ...>
[pid 77643] gettid( <unfinished ...>
[pid 77703] <... gettid resumed>) = 78
[pid 77643] <... gettid resumed>) = 18
[pid 77703] write(2, "[67800533664577] [ID: 00000078] "..., 103 <unfinished ...>
[67800533664577] [ID: 00000078] fv_panic: libvhost-user: Error while recvmsg: Connection reset by peer
[pid 77643] futex(0x7fb41bbc94b0, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 77703] <... write resumed>) = 103
[pid 77703] futex(0x7fb41bbc94b0, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 77643] <... futex resumed>) = 0
[pid 77643] write(2, "[67800533672939] [ID: 00000018] "..., 75[67800533672939] [ID: 00000018] fv_queue_thread: Waiting for Queue 1 event
) = 75
[pid 77643] futex(0x7fb41bbc94b0, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 77703] exit_group(1 <unfinished ...>
@rhvgoyal @dagrh @stefanha anything that comes to your mind regarding recent changes from virtiofsd or libvhost-user that could explain why things are not working anymore for Cloud-Hypervisor?
sboeuf
on 24 Jul 2020
@sboeuf Not that I know of; I know it added support for the newer vhost protocol that allows more than 8 slots; but in theory it should just fall back.
If I'm reading that strace right, isn't that the CH side closing the socket?
dagrh
on 24 Jul 2020
@sboef You could try this with a vanilla 5.0 qemu and see if it works; in my world I have the 5.0 stuff + the new vhost-user feature for the added slots (which I opened a cloud-hypervisor feature to add) - but it should be falling back; so lets see if you take that out what happens, it seems the most likely change.
dagrh
on 24 Jul 2020
Looks like @sboeuf is gone for the day. @jcvenegas Can you give this a try?
amshinde
on 24 Jul 2020
@amshinde @dagrh I will give it a try
jcvenegas
on 24 Jul 2020
I confirm that using 5.0 branch it works cloud-hypervisor
jcvenegas
on 24 Jul 2020
My bad, my script build a wrong qemu verison, cloud-hypervisor keeps failing:
docker run -ti --rm --runtime kata-runtime busybox sh
standard_init_linux.go:211: exec user process caused "function not implemented"
ERRO[0000] init failed error="standard_init_linux.go:211: exec user process caused \"function not implemented\"" name=kata-agent pid=1 source=agent
panic: --this line should have never been executed, congratulations--
goroutine 1 [running, locked to thread]:
main.init.0()
/tmp/jenkins/workspace/image-nightly-x86_64/go/src/github.com/kata-containers/agent/agent.go:1508 +0x10f
/usr/bin/qemu-virtiofs-system-x86_64 --version
QEMU emulator version 5.0.0 (kata-static)
Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
I'm not sure if this will help, but I just tried with the 1.12.0-alpha0 release using the clh 0.8 configuration, but instead using kernel 5.7.9, and qemu 5.1.0-rc1's virtiofsd with virtio_fs_cache_size = 0 in my kubernetes/containerd setup and get...
Warning FailedCreatePodSandBox 7s kubelet, 10.94.4.205 Failed to create pod sandbox: rpc error: code = Unknown desc = failed to create containerd task: virtiofsd did not announce socket connection: unknown
skaegi
on 26 Jul 2020
@dagrh I found the culprit. The list of FS_MAP, FS_UNMAP, FS_SYNC and FS_IO constants have been updated from 4,5,6,7 to 6,7,8,9 :)
sboeuf
on 27 Jul 2020
Everything should be fixed with the PR https://github.com/cloud-hypervisor/vhost/pull/21
sboeuf
on 27 Jul 2020
Ah! Remember because DAX is still not upstream we're still chasing space in the enums; SLAVE_VRING_CALL landed and we had to shuffle up.
dagrh
on 27 Jul 2020
Yep :)
sboeuf
on 27 Jul 2020
@dagrh one question, as I want to make sure we can catch these issues as soon as possible, can I reliably use virtio-fs-dev branch from CH? I mean to say, do you expect it to be broken sometimes, or is it always in a functional state?
sboeuf
on 27 Jul 2020
@dagrh one question, as I want to make sure we can catch these issues as soon as possible, can I reliably use
virtio-fs-devbranch from CH? I mean to say, do you expect it to be broken sometimes, or is it always in a functional state?
It should always work, but it only gets light testing, nothing too heavy.
dagrh
on 27 Jul 2020
It should always work, but it only gets light testing, nothing too heavy.
Ok I'll give this a try then!
sboeuf
on 27 Jul 2020
@jcvenegas @amshinde ok all the fixes have been merged in Cloud-Hypervisor. Could you please have a try and let me know if this solved the problem :)
sboeuf
on 27 Jul 2020
@sboeuf thanks for the quick fix, I was able to boot a container with master, I have upgraded the PR https://github.com/kata-containers/runtime/pull/2840 and CI is runing full cloud-hypervisor test now. I'll notify later if there is more errors.
jcvenegas
on 27 Jul 2020
Related issues
ZeroMagic
路
5Comments
egernst
路
8Comments
maartenvdezz
路
10Comments
AkihiroSuda
路
4Comments
joshku
路
8Comments