Bug 1776306 - [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
Summary: [rhv-4.4.0-4] - Export VM(on a system upgraded from 4.3) as ova fails - Comm...
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage
Version: 4.4.0
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ovirt-4.4.0
: ---
Assignee: Liran Rotenberg
QA Contact: Ilan Zuckerman
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-11-25 12:58 UTC by Avihai
Modified: 2020-04-02 10:57 UTC (History)
6 users (show)

Fixed In Version: ovirt-engine 4.4.0-27 22b6f82
Clone Of:
Environment:
Last Closed: 2020-04-02 10:57:21 UTC
oVirt Team: Virt
Embargoed:
pm-rhel: ovirt-4.4+


Attachments (Terms of Use)
engine log (150.13 KB, application/gzip)
2019-11-25 12:58 UTC, Avihai
no flags Details
rhv-4.4.0-5 upgraded scale team env logs (1.95 MB, application/gzip)
2019-12-09 07:30 UTC, Avihai
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 105744 0 master MERGED packaging: remove ova scripts from templates 2021-02-16 06:36:31 UTC

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?


Note You need to log in before you can comment on or make changes to this bug.