Bug 1904132

Summary: Fail to start VM with sidecar - "Unable to create tap device vnet4: Operation not permitted"
Product: Container Native Virtualization (CNV) Reporter: Ruth Netser <rnetser>
Component: NetworkingAssignee: Miguel Duarte Barroso <mduarted>
Status: CLOSED WORKSFORME QA Contact: Meni Yakove <myakove>
Severity: high Docs Contact:
Priority: unspecified    
Version: 2.6.0CC: alkaplan, cnv-qe-bugs, ellorent, oshoval, phoracek
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-05-18 09:49:52 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1905929, 1920437, 1947824    
Bug Blocks:    

Description Ruth Netser 2020-12-03 16:05:34 UTC 
Description of problem:
Cannot start a VM with sidecar.

Version-Release number of selected component (if applicable):
cluster-network-addons-operator-container-v2.6.0-5

How reproducible:
100%

Steps to Reproduce:
1. Create a VM with sidecar
2. Start the VM


Actual results:
VM fails to start:
$ oc get vm,vmi,pod -n virt-general-custom-hooks-test-vm-with-sidecar
NAME                                                                  AGE   VOLUME
virtualmachine.kubevirt.io/vmi-with-sidecar-hook-1607011105-5713377   12s   

NAME                                                                          AGE   PHASE       IP            NODENAME
virtualmachineinstance.kubevirt.io/vmi-with-sidecar-hook-1607011105-5713377   11s   Scheduled   10.129.2.65   pytest-nightly-pscgr-worker-0-xj94k

NAME                                                               READY   STATUS    RESTARTS   AGE
pod/virt-launcher-vmi-with-sidecar-hook-1607011105-5713377-x5dtv   3/3     Running   0          11s



Expected results:
VM should be running

Additional info:
$ oc describe vmi -n virt-general-custom-hooks-test-vm-with-sidecar 
Name:         vmi-with-sidecar-hook-1607011105-5713377
Namespace:    virt-general-custom-hooks-test-vm-with-sidecar
Labels:       kubevirt.io/domain=vmi-with-sidecar-hook-1607011105-5713377
              kubevirt.io/nodeName=pytest-nightly-pscgr-worker-0-xj94k
              kubevirt.io/vm=vmi-with-sidecar-hook-1607011105-5713377
              special=vmi-with-sidecar-hook-1607011105-5713377
Annotations:  hooks.kubevirt.io/hookSidecars: [{"image": "kubevirt/example-hook-sidecar:v0.13.3"}]
              kubevirt.io/latest-observed-api-version: v1alpha3
              kubevirt.io/storage-observed-api-version: v1alpha3
              smbios.vm.kubevirt.io/baseBoardManufacturer: Radical Edward
API Version:  kubevirt.io/v1alpha3
Kind:         VirtualMachineInstance
Metadata:
  Creation Timestamp:  2020-12-03T15:58:26Z
  Finalizers:
    foregroundDeleteVirtualMachine
  Generation:  45
  Managed Fields:
    API Version:  kubevirt.io/v1alpha3
    Fields Type:  FieldsV1
    fieldsV1:
      f:metadata:
        f:annotations:
          .:
          f:hooks.kubevirt.io/hookSidecars:
          f:kubevirt.io/latest-observed-api-version:
          f:kubevirt.io/storage-observed-api-version:
          f:smbios.vm.kubevirt.io/baseBoardManufacturer:
        f:labels:
          .:
          f:kubevirt.io/domain:
          f:kubevirt.io/nodeName:
          f:kubevirt.io/vm:
          f:special:
        f:ownerReferences:
      f:spec:
        .:
        f:domain:
          .:
          f:cpu:
            .:
            f:cores:
          f:devices:
            .:
            f:disks:
            f:interfaces:
            f:rng:
          f:firmware:
            .:
            f:uuid:
          f:machine:
            .:
            f:type:
          f:resources:
            .:
            f:requests:
              .:
              f:memory:
        f:networks:
        f:terminationGracePeriodSeconds:
        f:volumes:
      f:status:
        .:
        f:activePods:
          .:
          f:9561c2c0-a456-475d-ae98-e9805de639cf:
        f:guestOSInfo:
        f:nodeName:
        f:phase:
        f:qosClass:
    Manager:      virt-controller
    Operation:    Update
    Time:         2020-12-03T15:58:33Z
    API Version:  kubevirt.io/v1alpha3
    Fields Type:  FieldsV1
    fieldsV1:
      f:status:
        f:conditions:
        f:interfaces:
        f:migrationMethod:
    Manager:    virt-handler
    Operation:  Update
    Time:       2020-12-03T15:58:47Z
  Owner References:
    API Version:           kubevirt.io/v1alpha3
    Block Owner Deletion:  true
    Controller:            true
    Kind:                  VirtualMachine
    Name:                  vmi-with-sidecar-hook-1607011105-5713377
    UID:                   af6beff7-034a-495b-a38f-3b8ecb7e5013
  Resource Version:        2658807
  Self Link:               /apis/kubevirt.io/v1alpha3/namespaces/virt-general-custom-hooks-test-vm-with-sidecar/virtualmachineinstances/vmi-with-sidecar-hook-1607011105-5713377
  UID:                     880487bb-f7c1-4100-b014-821c8980239e
Spec:
  Domain:
    Cpu:
      Cores:  1
    Devices:
      Disks:
        Disk:
          Bus:  virtio
        Name:   containerdisk
        Disk:
          Bus:  virtio
        Name:   cloudinitdisk
      Interfaces:
        Mac Address:  02:d5:98:00:00:5a
        Masquerade:
        Name:  default
      Rng:
    Features:
      Acpi:
        Enabled:  true
    Firmware:
      Uuid:  f0014236-4024-5d30-b1fa-8e185373cea6
    Machine:
      Type:  pc-q35-rhel8.2.0
    Resources:
      Requests:
        Cpu:     100m
        Memory:  1Gi
  Networks:
    Name:  default
    Pod:
  Termination Grace Period Seconds:  30
  Volumes:
    Container Disk:
      Image:              quay.io/openshift-cnv/qe-cnv-tests-fedora:33
      Image Pull Policy:  IfNotPresent
    Name:                 containerdisk
    Cloud Init No Cloud:
      User Data:  #cloud-config
chpasswd: { expire: False }
password: fedora

    Name:  cloudinitdisk
Status:
  Active Pods:
    9561c2c0-a456-475d-ae98-e9805de639cf:  pytest-nightly-pscgr-worker-0-xj94k
  Conditions:
    Last Probe Time:       <nil>
    Last Transition Time:  <nil>
    Status:                True
    Type:                  LiveMigratable
    Last Probe Time:       <nil>
    Last Transition Time:  2020-12-03T15:58:36Z
    Message:               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Cannot set interface MAC to fe:d5:98:00:00:5a on 'tap0': Operation not permitted')"
    Reason:                Synchronizing with the Domain failed.
    Status:                False
    Type:                  Synchronized
  Guest OS Info:
  Interfaces:
    Ip Address:  10.129.2.65
    Ip Addresses:
      10.129.2.65
    Mac:             52:54:00:3a:fb:68
    Name:            default
  Migration Method:  BlockMigration
  Node Name:         pytest-nightly-pscgr-worker-0-xj94k
  Phase:             Scheduled
  Qos Class:         Burstable
Events:
  Type     Reason            Age                From                       Message
  ----     ------            ----               ----                       -------
  Normal   SuccessfulCreate  21s                virtualmachine-controller  Created virtual machine pod virt-launcher-vmi-with-sidecar-hook-1607011105-5713377-x5dtv
  Warning  SyncFailed        11s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Cannot set interface MAC to fe:d5:98:00:00:5a on 'tap0': Operation not permitted')"
  Warning  SyncFailed        11s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet0: Operation not permitted')"
  Warning  SyncFailed        11s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet1: Operation not permitted')"
  Warning  SyncFailed        11s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet2: Operation not permitted')"
  Warning  SyncFailed        11s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet3: Operation not permitted')"
  Warning  SyncFailed        10s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet4: Operation not permitted')"
  Warning  SyncFailed        10s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet5: Operation not permitted')"
  Warning  SyncFailed        10s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet6: Operation not permitted')"
  Warning  SyncFailed        10s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet7: Operation not permitted')"
  Warning  SyncFailed        7s (x16 over 10s)  virt-handler               (combined from similar events): server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet23: Operation not permitted')"



$ oc logs -n virt-general-custom-hooks-test-vm-with-sidecar virt-launcher-vmi-with-sidecar-hook-1607011105-5713377-x5dtv -c compute
2020/12/03 15:58:31 WARNING: proto: file "api.proto" is already registered
A future release will panic on registration conflicts. See:
https://developers.google.com/protocol-buffers/docs/reference/go/faq#namespace-conflict

2020/12/03 15:58:31 WARNING: proto: file "api.proto" is already registered
A future release will panic on registration conflicts. See:
https://developers.google.com/protocol-buffers/docs/reference/go/faq#namespace-conflict

2020/12/03 15:58:31 WARNING: proto: file "api.proto" is already registered
A future release will panic on registration conflicts. See:
https://developers.google.com/protocol-buffers/docs/reference/go/faq#namespace-conflict

2020/12/03 15:58:31 WARNING: proto: file "api.proto" is already registered
A future release will panic on registration conflicts. See:
https://developers.google.com/protocol-buffers/docs/reference/go/faq#namespace-conflict

{"component":"virt-launcher","level":"info","msg":"Collected all requested hook sidecar sockets","pos":"manager.go:68","timestamp":"2020-12-03T15:58:33.742373Z"}
{"component":"virt-launcher","level":"info","msg":"Sorted all collected sidecar sockets per hook point based on their priority and name: map[OnDefineDomain:[0xc0005269c0]]","pos":"manager.go:71","timestamp":"2020-12-03T15:58:33.742795Z"}
{"component":"virt-launcher","level":"info","msg":"Connecting to libvirt daemon: qemu:///system","pos":"libvirt.go:380","timestamp":"2020-12-03T15:58:33.754931Z"}
{"component":"virt-launcher","level":"info","msg":"Connecting to libvirt daemon failed: virError(Code=38, Domain=7, Message='Failed to connect socket to '/var/run/libvirt/libvirt-sock': No such file or directory')","pos":"libvirt.go:388","timestamp":"2020-12-03T15:58:33.765362Z"}
{"component":"virt-launcher","level":"info","msg":"libvirt version: 6.6.0, package: 7.module+el8.3.0+8424+5ea525c5 (Red Hat, Inc. \u003chttp://bugzilla.redhat.com/bugzilla\u003e, 2020-10-13-08:21:17, )","subcomponent":"libvirt","thread":"47","timestamp":"2020-12-03T15:58:33.807000Z"}
{"component":"virt-launcher","level":"info","msg":"hostname: vmi-with-sidecar-hook-1607011105-5713377","subcomponent":"libvirt","thread":"47","timestamp":"2020-12-03T15:58:33.807000Z"}
{"component":"virt-launcher","level":"error","msg":"internal error: Child process (dmidecode -q -t 0,1,2,3,4,11,17) unexpected exit status 1: /dev/mem: No such file or directory","pos":"virCommandWait:2744","subcomponent":"libvirt","thread":"47","timestamp":"2020-12-03T15:58:33.807000Z"}
{"component":"virt-launcher","level":"info","msg":"Connected to libvirt daemon","pos":"libvirt.go:396","timestamp":"2020-12-03T15:58:34.269194Z"}
{"component":"virt-launcher","level":"info","msg":"Registered libvirt event notify callback","pos":"client.go:394","timestamp":"2020-12-03T15:58:34.272735Z"}
{"component":"virt-launcher","level":"info","msg":"Marked as ready","pos":"virt-launcher.go:71","timestamp":"2020-12-03T15:58:34.273014Z"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Executing PreStartHook on VMI pod environment","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"manager.go:994","timestamp":"2020-12-03T15:58:35.355097Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Starting PreCloudInitIso hook","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"manager.go:1003","timestamp":"2020-12-03T15:58:35.355195Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","level":"info","msg":"Found nameservers in /etc/resolv.conf: \ufffd\u001e\u0000\n","pos":"converter.go:1808","timestamp":"2020-12-03T15:58:35.355925Z"}
{"component":"virt-launcher","level":"info","msg":"Found search domains in /etc/resolv.conf: virt-general-custom-hooks-test-vm-with-sidecar.svc.cluster.local svc.cluster.local cluster.local pytest-nightly.cnv-qe.rhcloud.com","pos":"converter.go:1809","timestamp":"2020-12-03T15:58:35.355984Z"}
{"component":"virt-launcher","level":"info","msg":"Starting SingleClientDHCPServer","pos":"dhcp.go:63","timestamp":"2020-12-03T15:58:35.356132Z"}
{"component":"virt-launcher","level":"info","msg":"Driver cache mode for /var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2 set to none","pos":"converter.go:252","timestamp":"2020-12-03T15:58:35.379920Z"}
{"component":"virt-launcher","level":"error","msg":"Error when closing file","pos":"os_helper.go:34","reason":"invalid argument","timestamp":"2020-12-03T15:58:35.390268Z"}
{"component":"virt-launcher","level":"info","msg":"Driver cache mode for /var/run/kubevirt-ephemeral-disks/cloud-init-data/virt-general-custom-hooks-test-vm-with-sidecar/vmi-with-sidecar-hook-1607011105-5713377/noCloud.iso set to none","pos":"converter.go:252","timestamp":"2020-12-03T15:58:35.390360Z"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Domain XML generated. Base64 dump PGRvbWFpbiB0eXBlPSJrdm0iPjxuYW1lPnZpcnQtZ2VuZXJhbC1jdXN0b20taG9va3MtdGVzdC12bS13aXRoLXNpZGVjYXJfdm1pLXdpdGgtc2lkZWNhci1ob29rLTE2MDcwMTExMDUtNTcxMzM3NzwvbmFtZT48bWVtb3J5IHVuaXQ9ImIiPjEwNzM3NDE4MjQ8L21lbW9yeT48b3M+PHR5cGUgYXJjaD0ieDg2XzY0IiBtYWNoaW5lPSJwYy1xMzUtcmhlbDguMi4wIj5odm08L3R5cGU+PHNtYmlvcyBtb2RlPSJzeXNpbmZvIj48L3NtYmlvcz48L29zPjxzeXNpbmZvIHR5cGU9InNtYmlvcyI+PHN5c3RlbT48ZW50cnkgbmFtZT0idXVpZCI+ZjAwMTQyMzYtNDAyNC01ZDMwLWIxZmEtOGUxODUzNzNjZWE2PC9lbnRyeT48ZW50cnkgbmFtZT0ibWFudWZhY3R1cmVyIj5SZWQgSGF0PC9lbnRyeT48ZW50cnkgbmFtZT0iZmFtaWx5Ij5SZWQgSGF0PC9lbnRyeT48ZW50cnkgbmFtZT0icHJvZHVjdCI+Q29udGFpbmVyLW5hdGl2ZSB2aXJ0dWFsaXphdGlvbjwvZW50cnk+PGVudHJ5IG5hbWU9InNrdSI+Mi42LjA8L2VudHJ5PjxlbnRyeSBuYW1lPSJ2ZXJzaW9uIj4yLjYuMDwvZW50cnk+PC9zeXN0ZW0+PGJpb3M+PC9iaW9zPjxiYXNlQm9hcmQ+PGVudHJ5IG5hbWU9Im1hbnVmYWN0dXJlciI+UmFkaWNhbCBFZHdhcmQ8L2VudHJ5PjwvYmFzZUJvYXJkPjwvc3lzaW5mbz48ZGV2aWNlcz48aW50ZXJmYWNlIHR5cGU9ImV0aGVybmV0Ij48c291cmNlPjwvc291cmNlPjx0YXJnZXQgZGV2PSJ0YXAwIj48L3RhcmdldD48bW9kZWwgdHlwZT0idmlydGlvIj48L21vZGVsPjxtYWMgYWRkcmVzcz0iMDI6ZDU6OTg6MDA6MDA6NWEiPjwvbWFjPjxhbGlhcyBuYW1lPSJ1YS1kZWZhdWx0Ij48L2FsaWFzPjwvaW50ZXJmYWNlPjxjaGFubmVsIHR5cGU9InVuaXgiPjx0YXJnZXQgbmFtZT0ib3JnLnFlbXUuZ3Vlc3RfYWdlbnQuMCIgdHlwZT0idmlydGlvIj48L3RhcmdldD48L2NoYW5uZWw+PGNvbnRyb2xsZXIgdHlwZT0idXNiIiBpbmRleD0iMCIgbW9kZWw9Im5vbmUiPjwvY29udHJvbGxlcj48Y29udHJvbGxlciB0eXBlPSJ2aXJ0aW8tc2VyaWFsIiBpbmRleD0iMCI+PC9jb250cm9sbGVyPjx2aWRlbz48bW9kZWwgdHlwZT0idmdhIiBoZWFkcz0iMSIgdnJhbT0iMTYzODQiPjwvbW9kZWw+PC92aWRlbz48Z3JhcGhpY3MgdHlwZT0idm5jIj48bGlzdGVuIHR5cGU9InNvY2tldCIgc29ja2V0PSIvdmFyL3J1bi9rdWJldmlydC1wcml2YXRlLzg4MDQ4N2JiLWY3YzEtNDEwMC1iMDE0LTgyMWM4OTgwMjM5ZS92aXJ0LXZuYyI+PC9saXN0ZW4+PC9ncmFwaGljcz48bWVtYmFsbG9vbiBtb2RlbD0idmlydGlvIj48L21lbWJhbGxvb24+PGRpc2sgZGV2aWNlPSJkaXNrIiB0eXBlPSJmaWxlIj48c291cmNlIGZpbGU9Ii92YXIvcnVuL2t1YmV2aXJ0LWVwaGVtZXJhbC1kaXNrcy9kaXNrLWRhdGEvY29udGFpbmVyZGlzay9kaXNrLnFjb3cyIj48L3NvdXJjZT48dGFyZ2V0IGJ1cz0idmlydGlvIiBkZXY9InZkYSI+PC90YXJnZXQ+PGRyaXZlciBjYWNoZT0ibm9uZSIgbmFtZT0icWVtdSIgdHlwZT0icWNvdzIiPjwvZHJpdmVyPjxhbGlhcyBuYW1lPSJ1YS1jb250YWluZXJkaXNrIj48L2FsaWFzPjxiYWNraW5nU3RvcmUgdHlwZT0iZmlsZSI+PGZvcm1hdCB0eXBlPSJxY293MiI+PC9mb3JtYXQ+PHNvdXJjZSBmaWxlPSIvdmFyL3J1bi9rdWJldmlydC9jb250YWluZXItZGlza3MvZGlza18wLmltZyI+PC9zb3VyY2U+PC9iYWNraW5nU3RvcmU+PC9kaXNrPjxkaXNrIGRldmljZT0iZGlzayIgdHlwZT0iZmlsZSI+PHNvdXJjZSBmaWxlPSIvdmFyL3J1bi9rdWJldmlydC1lcGhlbWVyYWwtZGlza3MvY2xvdWQtaW5pdC1kYXRhL3ZpcnQtZ2VuZXJhbC1jdXN0b20taG9va3MtdGVzdC12bS13aXRoLXNpZGVjYXIvdm1pLXdpdGgtc2lkZWNhci1ob29rLTE2MDcwMTExMDUtNTcxMzM3Ny9ub0Nsb3VkLmlzbyI+PC9zb3VyY2U+PHRhcmdldCBidXM9InZpcnRpbyIgZGV2PSJ2ZGIiPjwvdGFyZ2V0Pjxkcml2ZXIgY2FjaGU9Im5vbmUiIG5hbWU9InFlbXUiIHR5cGU9InJhdyI+PC9kcml2ZXI+PGFsaWFzIG5hbWU9InVhLWNsb3VkaW5pdGRpc2siPjwvYWxpYXM+PC9kaXNrPjxzZXJpYWwgdHlwZT0idW5peCI+PHRhcmdldCBwb3J0PSIwIj48L3RhcmdldD48c291cmNlIG1vZGU9ImJpbmQiIHBhdGg9Ii92YXIvcnVuL2t1YmV2aXJ0LXByaXZhdGUvODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllL3ZpcnQtc2VyaWFsMCI+PC9zb3VyY2U+PC9zZXJpYWw+PGNvbnNvbGUgdHlwZT0icHR5Ij48dGFyZ2V0IHR5cGU9InNlcmlhbCIgcG9ydD0iMCI+PC90YXJnZXQ+PC9jb25zb2xlPjxybmcgbW9kZWw9InZpcnRpbyI+PGJhY2tlbmQgbW9kZWw9InJhbmRvbSI+L2Rldi91cmFuZG9tPC9iYWNrZW5kPjwvcm5nPjwvZGV2aWNlcz48bWV0YWRhdGE+PGt1YmV2aXJ0IHhtbG5zPSJodHRwOi8va3ViZXZpcnQuaW8iPjx1aWQ+ODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllPC91aWQ+PGdyYWNlcGVyaW9kPjxkZWxldGlvbkdyYWNlUGVyaW9kU2Vjb25kcz4zMDwvZGVsZXRpb25HcmFjZVBlcmlvZFNlY29uZHM+PC9ncmFjZXBlcmlvZD48L2t1YmV2aXJ0PjwvbWV0YWRhdGE+PGZlYXR1cmVzPjxhY3BpPjwvYWNwaT48L2ZlYXR1cmVzPjxjcHUgbW9kZT0iaG9zdC1tb2RlbCI+PHRvcG9sb2d5IHNvY2tldHM9IjEiIGNvcmVzPSIxIiB0aHJlYWRzPSIxIj48L3RvcG9sb2d5PjwvY3B1Pjx2Y3B1IHBsYWNlbWVudD0ic3RhdGljIj4xPC92Y3B1Pjxpb3RocmVhZHM+MTwvaW90aHJlYWRzPjwvZG9tYWluPg==","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"libvirt_helper.go:99","timestamp":"2020-12-03T15:58:35.410904Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Domain defined.","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"manager.go:1327","timestamp":"2020-12-03T15:58:36.325265Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 0 with reason 0 received","pos":"client.go:358","timestamp":"2020-12-03T15:58:36.325561Z"}
{"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Shutoff(5):Unknown(0)","pos":"client.go:241","timestamp":"2020-12-03T15:58:36.354207Z"}
{"component":"virt-launcher","level":"info","msg":"generated nocloud iso file /var/run/kubevirt-ephemeral-disks/cloud-init-data/virt-general-custom-hooks-test-vm-with-sidecar/vmi-with-sidecar-hook-1607011105-5713377/noCloud.iso","pos":"cloud-init.go:579","timestamp":"2020-12-03T15:58:36.355370Z"}
{"component":"virt-launcher","level":"info","msg":"Successfully connected to domain notify socket at /var/run/kubevirt/domain-notify-pipe.sock","pos":"client.go:136","timestamp":"2020-12-03T15:58:36.373368Z"}
{"component":"virt-launcher","level":"error","msg":"Cannot set interface MAC to fe:d5:98:00:00:5a on 'tap0': Operation not permitted","pos":"virNetDevSetMACInternal:275","subcomponent":"libvirt","thread":"33","timestamp":"2020-12-03T15:58:36.375000Z"}
{"component":"virt-launcher","level":"info","msg":"Detected domain with UUID f0014236-4024-5d30-b1fa-8e185373cea6","pos":"virt-launcher.go:217","timestamp":"2020-12-03T15:58:36.380127Z"}
{"component":"virt-launcher","level":"info","msg":"Monitoring loop: rate 1s start timeout 5m0s","pos":"monitor.go:164","timestamp":"2020-12-03T15:58:36.380256Z"}
{"component":"virt-launcher","level":"info","msg":"Domain name event: virt-general-custom-hooks-test-vm-with-sidecar_vmi-with-sidecar-hook-1607011105-5713377","pos":"client.go:334","timestamp":"2020-12-03T15:58:36.381767Z"}
{"component":"virt-launcher","kind":"","level":"error","msg":"Starting the VirtualMachineInstance failed.","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"manager.go:1359","reason":"virError(Code=38, Domain=0, Message='Cannot set interface MAC to fe:d5:98:00:00:5a on 'tap0': Operation not permitted')","timestamp":"2020-12-03T15:58:36.432794Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","kind":"","level":"error","msg":"Failed to sync vmi","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"server.go:161","reason":"virError(Code=38, Domain=0, Message='Cannot set interface MAC to fe:d5:98:00:00:5a on 'tap0': Operation not permitted')","timestamp":"2020-12-03T15:58:36.432986Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Domain XML generated. Base64 dump PGRvbWFpbiB0eXBlPSJrdm0iPjxuYW1lPnZpcnQtZ2VuZXJhbC1jdXN0b20taG9va3MtdGVzdC12bS13aXRoLXNpZGVjYXJfdm1pLXdpdGgtc2lkZWNhci1ob29rLTE2MDcwMTExMDUtNTcxMzM3NzwvbmFtZT48bWVtb3J5IHVuaXQ9ImIiPjEwNzM3NDE4MjQ8L21lbW9yeT48b3M+PHR5cGUgYXJjaD0ieDg2XzY0IiBtYWNoaW5lPSJwYy1xMzUtcmhlbDguMi4wIj5odm08L3R5cGU+PHNtYmlvcyBtb2RlPSJzeXNpbmZvIj48L3NtYmlvcz48L29zPjxzeXNpbmZvIHR5cGU9InNtYmlvcyI+PHN5c3RlbT48ZW50cnkgbmFtZT0idXVpZCI+ZjAwMTQyMzYtNDAyNC01ZDMwLWIxZmEtOGUxODUzNzNjZWE2PC9lbnRyeT48ZW50cnkgbmFtZT0ibWFudWZhY3R1cmVyIj5SZWQgSGF0PC9lbnRyeT48ZW50cnkgbmFtZT0iZmFtaWx5Ij5SZWQgSGF0PC9lbnRyeT48ZW50cnkgbmFtZT0icHJvZHVjdCI+Q29udGFpbmVyLW5hdGl2ZSB2aXJ0dWFsaXphdGlvbjwvZW50cnk+PGVudHJ5IG5hbWU9InNrdSI+Mi42LjA8L2VudHJ5PjxlbnRyeSBuYW1lPSJ2ZXJzaW9uIj4yLjYuMDwvZW50cnk+PC9zeXN0ZW0+PGJpb3M+PC9iaW9zPjxiYXNlQm9hcmQ+PGVudHJ5IG5hbWU9Im1hbnVmYWN0dXJlciI+UmFkaWNhbCBFZHdhcmQ8L2VudHJ5PjwvYmFzZUJvYXJkPjwvc3lzaW5mbz48ZGV2aWNlcz48aW50ZXJmYWNlIHR5cGU9ImV0aGVybmV0Ij48c291cmNlPjwvc291cmNlPjxtb2RlbCB0eXBlPSJ2aXJ0aW8iPjwvbW9kZWw+PGFsaWFzIG5hbWU9InVhLWRlZmF1bHQiPjwvYWxpYXM+PC9pbnRlcmZhY2U+PGNoYW5uZWwgdHlwZT0idW5peCI+PHRhcmdldCBuYW1lPSJvcmcucWVtdS5ndWVzdF9hZ2VudC4wIiB0eXBlPSJ2aXJ0aW8iPjwvdGFyZ2V0PjwvY2hhbm5lbD48Y29udHJvbGxlciB0eXBlPSJ1c2IiIGluZGV4PSIwIiBtb2RlbD0ibm9uZSI+PC9jb250cm9sbGVyPjxjb250cm9sbGVyIHR5cGU9InZpcnRpby1zZXJpYWwiIGluZGV4PSIwIj48L2NvbnRyb2xsZXI+PHZpZGVvPjxtb2RlbCB0eXBlPSJ2Z2EiIGhlYWRzPSIxIiB2cmFtPSIxNjM4NCI+PC9tb2RlbD48L3ZpZGVvPjxncmFwaGljcyB0eXBlPSJ2bmMiPjxsaXN0ZW4gdHlwZT0ic29ja2V0IiBzb2NrZXQ9Ii92YXIvcnVuL2t1YmV2aXJ0LXByaXZhdGUvODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllL3ZpcnQtdm5jIj48L2xpc3Rlbj48L2dyYXBoaWNzPjxtZW1iYWxsb29uIG1vZGVsPSJ2aXJ0aW8iPjwvbWVtYmFsbG9vbj48ZGlzayBkZXZpY2U9ImRpc2siIHR5cGU9ImZpbGUiPjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQtZXBoZW1lcmFsLWRpc2tzL2Rpc2stZGF0YS9jb250YWluZXJkaXNrL2Rpc2sucWNvdzIiPjwvc291cmNlPjx0YXJnZXQgYnVzPSJ2aXJ0aW8iIGRldj0idmRhIj48L3RhcmdldD48ZHJpdmVyIG5hbWU9InFlbXUiIHR5cGU9InFjb3cyIj48L2RyaXZlcj48YWxpYXMgbmFtZT0idWEtY29udGFpbmVyZGlzayI+PC9hbGlhcz48YmFja2luZ1N0b3JlIHR5cGU9ImZpbGUiPjxmb3JtYXQgdHlwZT0icWNvdzIiPjwvZm9ybWF0Pjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQvY29udGFpbmVyLWRpc2tzL2Rpc2tfMC5pbWciPjwvc291cmNlPjwvYmFja2luZ1N0b3JlPjwvZGlzaz48ZGlzayBkZXZpY2U9ImRpc2siIHR5cGU9ImZpbGUiPjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQtZXBoZW1lcmFsLWRpc2tzL2Nsb3VkLWluaXQtZGF0YS92aXJ0LWdlbmVyYWwtY3VzdG9tLWhvb2tzLXRlc3Qtdm0td2l0aC1zaWRlY2FyL3ZtaS13aXRoLXNpZGVjYXItaG9vay0xNjA3MDExMTA1LTU3MTMzNzcvbm9DbG91ZC5pc28iPjwvc291cmNlPjx0YXJnZXQgYnVzPSJ2aXJ0aW8iIGRldj0idmRiIj48L3RhcmdldD48ZHJpdmVyIG5hbWU9InFlbXUiIHR5cGU9InJhdyI+PC9kcml2ZXI+PGFsaWFzIG5hbWU9InVhLWNsb3VkaW5pdGRpc2siPjwvYWxpYXM+PC9kaXNrPjxzZXJpYWwgdHlwZT0idW5peCI+PHRhcmdldCBwb3J0PSIwIj48L3RhcmdldD48c291cmNlIG1vZGU9ImJpbmQiIHBhdGg9Ii92YXIvcnVuL2t1YmV2aXJ0LXByaXZhdGUvODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllL3ZpcnQtc2VyaWFsMCI+PC9zb3VyY2U+PC9zZXJpYWw+PGNvbnNvbGUgdHlwZT0icHR5Ij48dGFyZ2V0IHR5cGU9InNlcmlhbCIgcG9ydD0iMCI+PC90YXJnZXQ+PC9jb25zb2xlPjxybmcgbW9kZWw9InZpcnRpbyI+PGJhY2tlbmQgbW9kZWw9InJhbmRvbSI+L2Rldi91cmFuZG9tPC9iYWNrZW5kPjwvcm5nPjwvZGV2aWNlcz48bWV0YWRhdGE+PGt1YmV2aXJ0IHhtbG5zPSJodHRwOi8va3ViZXZpcnQuaW8iPjx1aWQ+ODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllPC91aWQ+PGdyYWNlcGVyaW9kPjxkZWxldGlvbkdyYWNlUGVyaW9kU2Vjb25kcz4zMDwvZGVsZXRpb25HcmFjZVBlcmlvZFNlY29uZHM+PC9ncmFjZXBlcmlvZD48L2t1YmV2aXJ0PjwvbWV0YWRhdGE+PGZlYXR1cmVzPjxhY3BpPjwvYWNwaT48L2ZlYXR1cmVzPjxjcHUgbW9kZT0iaG9zdC1tb2RlbCI+PHRvcG9sb2d5IHNvY2tldHM9IjEiIGNvcmVzPSIxIiB0aHJlYWRzPSIxIj48L3RvcG9sb2d5PjwvY3B1Pjx2Y3B1IHBsYWNlbWVudD0ic3RhdGljIj4xPC92Y3B1Pjxpb3RocmVhZHM+MTwvaW90aHJlYWRzPjwvZG9tYWluPg==","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"libvirt_helper.go:99","timestamp":"2020-12-03T15:58:36.517041Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 0 with reason 1 received","pos":"client.go:358","timestamp":"2020-12-03T15:58:36.526231Z"}
{"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Shutoff(5):Failed(6)","pos":"client.go:241","timestamp":"2020-12-03T15:58:36.528908Z"}
{"component":"virt-launcher","level":"info","msg":"Domain name event: virt-general-custom-hooks-test-vm-with-sidecar_vmi-with-sidecar-hook-1607011105-5713377","pos":"client.go:334","timestamp":"2020-12-03T15:58:36.530965Z"}
{"component":"virt-launcher","level":"info","msg":"generated nocloud iso file /var/run/kubevirt-ephemeral-disks/cloud-init-data/virt-general-custom-hooks-test-vm-with-sidecar/vmi-with-sidecar-hook-1607011105-5713377/noCloud.iso","pos":"cloud-init.go:579","timestamp":"2020-12-03T15:58:36.540335Z"}
{"component":"virt-launcher","level":"error","msg":"Unable to create tap device vnet0: Operation not permitted","pos":"virNetDevTapCreate:382","subcomponent":"libvirt","thread":"32","timestamp":"2020-12-03T15:58:36.559000Z"}
{"component":"virt-launcher","kind":"","level":"error","msg":"Starting the VirtualMachineInstance failed.","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"manager.go:1359","reason":"virError(Code=38, Domain=0, Message='Unable to create tap device vnet0: Operation not permitted')","timestamp":"2020-12-03T15:58:36.561739Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","kind":"","level":"error","msg":"Failed to sync vmi","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"server.go:161","reason":"virError(Code=38, Domain=0, Message='Unable to create tap device vnet0: Operation not permitted')","timestamp":"2020-12-03T15:58:36.561880Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Domain XML generated. Base64 dump PGRvbWFpbiB0eXBlPSJrdm0iPjxuYW1lPnZpcnQtZ2VuZXJhbC1jdXN0b20taG9va3MtdGVzdC12bS13aXRoLXNpZGVjYXJfdm1pLXdpdGgtc2lkZWNhci1ob29rLTE2MDcwMTExMDUtNTcxMzM3NzwvbmFtZT48bWVtb3J5IHVuaXQ9ImIiPjEwNzM3NDE4MjQ8L21lbW9yeT48b3M+PHR5cGUgYXJjaD0ieDg2XzY0IiBtYWNoaW5lPSJwYy1xMzUtcmhlbDguMi4wIj5odm08L3R5cGU+PHNtYmlvcyBtb2RlPSJzeXNpbmZvIj48L3NtYmlvcz48L29zPjxzeXNpbmZvIHR5cGU9InNtYmlvcyI+PHN5c3RlbT48ZW50cnkgbmFtZT0idXVpZCI+ZjAwMTQyMzYtNDAyNC01ZDMwLWIxZmEtOGUxODUzNzNjZWE2PC9lbnRyeT48ZW50cnkgbmFtZT0ibWFudWZhY3R1cmVyIj5SZWQgSGF0PC9lbnRyeT48ZW50cnkgbmFtZT0iZmFtaWx5Ij5SZWQgSGF0PC9lbnRyeT48ZW50cnkgbmFtZT0icHJvZHVjdCI+Q29udGFpbmVyLW5hdGl2ZSB2aXJ0dWFsaXphdGlvbjwvZW50cnk+PGVudHJ5IG5hbWU9InNrdSI+Mi42LjA8L2VudHJ5PjxlbnRyeSBuYW1lPSJ2ZXJzaW9uIj4yLjYuMDwvZW50cnk+PC9zeXN0ZW0+PGJpb3M+PC9iaW9zPjxiYXNlQm9hcmQ+PGVudHJ5IG5hbWU9Im1hbnVmYWN0dXJlciI+UmFkaWNhbCBFZHdhcmQ8L2VudHJ5PjwvYmFzZUJvYXJkPjwvc3lzaW5mbz48ZGV2aWNlcz48aW50ZXJmYWNlIHR5cGU9ImV0aGVybmV0Ij48c291cmNlPjwvc291cmNlPjxtb2RlbCB0eXBlPSJ2aXJ0aW8iPjwvbW9kZWw+PGFsaWFzIG5hbWU9InVhLWRlZmF1bHQiPjwvYWxpYXM+PC9pbnRlcmZhY2U+PGNoYW5uZWwgdHlwZT0idW5peCI+PHRhcmdldCBuYW1lPSJvcmcucWVtdS5ndWVzdF9hZ2VudC4wIiB0eXBlPSJ2aXJ0aW8iPjwvdGFyZ2V0PjwvY2hhbm5lbD48Y29udHJvbGxlciB0eXBlPSJ1c2IiIGluZGV4PSIwIiBtb2RlbD0ibm9uZSI+PC9jb250cm9sbGVyPjxjb250cm9sbGVyIHR5cGU9InZpcnRpby1zZXJpYWwiIGluZGV4PSIwIj48L2NvbnRyb2xsZXI+PHZpZGVvPjxtb2RlbCB0eXBlPSJ2Z2EiIGhlYWRzPSIxIiB2cmFtPSIxNjM4NCI+PC9tb2RlbD48L3ZpZGVvPjxncmFwaGljcyB0eXBlPSJ2bmMiPjxsaXN0ZW4gdHlwZT0ic29ja2V0IiBzb2NrZXQ9Ii92YXIvcnVuL2t1YmV2aXJ0LXByaXZhdGUvODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllL3ZpcnQtdm5jIj48L2xpc3Rlbj48L2dyYXBoaWNzPjxtZW1iYWxsb29uIG1vZGVsPSJ2aXJ0aW8iPjwvbWVtYmFsbG9vbj48ZGlzayBkZXZpY2U9ImRpc2siIHR5cGU9ImZpbGUiPjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQtZXBoZW1lcmFsLWRpc2tzL2Rpc2stZGF0YS9jb250YWluZXJkaXNrL2Rpc2sucWNvdzIiPjwvc291cmNlPjx0YXJnZXQgYnVzPSJ2aXJ0aW8iIGRldj0idmRhIj48L3RhcmdldD48ZHJpdmVyIG5hbWU9InFlbXUiIHR5cGU9InFjb3cyIj48L2RyaXZlcj48YWxpYXMgbmFtZT0idWEtY29udGFpbmVyZGlzayI+PC9hbGlhcz48YmFja2luZ1N0b3JlIHR5cGU9ImZpbGUiPjxmb3JtYXQgdHlwZT0icWNvdzIiPjwvZm9ybWF0Pjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQvY29udGFpbmVyLWRpc2tzL2Rpc2tfMC5pbWciPjwvc291cmNlPjwvYmFja2luZ1N0b3JlPjwvZGlzaz48ZGlzayBkZXZpY2U9ImRpc2siIHR5cGU9ImZpbGUiPjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQtZXBoZW1lcmFsLWRpc2tzL2Nsb3VkLWluaXQtZGF0YS92aXJ0LWdlbmVyYWwtY3VzdG9tLWhvb2tzLXRlc3Qtdm0td2l0aC1zaWRlY2FyL3ZtaS13aXRoLXNpZGVjYXItaG9vay0xNjA3MDExMTA1LTU3MTMzNzcvbm9DbG91ZC5pc28iPjwvc291cmNlPjx0YXJnZXQgYnVzPSJ2aXJ0aW8iIGRldj0idmRiIj48L3RhcmdldD48ZHJpdmVyIG5hbWU9InFlbXUiIHR5cGU9InJhdyI+PC9kcml2ZXI+PGFsaWFzIG5hbWU9InVhLWNsb3VkaW5pdGRpc2siPjwvYWxpYXM+PC9kaXNrPjxzZXJpYWwgdHlwZT0idW5peCI+PHRhcmdldCBwb3J0PSIwIj48L3RhcmdldD48c291cmNlIG1vZGU9ImJpbmQiIHBhdGg9Ii92YXIvcnVuL2t1YmV2aXJ0LXByaXZhdGUvODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllL3ZpcnQtc2VyaWFsMCI+PC9zb3VyY2U+PC9zZXJpYWw+PGNvbnNvbGUgdHlwZT0icHR5Ij48dGFyZ2V0IHR5cGU9InNlcmlhbCIgcG9ydD0iMCI+PC90YXJnZXQ+PC9jb25zb2xlPjxybmcgbW9kZWw9InZpcnRpbyI+PGJhY2tlbmQgbW9kZWw9InJhbmRvbSI+L2Rldi91cmFuZG9tPC9iYWNrZW5kPjwvcm5nPjwvZGV2aWNlcz48bWV0YWRhdGE+PGt1YmV2aXJ0IHhtbG5zPSJodHRwOi8va3ViZXZpcnQuaW8iPjx1aWQ+ODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllPC91aWQ+PGdyYWNlcGVyaW9kPjxkZWxldGlvbkdyYWNlUGVyaW9kU2Vjb25kcz4zMDwvZGVsZXRpb25HcmFjZVBlcmlvZFNlY29uZHM+PC9ncmFjZXBlcmlvZD48L2t1YmV2aXJ0PjwvbWV0YWRhdGE+PGZlYXR1cmVzPjxhY3BpPjwvYWNwaT48L2ZlYXR1cmVzPjxjcHUgbW9kZT0iaG9zdC1tb2RlbCI+PHRvcG9sb2d5IHNvY2tldHM9IjEiIGNvcmVzPSIxIiB0aHJlYWRzPSIxIj48L3RvcG9sb2d5PjwvY3B1Pjx2Y3B1IHBsYWNlbWVudD0ic3RhdGljIj4xPC92Y3B1Pjxpb3RocmVhZHM+MTwvaW90aHJlYWRzPjwvZG9tYWluPg==","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"libvirt_helper.go:99","timestamp":"2020-12-03T15:58:36.630496Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 0 with reason 1 received","pos":"client.go:358","timestamp":"2020-12-03T15:58:36.664262Z"}
{"component":"virt-launcher","level":"info","msg":"generated nocloud iso file /var/run/kubevirt-ephemeral-disks/cloud-init-data/virt-general-custom-hooks-test-vm-with-sidecar/vmi-with-sidecar-hook-1607011105-5713377/noCloud.iso","pos":"cloud-init.go:579","timestamp":"2020-12-03T15:58:36.682188Z"}
{"component":"virt-launcher","level":"error","msg":"Unable to create tap device vnet1: Operation not permitted","pos":"virNetDevTapCreate:382","subcomponent":"libvirt","thread":"35","timestamp":"2020-12-03T15:58:36.709000Z"}
{"component":"virt-launcher","kind":"","level":"error","msg":"Starting the VirtualMachineInstance failed.","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"manager.go:1359","reason":"virError(Code=38, Domain=0, Message='Unable to create tap device vnet1: Operation not permitted')","timestamp":"2020-12-03T15:58:36.717403Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Shutoff(5):Failed(6)","pos":"client.go:241","timestamp":"2020-12-03T15:58:36.717550Z"}
{"component":"virt-launcher","kind":"","level":"error","msg":"Failed to sync vmi","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"server.go:161","reason":"virError(Code=38, Domain=0, Message='Unable to create tap device vnet1: Operation not permitted')","timestamp":"2020-12-03T15:58:36.717606Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","level":"info","msg":"Domain name event: virt-general-custom-hooks-test-vm-with-sidecar_vmi-with-sidecar-hook-1607011105-5713377","pos":"client.go:334","timestamp":"2020-12-03T15:58:36.721110Z"}
{"component":"virt-launcher","level":"info","msg":"2020-12-03 15:58:36.380+0000: shutting down, reason=failed","subcomponent":"qemu","timestamp":"2020-12-03T15:58:36.769364Z"}
{"component":"virt-launcher","level":"info","msg":"2020-12-03 15:58:36.559+0000: shutting down, reason=failed","subcomponent":"qemu","timestamp":"2020-12-03T15:58:36.769456Z"}
{"component":"virt-launcher","level":"info","msg":"2020-12-03 15:58:36.709+0000: shutting down, reason=failed","subcomponent":"qemu","timestamp":"2020-12-03T15:58:36.769482Z"}
{"component":"virt-launcher","kind":"","level":"info","msg":"Domain XML generated. Base64 dump PGRvbWFpbiB0eXBlPSJrdm0iPjxuYW1lPnZpcnQtZ2VuZXJhbC1jdXN0b20taG9va3MtdGVzdC12bS13aXRoLXNpZGVjYXJfdm1pLXdpdGgtc2lkZWNhci1ob29rLTE2MDcwMTExMDUtNTcxMzM3NzwvbmFtZT48bWVtb3J5IHVuaXQ9ImIiPjEwNzM3NDE4MjQ8L21lbW9yeT48b3M+PHR5cGUgYXJjaD0ieDg2XzY0IiBtYWNoaW5lPSJwYy1xMzUtcmhlbDguMi4wIj5odm08L3R5cGU+PHNtYmlvcyBtb2RlPSJzeXNpbmZvIj48L3NtYmlvcz48L29zPjxzeXNpbmZvIHR5cGU9InNtYmlvcyI+PHN5c3RlbT48ZW50cnkgbmFtZT0idXVpZCI+ZjAwMTQyMzYtNDAyNC01ZDMwLWIxZmEtOGUxODUzNzNjZWE2PC9lbnRyeT48ZW50cnkgbmFtZT0ibWFudWZhY3R1cmVyIj5SZWQgSGF0PC9lbnRyeT48ZW50cnkgbmFtZT0iZmFtaWx5Ij5SZWQgSGF0PC9lbnRyeT48ZW50cnkgbmFtZT0icHJvZHVjdCI+Q29udGFpbmVyLW5hdGl2ZSB2aXJ0dWFsaXphdGlvbjwvZW50cnk+PGVudHJ5IG5hbWU9InNrdSI+Mi42LjA8L2VudHJ5PjxlbnRyeSBuYW1lPSJ2ZXJzaW9uIj4yLjYuMDwvZW50cnk+PC9zeXN0ZW0+PGJpb3M+PC9iaW9zPjxiYXNlQm9hcmQ+PGVudHJ5IG5hbWU9Im1hbnVmYWN0dXJlciI+UmFkaWNhbCBFZHdhcmQ8L2VudHJ5PjwvYmFzZUJvYXJkPjwvc3lzaW5mbz48ZGV2aWNlcz48aW50ZXJmYWNlIHR5cGU9ImV0aGVybmV0Ij48c291cmNlPjwvc291cmNlPjxtb2RlbCB0eXBlPSJ2aXJ0aW8iPjwvbW9kZWw+PGFsaWFzIG5hbWU9InVhLWRlZmF1bHQiPjwvYWxpYXM+PC9pbnRlcmZhY2U+PGNoYW5uZWwgdHlwZT0idW5peCI+PHRhcmdldCBuYW1lPSJvcmcucWVtdS5ndWVzdF9hZ2VudC4wIiB0eXBlPSJ2aXJ0aW8iPjwvdGFyZ2V0PjwvY2hhbm5lbD48Y29udHJvbGxlciB0eXBlPSJ1c2IiIGluZGV4PSIwIiBtb2RlbD0ibm9uZSI+PC9jb250cm9sbGVyPjxjb250cm9sbGVyIHR5cGU9InZpcnRpby1zZXJpYWwiIGluZGV4PSIwIj48L2NvbnRyb2xsZXI+PHZpZGVvPjxtb2RlbCB0eXBlPSJ2Z2EiIGhlYWRzPSIxIiB2cmFtPSIxNjM4NCI+PC9tb2RlbD48L3ZpZGVvPjxncmFwaGljcyB0eXBlPSJ2bmMiPjxsaXN0ZW4gdHlwZT0ic29ja2V0IiBzb2NrZXQ9Ii92YXIvcnVuL2t1YmV2aXJ0LXByaXZhdGUvODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllL3ZpcnQtdm5jIj48L2xpc3Rlbj48L2dyYXBoaWNzPjxtZW1iYWxsb29uIG1vZGVsPSJ2aXJ0aW8iPjwvbWVtYmFsbG9vbj48ZGlzayBkZXZpY2U9ImRpc2siIHR5cGU9ImZpbGUiPjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQtZXBoZW1lcmFsLWRpc2tzL2Rpc2stZGF0YS9jb250YWluZXJkaXNrL2Rpc2sucWNvdzIiPjwvc291cmNlPjx0YXJnZXQgYnVzPSJ2aXJ0aW8iIGRldj0idmRhIj48L3RhcmdldD48ZHJpdmVyIG5hbWU9InFlbXUiIHR5cGU9InFjb3cyIj48L2RyaXZlcj48YWxpYXMgbmFtZT0idWEtY29udGFpbmVyZGlzayI+PC9hbGlhcz48YmFja2luZ1N0b3JlIHR5cGU9ImZpbGUiPjxmb3JtYXQgdHlwZT0icWNvdzIiPjwvZm9ybWF0Pjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQvY29udGFpbmVyLWRpc2tzL2Rpc2tfMC5pbWciPjwvc291cmNlPjwvYmFja2luZ1N0b3JlPjwvZGlzaz48ZGlzayBkZXZpY2U9ImRpc2siIHR5cGU9ImZpbGUiPjxzb3VyY2UgZmlsZT0iL3Zhci9ydW4va3ViZXZpcnQtZXBoZW1lcmFsLWRpc2tzL2Nsb3VkLWluaXQtZGF0YS92aXJ0LWdlbmVyYWwtY3VzdG9tLWhvb2tzLXRlc3Qtdm0td2l0aC1zaWRlY2FyL3ZtaS13aXRoLXNpZGVjYXItaG9vay0xNjA3MDExMTA1LTU3MTMzNzcvbm9DbG91ZC5pc28iPjwvc291cmNlPjx0YXJnZXQgYnVzPSJ2aXJ0aW8iIGRldj0idmRiIj48L3RhcmdldD48ZHJpdmVyIG5hbWU9InFlbXUiIHR5cGU9InJhdyI+PC9kcml2ZXI+PGFsaWFzIG5hbWU9InVhLWNsb3VkaW5pdGRpc2siPjwvYWxpYXM+PC9kaXNrPjxzZXJpYWwgdHlwZT0idW5peCI+PHRhcmdldCBwb3J0PSIwIj48L3RhcmdldD48c291cmNlIG1vZGU9ImJpbmQiIHBhdGg9Ii92YXIvcnVuL2t1YmV2aXJ0LXByaXZhdGUvODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllL3ZpcnQtc2VyaWFsMCI+PC9zb3VyY2U+PC9zZXJpYWw+PGNvbnNvbGUgdHlwZT0icHR5Ij48dGFyZ2V0IHR5cGU9InNlcmlhbCIgcG9ydD0iMCI+PC90YXJnZXQ+PC9jb25zb2xlPjxybmcgbW9kZWw9InZpcnRpbyI+PGJhY2tlbmQgbW9kZWw9InJhbmRvbSI+L2Rldi91cmFuZG9tPC9iYWNrZW5kPjwvcm5nPjwvZGV2aWNlcz48bWV0YWRhdGE+PGt1YmV2aXJ0IHhtbG5zPSJodHRwOi8va3ViZXZpcnQuaW8iPjx1aWQ+ODgwNDg3YmItZjdjMS00MTAwLWIwMTQtODIxYzg5ODAyMzllPC91aWQ+PGdyYWNlcGVyaW9kPjxkZWxldGlvbkdyYWNlUGVyaW9kU2Vjb25kcz4zMDwvZGVsZXRpb25HcmFjZVBlcmlvZFNlY29uZHM+PC9ncmFjZXBlcmlvZD48L2t1YmV2aXJ0PjwvbWV0YWRhdGE+PGZlYXR1cmVzPjxhY3BpPjwvYWNwaT48L2ZlYXR1cmVzPjxjcHUgbW9kZT0iaG9zdC1tb2RlbCI+PHRvcG9sb2d5IHNvY2tldHM9IjEiIGNvcmVzPSIxIiB0aHJlYWRzPSIxIj48L3RvcG9sb2d5PjwvY3B1Pjx2Y3B1IHBsYWNlbWVudD0ic3RhdGljIj4xPC92Y3B1Pjxpb3RocmVhZHM+MTwvaW90aHJlYWRzPjwvZG9tYWluPg==","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"libvirt_helper.go:99","timestamp":"2020-12-03T15:58:36.803924Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 0 with reason 1 received","pos":"client.go:358","timestamp":"2020-12-03T15:58:36.815349Z"}
{"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Shutoff(5):Failed(6)","pos":"client.go:241","timestamp":"2020-12-03T15:58:36.821116Z"}
{"component":"virt-launcher","level":"info","msg":"Domain name event: virt-general-custom-hooks-test-vm-with-sidecar_vmi-with-sidecar-hook-1607011105-5713377","pos":"client.go:334","timestamp":"2020-12-03T15:58:36.826423Z"}
{"component":"virt-launcher","level":"info","msg":"generated nocloud iso file /var/run/kubevirt-ephemeral-disks/cloud-init-data/virt-general-custom-hooks-test-vm-with-sidecar/vmi-with-sidecar-hook-1607011105-5713377/noCloud.iso","pos":"cloud-init.go:579","timestamp":"2020-12-03T15:58:36.827892Z"}
{"component":"virt-launcher","level":"error","msg":"Unable to create tap device vnet2: Operation not permitted","pos":"virNetDevTapCreate:382","subcomponent":"libvirt","thread":"35","timestamp":"2020-12-03T15:58:36.848000Z"}
{"component":"virt-launcher","kind":"","level":"error","msg":"Starting the VirtualMachineInstance failed.","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"manager.go:1359","reason":"virError(Code=38, Domain=0, Message='Unable to create tap device vnet2: Operation not permitted')","timestamp":"2020-12-03T15:58:36.851193Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
{"component":"virt-launcher","kind":"","level":"error","msg":"Failed to sync vmi","name":"vmi-with-sidecar-hook-1607011105-5713377","namespace":"virt-general-custom-hooks-test-vm-with-sidecar","pos":"server.go:161","reason":"virError(Code=38, Domain=0, Message='Unable to create tap device vnet2: Operation not permitted')","timestamp":"2020-12-03T15:58:36.851313Z","uid":"880487bb-f7c1-4100-b014-821c8980239e"}
Comment 1 Ruth Netser 2020-12-03 16:06:34 UTC 
sidecar log:
$ oc logs -n virt-general-custom-hooks-test-vm-with-sidecar virt-launcher-vmi-with-sidecar-hook-1607011105-5713377-x5dtv -c hook-sidecar-0
{"component":"smbios-hook-sidecar","level":"info","msg":"Starting hook server exposing 'info' and 'v1alpha1' services on socket /var/run/kubevirt-hooks/smbios.sock","pos":"smbios.go:131","timestamp":"2020-12-03T15:58:32.332135Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Hook's Info method has been called","pos":"smbios.go:44","timestamp":"2020-12-03T15:58:32.740912Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Hook's OnDefineDomain callback method has been called","pos":"smbios.go:63","timestamp":"2020-12-03T15:58:35.403369Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Successfully updated original domain spec with requested SMBIOS attributes","pos":"smbios.go:109","timestamp":"2020-12-03T15:58:35.405379Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Hook's OnDefineDomain callback method has been called","pos":"smbios.go:63","timestamp":"2020-12-03T15:58:36.515619Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Successfully updated original domain spec with requested SMBIOS attributes","pos":"smbios.go:109","timestamp":"2020-12-03T15:58:36.516675Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Hook's OnDefineDomain callback method has been called","pos":"smbios.go:63","timestamp":"2020-12-03T15:58:36.629267Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Successfully updated original domain spec with requested SMBIOS attributes","pos":"smbios.go:109","timestamp":"2020-12-03T15:58:36.630166Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Hook's OnDefineDomain callback method has been called","pos":"smbios.go:63","timestamp":"2020-12-03T15:58:36.802337Z"}
{"component":"smbios-hook-sidecar","level":"info","msg":"Successfully updated original domain spec with requested SMBIOS attributes","pos":"smbios.go:109","timestamp":"2020-12-03T15:58:36.803544Z"}
Comment 2 Petr Horáček 2020-12-03 16:10:12 UTC 
The adjusted domxml returned from the hook has the MAC in it:

    <interface type="ethernet">
      <source/>
      <target dev="tap0"/>
      <model type="virtio"/>
      <mac address="02:d5:98:00:00:5a"/>
      <alias name="ua-default"/>
    </interface>
Comment 3 Petr Horáček 2020-12-17 10:31:42 UTC 
We brought back the NET_ADMIN capability due to https://bugzilla.redhat.com/show_bug.cgi?id=1905929. With this capability back in virt-launcher, this issue will not reproduce. I'm putting this therefore on hold until the linked BZ gets resolved, we drop the capability and get a chance to reproduce it.
Comment 4 Alona Kaplan 2020-12-21 07:39:06 UTC 
(In reply to Petr Horáček from comment #2)
> The adjusted domxml returned from the hook has the MAC in it:
> 
>     <interface type="ethernet">
>       <source/>
>       <target dev="tap0"/>

 <target dev="tap0"/>

I think the issue here is that managed="no" is missing-
<target dev='tap0' managed='no'/>

>       <model type="virtio"/>
>       <mac address="02:d5:98:00:00:5a"/>
>       <alias name="ua-default"/>
>     </interface>
Comment 5 Alona Kaplan 2020-12-21 08:10:23 UTC 
Looking at the logs of this bug I see another strange thing.

The first domxml sent to libvirt is -
<interface type="ethernet">
<source></source>
<target dev="tap0"></target>
<model type="virtio"></model>
<mac address="02:d5:98:00:00:5a"></mac>
<alias name="ua-default"></alias>
</interface>

While all the other attempts send the following -
<interface type="ethernet">
<source></source>
<model type="virtio"></model>
<alias name="ua-default"></alias>
</interface>

Therefore, we see in the events that first libvirt tries to set mac on the predefined tap and then on the following attempts it tries to create new tap devices-
"LibvirtError(Code=38, Domain=0, Message='Cannot set interface MAC to fe:d5:98:00:00:5a on 'tap0': Operation not permitted')"
  Warning  SyncFailed        11s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet0: Operation not permitted')"
  Warning  SyncFailed        11s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet1: Operation not permitted')"
  Warning  SyncFailed        11s                virt-handler               server error. command SyncVMI failed: "LibvirtError(Code=38, Domain=0, Message='Unable to create tap device vnet2: Operation not permitted')"
...

I suspect that if the creation of the vm fails on the libvirt side. We are not invoking podInterface.PlugPhase2 (https://github.com/kubevirt/kubevirt/blob/161b36a91c329007147c11b6683e397dfa0b4551/pkg/virt-launcher/virtwrap/network/podinterface.go#L798).
Comment 6 Miguel Duarte Barroso 2020-12-21 08:12:21 UTC 
(In reply to Alona Kaplan from comment #4)
> (In reply to Petr Horáček from comment #2)
> > The adjusted domxml returned from the hook has the MAC in it:
> > 
> >     <interface type="ethernet">
> >       <source/>
> >       <target dev="tap0"/>
> 
>  <target dev="tap0"/>
> 
> I think the issue here is that managed="no" is missing-
> <target dev='tap0' managed='no'/>

Good catch. Without that attribute, libvirt will attempt to re-configure the existing tap device - in this case the MAC.

> 
> >       <model type="virtio"/>
> >       <mac address="02:d5:98:00:00:5a"/>
> >       <alias name="ua-default"/>
> >     </interface>
Comment 7 Alona Kaplan 2020-12-21 08:50:57 UTC 
(In reply to Miguel Duarte Barroso from comment #6)
> (In reply to Alona Kaplan from comment #4)
> > (In reply to Petr Horáček from comment #2)
> > > The adjusted domxml returned from the hook has the MAC in it:
> > > 
> > >     <interface type="ethernet">
> > >       <source/>
> > >       <target dev="tap0"/>
> > 
> >  <target dev="tap0"/>
> > 
> > I think the issue here is that managed="no" is missing-
> > <target dev='tap0' managed='no'/>
> 
> Good catch. Without that attribute, libvirt will attempt to re-configure the


Ruth, is there a chance the image of "example-hook-sidecar" you are using is very old?
The "managed" attribute was added to the "InterfaceTarget" domain schema about half a year ago (when the pre defined tap device was introduced).
I suspect that the "example-hook-sidecar" is old and doesn't have this attribute, therefore, when unmarshalling the domxml the "InterfaceTarget.managed" attribute is dropped.

> existing tap device - in this case the MAC.
> 
> > 
> > >       <model type="virtio"/>
> > >       <mac address="02:d5:98:00:00:5a"/>
> > >       <alias name="ua-default"/>
> > >     </interface>
Comment 8 Miguel Duarte Barroso 2020-12-21 09:20:43 UTC 
(In reply to Alona Kaplan from comment #7)
> (In reply to Miguel Duarte Barroso from comment #6)
> > (In reply to Alona Kaplan from comment #4)
> > > (In reply to Petr Horáček from comment #2)
> > > > The adjusted domxml returned from the hook has the MAC in it:
> > > > 
> > > >     <interface type="ethernet">
> > > >       <source/>
> > > >       <target dev="tap0"/>
> > > 
> > >  <target dev="tap0"/>
> > > 
> > > I think the issue here is that managed="no" is missing-
> > > <target dev='tap0' managed='no'/>
> > 
> > Good catch. Without that attribute, libvirt will attempt to re-configure the
> 
> 
> Ruth, is there a chance the image of "example-hook-sidecar" you are using is
> very old?
> The "managed" attribute was added to the "InterfaceTarget" domain schema
> about half a year ago (when the pre defined tap device was introduced).

The pre-defined tap device was introduced in v0.33.0: [0].

From the annotation on the pod's specification in the bug description, I get the feeling the sidecar container uses version v0.13.3 :
  - "hooks.kubevirt.io/hookSidecars: [{"image": "kubevirt/example-hook-sidecar:v0.13.3"}]"

> I suspect that the "example-hook-sidecar" is old and doesn't have this
> attribute, therefore, when unmarshalling the domxml the
> "InterfaceTarget.managed" attribute is dropped.
> 
> > existing tap device - in this case the MAC.
> > 
> > > 
> > > >       <model type="virtio"/>
> > > >       <mac address="02:d5:98:00:00:5a"/>
> > > >       <alias name="ua-default"/>
> > > >     </interface>

Right now, it is not possible to reproduce this issue, since CAP_NET_ADMIN was re-introduced, but I've tried to reproduce this some days go (on a build where CAP_NET_ADMIN was *NOT* present) and was not able to reproduce it.

[0] - https://github.com/kubevirt/kubevirt/releases/tag/v0.33.0
Comment 9 Alona Kaplan 2020-12-21 13:19:23 UTC 
(In reply to Miguel Duarte Barroso from comment #8)
> (In reply to Alona Kaplan from comment #7)
> > (In reply to Miguel Duarte Barroso from comment #6)
> > > (In reply to Alona Kaplan from comment #4)
> > > > (In reply to Petr Horáček from comment #2)
> > > > > The adjusted domxml returned from the hook has the MAC in it:
> > > > > 
> > > > >     <interface type="ethernet">
> > > > >       <source/>
> > > > >       <target dev="tap0"/>
> > > > 
> > > >  <target dev="tap0"/>
> > > > 
> > > > I think the issue here is that managed="no" is missing-
> > > > <target dev='tap0' managed='no'/>
> > > 
> > > Good catch. Without that attribute, libvirt will attempt to re-configure the
> > 
> > 
> > Ruth, is there a chance the image of "example-hook-sidecar" you are using is
> > very old?
> > The "managed" attribute was added to the "InterfaceTarget" domain schema
> > about half a year ago (when the pre defined tap device was introduced).
> 
> The pre-defined tap device was introduced in v0.33.0: [0].
> 
> From the annotation on the pod's specification in the bug description, I get
> the feeling the sidecar container uses version v0.13.3 :
>   - "hooks.kubevirt.io/hookSidecars: [{"image":
> "kubevirt/example-hook-sidecar:v0.13.3"}]"
> 
> > I suspect that the "example-hook-sidecar" is old and doesn't have this
> > attribute, therefore, when unmarshalling the domxml the
> > "InterfaceTarget.managed" attribute is dropped.
> > 
> > > existing tap device - in this case the MAC.
> > > 
> > > > 
> > > > >       <model type="virtio"/>
> > > > >       <mac address="02:d5:98:00:00:5a"/>
> > > > >       <alias name="ua-default"/>
> > > > >     </interface>
> 
> Right now, it is not possible to reproduce this issue, since CAP_NET_ADMIN
> was re-introduced, but I've tried to reproduce this some days go (on a build
> where CAP_NET_ADMIN was *NOT* present) and was not able to reproduce it.

A way to verify it with the CAP_NET_ADMIN is to check whether the managed="no" is passed on the domxml.
The domxml is printed to the log "Domain XML generated. Base64 dump, so it should be easy to find it.

> 
> [0] - https://github.com/kubevirt/kubevirt/releases/tag/v0.33.0
Comment 10 Quique Llorente 2021-02-11 11:59:13 UTC 
Verified manually that adding Phase2 call at domain re-creation works fine and VM is created.

Hacked kubevirt with the solution https://github.com/kubevirt/kubevirt/pull/4995.
Comment 11 Petr Horáček 2021-04-14 09:41:40 UTC 
Ruth, now when we dropped CAP_NET_ADMIN, this should be an issue again. Could you please try reproducing this with virt-handler-container-v4.8.0-40? Please make sure that the sidecar hook container image you use is updated to, i.e. it should be using kubevirt/example-hook-sidecar:v0.39 or newer. The old version that was originally used is the culprit here.
Comment 12 Ruth Netser 2021-05-10 13:28:00 UTC 
Waiting for a fix for bug 1958937, to verify with the latest sidecar hook container image
Comment 13 Ruth Netser 2021-05-18 09:49:52 UTC 
Works with virt-handler v4.8.0-47 and latest sidecar image (kubevirt/example-hook-sidecar:latest). Closing.