Bug 1623639
| Summary: | Upload image verification failed with error "Image virtual size 10737418240 is bigger than volume size 1073741824", code = 484 | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Yosi Ben Shimon <ybenshim> | ||||
| Component: | BLL.Storage | Assignee: | Daniel Erez <derez> | ||||
| Status: | CLOSED NOTABUG | QA Contact: | Elad <ebenahar> | ||||
| Severity: | medium | Docs Contact: | |||||
| Priority: | medium | ||||||
| Version: | 4.2.6 | CC: | bugs, nsoffer, ybenshim | ||||
| Target Milestone: | ovirt-4.2.7 | Keywords: | Automation, Regression | ||||
| Target Release: | --- | Flags: | rule-engine:
ovirt-4.2+
rule-engine: blocker+ |
||||
| Hardware: | x86_64 | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2018-09-05 15:14:36 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | Storage | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
As part of verifying untrusted volume size (https://gerrit.ovirt.org/#/c/93172/), we verify that uploaded image size is equal to the specified virtual size. Can you please ensure that the tests are using the uploaded image size (when creating the disk). I.e. 'provisioned_size=image_info["virtual-size"],' (See: https://github.com/oVirt/ovirt-engine-sdk/blob/master/sdk/examples/upload_disk.py) (In reply to Daniel Erez from comment #1) > As part of verifying untrusted volume size > (https://gerrit.ovirt.org/#/c/93172/), we verify that uploaded image size is > equal to the specified virtual size. Can you please ensure that the tests > are using the uploaded image size (when creating the disk). > I.e. 'provisioned_size=image_info["virtual-size"],' (See: > https://github.com/oVirt/ovirt-engine-sdk/blob/master/sdk/examples/ > upload_disk.py) The provision-size of the disk is 10G and the actual volume size is 1G (1073741824). I ran the same test case twice on different environments: 1. ovirt-engine-4.2.5.2-0.1.el7ev.noarch ovirt-imageio-proxy-1.4.2-0.el7ev.noarch vdsm-4.20.35-1.el7ev.x86_64 --> Success 2. ovirt-engine-4.2.6.4-0.1.el7ev.noarch ovirt-imageio-proxy-1.4.4-0.el7ev.noarch vdsm-4.20.39-1.el7ev.x86_64 --> Failure with the same exception as in the description of this bug. Adding regression. This bug report has Keywords: Regression or TestBlocker. Since no regressions or test blockers are allowed between releases, it is also being identified as a blocker for this release. Please resolve ASAP. (In reply to Yosi Ben Shimon from comment #2) > (In reply to Daniel Erez from comment #1) > > As part of verifying untrusted volume size > > (https://gerrit.ovirt.org/#/c/93172/), we verify that uploaded image size is > > equal to the specified virtual size. Can you please ensure that the tests > > are using the uploaded image size (when creating the disk). > > I.e. 'provisioned_size=image_info["virtual-size"],' (See: > > https://github.com/oVirt/ovirt-engine-sdk/blob/master/sdk/examples/ > > upload_disk.py) > > The provision-size of the disk is 10G and the actual volume size is 1G > (1073741824). > I ran the same test case twice on different environments: > > 1. > ovirt-engine-4.2.5.2-0.1.el7ev.noarch > ovirt-imageio-proxy-1.4.2-0.el7ev.noarch > vdsm-4.20.35-1.el7ev.x86_64 > --> Success > > 2. > ovirt-engine-4.2.6.4-0.1.el7ev.noarch > ovirt-imageio-proxy-1.4.4-0.el7ev.noarch > vdsm-4.20.39-1.el7ev.x86_64 > --> Failure with the same exception as in the description of this bug. > > Adding regression. This is expected, as it is a new validation we've added for 4.2.6 build. Can you attach the output of 'qemu-img info' on the uploaded file? The test case did not match the upload image validation added in 4.2.6. Closing this bug as NOTABUG. |
Created attachment 1479560 [details] logs Description of problem: An automation test case execution failed while trying to upload an image. The logs attached contains the logs for fcp, but it failed on nfs, gluster & iscsi as well. According to the logs, the upload was successfull, but the verification failed and exceptions can be found on the engine and vdsm logs. The image creation from the engine log: 2018-08-29 12:42:25,890+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (default task-32) [disks_create_967719bb-2946-4a12] START, CreateImageVDSCommand( CreateImageVDSCommandParameters:{storagePoolId='d1305af4-ab05-11e8-8111-001a4a168bfc', ignoreFailoverLimit='false', storageDomainId='011e4881-1144-4887-bfa8-462174c24b74', imageGroupId='79848a9d-2284-495d-85ce-e551605d099e', imageSizeInBytes='1073741824', volumeFormat='COW', newImageId='8dc3014a-71bd-4079-bbc0-b6b9ec28dbe7', imageType='Sparse', newImageDescription='{"DiskAlias":"disk_qcow2_v2_2912422554","DiskDescription":""}', imageInitialSizeInBytes='0'}), log id: 56a9755d AddImageTicketVDSCommand: 2018-08-29 12:43:10,914+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.AddImageTicketVDSCommand] (default task-64) [d1628604-99b2-4409-adc1-5e90698048a9] START, AddImageTicketVDSCommand(HostName = host_mixed_1, AddImageTicketVDSCommandParameters:{hostId='e77943da-3d9a-4605-bef1-5e09d40ea159', ticketId='a206d50f-b78b-4e5e-84bc-663c63f4bec8', timeout='300', operations='[write]', size='1073741824', url='file:///rhev/data-center/mnt/blockSD/011e4881-1144-4887-bfa8-462174c24b74/images/79848a9d-2284-495d-85ce-e551605d099e/8dc3014a-71bd-4079-bbc0-b6b9ec28dbe7', filename='null', sparse='false'}), log id: 23bdc01f Finalizing successful transfer: 2018-08-29 12:43:55,203+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [d1628604-99b2-4409-adc1-5e90698048a9] Finalizing successful transfer for Upload disk 'disk_qcow2_v2_2912422554' (disk id: '79848a9d-2284-495d-85ce-e551605d099e', image id: '8dc3014a-71bd-4079-bbc0-b6b9ec28dbe7') RemoveImageTicketVDSCommand: 2018-08-29 12:43:55,205+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [d1628604-99b2-4409-adc1-5e90698048a9] START, RemoveImageTicketVDSCommand(HostName = host_mixed_1, RemoveImageTicketVDSCommandParameters:{hostId='e77943da-3d9a-4605-bef1-5e09d40ea159', ticketId='a206d50f-b78b-4e5e-84bc-663c63f4bec8', timeout='null'}), log id: 49f6a314 2018-08-29 12:43:55,214+03 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.RemoveImageTicketVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [d1628604-99b2-4409-adc1-5e90698048a9] FINISH, RemoveImageTicketVDSCommand, return: StatusOnlyReturn [status=Status [code=0, message=Done]], log id: 49f6a314 Verificaiton exception: 2018-08-29 12:43:55,417+03 ERROR [org.ovirt.engine.core.bll.storage.disk.image.TransferDiskImageCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-81) [d1628604-99b2-4409-adc1-5e90698048a9] Failed to verify transferred image: {}: org.ovirt.engine.core.common.errors.EngineException: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to VerifyUntrustedVolumeVDS, error = Image verification failed: 'reason=Image virtual size 10737418240 is bigger than volume size 1073741824', code = 484 (Failed with error unexpected and code 16) at org.ovirt.engine.core.bll.VdsHandler.handleVdsResult(VdsHandler.java:118) [bll.jar:] at org.ovirt.engine.core.bll.VDSBrokerFrontendImpl.runVdsCommand(VDSBrokerFrontendImpl.java:33) [bll.jar:] at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.verifyImage(TransferImageCommand.java:459) [bll.jar:] at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.handleFinalizingSuccess(TransferImageCommand.java:424) [bll.jar:] at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.executeStateHandler(TransferImageCommand.java:184) [bll.jar:] at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommand.proceedCommandExecution(TransferImageCommand.java:153) [bll.jar:] at org.ovirt.engine.core.bll.storage.disk.image.TransferImageCommandCallback.doPolling(TransferImageCommandCallback.java:21) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:146) [bll.jar:] at org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:107) [bll.jar:] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_181] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [rt.jar:1.8.0_181] at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383) [javax.enterprise.concurrent.jar:1.0.0.redhat-1] at org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534) [javax.enterprise.concurrent.jar:1.0.0.redhat-1] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_181] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_181] at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_181] at org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250) [javax.enterprise.concurrent.jar:1.0.0.redhat-1] at org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78) Caused by: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to VerifyUntrustedVolumeVDS, error = Image verification failed: 'reason=Image virtual size 10737418240 is bigger than volume size 1073741824', code = 484 at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:225) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:195) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.ImageActionsVDSCommandBase.executeVdsBrokerCommand(ImageActionsVDSCommandBase.java:20) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVdsCommandWithNetworkEvent(VdsBrokerCommand.java:123) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:111) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73) [vdsbroker.jar:] at org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33) [dal.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:400) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown Source) [vdsbroker.jar:] at sun.reflect.GeneratedMethodAccessor283.invoke(Unknown Source) [:1.8.0_181] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181] at org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:51) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:79) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12) [common.jar:] at sun.reflect.GeneratedMethodAccessor66.invoke(Unknown Source) [:1.8.0_181] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.8.0_181] at java.lang.reflect.Method.invoke(Method.java:498) [rt.jar:1.8.0_181] at org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:85) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:73) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:57) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68) [weld-core-impl.jar:2.4.7.Final-redhat-1] at org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown Source) [vdsbroker.jar:] ... 17 more From vdsm log (after ticket deletion): 2018-08-29 12:43:55,245+0300 INFO (jsonrpc/3) [vdsm.api] START verify_untrusted_volume(spUUID='d1305af4-ab05-11e8-8111-001a4a168bfc', sdUUID='011e4881-1144-4887-bfa8-462174c24b74', imgUUID='79848a9d-2284-495d-85ce-e551605d099e', volUUID='8dc3014a-71bd-4079-bbc0-b6b9ec28dbe7') from=::ffff:10.46.16.252,40218, flow_id=d1628604-99b2-4409-adc1-5e90698048a9, task_id=9dffdcb1-f054-4212-b4e5-560a3a05f623 (api:46) 2018-08-29 12:43:55,368+0300 DEBUG (jsonrpc/3) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-11 /usr/bin/dd iflag=direct skip=7 bs=512 if=/dev/011e4881-1144-4887-bfa8-462174c24b74/metadata count=1 (cwd None) (commands:65) 2018-08-29 12:43:55,388+0300 DEBUG (jsonrpc/3) [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000332893 s, 1.5 MB/s\n'; <rc> = 0 (commands:86) 2018-08-29 12:43:55,388+0300 DEBUG (jsonrpc/3) [storage.Misc] err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000332893 s, 1.5 MB/s'], size: 512 (misc:124) 2018-08-29 12:43:55,389+0300 DEBUG (jsonrpc/3) [storage.Misc.excCmd] /usr/bin/taskset --cpu-list 0-11 /usr/bin/dd iflag=direct skip=7 bs=512 if=/dev/011e4881-1144-4887-bfa8-462174c24b74/metadata count=1 (cwd None) (commands:65) 2018-08-29 12:43:55,407+0300 DEBUG (jsonrpc/3) [storage.Misc.excCmd] SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000291568 s, 1.8 MB/s\n'; <rc> = 0 (commands:86) 2018-08-29 12:43:55,407+0300 DEBUG (jsonrpc/3) [storage.Misc] err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000291568 s, 1.8 MB/s'], size: 512 (misc:124) 2018-08-29 12:43:55,408+0300 INFO (jsonrpc/3) [vdsm.api] FINISH verify_untrusted_volume error=Image verification failed: 'reason=Image virtual size 10737418240 is bigger than volume size 1073741824' from=::ffff:10.46.16.252,40218, flow_id=d1628604-99b2-4409-adc1-5e90698048a9, task_id=9dffdcb1-f054-4212-b4e5-560a3a05f623 (api:50) 2018-08-29 12:43:55,408+0300 ERROR (jsonrpc/3) [storage.TaskManager.Task] (Task='9dffdcb1-f054-4212-b4e5-560a3a05f623') Unexpected error (task:875) Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/vdsm/storage/task.py", line 882, in _run return fn(*args, **kargs) File "<string>", line 2, in verify_untrusted_volume File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 48, in method ret = func(*args, **kwargs) File "/usr/lib/python2.7/site-packages/vdsm/storage/hsm.py", line 1557, in verify_untrusted_volume % (qemu_size, meta_size)) ImageVerificationError: Image verification failed: 'reason=Image virtual size 10737418240 is bigger than volume size 1073741824' 2018-08-29 12:43:55,408+0300 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='9dffdcb1-f054-4212-b4e5-560a3a05f623') Task._run: 9dffdcb1-f054-4212-b4e5-560a3a05f623 ('d1305af4-ab05-11e8-8111-001a4a168bfc', '011e4881-1144-4887-bfa8-462174c24b74', '79848a9d-2284-495d-85ce-e551605d099e', '8dc3014a-71bd-4079-bbc0-b6b9ec28dbe7') {} failed - stopping task (task:894) 2018-08-29 12:43:55,408+0300 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='9dffdcb1-f054-4212-b4e5-560a3a05f623') stopping in state failed (force False) (task:1256) 2018-08-29 12:43:55,408+0300 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='9dffdcb1-f054-4212-b4e5-560a3a05f623') ref 1 aborting True (task:1002) 2018-08-29 12:43:55,408+0300 INFO (jsonrpc/3) [storage.TaskManager.Task] (Task='9dffdcb1-f054-4212-b4e5-560a3a05f623') aborting: Task is aborted: "Image verification failed: 'reason=Image virtual size 10737418240 is bigger than volume size 1073741824'" - code 484 (task:1181) 2018-08-29 12:43:55,409+0300 DEBUG (jsonrpc/3) [storage.TaskManager.Task] (Task='9dffdcb1-f054-4212-b4e5-560a3a05f623') Prepare: aborted: Image verification failed: 'reason=Image virtual size 10737418240 is bigger than volume size 1073741824' (task:1186) Version-Release number of selected component (if applicable): ovirt-engine-4.2.6.4-0.1.el7ev.noarch vdsm-4.20.39-1.el7ev.x86_64 ovirt-imageio-daemon-1.4.4-0.el7ev.noarch How reproducible: Didn't manage to reproduce it again. Steps to Reproduce: 1. 2. 3. Actual results: The image Failed to upload Expected results: Additional info: see attached logs