Description of problem: At present we log a single correlation ID for the overall RemoveSnapshotCommand command means we have to review the engine.log for the remaining MergeSnapshotsVDSCommand correlation IDs. With BZ#844335 fixed in 3.2, enabling correlation IDs for all VDSM storage commands, it would help to have the MergeSnapshotsVDSCommand correlation IDs listed even if it is plain text in the message of the single line. Version-Release number of selected component (if applicable): rhevm-3.1.0-50.el6ev.noarch How reproducible: Always. Steps to Reproduce: 1. Delete a snapshot. 2. The correlation ID listed in the audit_log only covers the overall RemoveSnapshotCommand command. Actual results: The correlation ID listed in the audit_log only covers the overall RemoveSnapshotCommand command. Expected results: The correlation ID listed in the audit_log covers the overall RemoveSnapshotCommand command with the additional MergeSnapshotsVDSCommand IDs also listed. Additional info:
duplicate of bug 844335?
The correlation id reflects the overall command flow, it is listed in the tasks subtab, and it covers the overall operation (including MergeSnapshot). The correlation id is displayed in the engine log [1] (4e4d1134) for every internal command which is part of the overall command (RemoveSnapshotCommand). Lee, IIUC that is what you meant, right? or did you suggest anything else? [1]: 2013-06-03 13:32:29,532 INFO [org.ovirt.engine.core.bll.RemoveSnapshotCommand] (http--0.0.0.0-8700-5) [4e4d1134] Lock Acquired to object EngineLock [exclusiveLocks= key: 151a071b-869f-49d3-bd42-e19a56fae788 value: VM , sharedLocks= ] 2013-06-03 13:32:29,567 INFO [org.ovirt.engine.core.bll.RemoveSnapshotCommand] (http--0.0.0.0-8700-5) [4e4d1134] Running command: RemoveSnapshotCommand internal: false. Entities affected : ID: 151a071b-869f-49d3-bd42-e19a56fae788 Type: VM 2013-06-03 13:32:29,575 INFO [org.ovirt.engine.core.bll.RemoveSnapshotCommand] (http--0.0.0.0-8700-5) [4e4d1134] Lock freed to object EngineLock [exclusiveLocks= key: 151a071b-869f-49d3-bd42-e19a56fae788 value: VM , sharedLocks= ] 2013-06-03 13:32:29,605 INFO [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskCommand] (http--0.0.0.0-8700-5) [4e4d1134] Running command: RemoveSnapshotSingleDiskCommand internal: true. Entities affected : ID: 00000000-0000-0000-0000-000000000000 Type: Storage 2013-06-03 13:32:29,615 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.MergeSnapshotsVDSCommand] (http--0.0.0.0-8700-5) [4e4d1134] START, MergeSnapshotsVDSCommand( storagePoolId = efc43f69-2b34-484c-b546-c2040fa4a93e, ignoreFailoverLimit = false, compatabilityVersion = 3.2, storageDomainId = 22de00c8-c65f-4606-ad1f-76b39c7c6c27, imageGroupId = cc65de2f-08f6-402b-9740-ba05c0007156, imageId = 02fd6027-e734-4c32-b15d-0004841a4663, imageId2 = 06b9aefb-c4ea-43e4-8ef5-e117cbc0f130, vmId = 151a071b-869f-49d3-bd42-e19a56fae788, postZero = false), log id: 6cf240fb 2013-06-03 13:32:29,857 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.MergeSnapshotsVDSCommand] (http--0.0.0.0-8700-5) [4e4d1134] FINISH, MergeSnapshotsVDSCommand, log id: 6cf240fb 2013-06-03 13:32:29,875 INFO [org.ovirt.engine.core.bll.EntityAsyncTask] (http--0.0.0.0-8700-5) [4e4d1134] EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity 151a071b-869f-49d3-bd42-e19a56fae788 2013-06-03 13:32:29,877 INFO [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (http--0.0.0.0-8700-5) [4e4d1134] EntityMultiAsyncTasks::AttachTask: Attaching task 8b4124c7-2c85-44fa-bac5-540b198569cb to entity 151a071b-869f-49d3-bd42-e19a56fae788. 2013-06-03 13:32:29,925 INFO [org.ovirt.engine.core.bll.AsyncTaskManager] (http--0.0.0.0-8700-5) [4e4d1134] Adding task 8b4124c7-2c85-44fa-bac5-540b198569cb (Parent Command RemoveSnapshot, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet.. 2013-06-03 13:32:29,967 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (http--0.0.0.0-8700-5) [4e4d1134] BaseAsyncTask::StartPollingTask: Starting to poll task 8b4124c7-2c85-44fa-bac5-540b198569cb. 2013-06-03 13:32:29,968 INFO [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (http--0.0.0.0-8700-5) [4e4d1134] EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity 151a071b-869f-49d3-bd42-e19a56fae788 is RemoveSnapshot (determined by task 8b4124c7-2c85-44fa-bac5-540b198569cb) 2013-06-03 13:32:36,120 INFO [org.ovirt.engine.core.bll.AsyncTaskManager] (DefaultQuartzScheduler_Worker-23) Polling and updating Async Tasks: 2 tasks, 1 tasks to poll now 2013-06-03 13:32:36,127 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-23) SPMAsyncTask::PollTask: Polling task 8b4124c7-2c85-44fa-bac5-540b198569cb (Parent Command RemoveSnapshot, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'. 2013-06-03 13:32:36,151 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-23) BaseAsyncTask::OnTaskEndSuccess: Task 8b4124c7-2c85-44fa-bac5-540b198569cb (Parent Command RemoveSnapshot, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully. 2013-06-03 13:32:36,152 INFO [org.ovirt.engine.core.bll.EntityAsyncTask] (DefaultQuartzScheduler_Worker-23) EntityAsyncTask::EndActionIfNecessary: All tasks of entity 151a071b-869f-49d3-bd42-e19a56fae788 has ended -> executing EndAction 2013-06-03 13:32:36,153 INFO [org.ovirt.engine.core.bll.EntityAsyncTask] (DefaultQuartzScheduler_Worker-23) EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: 151a071b-869f-49d3-bd42-e19a56fae788): calling EndAction for action type RemoveSnapshot. 2013-06-03 13:32:36,154 INFO [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-8-thread-48) EntityAsyncTask::EndCommandAction [within thread] context: Attempting to EndAction RemoveSnapshot, executionIndex: 0 2013-06-03 13:32:36,168 INFO [org.ovirt.engine.core.bll.RemoveSnapshotCommand] (pool-8-thread-48) [4e4d1134] Ending command successfully: org.ovirt.engine.core.bll.RemoveSnapshotCommand 2013-06-03 13:32:36,200 INFO [org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskCommand] (pool-8-thread-48) [4e4d1134] Ending command successfully: org.ovirt.engine.core.bll.RemoveSnapshotSingleDiskCommand 2013-06-03 13:32:36,206 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-8-thread-48) [4e4d1134] START, GetImageInfoVDSCommand( storagePoolId = efc43f69-2b34-484c-b546-c2040fa4a93e, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 22de00c8-c65f-4606-ad1f-76b39c7c6c27, imageGroupId = cc65de2f-08f6-402b-9740-ba05c0007156, imageId = 06b9aefb-c4ea-43e4-8ef5-e117cbc0f130), log id: 31b9a652 2013-06-03 13:32:36,283 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-8-thread-48) [4e4d1134] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@fc69d65b, log id: 31b9a652 2013-06-03 13:32:36,301 INFO [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-8-thread-48) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type RemoveSnapshot completed, handling the result. 2013-06-03 13:32:36,302 INFO [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-8-thread-48) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type RemoveSnapshot succeeded, clearing tasks. 2013-06-03 13:32:36,309 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-8-thread-48) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 8b4124c7-2c85-44fa-bac5-540b198569cb
(In reply to Maor from comment #3) > The correlation id reflects the overall command flow, it is listed in the > tasks subtab, and it covers the overall operation (including MergeSnapshot). > The correlation id is displayed in the engine log [1] (4e4d1134) for every > internal command which is part of the overall command > (RemoveSnapshotCommand). > Lee, IIUC that is what you meant, right? or did you suggest anything else? This was it, in 3.1 we had different correlation IDs for the various sub commands but as you've shown this has been corrected in 3.2. Closing this as a dup of 844335. *** This bug has been marked as a duplicate of bug 844335 ***