Attachment 1479436 Details for Bug 1622068 – engine.log

engine.log

engine.log (text/plain), 16.91 KB, created by mxie@redhat.com on 2018-08-29 10:01:14 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: mxie@redhat.com

Created: 2018-08-29 10:01:14 UTC

Size: 16.91 KB

patch

obsolete

>2018-08-29 05:45:03,644-04 INFO  [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks.
>2018-08-29 05:45:03,644-04 INFO  [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 16 threads waiting for tasks and 0 tasks in queue.
>2018-08-29 05:45:03,644-04 INFO  [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engineScheduled' is using 0 threads out of 100, 100 threads waiting for tasks.
>2018-08-29 05:45:03,644-04 INFO  [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'engineThreadMonitoring' is using 1 threads out of 1, 0 threads waiting for tasks.
>2018-08-29 05:45:03,644-04 INFO  [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedThreadFactory-engineThreadMonitoring-Thread-1) [] Thread pool 'hostUpdatesChecker' is using 0 threads out of 5, 5 threads waiting for tasks.
>2018-08-29 05:46:13,639-04 INFO  [org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor] (default task-35) [5a68e319-cdda-49f2-b283-842b036b180d] Executing Ansible command: ANSIBLE_STDOUT_CALLBACK=ovaqueryplugin [/usr/bin/ansible-playbook, --ssh-common-args=-F /var/lib/ovirt-engine/.ssh/config, --private-key=/etc/pki/ovirt-engine/keys/engine_id_rsa, --inventory=/tmp/ansible-inventory4831310025232815029, --extra-vars=ovirt_query_ova_path=/home/esx6.0-rhel7.5-x86_64, --extra-vars=list_directory=True, /usr/share/ovirt-engine/playbooks/ovirt-ova-query.yml] [Logfile: /var/log/ovirt-engine/ova/ovirt-query-ova-ansible-20180829054613-10.73.224.199.log]
>2018-08-29 05:46:14,702-04 INFO  [org.ovirt.engine.core.common.utils.ansible.AnsibleExecutor] (default task-35) [5a68e319-cdda-49f2-b283-842b036b180d] Ansible playbook command has exited with value: 0
>2018-08-29 05:46:14,705-04 WARN  [org.ovirt.engine.core.utils.ovf.OvfReader] (default task-35) [5a68e319-cdda-49f2-b283-842b036b180d] could not retrieve volume id of vmdisk1 from ovf, generating new guid
>2018-08-29 05:46:14,705-04 WARN  [org.ovirt.engine.core.utils.ovf.OvfReader] (default task-35) [5a68e319-cdda-49f2-b283-842b036b180d] could not retrieve disk id of vmdisk1 from ovf, generating new guid
>2018-08-29 05:46:27,804-04 INFO  [org.ovirt.engine.core.bll.exportimport.ImportVmFromOvaCommand] (default task-44) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Lock Acquired to object 'EngineLock:{exclusiveLocks='[174e4acd-1a00-4bea-a07b-bdc299179c51=VM, esx6.0-rhel7.5-x86_64=VM_NAME]', sharedLocks=''}'
>2018-08-29 05:46:27,859-04 INFO  [org.ovirt.engine.core.bll.exportimport.ImportVmFromOvaCommand] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Running command: ImportVmFromOvaCommand internal: false. Entities affected :  ID: 5fbc6d3f-a6df-462a-9879-7e1bea947dc8 Type: StorageAction group IMPORT_EXPORT_VM with role type ADMIN
>2018-08-29 05:46:27,945-04 INFO  [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Running command: AddDiskCommand internal: true. Entities affected :  ID: 174e4acd-1a00-4bea-a07b-bdc299179c51 Type: VMAction group CONFIGURE_VM_STORAGE with role type USER,  ID: 5fbc6d3f-a6df-462a-9879-7e1bea947dc8 Type: StorageAction group CREATE_DISK with role type USER
>2018-08-29 05:46:28,007-04 INFO  [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Running command: AddImageFromScratchCommand internal: true. Entities affected :  ID: 5fbc6d3f-a6df-462a-9879-7e1bea947dc8 Type: Storage
>2018-08-29 05:46:28,062-04 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] START, CreateImageVDSCommand( CreateImageVDSCommandParameters:{storagePoolId='ff73fb93-bc7b-44d3-b8f8-82d4d44ebef3', ignoreFailoverLimit='false', storageDomainId='5fbc6d3f-a6df-462a-9879-7e1bea947dc8', imageGroupId='b395548c-e03c-4e59-9052-2a5ab7e1004c', imageSizeInBytes='17179869184', volumeFormat='RAW', newImageId='5e92d745-cdbe-488d-a053-8d277e5d0416', imageType='Sparse', newImageDescription='{"DiskAlias":"vmdisk1","DiskDescription":""}', imageInitialSizeInBytes='0'}), log id: 30b6a78e
>2018-08-29 05:46:28,063-04 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] -- executeIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
>2018-08-29 05:46:28,334-04 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] FINISH, CreateImageVDSCommand, return: 5e92d745-cdbe-488d-a053-8d277e5d0416, log id: 30b6a78e
>2018-08-29 05:46:28,336-04 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command '285c736a-fbb1-4dbd-aa9a-e6e907692416'
>2018-08-29 05:46:28,336-04 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] CommandMultiAsyncTasks::attachTask: Attaching task '9fa1fe39-acc3-4f07-aa49-78c20817679e' to command '285c736a-fbb1-4dbd-aa9a-e6e907692416'.
>2018-08-29 05:46:28,377-04 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Adding task '9fa1fe39-acc3-4f07-aa49-78c20817679e' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet..
>2018-08-29 05:46:28,418-04 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] BaseAsyncTask::startPollingTask: Starting to poll task '9fa1fe39-acc3-4f07-aa49-78c20817679e'.
>2018-08-29 05:46:28,510-04 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] EVENT_ID: ADD_DISK_INTERNAL(2,036), Add-Disk operation of 'vmdisk1' was initiated by the system.
>2018-08-29 05:46:28,551-04 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-115094) [a3cefa92-ad81-4a1b-9055-5da310fe2495] EVENT_ID: IMPORTEXPORT_STARTING_IMPORT_VM(1,165), Starting to import Vm esx6.0-rhel7.5-x86_64 to Data Center P2V, Cluster P2V
>2018-08-29 05:46:29,982-04 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-51) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Command 'AddDisk' (id: '4a29155a-ba4d-4354-86f6-23802cf90136') waiting on child command id: '285c736a-fbb1-4dbd-aa9a-e6e907692416' type:'AddImageFromScratch' to complete
>2018-08-29 05:46:29,986-04 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-51) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Command 'ImportVmFromOva' (id: '65c7259e-1add-421c-8176-8cb4bc12b464') waiting on child command id: '4a29155a-ba4d-4354-86f6-23802cf90136' type:'AddDisk' to complete
>2018-08-29 05:46:33,525-04 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedThreadFactory-engineScheduled-Thread-33) [] Polling and updating Async Tasks: 1 tasks, 1 tasks to poll now
>2018-08-29 05:46:33,530-04 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-33) [] SPMAsyncTask::PollTask: Polling task '9fa1fe39-acc3-4f07-aa49-78c20817679e' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'success'.
>2018-08-29 05:46:33,532-04 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-33) [] BaseAsyncTask::onTaskEndSuccess: Task '9fa1fe39-acc3-4f07-aa49-78c20817679e' (Parent Command 'AddImageFromScratch', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended successfully.
>2018-08-29 05:46:33,533-04 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-33) [] CommandAsyncTask::endActionIfNecessary: All tasks of command '285c736a-fbb1-4dbd-aa9a-e6e907692416' has ended -> executing 'endAction'
>2018-08-29 05:46:33,533-04 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-33) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: '285c736a-fbb1-4dbd-aa9a-e6e907692416'): calling endAction '.
>2018-08-29 05:46:33,534-04 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-115095) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'AddImageFromScratch',
>2018-08-29 05:46:33,537-04 INFO  [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Command [id=285c736a-fbb1-4dbd-aa9a-e6e907692416]: Updating status to 'SUCCEEDED', The command end method logic will be executed by one of its parent commands.
>2018-08-29 05:46:33,538-04 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'AddImageFromScratch' completed, handling the result.
>2018-08-29 05:46:33,538-04 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'AddImageFromScratch' succeeded, clearing tasks.
>2018-08-29 05:46:33,538-04 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] SPMAsyncTask::ClearAsyncTask: Attempting to clear task '9fa1fe39-acc3-4f07-aa49-78c20817679e'
>2018-08-29 05:46:33,538-04 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='ff73fb93-bc7b-44d3-b8f8-82d4d44ebef3', ignoreFailoverLimit='false', taskId='9fa1fe39-acc3-4f07-aa49-78c20817679e'}), log id: 39c4aad3
>2018-08-29 05:46:33,539-04 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] START, HSMClearTaskVDSCommand(HostName = 10.73.224.199, HSMTaskGuidBaseVDSCommandParameters:{hostId='f80d10de-685e-46a9-9634-a8b0ca3f5bb7', taskId='9fa1fe39-acc3-4f07-aa49-78c20817679e'}), log id: 3dfc290c
>2018-08-29 05:46:33,565-04 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] FINISH, HSMClearTaskVDSCommand, log id: 3dfc290c
>2018-08-29 05:46:33,565-04 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] FINISH, SPMClearTaskVDSCommand, log id: 39c4aad3
>2018-08-29 05:46:33,570-04 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] BaseAsyncTask::removeTaskFromDB: Removed task '9fa1fe39-acc3-4f07-aa49-78c20817679e' from DataBase
>2018-08-29 05:46:33,570-04 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-115095) [a3cefa92-ad81-4a1b-9055-5da310fe2495] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity '285c736a-fbb1-4dbd-aa9a-e6e907692416'
>2018-08-29 05:46:33,993-04 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Command 'AddDisk' id: '4a29155a-ba4d-4354-86f6-23802cf90136' child commands '[285c736a-fbb1-4dbd-aa9a-e6e907692416]' executions were completed, status 'SUCCEEDED'
>2018-08-29 05:46:34,008-04 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-7) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Command 'ImportVmFromOva' (id: '65c7259e-1add-421c-8176-8cb4bc12b464') waiting on child command id: '4a29155a-ba4d-4354-86f6-23802cf90136' type:'AddDisk' to complete
>2018-08-29 05:46:35,011-04 INFO  [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Ending command 'org.ovirt.engine.core.bll.storage.disk.AddDiskCommand' successfully.
>2018-08-29 05:46:35,016-04 INFO  [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand' successfully.
>2018-08-29 05:46:35,021-04 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] START, GetImageInfoVDSCommand( GetImageInfoVDSCommandParameters:{storagePoolId='ff73fb93-bc7b-44d3-b8f8-82d4d44ebef3', ignoreFailoverLimit='false', storageDomainId='5fbc6d3f-a6df-462a-9879-7e1bea947dc8', imageGroupId='b395548c-e03c-4e59-9052-2a5ab7e1004c', imageId='5e92d745-cdbe-488d-a053-8d277e5d0416'}), log id: 3d7d8d70
>2018-08-29 05:46:35,022-04 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] START, GetVolumeInfoVDSCommand(HostName = 10.73.224.199, GetVolumeInfoVDSCommandParameters:{hostId='f80d10de-685e-46a9-9634-a8b0ca3f5bb7', storagePoolId='ff73fb93-bc7b-44d3-b8f8-82d4d44ebef3', storageDomainId='5fbc6d3f-a6df-462a-9879-7e1bea947dc8', imageGroupId='b395548c-e03c-4e59-9052-2a5ab7e1004c', imageId='5e92d745-cdbe-488d-a053-8d277e5d0416'}), log id: 3e130207
>2018-08-29 05:46:35,035-04 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVolumeInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] FINISH, GetVolumeInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@c631f254, log id: 3e130207
>2018-08-29 05:46:35,035-04 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage.DiskImage@c631f254, log id: 3d7d8d70
>2018-08-29 05:46:35,129-04 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [] EVENT_ID: USER_ADD_DISK_TO_VM_FINISHED_SUCCESS(97), The disk vmdisk1 was successfully added to VM esx6.0-rhel7.5-x86_64.
>2018-08-29 05:46:35,224-04 INFO  [org.ovirt.engine.core.bll.exportimport.ConvertOvaCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Running command: ConvertOvaCommand internal: true. Entities affected :  ID: 174e4acd-1a00-4bea-a07b-bdc299179c51 Type: VM
>2018-08-29 05:46:35,226-04 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConvertOvaVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] START, ConvertOvaVDSCommand(HostName = 10.73.224.199, ConvertOvaVDSParameters:{hostId='f80d10de-685e-46a9-9634-a8b0ca3f5bb7', ovaPath='/home/esx6.0-rhel7.5-x86_64', vmName='esx6.0-rhel7.5-x86_64', storageDomainId='5fbc6d3f-a6df-462a-9879-7e1bea947dc8', storagePoolId='ff73fb93-bc7b-44d3-b8f8-82d4d44ebef3', virtioIsoPath='null', Disk0='b395548c-e03c-4e59-9052-2a5ab7e1004c'}), log id: 5bd354e3
>2018-08-29 05:46:35,299-04 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConvertOvaVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-97) [a3cefa92-ad81-4a1b-9055-5da310fe2495] FINISH, ConvertOvaVDSCommand, return: 174e4acd-1a00-4bea-a07b-bdc299179c51, log id: 5bd354e3
>2018-08-29 05:46:37,359-04 INFO  [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-84) [a3cefa92-ad81-4a1b-9055-5da310fe2495] Command 'ImportVmFromOva' (id: '65c7259e-1add-421c-8176-8cb4bc12b464') waiting on child command id: '6a9de393-74aa-4ca2-b814-89d5f0357f6f' type:'ConvertOva' to complete
>

Actions: View

Attachments on bug 1622068: 1478463 | 1478464 | 1478465 | 1478466 | 1479436 | 1479437