Created attachment 1634974 [details]
logs

Description of problem:
Upload qcow2 image using webadmin UI fails with error "Image daemon is unsupported" during AddImageTicketVDS command.

The reason is that ovirt-imageio-deamon is not installed.

I'm specifying all the flow although the root cause is the deamon just for additional info.

After failure, the image stuck in "paused by system" status.

From the engine log:
2019-11-11 20:49:11,882+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] START, AddImageTicketVDSCommand(HostName = host_mixed_1, AddImageTicketVDSCommandParameters:{hostId='5d6b80ec-dc66-492b-942e-d41b3eb51603', ticketId='3cc7de8e-cedc-4064-8c16-138ff08bb697', timeout='300', operations='[write]', size='257949696', url='file:///rhev/data-center/mnt/blockSD/eb236c05-319d-4f13-b3f9-974ea84f96ce/images/dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa/cba332a9-64ae-4aa7-b39b-3f42a6defd97', filename='null', sparse='false', transferId='274149a2-7676-4158-8be9-85b1a4162279'}), log id: 4375d799
2019-11-11 20:49:11,896+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] Failed in 'AddImageTicketVDS' method
2019-11-11 20:49:11,908+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command AddImageTicketVDS failed: Image daemon is unsupported: ()
2019-11-11 20:49:11,908+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand' return value 'StatusOnlyReturn [status=Status [code=483, message=Image daemon is unsupported: ()]]'
2019-11-11 20:49:11,908+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] HostName = host_mixed_1
2019-11-11 20:49:11,909+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] Command 'AddImageTicketVDSCommand(HostName = host_mixed_1, AddImageTicketVDSCommandParameters:{hostId='5d6b80ec-dc66-492b-942e-d41b3eb51603', ticketId='3cc7de8e-cedc-4064-8c16-138ff08bb697', timeout='300', operations='[write]', size='257949696', url='file:///rhev/data-center/mnt/blockSD/eb236c05-319d-4f13-b3f9-974ea84f96ce/images/dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa/cba332a9-64ae-4aa7-b39b-3f42a6defd97', filename='null', sparse='false', transferId='274149a2-7676-4158-8be9-85b1a4162279'})' execution failed: VDSGenericException: VDSErrorException: Failed to AddImageTicketVDS, error = Image daemon is unsupported: (), code = 483
2019-11-11 20:49:11,909+02 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] FINISH, AddImageTicketVDSCommand, return: , log id: 4375d799
2019-11-11 20:49:11,909+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] Failed to start image transfer session: {}: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to AddImageTicketVDS, error = Image daemon is unsupported: (), code = 483 (Failed with error ImageDeamonUnsupported and code 483)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:114)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand.addImageTicketToDaemon(TransferDiskImageCommand.java:1030)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand.startImageTransferSession(TransferDiskImageCommand.java:977)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand.handleImageIsReadyForTransfer(TransferDiskImageCommand.java:581)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand.handleInitializing(TransferDiskImageCommand.java:552)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand.executeStateHandler(TransferDiskImageCommand.java:478)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand.proceedCommandExecution(TransferDiskImageCommand.java:465)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommandCallback.doPolling(TransferImageCommandCallback.java:21)
        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)
Caused by: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to AddImageTicketVDS, error = Image daemon is unsupported: (), code = 483
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:224)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:194)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand.executeVdsBrokerCommand(AddImageTicketVDSCommand.java:24)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVdsCommandWithNetworkEvent(VdsBrokerCommand.java:123)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:111)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:65)
        at org.ovirt.engine.core.dal//org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:31)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:398)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown Source)
        at jdk.internal.reflect.GeneratedMethodAccessor69.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.jboss.weld.core.6.Final-redhat-00002//org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51)
        at org.jboss.weld.core.6.Final-redhat-00002//org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:78)
        at org.ovirt.engine.core.common//org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12)
        at jdk.internal.reflect.GeneratedMethodAccessor58.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.jboss.weld.core.6.Final-redhat-00002//org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
        at org.jboss.weld.core.6.Final-redhat-00002//org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
        at org.jboss.weld.core.6.Final-redhat-00002//org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
        at org.jboss.weld.core.6.Final-redhat-00002//org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
        at org.jboss.weld.core.6.Final-redhat-00002//org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
        at org.jboss.weld.core.6.Final-redhat-00002//org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
        at deployment.engine.ear//org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown Source)
        ... 18 more
2019-11-11 20:49:11,911+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] Failed to add image ticket to ovirt-imageio-daemon
2019-11-11 20:49:11,917+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] EVENT_ID: TRANSFER_IMAGE_STOPPED_BY_SYSTEM_FAILED_TO_ADD_TICKET_TO_DAEMON(1,069), Transfer was stopped by system. Reason: failed to add image ticket to ovirt-imageio-daemon.
2019-11-11 20:49:11,919+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.ImageTransferUpdater] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] Updating image transfer 274149a2-7676-4158-8be9-85b1a4162279 (image dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa) phase to Paused by System
2019-11-11 20:49:11,923+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] Returning from proceedCommandExecution after starting transfer session for image transfer command '274149a2-7676-4158-8be9-85b1a4162279'
2019-11-11 20:49:13,011+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-63) [b8f6852e-b749-4a93-bbfd-2fabca12b3f9] Transfer was paused by system. Upload disk 'aaa' (disk id: 'dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa', image id: 'cba332a9-64ae-4aa7-b39b-3f42a6defd97')


VDSM log:
2019-11-11 13:48:56,052-0500 INFO  (jsonrpc/3) [vdsm.api] START createVolume(sdUUID='eb236c05-319d-4f13-b3f9-974ea84f96ce', spUUID='00d9bb6c-d64b-4bd1-8fb0-e3c6f80fdacc', imgUUID='dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa', size='10737418240', volFormat=4, preallocate=2, diskType='DATA', volUUID='cba332a9-64ae-4aa7-b39b-3f42a6defd97', desc='{"DiskAlias":"aaa","DiskDescription":""}', srcImgUUID='00000000-0000-0000-0000-000000000000', srcVolUUID='00000000-0000-0000-0000-000000000000', initialSize='257949696') from=::ffff:10.35.161.127,48758, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=6d625fc6-b3a6-474e-80d6-69d9e749647e (api:48)
2019-11-11 13:48:56,055-0500 INFO  (jsonrpc/3) [IOProcessClient] (Global) Starting client (__init__:308)
2019-11-11 13:48:56,091-0500 INFO  (ioprocess/3450) [IOProcess] (Global) Starting ioprocess (__init__:434)
2019-11-11 13:48:56,132-0500 INFO  (jsonrpc/3) [vdsm.api] FINISH createVolume return=None from=::ffff:10.35.161.127,48758, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=6d625fc6-b3a6-474e-80d6-69d9e749647e (api:54)
2019-11-11 13:49:07,640-0500 INFO  (jsonrpc/4) [vdsm.api] START clearTask(taskID='6d625fc6-b3a6-474e-80d6-69d9e749647e', spUUID=None, options=None) from=::ffff:10.35.161.127,48684, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=d31aac74-8fb5-40f0-bce1-9093420d79db (api:48)
2019-11-11 13:49:07,661-0500 INFO  (jsonrpc/4) [vdsm.api] FINISH clearTask return=None from=::ffff:10.35.161.127,48684, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=d31aac74-8fb5-40f0-bce1-9093420d79db (api:54)

2019-11-11 13:49:10,347-0500 INFO  (jsonrpc/7) [vdsm.api] START prepareImage(sdUUID='eb236c05-319d-4f13-b3f9-974ea84f96ce', spUUID='00d9bb6c-d64b-4bd1-8fb0-e3c6f80fdacc', imgUUID='dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa', leafUUID='cba332a9-64ae-4aa7-b39b-3f42a6defd97', allowIllegal=True) from=::ffff:10.35.161.127,48684, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=6996ef27-009b-4271-84ed-a2d23c4b09cd (api:48)

2019-11-11 13:49:11,474-0500 INFO  (jsonrpc/7) [vdsm.api] FINISH prepareImage return={'path': '/rhev/data-center/mnt/blockSD/eb236c05-319d-4f13-b3f9-974ea84f96ce/images/dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa/cba332a9-64ae-4aa7-b39b-3f42a6defd97', 'info': {'type': 'block', 'path': '/rhev/data-center/mnt/blockSD/eb236c05-319d-4f13-b3f9-974ea84f96ce/images/dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa/cba332a9-64ae-4aa7-b39b-3f42a6defd97'}, 'imgVolumesInfo': [{'domainID': 'eb236c05-319d-4f13-b3f9-974ea84f96ce', 'imageID': 'dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa', 'volumeID': 'cba332a9-64ae-4aa7-b39b-3f42a6defd97', 'path': '/rhev/data-center/mnt/blockSD/eb236c05-319d-4f13-b3f9-974ea84f96ce/images/dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa/cba332a9-64ae-4aa7-b39b-3f42a6defd97', 'leasePath': '/dev/eb236c05-319d-4f13-b3f9-974ea84f96ce/leases', 'leaseOffset': 109051904}]} from=::ffff:10.35.161.127,48684, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=6996ef27-009b-4271-84ed-a2d23c4b09cd (api:54)
2019-11-11 13:49:11,477-0500 INFO  (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call Image.prepare succeeded in 1.13 seconds (__init__:312)
2019-11-11 13:49:11,500-0500 INFO  (jsonrpc/0) [vdsm.api] START setVolumeLegality(sdUUID='eb236c05-319d-4f13-b3f9-974ea84f96ce', spUUID='00d9bb6c-d64b-4bd1-8fb0-e3c6f80fdacc', imgUUID='dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa', volUUID='cba332a9-64ae-4aa7-b39b-3f42a6defd97', legality='ILLEGAL', options=None) from=::ffff:10.35.161.127,48758, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=11444cd8-3a6e-4b59-9bd0-a294014a650e (api:48)

2019-11-11 13:49:11,887-0500 INFO  (jsonrpc/5) [vdsm.api] START add_image_ticket(ticket={'ops': ['write'], 'size': 257949696, 'sparse': False, 'transfer_id': '274149a2-7676-4158-8be9-85b1a4162279', 'uuid': '3cc7de8e-cedc-4064-8c16-138ff08bb697', 'timeout': 300, 'url': 'file:///rhev/data-center/mnt/blockSD/eb236c05-319d-4f13-b3f9-974ea84f96ce/images/dd040d8a-a9ad-4e1e-bad4-f9c7f4ae0afa/cba332a9-64ae-4aa7-b39b-3f42a6defd97'}) from=::ffff:10.35.161.127,48684, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=e736d917-1824-46cf-bff5-e1e3f4342a61 (api:48)
2019-11-11 13:49:11,887-0500 INFO  (jsonrpc/5) [vdsm.api] FINISH add_image_ticket error=Image daemon is unsupported: () from=::ffff:10.35.161.127,48684, flow_id=b8f6852e-b749-4a93-bbfd-2fabca12b3f9, task_id=e736d917-1824-46cf-bff5-e1e3f4342a61 (api:52)
2019-11-11 13:49:11,888-0500 ERROR (jsonrpc/5) [storage.TaskManager.Task] (Task='e736d917-1824-46cf-bff5-e1e3f4342a61') Unexpected error (task:889)
Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/vdsm/storage/task.py", line 896, in _run
    return fn(*args, **kargs)
  File "<decorator-gen-147>", line 2, in add_image_ticket
  File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 50, in method
    ret = func(*args, **kwargs)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/hsm.py", line 3050, in add_image_ticket
    imagetickets.add_ticket(ticket)
  File "/usr/lib/python3.6/site-packages/vdsm/storage/imagetickets.py", line 48, in wrapper
    raise se.ImageDaemonUnsupported()
vdsm.storage.exception.ImageDaemonUnsupported: Image daemon is unsupported: ()


Version-Release number of selected component (if applicable):
ovirt-engine-4.4.0-0.4.master.el7.noarch
ovirt-imageio-common-1.5.2-0.el7ev.x86_64
ovirt-imageio-proxy-1.5.2-0.el7ev.noarch

vdsm-4.40.0-127.gitc628cce.el8ev.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Create a qcow image
2. Try to upload the image vi UI (Storage -> disks -> upload)
3.

Actual results:
The image fails to be uploaded and stuck in "paused by system" status

Expected results:
The deamon should be installed an running. And the image should be uploaded successfully.

Additional info:
When searching for "ovirt-imageio-daemon":

[root@storage-ge6-vdsm1 ~]# rpm -qa | grep image
genisoimage-1.1.11-39.el8.x86_6