cloud-hypervisor: Faild to create VM using latest virtiofsd (5.0 rease)

[jcvenegas]

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]

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

[jcvenegas]

@dagrh could you point if there are additional changes that also requried changes on qemu to keep working with the new virtiofsd ?

[sboeuf]

@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: cloud-hypervisor/vhost#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?

[dagrh]

@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]

@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.

[amshinde]

Looks like @sboeuf is gone for the day. @jcvenegas Can you give this a try?

[jcvenegas]

@amshinde @dagrh I will give it a try

[jcvenegas]

I confirm that using 5.0 branch it works cloud-hypervisor

[jcvenegas]

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

[skaegi]

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

[sboeuf]

@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]

Everything should be fixed with the PR cloud-hypervisor/vhost#21

[dagrh]

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.