Cannot deploy functions on single node cluster: RevisionMissing

[XieGuochao]

Describe the bug
I use scripts/cloudlab/start_onenode_vhive_cluster.sh to create a single node cluster on a QEMU-KVM VM with a fresh Ubuntu 20.04 image. The setup is done and the knative is up. However, when I try to deploy hello-world or other functions, the deployer hangs forever and knative reports RevisionMissing : Configuration "helloworld-0" is waiting for a Revision to become ready.

To Reproduce

export GITHUB_VHIVE_ARGS="[-dbg] [-snapshots] [-upf]" # specify if to enable debug logs; cold starts: snapshots, REAP snapshots (optional)
scripts/cloudlab/start_onenode_vhive_cluster.sh

Then, in another terminal:

source /etc/profile && pushd ./examples/deployer && go build && popd && ./examples/deployer/deployer

Expected behavior
Hello-world function should be deployed successfully.

Logs
Possible errors of scripts/cloudlab/start_onenode_vhive_cluster.sh:

Clean up host resources if left after previous runs
W0427 12:19:47.168986  842831 loader.go:221] Config not found: /etc/kubernetes/admin.conf
Error: no kubeconfig has been provided, please use a valid configuration to connect to the cluster
Run 'kn --help' for usage
[preflight] Running pre-flight checks
W0427 12:19:47.264698  842841 removeetcdmember.go:79] [reset] No kubeadm config, using etcd pod spec to get data directory
[reset] No etcd config found. Assuming external etcd
[reset] Please, manually reset etcd to prevent further issues
[reset] Stopping the kubelet service
[reset] Unmounting mounted directories in "/var/lib/kubelet"
W0427 12:19:49.301695  842841 cleanupnode.go:81] [reset] Failed to remove containers: output: time="2022-04-27T12:19:49Z" level=fatal msg="connect: connect endpoint 'unix:///etc/vhive-cri/vhive-cri.sock', make sure you are running as root and the endpoint has been started: context deadline exceeded"
, error: exit status 1
...
Removed fc-dev-thinpool
device-mapper: remove ioctl on fc-dev-thinpool  failed: No such device or address
Command failed.
rm: cannot remove '/etc/vhive-cri/vhive-cri.sock': No such file or directory
rm: cannot remove '/home/ubuntu/.kube/config': No such file or directory
Cleaning /var/lib/firecracker-containerd/runtime /var/lib/firecracker-containerd/snapshotter
Cleaning /run/firecracker-containerd/*
Creating a fresh devmapper
0 209715200 thin-pool /dev/loop19 /dev/loop18 128 32768 1 skip_block_zeroing
device-mapper: reload ioctl on fc-dev-thinpool  failed: No such device or address
Command failed.
...
horizontalpodautoscaler.autoscaling/broker-ingress-hpa created
horizontalpodautoscaler.autoscaling/broker-filter-hpa created
NAME                   TYPE           CLUSTER-IP      EXTERNAL-IP     PORT(S)                                                                      AGE
istio-ingressgateway   LoadBalancer   10.104.231.15   192.168.1.240   15021:31845/TCP,80:31468/TCP,443:31490/TCP,15012:32595/TCP,15443:32031/TCP   67s
All logs are stored in /tmp/ctrd-logs/

kn service list (I tried both hello-world and decoder):

NAME           URL                                                  LATEST   AGE     CONDITIONS   READY     REASON
decoder        http://decoder.default.192.168.1.240.sslip.io                 10m     0 OK / 3     False     RevisionMissing : Configuration "decoder" does not have any ready Revision.
helloworld-0   http://helloworld-0.default.192.168.1.240.sslip.io            6m38s   0 OK / 3     Unknown   RevisionMissing : Configuration "helloworld-0" is waiting for a Revision to become ready.

tail -n 30 /tmp/ctrd-logs/ctrd.err:

time="2022-04-27T12:34:46.735084996Z" level=info msg="ImageUpdate event &ImageUpdate{Name:sha256:2848b4705f4559208a4124826446a9f27b5d1e7118e056cbbb58996b48234fb4,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:34:46.786854073Z" level=info msg="ImageUpdate event &ImageUpdate{Name:docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:34:46.788573172Z" level=info msg="PullImage \"index.docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b\" returns image reference \"sha256:2848b4705f4559208a4124826446a9f27b5d1e7118e056cbbb58996b48234fb4\""
time="2022-04-27T12:34:55.823288227Z" level=info msg="CreateContainer within sandbox \"a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363\" for container &ContainerMetadata{Name:user-container,Attempt:29,}"
time="2022-04-27T12:34:58.239102083Z" level=info msg="CreateContainer within sandbox \"a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363\" for &ContainerMetadata{Name:user-container,Attempt:29,} returns container id \"1647b0b5270ac945062e5af13e13a5074ebc282822dd5d0343f221169720e61d\""
time="2022-04-27T12:34:58.820507776Z" level=info msg="PullImage \"index.docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b\""
time="2022-04-27T12:35:00.199846800Z" level=info msg="ImageUpdate event &ImageUpdate{Name:docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:00.324660325Z" level=info msg="ImageUpdate event &ImageUpdate{Name:sha256:2848b4705f4559208a4124826446a9f27b5d1e7118e056cbbb58996b48234fb4,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:00.396102718Z" level=info msg="ImageUpdate event &ImageUpdate{Name:docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:00.398102089Z" level=info msg="PullImage \"index.docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b\" returns image reference \"sha256:2848b4705f4559208a4124826446a9f27b5d1e7118e056cbbb58996b48234fb4\""
time="2022-04-27T12:35:00.403763322Z" level=info msg="CreateContainer within sandbox \"cb1585eeca3ee8af9ae75bd9ecf1309c64d150c29be33d67c5b931c248d81591\" for container &ContainerMetadata{Name:user-container,Attempt:22,}"
time="2022-04-27T12:35:00.404074431Z" level=error msg="get state for cb1585eeca3ee8af9ae75bd9ecf1309c64d150c29be33d67c5b931c248d81591" error="context canceled: unknown"
time="2022-04-27T12:35:00.404172402Z" level=warning msg="unknown status" status=0
time="2022-04-27T12:35:01.952869360Z" level=info msg="CreateContainer within sandbox \"cb1585eeca3ee8af9ae75bd9ecf1309c64d150c29be33d67c5b931c248d81591\" for &ContainerMetadata{Name:user-container,Attempt:22,} returns container id \"24d009e8432f6ee2485bc729a1eaa7e2a385afe54fed63aa9b3429f8f8605eb7\""
time="2022-04-27T12:35:09.824499102Z" level=info msg="CreateContainer within sandbox \"a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363\" for container &ContainerMetadata{Name:user-container,Attempt:30,}"
time="2022-04-27T12:35:12.106024088Z" level=info msg="CreateContainer within sandbox \"a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363\" for &ContainerMetadata{Name:user-container,Attempt:30,} returns container id \"8cbd8b68bd11c482708df287b31dddc36c826dd70c42f3df5a9fc524a92f7189\""
time="2022-04-27T12:35:12.824292721Z" level=info msg="PullImage \"index.docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b\""
time="2022-04-27T12:35:14.436304578Z" level=info msg="ImageUpdate event &ImageUpdate{Name:docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:14.549422361Z" level=info msg="ImageUpdate event &ImageUpdate{Name:sha256:2848b4705f4559208a4124826446a9f27b5d1e7118e056cbbb58996b48234fb4,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:14.574547810Z" level=info msg="ImageUpdate event &ImageUpdate{Name:docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:14.575633084Z" level=info msg="PullImage \"index.docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b\" returns image reference \"sha256:2848b4705f4559208a4124826446a9f27b5d1e7118e056cbbb58996b48234fb4\""
time="2022-04-27T12:35:21.823556614Z" level=info msg="CreateContainer within sandbox \"a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363\" for container &ContainerMetadata{Name:user-container,Attempt:31,}"
time="2022-04-27T12:35:24.106022322Z" level=info msg="CreateContainer within sandbox \"a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363\" for &ContainerMetadata{Name:user-container,Attempt:31,} returns container id \"c23831b0bcff8783b48995041418ccc44f845ff9f18fbc64fba7f139c29a99c4\""
time="2022-04-27T12:35:29.819833382Z" level=info msg="PullImage \"index.docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b\""
time="2022-04-27T12:35:31.355462870Z" level=info msg="ImageUpdate event &ImageUpdate{Name:docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:31.471350718Z" level=info msg="ImageUpdate event &ImageUpdate{Name:sha256:2848b4705f4559208a4124826446a9f27b5d1e7118e056cbbb58996b48234fb4,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:31.522284700Z" level=info msg="ImageUpdate event &ImageUpdate{Name:docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b,Labels:map[string]string{io.cri-containerd.image: managed,},XXX_unrecognized:[],}"
time="2022-04-27T12:35:31.523983438Z" level=info msg="PullImage \"index.docker.io/vhiveease/video-analytics-decoder@sha256:ac850dc42e6517db91fba40ca0e44b2c071897346422adb072ab48a6ce03e37b\" returns image reference \"sha256:2848b4705f4559208a4124826446a9f27b5d1e7118e056cbbb58996b48234fb4\""
time="2022-04-27T12:35:32.828161219Z" level=info msg="CreateContainer within sandbox \"a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363\" for container &ContainerMetadata{Name:user-container,Attempt:32,}"
time="2022-04-27T12:35:34.765950911Z" level=info msg="CreateContainer within sandbox \"a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363\" for &ContainerMetadata{Name:user-container,Attempt:32,} returns container id \"494c5d284280741d9e93c31abb91d6a6d47f147de438d2d2d007d737fd4443d3\""

tail -n 30 fccd.err:

time="2022-04-27T12:36:12.209974072Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/48/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker
time="2022-04-27T12:36:12.210387236Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/48/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker
time="2022-04-27T12:36:12.210420813Z" level=info msg="Attaching NIC 48_tap (hwaddr 02:FC:00:00:00:2F) at index 1" runtime=aws.firecracker
time="2022-04-27T12:36:12.238885543Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker
time="2022-04-27T12:36:12.238970308Z" level=info msg="calling agent" runtime=aws.firecracker vmID=48
time="2022-04-27T12:36:12.286834699Z" level=warning msg="firecracker exited: exit status 1" runtime=aws.firecracker
time="2022-04-27T12:36:12.339458965Z" level=error attempt=1 error="non-temporary vsock dial failure: failed to dial \"firecracker.vsock\" within 100ms: dial unix firecracker.vsock: connect: connection refused" runtime=aws.firecracker vmID=48
time="2022-04-27T12:36:12.339617147Z" level=error msg="failed to create VM" error="failed to dial the VM over vsock: non-temporary vsock dial failure: failed to dial \"firecracker.vsock\" within 100ms: dial unix firecracker.vsock: connect: connection refused" runtime=aws.firecracker vmID=48
time="2022-04-27T12:36:12.340282563Z" level=error msg="shim CreateVM returned error" error="rpc error: code = Unknown desc = failed to create VM: failed to dial the VM over vsock: non-temporary vsock dial failure: failed to dial \"firecracker.vsock\" within 100ms: dial unix firecracker.vsock: connect: connection refused"
time="2022-04-27T12:36:12.344061496Z" level=debug msg="shim has been terminated" error="signal: killed" vmID=48
time="2022-04-27T12:36:28.130926714Z" level=debug msg="create VM request: VMID:\"49\" MachineCfg:<MemSizeMib:256 VcpuCount:1 > KernelArgs:\"ro noapic reboot=k panic=1 pci=off nomodules systemd.log_color=false systemd.unit=firecracker.target init=/sbin/overlay-init tsc=reliable quiet 8250.nr_uarts=0 ipv6.disable=1\" NetworkInterfaces:<StaticConfig:<MacAddress:\"02:FC:00:00:00:30\" HostDevName:\"49_tap\" IPConfig:<PrimaryAddr:\"190.128.0.50/10\" GatewayAddr:\"190.128.0.1\" Nameservers:\"8.8.8.8\" > > > TimeoutSeconds:100 "
time="2022-04-27T12:36:28.131072912Z" level=debug msg="using namespace: firecracker-containerd"
time="2022-04-27T12:36:28.131637723Z" level=debug msg="starting containerd-shim-aws-firecracker" vmID=49
time="2022-04-27T12:36:28.182120893Z" level=info msg="starting signal loop" namespace=firecracker-containerd path=/var/lib/firecracker-containerd/shim-base/firecracker-containerd/49 pid=866506
time="2022-04-27T12:36:28.182824480Z" level=info msg="creating new VM" runtime=aws.firecracker vmID=49
time="2022-04-27T12:36:28.183358613Z" level=info msg="Called startVMM(), setting up a VMM on firecracker.sock" runtime=aws.firecracker
time="2022-04-27T12:36:28.198105887Z" level=info msg="refreshMachineConfiguration: [GET /machine-config][200] getMachineConfigurationOK  &{CPUTemplate:T2 HtEnabled:0xc00041b1c3 MemSizeMib:0xc00041b1b8 TrackDirtyPages:false VcpuCount:0xc00041b1b0}" runtime=aws.firecracker
time="2022-04-27T12:36:28.198494344Z" level=info msg="PutGuestBootSource: [PUT /boot-source][204] putGuestBootSourceNoContent " runtime=aws.firecracker
time="2022-04-27T12:36:28.198533415Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/runtime/default-rootfs.img, slot root_drive, root true." runtime=aws.firecracker
time="2022-04-27T12:36:28.199089217Z" level=info msg="Attached drive /var/lib/firecracker-containerd/runtime/default-rootfs.img: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker
time="2022-04-27T12:36:28.199118722Z" level=info msg="Attaching drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/49/ctrstub0, slot MN2HE43UOVRDA, root false." runtime=aws.firecracker
time="2022-04-27T12:36:28.199400536Z" level=info msg="Attached drive /var/lib/firecracker-containerd/shim-base/firecracker-containerd/49/ctrstub0: [PUT /drives/{drive_id}][204] putGuestDriveByIdNoContent " runtime=aws.firecracker
time="2022-04-27T12:36:28.199454442Z" level=info msg="Attaching NIC 49_tap (hwaddr 02:FC:00:00:00:30) at index 1" runtime=aws.firecracker
time="2022-04-27T12:36:28.228479548Z" level=info msg="startInstance successful: [PUT /actions][204] createSyncActionNoContent " runtime=aws.firecracker
time="2022-04-27T12:36:28.228512818Z" level=info msg="calling agent" runtime=aws.firecracker vmID=49
time="2022-04-27T12:36:28.266615417Z" level=warning msg="firecracker exited: exit status 1" runtime=aws.firecracker
time="2022-04-27T12:36:28.329077788Z" level=error attempt=1 error="non-temporary vsock dial failure: failed to dial \"firecracker.vsock\" within 100ms: dial unix firecracker.vsock: connect: connection refused" runtime=aws.firecracker vmID=49
time="2022-04-27T12:36:28.329364130Z" level=error msg="failed to create VM" error="failed to dial the VM over vsock: non-temporary vsock dial failure: failed to dial \"firecracker.vsock\" within 100ms: dial unix firecracker.vsock: connect: connection refused" runtime=aws.firecracker vmID=49
time="2022-04-27T12:36:28.330141862Z" level=error msg="shim CreateVM returned error" error="rpc error: code = Unknown desc = failed to create VM: failed to dial the VM over vsock: non-temporary vsock dial failure: failed to dial \"firecracker.vsock\" within 100ms: dial unix firecracker.vsock: connect: connection refused"
time="2022-04-27T12:36:28.333953679Z" level=debug msg="shim has been terminated" error="signal: killed" vmID=49

tail -n 10 /tmp/otrd-logs/orch.out:

time="2022-04-27T12:36:58.445290263Z" level=error error="VM config for pod does not exist"
time="2022-04-27T12:37:06.221295742Z" level=error error="failed to provide non empty guest image in user container config"
time="2022-04-27T12:37:06.227014375Z" level=error msg="VM config for pod cb1585eeca3ee8af9ae75bd9ecf1309c64d150c29be33d67c5b931c248d81591 does not exist"
time="2022-04-27T12:37:06.227060064Z" level=error error="VM config for pod does not exist"
time="2022-04-27T12:37:13.145686045Z" level=warning msg="Failed to Fetch k8s dns clusterIP exit status 1\nThe connection to the server localhost:8080 was refused - did you specify the right host or port?\n\n"
time="2022-04-27T12:37:13.145811084Z" level=warning msg="Using google dns 8.8.8.8\n"
time="2022-04-27T12:37:13.421471045Z" level=error msg="coordinator failed to start VM" error="failed to create the microVM in firecracker-containerd: rpc error: code = Unknown desc = failed to create VM: failed to dial the VM over vsock: non-temporary vsock dial failure: failed to dial \"firecracker.vsock\" within 100ms: dial unix firecracker.vsock: connect: connection refused" image="ghcr.io/ease-lab/helloworld:var_workload" vmID=55
time="2022-04-27T12:37:13.421693375Z" level=error msg="failed to start VM" error="failed to create the microVM in firecracker-containerd: rpc error: code = Unknown desc = failed to create VM: failed to dial the VM over vsock: non-temporary vsock dial failure: failed to dial \"firecracker.vsock\" within 100ms: dial unix firecracker.vsock: connect: connection refused"
time="2022-04-27T12:37:13.449648098Z" level=error msg="VM config for pod a24ab5fa2abb7a203c98e7d93b37c8094bc1604ac377c791c391760f01229363 does not exist"
time="2022-04-27T12:37:13.449716879Z" level=error error="VM config for pod does not exist"

[ustiugov]

@XieGuochao you are running vHive with Firecracker. vSwarm yamls are written only for container-based and gVisor based isolation. One can easily modiy those yamls to run with Firecracker, by comparing the content of the yaml files in vHive and vSwarm.

Please see the developer's guide on how to run with containers

[XieGuochao]

Hi, I also tried source /etc/profile && pushd ./examples/deployer && go build && popd && ./examples/deployer/deployer with examples/deployer/functions.json like the following:

{
    "functions": [
        {
            "name": "helloworld",
            "file": "helloworld.yaml",
            "count": 1
        }
    ]
}

And it has the same error.
Do you mean that the helloworld.yaml is also not in Firecracker form?

[ustiugov]

For all problems, you need to provide precise steps to reproduce. But, I think, the answer you are looking for now is that the vHive quickstart guide should work, otherwise please raise an issue in the vHive repo.

[XieGuochao]

Oh sorry, I raised it at the wrong repo. vhive-serverless/vHive#525