Bug 1442688
| Summary: | Hide expected exception during snapshot merge. | ||
|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Yaniv Kaul <ykaul> |
| Component: | BLL.Storage | Assignee: | Ala Hino <ahino> |
| Status: | CLOSED UPSTREAM | QA Contact: | Kevin Alon Goldblatt <kgoldbla> |
| Severity: | medium | Docs Contact: | |
| Priority: | medium | ||
| Version: | --- | CC: | ahino, amureini, bugs, ylavi |
| Target Milestone: | ovirt-4.2.0 | Keywords: | Reopened |
| Target Release: | 4.2.0.2 | Flags: | rule-engine:
ovirt-4.2+
|
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | Enhancement | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2017-08-21 15:22:46 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: | |||
Ala, didn't you already have a patch for this? Unfortunately, not for this one. You are probably referring to https://bugzilla.redhat.com/1376580 that was fixed We handled not logging the VolumeDoesNotExist error at the engine side long time ago (patch https://gerrit.ovirt.org/#/c/53945/ the was merged on more than year ago) in live merge context, and as this logic is common with cold merge, I can't see how we ran into this again. In my tests, both cold and live merge, I see the following log message, which is the one I expect to see, no stack traces, only a log message with expectedEngineErrors='[VolumeDoesNotExist]': 2017-07-30 12:26:49,715+03 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [ad173463-1782-4124-92c7-980686c7bc3e] Command 'GetVolumeInfoVDSCommand(HostName = rich-el73-host02, GetVolumeInfoVDSCommandParameters:{expectedEngineErrors='[VolumeDoesNotExist]', hostId='400db8c1-8012-4f50-bc44-36386fd95d04', storagePoolId='e70b69ce-4809-451a-89b3-7c2df2760cb7', storageDomainId='c81fbcbc-44d0-42f6-91e2-53e7b3399a61', imageGroupId='81454380-8b09-4c11-816a-58b2e326c5b9', imageId='b5750c67-44e3-4133-9b8c-454b9aafafee'})' execution failed: VDSGenericException: VDSErrorException: Failed to GetVolumeInfoVDS, error = Volume does not exist: (u'b5750c67-44e3-4133-9b8c-454b9aafafee',), code = 201 At Vdsm side, this is reported at BZ 1408304. Closing for works for me. On a second thought, I better move this bug to ON_QA so the QE guys can double check me on this. Changing to closed upstream |
Description of problem: Since it's expected volume will not be found in the flow, please catch and treat it properly, either in VDSM or Engine. Specifically: 2017-04-17 02:42:33,802-04 INFO [org.ovirt.engine.core.bll.snapshots.ColdMergeSnapshotSingleDiskCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] Command 'ColdMergeSnapshotSingleDisk' id '5ac9b4e8-0600-4622-881e-6cb50c1e9f24' executing step 'DESTROY_IMAGE_CHECK' 2017-04-17 02:42:33,853-04 INFO [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] Running command: DestroyImageCheckCommand internal: true. 2017-04-17 02:42:33,857-04 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] START, SPMGetVolumeInfoVDSCommand( SPMGetV olumeInfoVDSCommandParameters:{expectedEngineErrors='[VolumeDoesNotExist]', runAsync='true', storagePoolId='9ceb6689-3130-4f69-bb64-38d050b00696', ignoreFailoverLimit='false', storageDomainId='0a78f0d5-86be-4e3d -a7e3-ead6228934e5', imageGroupId='ecffccdd-1f5f-4b63-b148-066c7e192fb7', imageId='c38545d0-c119-4c19-af57-4a3fc39edab2'}), log id: 18cc4fd1 2017-04-17 02:42:33,858-04 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] Executing GetVolumeInfo using the current SPM 2017-04-17 02:42:33,859-04 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] START, GetVolumeInfoVDSCommand(HostName = lag o-basic-suite-master-host0, GetVolumeInfoVDSCommandParameters:{expectedEngineErrors='[VolumeDoesNotExist]', runAsync='true', hostId='233873a0-4e66-4a70-a2e6-940e88cd8e89', storagePoolId='9ceb6689-3130-4f69-bb64- 38d050b00696', storageDomainId='0a78f0d5-86be-4e3d-a7e3-ead6228934e5', imageGroupId='ecffccdd-1f5f-4b63-b148-066c7e192fb7', imageId='c38545d0-c119-4c19-af57-4a3fc39edab2'}), log id: 3e656ff5 2017-04-17 02:42:33,859-04 DEBUG [org.ovirt.vdsm.jsonrpc.client.reactors.stomp.impl.Message] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] SEND ovirtCorrelationId:5e9f5b1d-795c-456a-ad2c-005dff119f1a destination:jms.topic.vdsm_requests reply-to:jms.topic.vdsm_responses content-length:309 {"jsonrpc":"2.0","method":"Volume.getInfo","params":{"storagepoolID":"9ceb6689-3130-4f69-bb64-38d050b00696","storagedomainID":"0a78f0d5-86be-4e3d-a7e3-ead6228934e5","imageID":"ecffccdd-1f5f-4b63-b148-066c7e192fb 7","volumeID":"c38545d0-c119-4c19-af57-4a3fc39edab2"},"id":"07b645a4-904d-47d3-96ac-35999a279282"}^@ 2017-04-17 02:42:33,859-04 DEBUG [org.ovirt.vdsm.jsonrpc.client.reactors.stomp.StompCommonClient] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] Message sent: SEND destination:jms.topic.vdsm_requests content-length:309 ovirtCorrelationId:5e9f5b1d-795c-456a-ad2c-005dff119f1a reply-to:jms.topic.vdsm_responses <JsonRpcRequest id: "07b645a4-904d-47d3-96ac-35999a279282", method: Volume.getInfo, params: {storagepoolID=9ceb6689-3130-4f69-bb64-38d050b00696, storagedomainID=0a78f0d5-86be-4e3d-a7e3-ead6228934e5, imageID=ecff ccdd-1f5f-4b63-b148-066c7e192fb7, volumeID=c38545d0-c119-4c19-af57-4a3fc39edab2}> 2017-04-17 02:42:33,871-04 DEBUG [org.ovirt.vdsm.jsonrpc.client.reactors.stomp.impl.Message] (SSL Stomp Reactor) [18f9ffcf] MESSAGE content-length:168 destination:jms.topic.vdsm_responses content-type:application/json subscription:c2d18280-b656-410a-bcc2-b9096f5d62a9 {"jsonrpc": "2.0", "id": "07b645a4-904d-47d3-96ac-35999a279282", "error": {"message": "Volume does not exist: (u'c38545d0-c119-4c19-af57-4a3fc39edab2',)", "code": 201}}^@ 2017-04-17 02:42:33,871-04 DEBUG [org.ovirt.vdsm.jsonrpc.client.internal.ResponseWorker] (ResponseWorker) [] Message received: {"jsonrpc": "2.0", "id": "07b645a4-904d-47d3-96ac-35999a279282", "error": {"message" : "Volume does not exist: (u'c38545d0-c119-4c19-af57-4a3fc39edab2',)", "code": 201}} 2017-04-17 02:42:33,873-04 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] Failed in 'GetVolumeInfoVDS' method 2017-04-17 02:42:33,873-04 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand' return value ' VolumeInfoReturn:{status='Status [code=201, message=Volume does not exist: (u'c38545d0-c119-4c19-af57-4a3fc39edab2',)]'} ' 2017-04-17 02:42:33,873-04 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] HostName = lago-basic-suite-master-host0 2017-04-17 02:42:33,874-04 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] Command 'GetVolumeInfoVDSCommand(HostName = lago-basic-suite-master-host0, GetVolumeInfoVDSCommandParameters:{expectedEngineErrors='[VolumeDoesNotExist]', runAsync='true', hostId='233873a0-4e66-4a70-a2e6-940e88cd8e89', storagePoolId='9ceb6689-3130-4f69-bb64-38d050b00696', storageDomainId='0a78f0d5-86be-4e3d-a7e3-ead6228934e5', imageGroupId='ecffccdd-1f5f-4b63-b148-066c7e192fb7', imageId='c38545d0-c119-4c19-af57-4a3fc39edab2'})' execution failed: VDSGenericException: VDSErrorException: Failed to GetVolumeInfoVDS, error = Volume does not exist: (u'c38545d0-c119-4c19-af57-4a3fc39edab2',), code = 201 2017-04-17 02:42:33,874-04 DEBUG [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (DefaultQuartzScheduler3) [5e9f5b1d-795c-456a-ad2c-005dff119f1a] Exception: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to GetVolumeInfoVDS, error = Volume does not exist: (u'c38545d0-c119-4c19-af57-4a3fc39edab2',), code = 201 at org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:76) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:222) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:192) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand.executeVdsBrokerCommand(GetVolumeInfoVDSCommand.java:32) [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:404) [vdsbroker.jar:] at org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetVolumeInfoVDSCommand.executeIrsBrokerCommand(SPMGetVolumeInfoVDSCommand.java:28) [vdsbroker.jar:]