Bug 1776306

Summary: [rhv-4.4.0-4] - Export VM(on a system upgraded from 4.3) as ova fails - Command 'ExportVmToOva' failed when attempting to perform the next operation
Product: [oVirt] ovirt-engine Reporter: Avihai <aefrat>
Component: BLL.StorageAssignee: Liran Rotenberg <lrotenbe>
Status: CLOSED UPSTREAM QA Contact: Ilan Zuckerman <izuckerm>
Severity: high Docs Contact:
Priority: unspecified    
Version: 4.4.0CC: amarchuk, bpelled, bugs, lrotenbe, lsvaty, rbarry
Target Milestone: ovirt-4.4.0Flags: pm-rhel: ovirt-4.4+
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ovirt-engine 4.4.0-27 22b6f82 Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-04-02 10:57:21 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Virt RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
engine log
none
rhv-4.4.0-5 upgraded scale team env logs none

Description Avihai 2019-11-25 12:58:29 UTC
Created attachment 1639473 [details]
engine log

Description of problem:
Export VM as ova fails(tried it via webadmin)

Engine log:
2019-11-25 14:37:08,369+02 ERROR [org.ovirt.engine.core.bll.CreateOvaCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-73) [2269f616] Failed to create OVA. Please check logs for more details: /var/log/ovirt-engine/ova/ovirt-export-ova-ansible-20191125143657-storage-ge4-vdsm2.scl.lab.tlv.redhat.com-2269f616.log
2019-11-25 14:37:08,375+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-73) [2269f616] START, TeardownImageVDSCommand(HostName = host_mixed_2, ImageActionsVDSCommandParameters:{hostId='2cddb970-871b-42d9-bdd2-026621118c48'}), log id: 760e27b5
2019-11-25 14:37:08,391+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.TeardownImageVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-73) [2269f616] FINISH, TeardownImageVDSCommand, return: StatusReturn:{status='Status [code=0, message=Done]'}, log id: 760e27b5
2019-11-25 14:37:08,395+02 ERROR [org.ovirt.engine.core.bll.exportimport.ExportVmToOvaCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-73) [2269f616] Failed to create OVA file
2019-11-25 14:37:08,395+02 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-73) [2269f616] Command 'ExportVmToOva' id: '5f137df4-14b5-4e1f-9e63-533e1bbeba88' with children [3f2ea3ba-567b-4e66-92e8-82bd2ef7a99e] failed when attempting to perform the next operation, marking as 'ACTIVE'
2019-11-25 14:37:08,395+02 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-73) [2269f616] EngineException: ENGINE (Failed with error ENGINE and code 5001): org.ovirt.engine.core.common.errors.EngineException: EngineException: ENGINE (Failed with error ENGINE and code 5001)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.exportimport.ExportOvaCommand.createOva(ExportOvaCommand.java:118)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.exportimport.ExportVmToOvaCommand.executeNextOperation(ExportVmToOvaCommand.java:230)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.exportimport.ExportVmToOvaCommand.performNextOperation(ExportVmToOvaCommand.java:222)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback.childCommandsExecutionEnded(SerialChildCommandsExecutionCallback.java:32)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.ChildCommandsCallbackBase.doPolling(ChildCommandsCallbackBase.java:80)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:175)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:109)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383)
        at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:834)
        at org.glassfish.javax.enterprise.concurrent.0.redhat-1//org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)

2019-11-25 14:37:08,396+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-73) [2269f616] Command 'ExportVmToOva' id: '5f137df4-14b5-4e1f-9e63-533e1bbeba88' child commands '[3f2ea3ba-567b-4e66-92e8-82bd2ef7a99e]' executions were completed, status 'FAILED'
2019-11-25 14:37:09,451+02 ERROR [org.ovirt.engine.core.bll.exportimport.ExportVmToOvaCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-57) [4fee391c-cc2c-4df1-b861-0b055575bd92] Ending command 'org.ovirt.engine.core.bll.exportimport.ExportVmToOvaCommand' with failure.


Version-Release number of selected component (if applicable):
rhv-4.4.0-4 (http://bob.eng.lab.tlv.redhat.com/builds/4.4/rhv-4.4.0-4/)

ovirt-engine-4.4.0-0.4.master.el7.noarch
vdsm-4.40.0-127.gitc628cce.el8ev.x86_64
python3-libvirt-5.0.0-5.module+el8.0.1+3755+6782b0ed.x86_64
qemu-kvm-3.1.0-30.module+el8.0.1+3755+6782b0ed.x86_64

How reproducible:
100%

Steps to Reproduce:
1.Via webadmin choose a VM and perform Export VM as ova fails


Actual results:
Export VM as ova fails -  Command 'ExportVmToOva' failed when attempting to perform the next operation

Expected results:
should work.

Additional info:

Comment 1 Liran Rotenberg 2019-11-28 12:57:11 UTC
Can you provide the export ova ansible log? It is in:
/var/log/ovirt-engine/ova/ovirt-export-ova-ansible-20191125143657-storage-ge4-vdsm2.scl.lab.tlv.redhat.com-2269f616.log

Comment 2 Avihai 2019-12-08 14:25:41 UTC
(In reply to Liran Rotenberg from comment #1)
> Can you provide the export ova ansible log? It is in:
> /var/log/ovirt-engine/ova/ovirt-export-ova-ansible-20191125143657-storage-
> ge4-vdsm2.scl.lab.tlv.redhat.com-2269f616.log

The system has been reprovisioned from scratch and the issue is not seen anymore (checked rhv-4.4.0-6).
I suspect that the root cause for this issue is upgraded 4.3 -> 4.4 VM's.

I will try the upgrade flow and update.

Comment 3 Avihai 2019-12-09 07:28:19 UTC
Issue occurs all the time on another scale ENV which was upgraded(4.3->rhv 4.4.0-5).
I attatched engine + the requested correlating /ova/ovirt-export-ova-ansible log.


Engine:
2019-12-08 18:24:47,724-05 INFO  [org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [5caf7316] Ansible playbook command has exited with value: 2
2019-12-08 18:24:47,724-05 ERROR [org.ovirt.engine.core.bll.CreateOvaCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [5caf7316] Failed to create OVA. Please check logs for more details: /var/log/ov
irt-engine/ova/ovirt-export-ova-ansible-20191208182441-f01-h22-000-r620.rdu2.scalelab.redhat.com-5caf7316.log
2019-12-08 18:24:47,726-05 ERROR [org.ovirt.engine.core.bll.exportimport.ExportVmToOvaCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [5caf7316] Failed to create OVA file
2019-12-08 18:24:47,726-05 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [5caf7316] Command 'ExportVmToOva' id: '8ea123b7-de6e-4c1a-9
91f-cb960b1410a1' with children [75bc2618-447a-4f45-9489-c62e9d94c43b] failed when attempting to perform the next operation, marking as 'ACTIVE'
2019-12-08 18:24:47,726-05 ERROR [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [5caf7316] EngineException: ENGINE (Failed with error ENGINE
 and code 5001): org.ovirt.engine.core.common.errors.EngineException: EngineException: ENGINE (Failed with error ENGINE and code 5001)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.exportimport.ExportOvaCommand.createOva(ExportOvaCommand.java:118)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.exportimport.ExportVmToOvaCommand.executeNextOperation(ExportVmToOvaCommand.java:230)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.exportimport.ExportVmToOvaCommand.performNextOperation(ExportVmToOvaCommand.java:222)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback.childCommandsExecutionEnded(SerialChildCommandsExecutionCallback.java:32)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.ChildCommandsCallbackBase.doPolling(ChildCommandsCallbackBase.java:80)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:175)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:109)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)


# From ovirt-export-ova-ansible-20191208182441-f01-h22-000-r620.rdu2.scalelab.redhat.com-5caf7316.log:

2019-12-08 18:24:46,821 p=ovirt u=32664 | fatal: [f01-h22-000-r620.rdu2.scalelab.redhat.com]: FAILED! => {
    "changed": true, 
    "rc": 1
}

STDOUT:

writing ovf: <?xml version="1.0" encoding="UTF-8"?><ovf:Envelope xmlns:ovf="http://schemas.dmtf.org/ovf/envelope/1" xmlns:rasd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData" xmlns:vssd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://schemas.dmtf.org/ovf/envelope/1" xmlns:ovirt="http://www.ovirt.org/ovf"><References></References><NetworkSection><Info>List of networks</Info></NetworkSection><DiskSection><Info>List of Virtual Disks</Info></DiskSection><VirtualSystem ovf:id="45e5c04a-9e4f-4687-ad59-1e8e37a9540b"><Name>new_vm_4.4</Name><Description></Description><Comment></Comment><CreationDate>2019/12/08 23:20:12</CreationDate><ExportDate>2019/12/08 23:24:41</ExportDate><DeleteProtected>false</DeleteProtected><SsoMethod>guest_agent</SsoMethod><IsSmartcardEnabled>false</IsSmartcardEnabled><NumOfIoThreads>1</NumOfIoThreads><TimeZone>Etc/GMT</TimeZone><default_boot_sequence>0</default_boot_sequence><Generation>6</Generation><ClusterCompatibilityVersion>4.4</ClusterCompatibilityVersion><VmType>0</VmType><ResumeBehavior>AUTO_RESUME</ResumeBehavior><MinAllocatedMem>1024</MinAllocatedMem><IsStateless>false</IsStateless><IsRunAndPause>false</IsRunAndPause><AutoStartup>false</AutoStartup><Priority>1</Priority><CreatedByUserId>79325730-00a9-11ea-9c29-02e6ef0f2614</CreatedByUserId><MigrationSupport>0</MigrationSupport><IsBootMenuEnabled>false</IsBootMenuEnabled><IsSpiceFileTransferEnabled>true</IsSpiceFileTransferEnabled><IsSpiceCopyPasteEnabled>true</IsSpiceCopyPasteEnabled><AllowConsoleReconnect>false</AllowConsoleReconnect><ConsoleDisconnectAction>LOCK_SCREEN</ConsoleDisconnectAction><CustomEmulatedMachine></CustomEmulatedMachine><BiosType>0</BiosType><CustomCpuName></CustomCpuName><PredefinedProperties></PredefinedProperties><UserDefinedProperties></UserDefinedProperties><MaxMemorySizeMb>4096</MaxMemorySizeMb><MultiQueuesEnabled>true</MultiQueuesEnabled><UseHostCpu>false</UseHostCpu><TemplateId>00000000-0000-0000-0000-000000000000</TemplateId><IsInitilized>false</IsInitilized><Origin>0</Origin><quota_id>c2a599e1-f1a0-4d1e-98c3-9669c09a2976</quota_id><DefaultDisplayType>1</DefaultDisplayType><TrustedService>false</TrustedService><OriginalTemplateId>00000000-0000-0000-0000-000000000000</OriginalTemplateId><OriginalTemplateName>Blank</OriginalTemplateName><UseLatestVersion>false</UseLatestVersion><StopTime>2019/12/08 23:20:12</StopTime><CpuPinning></CpuPinning><OperatingSystemSection ovf:id="1" ovirt:id="0" ovf:required="false"><Info>Guest Operating System</Info><Description>Other OS</Description></OperatingSystemSection><VirtualHardwareSection><Info>1 CPU, 1024 Memory</Info><System><vssd:VirtualSystemType>ENGINE 4.4.0.0</vssd:VirtualSystemType></System><Item><rasd:Caption>1 virtual cpu</rasd:Caption><rasd:Description>Number of virtual CPU</rasd:Description><rasd:InstanceId>1</rasd:InstanceId><rasd:ResourceType>3</rasd:ResourceType><rasd:num_of_sockets>1</rasd:num_of_sockets><rasd:cpu_per_socket>1</rasd:cpu_per_socket><rasd:threads_per_cpu>1</rasd:threads_per_cpu><rasd:max_num_of_vcpus>16</rasd:max_num_of_vcpus><rasd:VirtualQuantity>1</rasd:VirtualQuantity></Item><Item><rasd:Caption>1024 MB of memory</rasd:Caption><rasd:Description>Memory Size</rasd:Description><rasd:InstanceId>2</rasd:InstanceId><rasd:ResourceType>4</rasd:ResourceType><rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits><rasd:VirtualQuantity>1024</rasd:VirtualQuantity></Item><Item><rasd:Caption>USB Controller</rasd:Caption><rasd:InstanceId>3</rasd:InstanceId><rasd:ResourceType>23</rasd:ResourceType><rasd:UsbPolicy>DISABLED</rasd:UsbPolicy></Item><Item><rasd:Caption>Graphical Controller</rasd:Caption><rasd:InstanceId>a1dc5225-4394-4ca3-b9f4-b1b2a94b29a1</rasd:InstanceId><rasd:ResourceType>32768</rasd:ResourceType><rasd:VirtualQuantity>1</rasd:VirtualQuantity><rasd:SinglePciQxl>false</rasd:SinglePciQxl><Type>video</Type><Device>qxl</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias></Alias><SpecParams><vgamem>16384</vgamem><heads>1</heads><ram>65536</ram><vram>8192</vram></SpecParams></Item><Item><rasd:Caption>Graphical Framebuffer</rasd:Caption><rasd:InstanceId>c19c8ac1-d31f-4843-bc1e-80b96e11a993</rasd:InstanceId><rasd:ResourceType>24</rasd:ResourceType><Type>graphics</Type><Device>spice</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias></Alias></Item><Item><rasd:Caption>Graphical Framebuffer</rasd:Caption><rasd:InstanceId>f46393e9-b32b-45d9-a490-54e1d9ad0a9a</rasd:InstanceId><rasd:ResourceType>24</rasd:ResourceType><Type>graphics</Type><Device>vnc</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias></Alias></Item><Item><rasd:Caption>CDROM</rasd:Caption><rasd:InstanceId>38570193-150b-4017-9292-40a9c15bae40</rasd:InstanceId><rasd:ResourceType>15</rasd:ResourceType><Type>disk</Type><Device>cdrom</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>true</IsReadOnly><Alias></Alias><SpecParams><path></path></SpecParams></Item><Item><rasd:ResourceType>0</rasd:ResourceType><rasd:InstanceId>fb9cd6bd-a562-4aa2-b65b-1446c3ef9e00</rasd:InstanceId><Type>rng</Type><Device>virtio</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias></Alias><SpecParams><source>urandom</source></SpecParams></Item><Item><rasd:ResourceType>0</rasd:ResourceType><rasd:InstanceId>27a9d8fb-94b2-4a8d-9344-9a96a6f28ec9</rasd:InstanceId><Type>controller</Type><Device>usb</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias></Alias><SpecParams><index>0</index><model>qemu-xhci</model></SpecParams></Item><Item><rasd:ResourceType>0</rasd:ResourceType><rasd:InstanceId>3ebf38e3-6f5e-499f-9a69-e4537a026d10</rasd:InstanceId><Type>controller</Type><Device>virtio-serial</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias>58ca7b19-0071-00c0-01d6-000000000212</Alias></Item><Item><rasd:ResourceType>0</rasd:ResourceType><rasd:InstanceId>fc04a082-375f-4095-af3e-569017120ec7</rasd:InstanceId><Type>controller</Type><Device>virtio-scsi</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>false</IsReadOnly><Alias></Alias><SpecParams><ioThreadId></ioThreadId></SpecParams></Item><Item><rasd:ResourceType>0</rasd:ResourceType><rasd:InstanceId>55879334-c80e-43b7-9987-830e47899584</rasd:InstanceId><Type>balloon</Type><Device>memballoon</Device><rasd:Address></rasd:Address><BootOrder>0</BootOrder><IsPlugged>true</IsPlugged><IsReadOnly>true</IsReadOnly><Alias></Alias><SpecParams><model>virtio</model></SpecParams></Item></VirtualHardwareSection></VirtualSystem></ovf:Envelope>
Traceback (most recent call last):
  File "/root/.ansible/tmp/ansible-tmp-1575847486.41-2456953119444/pack_ova.py", line 90, in <module>
    write_ovf(entity, ova_file, ovf)
  File "/root/.ansible/tmp/ansible-tmp-1575847486.41-2456953119444/pack_ova.py", line 38, in write_ovf
    ova_file.write(ovf)
TypeError: a bytes-like object is required, not 'str'

Comment 4 Avihai 2019-12-09 07:30:18 UTC
Created attachment 1643189 [details]
rhv-4.4.0-5 upgraded scale team env logs

Comment 5 Avihai 2019-12-09 07:33:48 UTC
Hi Liran, please check it out and ping me if you are missing something or ping Ilan Z. if you need his ENV to debug.
I also noticed this issue is not about a VM that got upgraded as in his ENV this issue also occured for new VM's created after upgrade to 4.4.

What I do notice is:
1) On newly reprovisioned ENV's from scratch(not upgraded) on rhv 4.4.0-6 the issue does not occur
2) On upgraded ENVs(4.3-> 4.4) the issue does occur 100% on any VM(old or newly created)

Comment 6 Liran Rotenberg 2019-12-15 13:49:51 UTC
The problem is compatibility of python2 and python3.
The engine run python scripts that determined on build time which version to use(of the engine's machine).
When running those script on el8 based, which run python3, the script fails.
It will also fail when in the future we will run from el8 engine on el7 hosts(cluster version 4.3).

Fixing those script to run upon the destination machine's python and make the code compatible on both is the solution.

Comment 7 Lukas Svaty 2020-02-13 13:02:02 UTC
Liran, can you fill fixed in version please?

Comment 9 Sandro Bonazzola 2020-03-20 14:57:21 UTC
This bug is targeted to 4.4.1 and in modified state. can we re-target to 4.4.0 and move to QA?