Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 958258

Summary:	The correlation IDs of all MergeSnapshotsVDSCommand commands should be logged in the audit_log.
Product:	Red Hat Enterprise Virtualization Manager	Reporter:	Lee Yarwood <lyarwood>
Component:	ovirt-engine	Assignee:	Nobody's working on this, feel free to take it <nobody>
Status:	CLOSED DUPLICATE	QA Contact:
Severity:	medium	Docs Contact:
Priority:	medium
Version:	3.1.3	CC:	abaron, acathrow, dyasny, iheim, lpeer, lyarwood, mlipchuk, Rhev-m-bugs, yeylon, ykaul
Target Milestone:	---
Target Release:	3.3.0
Hardware:	All
OS:	Linux
Whiteboard:	storage
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2013-06-03 13:32:26 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:
Bug Depends On:
Bug Blocks:	902971

Description Lee Yarwood 2013-04-30 17:52:50 UTC

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:

Comment 1 Itamar Heim 2013-05-01 11:47:45 UTC

duplicate of bug 844335?

Comment 3 Maor 2013-06-03 11:43:10 UTC

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

Comment 4 Lee Yarwood 2013-06-03 13:32:26 UTC

(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 ***