Bug 1534227 - Confusing logging when cold-moving a disk - the term CreateSnapshot is referenced
Summary: Confusing logging when cold-moving a disk - the term CreateSnapshot is refere...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: BLL.Storage
Version: 4.2.1
Hardware: x86_64
OS: Unspecified
medium
medium
Target Milestone: ovirt-4.2.1
: ---
Assignee: Allon Mureinik
QA Contact: Elad
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2018-01-14 11:42 UTC by Elad
Modified: 2018-02-12 11:49 UTC (History)
4 users (show)

Fixed In Version: ovirt-engine-4.2.1.2
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-02-12 11:49:54 UTC
oVirt Team: Storage
Embargoed:
rule-engine: ovirt-4.2+
ylavi: exception+


Attachments (Terms of Use)
engine and vdsm logs from 4.2 and 4.1 (2.28 MB, application/x-gzip)
2018-01-14 11:42 UTC, Elad
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 86331 0 master MERGED core: CreateSnapshotVDSCommand logging 2018-01-15 12:15:51 UTC
oVirt gerrit 86332 0 master MERGED core: Rename VDSCommand's CreateSnapshot to CreateVolume 2018-01-15 12:15:54 UTC

Description Elad 2018-01-14 11:42:12 UTC
Created attachment 1380980 [details]
engine and vdsm logs from 4.2 and 4.1

Description of problem:
CreateSnapshotVDSCommand is initiated as past of MoveDiskCommand
This seems to be happening for a while as it occurs on both RHV 4.2 and 4.1.7.6


Version-Release number of selected component (if applicable):
rhvm-4.2.1-0.2.el7.noarch
vdsm-4.20.11-1.el7ev.x86_64

rhevm-4.1.7.6-0.1.el7.noarch
vdsm-4.19.36-1.el7ev.x86_64


How reproducible:
Always

Steps to Reproduce:
1. Create a VM with disk attached
2. While the VM is down, move the disk to a different domain
3.


Actual results:

Snapshot creation is initiated as part of disk cold move:


4.2:

2018-01-14 13:30:51,365+02 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [9f6bdd3e-6f7c-4d22-8dd9-11134186d76a] Command 'MoveImageGroup' (id: 'ab682ed0-5a56-4459-91ff-faffd1f0b166') waiting on child command id: '752855d2-38d3-4a03-8daa-089df3fd8957' type:'CopyImageGroupWithData' to complete
2018-01-14 13:30:51,368+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [9f6bdd3e-6f7c-4d22-8dd9-11134186d76a] Starting child command 1 of 1, image '84852761-6715-442b-9735-1fb6070abd13'
2018-01-14 13:30:51,408+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [9f6bdd3e-6f7c-4d22-8dd9-11134186d76a] Running command: CreateVolumeContainerCommand internal: true.
2018-01-14 13:30:51,435+02 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-54) [9f6bdd3e-6f7c-4d22-8dd9-11134186d76a] START, CreateSnapshotVDSCommand( CreateSnapshotVDSCommandParameters:{storagePoolId='6ccfd104-5f57-4a83-a24d-9d7a5a5c92c8', ignoreFailoverLimit='false', storageDomainId='28f3176f-a7a8-499f-83f7-ee0404977e7b', imageGroupId='30aaab0b-01b1-455c-82b0-9a47b065726b', imageSizeInBytes='1073741824', volumeFormat='RAW', newImageId='84852761-6715-442b-9735-1fb6070abd13', imageType='Preallocated', newImageDescription='null', imageInitialSizeInBytes='0', imageId='00000000-0000-0000-0000-000000000000', sourceImageGroupId='00000000-0000-0000-0000-000000000000'}), log id: 6a24f12d



4.1:

2018-01-14 13:32:07,795+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.MoveImageGroupCommand] (org.ovirt.thread.pool-6-thread-3) [55344af7-15fd-41c3-bceb-8c69c2cb9200] Running command: MoveImageGroupComm
and internal: true. Entities affected :  ID: daf92ffc-1108-4b64-9a96-1f5d13c449fb Type: Storage
2018-01-14 13:32:08,001+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.CopyImageGroupWithDataCommand] (org.ovirt.thread.pool-6-thread-3) [55344af7-15fd-41c3-bceb-8c69c2cb9200] Running command: CopyImageG
roupWithDataCommand internal: true.
2018-01-14 13:32:08,208+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand] (org.ovirt.thread.pool-6-thread-3) [55344af7-15fd-41c3-bceb-8c69c2cb9200] Running command: C
loneImageGroupVolumesStructureCommand internal: true.
2018-01-14 13:32:08,371+02 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-3) [55344af7-15fd-41c3-bceb-8c69c2cb9200] EVENT_ID: USER_MOVED_DISK(2,008),
 Correlation ID: 55344af7-15fd-41c3-bceb-8c69c2cb9200, Job ID: 953f4703-3265-42a5-89c3-e3039ac48242, Call Stack: null, Custom ID: null, Custom Event ID: -1, Message: User admin@internal-authz moving disk test_Di
sk1 to domain nested_storage_nfs.
2018-01-14 13:32:08,521+02 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (DefaultQuartzScheduler9) [55344af7-15fd-41c3-bceb-8c69c2cb9200] Command 'CopyImageGroupWithData' (id: 'b2997a47-
eff9-478a-8467-d6e643153401') waiting on child command id: '6f089dd2-0dda-4bd2-9782-3a5be23facfd' type:'CloneImageGroupVolumesStructure' to complete
2018-01-14 13:32:08,526+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.CloneImageGroupVolumesStructureCommand] (DefaultQuartzScheduler9) [55344af7-15fd-41c3-bceb-8c69c2cb9200] Starting child command 1 of
 1, image 'e4bd9ca7-0d33-4050-abd4-98e6c977db54'
2018-01-14 13:32:08,644+02 INFO  [org.ovirt.engine.core.bll.storage.disk.image.CreateVolumeContainerCommand] (DefaultQuartzScheduler9) [55344af7-15fd-41c3-bceb-8c69c2cb9200] Running command: CreateVolumeContaine
rCommand internal: true.
2018-01-14 13:32:08,686+02 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (DefaultQuartzScheduler9) [55344af7-15fd-41c3-bceb-8c69c2cb9200] START, CreateSnapshotVDSCommand( CreateSnaps
hotVDSCommandParameters:{runAsync='true', storagePoolId='d633f884-45f6-4f9e-884d-85821cefd033', ignoreFailoverLimit='false', storageDomainId='daf92ffc-1108-4b64-9a96-1f5d13c449fb', imageGroupId='afee9cb2-9a1e-4b
58-a24f-4ef18f254fe7', imageSizeInBytes='1073741824', volumeFormat='RAW', newImageId='e4bd9ca7-0d33-4050-abd4-98e6c977db54', imageType='Sparse', newImageDescription='null', imageInitialSizeInBytes='0', imageId='
00000000-0000-0000-0000-000000000000', sourceImageGroupId='00000000-0000-0000-0000-000000000000'}), log id: 51ad2df6

Expected results:
Cold disk move should not trigger snapshot creation. 

Additional info:
engine and vdsm logs from 4.2 and 4.1

Comment 1 Allon Mureinik 2018-01-14 15:55:30 UTC
When an image is cold-moved, the structure is replicated to the destination domain by a bunch of CreateSnapshotVDSCommand calls, and then the data is synched from source to dest.

There is no snapshot creation in the logs (despite the less than brilliant command name).

Comment 2 Elad 2018-01-14 16:44:07 UTC
Allon, does it mean that CreateSnapshotVDSCommand doesn't create a snapshot? 
It's very confusing

Comment 3 Allon Mureinik 2018-01-15 05:55:25 UTC
(In reply to Elad from comment #2)
> Allon, does it mean that CreateSnapshotVDSCommand doesn't create a snapshot? 
> It's very confusing

CreateSnapshotVDSCommand was introduced in the early days of the engine (3.0 IIRC), when the only flow that created a volume (without creating an entire image) was taking a snapshot. It was a bad name back in the day (since it mixed levels of functionality), and nowadays is downright confusing, as you mentioned, since it's being used for other flows too (like cold moving a disk).

While there isn't any functional problem (as I noted in comment 1, no redundant snapshot is created), it does generate a very confusing log as you noted in comment 2.
I think we can rename this command without breaking anything to help make the log clearer. I'm reopening this BZ and repurposing it for this renaming (priority and severity adjusted accordingly), and will post a patch to hopefully do so for 4.2.2.
If the upstream review process deems this patch to be too risky we'll rethink and retarget.

Comment 4 Elad 2018-01-29 11:20:42 UTC
Disk cold move now involves CreateVolume instead of CreateSnapshot



2018-01-29 13:17:18,510+02 INFO  [org.ovirt.engine.core.bll.storage.disk.MoveDiskCommand] (default task-1) [e0159d45-30f0-45e2-8e2b-4587c917fa7d] Running command: MoveDiskCommand internal: false. Entities affect
ed :  ID: 0b1811a6-37aa-43e8-a72c-d5118a4499e3 Type: DiskAction group CONFIGURE_DISK_STORAGE with role type USER


2018-01-29 13:17:21,414+02 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateVolumeVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-96) [e0159d45-30f0-45e2-8e2b-4587c917fa7d] START, CreateVolumeV
DSCommand( CreateVolumeVDSCommandParameters:{storagePoolId='aa0b1185-8bf0-4ca4-978b-c6b7df55140c', ignoreFailoverLimit='false', storageDomainId='db01428b-6609-4599-8ca5-ce78fe5f4a74', imageGroupId='0b1811a6-37aa
-43e8-a72c-d5118a4499e3', imageSizeInBytes='1073741824', volumeFormat='RAW', newImageId='600809ab-0e38-4bb2-8966-d0af986d0705', imageType='Preallocated', newImageDescription='null', imageInitialSizeInBytes='0', 
imageId='00000000-0000-0000-0000-000000000000', sourceImageGroupId='00000000-0000-0000-0000-000000000000'}), log id: 24497fcb



Used:
rhvm-4.2.1.3-0.1.el7.noarch

Comment 5 Sandro Bonazzola 2018-02-12 11:49:54 UTC
This bugzilla is included in oVirt 4.2.1 release, published on Feb 12th 2018.

Since the problem described in this bug report should be
resolved in oVirt 4.2.1 release, it has been closed with a resolution of CURRENT RELEASE.

If the solution does not work for you, please open a new bug report.


Note You need to log in before you can comment on or make changes to this bug.