Created attachment 1118704 [details] engine and vdsm logs Description of problem: Live merge operation fails noting Failed child command status for step 'DESTROY_IMAGE_CHECK' Version-Release number of selected component (if applicable): 3.6.2.6-0.1 How reproducible: 100% Steps to Reproduce: 1. Create a VM with 3 snapshots (cold snapshot), each with unique changes within files on OS 2. Power on the VM 3. Attempt to remove the middle snapshot (2/3) Actual results: The live merge operation fails Expected results: Additional info: Pertinent failure from the engine log: 2016-01-27 09:13:20,193 INFO [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-62) [67edccaf] Executing Live Merge command step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:20,208 INFO [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-7) [45262bff] Running command: DestroyImageCheckCommand internal: true. 2016-01-27 09:13:20,208 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-7) [45262bff] START, GetVolumeInfoVDSCommand(HostName = host_mixed_3, GetVolumeInfoVDSCommandParameters:{runAsync='true', hostId='d60dfddc-b6b0-487d-ba88-602423ca5a5e', storagePoolId='dfbf2ed4-9b61-4b8f-974a-a7868bffc659', storageDomainId='9c8d54b4-719c-446e-91e1-ea10d97ed97e', imageGroupId='86884e6d-f098-4cc8-9a65-d49e783b0163', imageId='df1ed51b-a015-4041-9b01-84f4d1bcdd0b'}), log id: 5e294fd5 2016-01-27 09:13:20,219 INFO [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-62) [2524120f] Executing Live Merge command step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:20,231 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-6) [4bd5b450] FINISH, GetVolumeInfoVDSCommand, log id: 1848cad8 2016-01-27 09:13:20,231 ERROR [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-6) [4bd5b450] The following images were not removed: [894cf020-474d-44aa-94f1-e34c809bfe4e] 2016-01-27 09:13:20,239 INFO [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-62) [413ab29f] Executing Live Merge command step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:20,239 INFO [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-8) [3640000c] Running command: DestroyImageCheckCommand internal: true. 2016-01-27 09:13:20,246 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-8) [3640000c] START, GetVolumeInfoVDSCommand(HostName = host_mixed_3, GetVolumeInfoVDSCommandParameters:{runAsync='true', hostId='d60dfddc-b6b0-487d-ba88-602423ca5a5e', storagePoolId='dfbf2ed4-9b61-4b8f-974a-a7868bffc659', storageDomainId='9c8d54b4-719c-446e-91e1-ea10d97ed97e', imageGroupId='b6d31812-6e55-47a3-b8b8-d72bea789dd1', imageId='e4b2d90b-3748-44f5-8292-c04b0f32487e'}), log id: 278b008e 2016-01-27 09:13:20,261 INFO [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-9) [10062c81] Running command: DestroyImageCheckCommand internal: true. 2016-01-27 09:13:20,262 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-9) [10062c81] START, GetVolumeInfoVDSCommand(HostName = host_mixed_3, GetVolumeInfoVDSCommandParameters:{runAsync='true', hostId='d60dfddc-b6b0-487d-ba88-602423ca5a5e', storagePoolId='dfbf2ed4-9b61-4b8f-974a-a7868bffc659', storageDomainId='9c8d54b4-719c-446e-91e1-ea10d97ed97e', imageGroupId='7f3b7843-1ec7-4a0e-9735-4daeae310184', imageId='da2fb265-59e0-4584-8329-7cf5e2ab87f2'}), log id: 572b170d 2016-01-27 09:13:20,263 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-7) [45262bff] FINISH, GetVolumeInfoVDSCommand, log id: 5e294fd5 2016-01-27 09:13:20,263 ERROR [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-7) [45262bff] The following images were not removed: [df1ed51b-a015-4041-9b01-84f4d1bcdd0b] 2016-01-27 09:13:20,286 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-8) [3640000c] FINISH, GetVolumeInfoVDSCommand, log id: 278b008e 2016-01-27 09:13:20,287 ERROR [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-8) [3640000c] The following images were not removed: [e4b2d90b-3748-44f5-8292-c04b0f32487e] 2016-01-27 09:13:21,260 INFO [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-76) [5df20b6] Executing Live Merge command step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:21,278 INFO [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-10) [51d050cc] Running command: DestroyImageCheckCommand internal: true. 2016-01-27 09:13:21,280 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-10) [51d050cc] START, GetVolumeInfoVDSCommand(HostName = host_mixed_3, GetVolumeInfoVDSCommandParameters:{runAsync='true', hostId='d60dfddc-b6b0-487d-ba88-602423ca5a5e', storagePoolId='dfbf2ed4-9b61-4b8f-974a-a7868bffc659', storageDomainId='9c8d54b4-719c-446e-91e1-ea10d97ed97e', imageGroupId='650b3c2f-7c16-401e-8c0f-3fa3b51d5a50', imageId='797010e8-9286-4371-86e5-9e8d450667f5'}), log id: 746aa559 2016-01-27 09:13:21,302 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-9) [10062c81] FINISH, GetVolumeInfoVDSCommand, log id: 572b170d 2016-01-27 09:13:21,302 ERROR [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-9) [10062c81] The following images were not removed: [da2fb265-59e0-4584-8329-7cf5e2ab87f2] 2016-01-27 09:13:22,273 INFO [org.ovirt.engine.core.bll.RemoveSnapshotCommandCallback] (DefaultQuartzScheduler_Worker-72) [] Waiting on Live Merge child commands to complete 2016-01-27 09:13:22,894 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (pool-6-thread-10) [51d050cc] FINISH, GetVolumeInfoVDSCommand, log id: 746aa559 2016-01-27 09:13:22,894 ERROR [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-6-thread-10) [51d050cc] The following images were not removed: [797010e8-9286-4371-86e5-9e8d450667f5] 2016-01-27 09:13:30,282 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-46) [4119c6bc] Failed child command status for step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:30,290 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-46) [67edccaf] Failed child command status for step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:30,297 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-46) [2524120f] Failed child command status for step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:30,303 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-46) [413ab29f] Failed child command status for step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:31,316 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-48) [4119c6bc] Merging of snapshot 'ce039203-6544-41d1-9449-eac1a009ccab' images '256e51cd-87e6-40fe-8346-1035625605fb'..'894cf020-474d-44aa-94f1-e34c809bfe4e' failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation. 2016-01-27 09:13:31,329 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-48) [67edccaf] Merging of snapshot 'ce039203-6544-41d1-9449-eac1a009ccab' images '0d164815-9279-4ed2-9c6f-fbaac35c0de8'..'df1ed51b-a015-4041-9b01-84f4d1bcdd0b' failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation. 2016-01-27 09:13:31,342 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-48) [2524120f] Merging of snapshot 'ce039203-6544-41d1-9449-eac1a009ccab' images 'c31ca3f2-76e0-4b93-8fa9-6e2f9d842a06'..'e4b2d90b-3748-44f5-8292-c04b0f32487e' failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation. 2016-01-27 09:13:31,356 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-48) [413ab29f] Merging of snapshot 'ce039203-6544-41d1-9449-eac1a009ccab' images '693d5f0b-8bae-49d1-ad22-fd605f4c91bf'..'da2fb265-59e0-4584-8329-7cf5e2ab87f2' failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation. 2016-01-27 09:13:31,370 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-48) [5df20b6] Failed child command status for step 'DESTROY_IMAGE_CHECK' 2016-01-27 09:13:31,383 INFO [org.ovirt.engine.core.bll.RemoveSnapshotCommandCallback] (DefaultQuartzScheduler_Worker-48) [snapshots_delete_2a3b8ef0-0690-4b69] All Live Merge child commands have completed, status 'FAILED' 2016-01-27 09:13:32,393 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-25) [5df20b6] Merging of snapshot 'ce039203-6544-41d1-9449-eac1a009ccab' images '3e85be88-43c5-4f78-924b-0a0219578d88'..'797010e8-9286-4371-86e5-9e8d450667f5' failed. Images have been marked illegal and can no longer be previewed or reverted to. Please retry Live Merge on the snapshot to complete the operation. 2016-01-27 09:13:32,406 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotCommand] (DefaultQuartzScheduler_Worker-25) [snapshots_delete_2a3b8ef0-0690-4b69] Ending command 'org.ovirt.engine.core.bll.RemoveSnapshotCommand' with failure. 2016-01-27 09:13:32,438 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-25) [snapshots_delete_2a3b8ef0-0690-4b69] Correlation ID: snapshots_delete_2a3b8ef0-0690-4b69, Job ID: 21b4b54c-50ac-4909-8ade-d9fcd98b1aea, Call Stack: null, Custom Event ID: -1, Message: Failed to delete snapshot 'snapshot_12215_iscsi_1' for VM 'live_merge_vm_iscsi'. 2016-01-27 09:14:28,366 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler_Worker-72) [] Setting new tasks map. The map contains now 0 tasks 2016-01-27 09:14:28,366 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler_Worker-72) [] Cleared all tasks of pool 'dfbf2ed4-9b61-4b8f-974a-a7868bffc659'. Please find the attached engine and vdsm logs
Gilad, the engine logs that you provided does not contain the logs you are describing in the bug. it seems that the dates are synced between the host and engine, but it is from Oct, while what you are describing is from 2016-01-27.. can you please provide the right logs, engine+VDSM? Thanks.
Created attachment 1118760 [details] engine and vdsm logs - 2016-01-27
Hi Amit, I attached the correct logs now.
After the failure, does the VM continue to run normally? Does the data on the disk seem to be valid?
Hi Greg, This looks to be related to your fix for https://bugzilla.redhat.com/show_bug.cgi?id=1213157 . Could you take a look?
Bug tickets must have version flags set prior to targeting them to a release. Please ask maintainer to set the correct version flags and only then set the target milestone.
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 this scenario there are multiple virt hosts involved, and the SPM host is different than the host running the VM. During live merge, we execute DestroyImageVDSCommand on the SPM, and then call GetVolumeInfo on the virt host to confirm removal. We had thought this would be fine since GetVolumeInfo checks the storage, but something isn't being sync'd and GetVolumeInfo on the virt host claims the volume is ok even after it has been removed via the SPM. For the fix mentioned in comment 5, we added the GetVolumeInfo verb to engine and chose to call it through vdsbroker. I'm not sure which course of action is best here... a) change this to irsbroker (spm), b) call something else to sync the vds after removal via spm, c) use a different verb (e.g. the originally-chosen GetVolumeChain), d) something else? Adam, any thoughts? (Random aside: it too some digging to find the actual error in the log because using GetVolumeInfo injects a couple ERROR messages for every successful live merge. We may want to think of a way around this...)
(In reply to Greg Padgett from comment #8) > In this scenario there are multiple virt hosts involved, and the SPM host is > different than the host running the VM. > > During live merge, we execute DestroyImageVDSCommand on the SPM, and then > call GetVolumeInfo on the virt host to confirm removal. We had thought this > would be fine since GetVolumeInfo checks the storage, but something isn't > being sync'd and GetVolumeInfo on the virt host claims the volume is ok even > after it has been removed via the SPM. I can only see this being possible for block storage. In that case, you might need to refresh the domain on the hsm host if you want the hsm host to notice the removed volume. > For the fix mentioned in comment 5, we added the GetVolumeInfo verb to > engine and chose to call it through vdsbroker. I'm not sure which course of > action is best here... > > a) change this to irsbroker (spm), > b) call something else to sync the vds after removal via spm, > c) use a different verb (e.g. the originally-chosen GetVolumeChain), > d) something else? > > Adam, any thoughts? I am assuming this only happens for block volumes. If we observe it on file domains then something even stranger is happening and we need to look deeper. I think getVolumeInfo is still the right approach. It seems fine to use the SPM to confirm removal. Do you know if engine refreshes all hosts that are using a domain after every operation that might change LVM state? I think we should try hard to follow existing engine convention with regard to refreshing hosts. > > (Random aside: it too some digging to find the actual error in the log > because using GetVolumeInfo injects a couple ERROR messages for every > successful live merge. We may want to think of a way around this...)
(In reply to Adam Litke from comment #9) > (In reply to Greg Padgett from comment #8) [trim] > I am assuming this only happens for block volumes. If we observe it on file > domains then something even stranger is happening and we need to look deeper. Indeed, this bz involves block storage. > I think getVolumeInfo is still the right approach. It seems fine to use the > SPM to confirm removal. Do you know if engine refreshes all hosts that are > using a domain after every operation that might change LVM state? I think > we should try hard to follow existing engine convention with regard to > refreshing hosts. Would this be the RefreshVolume verb? Engine only uses this from MergeExtendCommand (in fact, it was added to engine for that). No other refresh-like actions jump out to me from a cursory check of other block-related snapshot operations, but I could have overlooked something. The option of sending getVolumeInfo to the SPM is appealing--much simpler. Are there any downsides to /not/ issuing a refresh on the non-SPM hosts after removing the volume via the SPM? Since engine won't be using the volume any more, I don't think any faults would occur--but I'm not sure what happens on the vdsm side wrt stale metadata and such, nor how well this solution fits with the upcoming SPM removal.
I think the right fix for 3.6 would be to query the spm after removing volumes, since non-spm hosts are not aware of storage changes. In 4.0 we will have to work on invalidating lvm cache when quering volume info and maybe other metadata related queries.
Created attachment 1122560 [details] sql script to handle cleanup after experiencing this failure Because the cleanup for this is difficult, I wrote a sql script that can be used which performs the database updates done at the end of a successful Live Merge. It's appropriate to use if Live merge fails with a message like the following in your engine log: 2016-02-09 15:09:43,220 ERROR [org.ovirt.engine.core.bll.DestroyImageCheckCommand] (pool-7-thread-4) [6ab159d3] The following images were not removed: [11aedd61-b3a7-46ae-b7d4-982e9e58b863] [...] 2016-02-09 15:10:43,214 ERROR [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskLiveCommand] (DefaultQuartzScheduler_Worker-62) [91baf933] Failed child command status for step 'DESTROY_IMAGE_CHECK' In this instance, you would run the below commands with the following: VM_NAME = the name of the VM with the snapshot you were removing SNAPSHOT_DESC = the description of the snapshot you were removing IMAGE_ID = the image from the above log message, e.g. 11aedd61-b3a7-46ae-b7d4-982e9e58b863 To use it: 1. Back up your database 2. psql <dbname> -U <dbuser> < /path/to/repair_failed_merge.sql 3. psql <dbname> -U <dbuser> -c "SELECT ovirt_repair_failed_merge('VM_NAME', 'SNAPSHOT_DESC', 'IMAGE_ID')" If all went well, it will print "Success". It performs a few verifications before modifying any data, so if it reports an error then there may be a problem with the input or the script. Please let me know if any issues.
Verified to be fixed on build 3.6.3.2-0.1, ran our entire Live merge plan for tier 1 and tier 2 cases with iSCSI, all passed.
Created attachment 1132520 [details] sql script to handle cleanup after experiencing this failure (updated) In case anyone runs into this, I updated the script to: - handle snapshots with multiple disks - maintain backward compatibility with 3.5 It now requires an additional parameter of the disk alias, thus params are: v_vm_name VARCHAR v_snapshot_name VARCHAR v_disk_alias VARCHAR v_removed_image_uuid VARCHAR I also added a warning if it proceeds to check the child snapshot, so that if it fails to find any match, it will have at least hinted that it may be due to the image status (must be illegal) or parent image assignment. Occasionally the image may have to be marked illegal by hand in order to proceed. For backwards compatibility it will check for the existence of the volume_classification column before attempting to update it, thus it is compatible with both 3.5 and 3.6 schemas.
For anyone that uses this workaround, note that it is best to remove the stored procedure after use. Leaving it may cause trouble later on (especially if installed via a different dbuser than the rest of the engine database). psql <dbname> -U <dbuser> -c 'DROP FUNCTION ovirt_repair_failed_merge(varchar, varchar, varchar, varchar)'
*** Bug 1329000 has been marked as a duplicate of this bug. ***