[ovirt-devel] Help debugging engine.log

Mon May 12 13:43:06 UTC 2014

On 05/12/2014 03:27 AM, Sandro Bonazzola wrote:
> Il 12/05/2014 08:52, Oved Ourfalli ha scritto:
>>
>>
>> ----- Original Message -----
>>> From: "Sandro Bonazzola" <sbonazzo at redhat.com>
>>> To: devel at ovirt.org
>>> Sent: Friday, April 18, 2014 5:03:00 PM
>>> Subject: [ovirt-devel] Help debugging engine.log
>>>
>>> the following lines appear after adding the first host to an engine running
>>> inside Hosted Engine VM.
>>> Can anybody tell what the following lines are meaning?
>>>
>>>
>>> 2014-04-18 17:21:57,223 INFO
>>> [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-4-thread-5)
>>> [751509c7] FINISH, SetVdsStatusVDSCommand,
>>> log id: 6bb07f05
>>> 2014-04-18 17:21:57,223 INFO  [org.ovirt.engine.core.bll.InstallVdsCommand]
>>> (pool-4-thread-5) [751509c7] After Installation host hosted_engine_1, VDS
>>> 2014-04-18 17:21:57,243 INFO
>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>> (pool-4-thread-5) [751509c7] Correlation ID:
>>> 751509c7, Job ID: c7abd67c-5655-4ea8-8226-c51eda9c9675, Call Stac
>>> k: null, Custom Event ID: -1, Message: Host hosted_engine_1 installed
>>
>>
>> The hosted_engine_1 host has been bootstrapped.
>>
>>
>>> 2014-04-18 17:21:57,255 INFO  [org.ovirt.engine.core.bll.InstallVdsCommand]
>>> (pool-4-thread-5) [751509c7] Lock freed to object EngineLock
>>> [exclusiveLocks= key: f609e5f8-1676-4e87-98ec-9477afc27557 value: VDS
>>> , sharedLocks= ]
>>> 2014-04-18 17:21:58,764 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand]
>>> (DefaultQuartzScheduler_Worker-3) START,
>>> GetHardwareInfoVDSCommand(HostName = hosted_engine_1, HostId = f609e5f
>>> 8-1676-4e87-98ec-9477afc27557, vds=Host[hosted_engine_1]), log id: 496d80d8
>>> 2014-04-18 17:21:58,834 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand]
>>> (DefaultQuartzScheduler_Worker-3) FINISH,
>>> GetHardwareInfoVDSCommand, log id: 496d80d8
>>> 2014-04-18 17:21:58,944 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand]
>>> (DefaultQuartzScheduler_Worker-3) START,
>>> GetHardwareInfoVDSCommand(HostName = hosted_engine_1, HostId =
>>> f609e5f8-1676-4e87-98ec-9477afc27557, vds=Host[hosted_engine_1]), log id:
>>> 36957393
>>> 2014-04-18 17:21:58,971 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand]
>>> (DefaultQuartzScheduler_Worker-3) FINISH,
>>> GetHardwareInfoVDSCommand, log id: 36957393
>>
>> Getting the hardware info finished.
>>
>>> 2014-04-18 17:21:58,989 INFO
>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>> (DefaultQuartzScheduler_Worker-3) Correlation ID:
>>> null, Call Stack: null, Custom Event ID: -1, Message: State was set to Up for
>>> host hosted_engine_1.
>>
>> Host status was set to up.
>>
>>> 2014-04-18 17:21:59,058 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand]
>>> (DefaultQuartzScheduler_Worker-3) START,
>>> FullListVdsCommand(HostName = hosted_engine_1, HostId =
>>> f609e5f8-1676-4e87-98ec-9477afc27557, vds=Host[hosted_engine_1],
>>> vmIds=[950f8a3a-82af-478e-8f99-9cd0556b9cfc]), log id: 16b792bc
>>> 2014-04-18 17:21:59,095 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand]
>>> (DefaultQuartzScheduler_Worker-3) FINISH,
>>> FullListVdsCommand, return: [Ljava.util.HashMap;@3a6e1bc2, log id: 16b792bc
>>
>> Listing VMs on the host.
>>
>>> 2014-04-18 17:21:59,096 INFO
>>> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
>>> (DefaultQuartzScheduler_Worker-3) Importing VM HostedEngine as
>>> HostedEngine, as it is running on the on Host, but does not exist in the
>>> engine.
>>> 2014-04-18 17:21:59,122 INFO
>>> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
>>> (DefaultQuartzScheduler_Worker-3) VDS::UpdateVmRunTimeInfo Error:
>>> found VM on a VDS that is not in the database!
>>> 2014-04-18 17:21:59,137 INFO  [org.ovirt.engine.core.bll.InitVdsOnUpCommand]
>>> (DefaultQuartzScheduler_Worker-3) [3a5f7d19] Running command:
>>> InitVdsOnUpCommand internal: true. Entities affected :  ID:
>>> 5849b030-626e-47cb-ad90-3ce782d831b3 Type: StoragePool
>>> 2014-04-18 17:21:59,144 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.SetMOMPolicyParametersVDSCommand]
>>> (DefaultQuartzScheduler_Worker-3)
>>> [3a5f7d19] START, SetMOMPolicyParametersVDSCommand(HostName =
>>> hosted_engine_1, HostId = f609e5f8-1676-4e87-98ec-9477afc27557), log id:
>>> 36c8962e
>>
>>
>> Identified the hosted engine VM, and importing it.
>>
>>
>>> 2014-04-18 17:21:59,223 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.SetMOMPolicyParametersVDSCommand]
>>> (DefaultQuartzScheduler_Worker-3)
>>> [3a5f7d19] FINISH, SetMOMPolicyParametersVDSCommand, log id: 36c8962e
>>
>> Don't know about that.
>
> Anyone for this?
>

Engine finished pushing its Memory Overcommitment Manager policy to the 
host (to control ksm/ballooning/etc)

>
>>
>>> 2014-04-18 17:21:59,228 INFO
>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>> (DefaultQuartzScheduler_Worker-3) [3a5f7d19]
>>> Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Failed
>>> to verify Power Management configuration for Host hosted_engine_1.
>>
>> You didn't define power management for this host, so it warns about that.
>>
>>> 2014-04-18 17:21:59,389 INFO
>>> [org.ovirt.engine.core.bll.AddVmFromScratchCommand]
>>> (DefaultQuartzScheduler_Worker-3) [266af7f3] Lock Acquired to object
>>> EngineLock [exclusiveLocks= key: HostedEngine value: VM_NAME
>>> , sharedLocks= ]
>>> 2014-04-18 17:21:59,453 INFO
>>> [org.ovirt.engine.core.bll.AddVmFromScratchCommand]
>>> (DefaultQuartzScheduler_Worker-3) [266af7f3] Running command:
>>> AddVmFromScratchCommand internal: true. Entities affected :  ID:
>>> 99408929-82cf-4dc7-a532-9d998063fa95 Type: VdsGroups
>>> 2014-04-18 17:21:59,707 INFO
>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>> (DefaultQuartzScheduler_Worker-3) [266af7f3]
>>> Correlation ID: 266af7f3, Job ID: 2c46a619-bc01-4b85-96bd-d3fc5e073901, Call
>>> Stack: null, Custom Event ID: -1, Message: VM HostedEngine was created by
>>> <UNKNOWN>.
>
> ^^ missing initialization somewhere? Why UNKNOWN?
>

The string used here is
   USER_ADD_VM=VM ${VmName} was created by ${UserName}.
so it's unknown because there's no user attributable to the import.

>
>>> 2014-04-18 17:21:59,714 INFO
>>> [org.ovirt.engine.core.bll.AddVmFromScratchCommand]
>>> (DefaultQuartzScheduler_Worker-3) [266af7f3] Lock freed to object
>>> EngineLock [exclusiveLocks= key: HostedEngine value: VM_NAME
>>> , sharedLocks= ]
>>> 2014-04-18 17:21:59,718 INFO
>>> [org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand]
>>> (DefaultQuartzScheduler_Worker-3) [5e0dc4d1]
>>> Running command: HandleVdsCpuFlagsOrClusterChangedCommand internal: true.
>>> Entities affected :  ID: f609e5f8-1676-4e87-98ec-9477afc27557 Type: VDS
>>
>>
>> iirc, importing the existing VM is like adding a new one in some way, so that's what you see here.
>>
>>
>>> 2014-04-18 17:21:59,766 INFO
>>> [org.ovirt.engine.core.bll.UpdateVdsGroupCommand]
>>> (DefaultQuartzScheduler_Worker-3) [32fd282a] Running command:
>>> UpdateVdsGroupCommand internal: true. Entities affected :  ID:
>>> 99408929-82cf-4dc7-a532-9d998063fa95 Type: VdsGroups
>>> 2014-04-18 17:22:00,015 INFO
>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>> (DefaultQuartzScheduler_Worker-3) [32fd282a]
>>> Correlation ID: 32fd282a, Call Stack: null, Custom Event ID: -1, Message:
>>> Host cluster Default was updated by system
>>> 2014-04-18 17:22:00,032 INFO
>>> [org.ovirt.engine.core.bll.HandleVdsVersionCommand]
>>> (DefaultQuartzScheduler_Worker-3) [4f38fad3] Running command:
>>> HandleVdsVersionCommand internal: true. Entities affected :  ID:
>>> f609e5f8-1676-4e87-98ec-9477afc27557 Type: VDS
>>> 2014-04-18 17:22:03,100 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand]
>>> (DefaultQuartzScheduler_Worker-6) START,
>>> FullListVdsCommand(HostName = hosted_engine_1, HostId =
>>> f609e5f8-1676-4e87-98ec-9477afc27557, vds=Host[hosted_engine_1],
>>> vmIds=[950f8a3a-82af-478e-8f99-9cd0556b9cfc]), log id: 4148c04c
>>> 2014-04-18 17:22:03,129 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand]
>>> (DefaultQuartzScheduler_Worker-6) FINISH,
>>> FullListVdsCommand, return: [Ljava.util.HashMap;@5f864ed0, log id: 4148c04c
>>> 2014-04-18 17:22:03,131 INFO
>>> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
>>> (DefaultQuartzScheduler_Worker-6) Received a console Device
>>> without an address when processing VM 950f8a3a-82af-478e-8f99-9cd0556b9cfc
>>> devices, skipping device: {alias=console0, specParams={}, device=console,
>>> type=console, deviceId=c627f372-2893-4b79-b534-f51c86374d1b}
>>> 2014-04-18 17:22:03,131 INFO
>>> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
>>> (DefaultQuartzScheduler_Worker-6) Received a memballoon Device
>>> without an address when processing VM 950f8a3a-82af-478e-8f99-9cd0556b9cfc
>>> devices, skipping device: {alias=balloon0, specParams={model=none},
>>> device=memballoon, type=balloon}
>>> 2014-04-18 17:22:03,132 ERROR
>>> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo]
>>> (DefaultQuartzScheduler_Worker-6) Empty or NULL values were
>>> passed for a VM 950f8a3a-82af-478e-8f99-9cd0556b9cfc device, Device is
>>> skipped
>
> Is there an error in the VM configuration? Does above mean that memballon and virtual console are not working?
>

Some kind of error, either configuration or maybe something transient due 
to the timing.  The above messages indicate the devices were removed from 
the engine db... of course they could have been added back after a later 
update if it was a temporary condition.

The vdsm logs should show us what was returned to the engine, do you 
happen to have them for this time period?

>
>>> 2014-04-18 17:53:16,713 INFO  [org.ovirt.engine.core.bll.LogoutUserCommand]
>>> (ajp-/127.0.0.1:8702-5) [3829e38e] Running command: LogoutUserCommand
>>> internal: false.
>>> 2014-04-18 17:53:16,725 INFO
>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>> (ajp-/127.0.0.1:8702-5) [3829e38e] Correlation
>>> ID: 3829e38e, Call Stack: null, Custom Event ID: -1, Message: User
>>> admin at internal logged out.
>>> 2014-04-18 17:54:28,145 INFO
>>> [org.ovirt.engine.core.bll.LoginAdminUserCommand] (ajp-/127.0.0.1:8702-4)
>>> Running command: LoginAdminUserCommand
>>> internal: false.
>>> 2014-04-18 17:54:28,149 INFO
>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>> (ajp-/127.0.0.1:8702-4) Correlation ID: null,
>>> Call Stack: null, Custom Event ID: -1, Message: User admin at internal logged
>>> in.
>>> 2014-04-18 17:54:28,207 INFO  [org.ovirt.engine.core.bll.LoginUserCommand]
>>> (ajp-/127.0.0.1:8702-8) Running command: LoginUserCommand internal: false.
>>> 2014-04-18 17:54:28,212 INFO
>>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>> (ajp-/127.0.0.1:8702-8) Correlation ID: null,
>>> Call Stack: null, Custom Event ID: -1, Message: User admin at internal logged
>>> in.
>>>
>>
>> Other messages show you updated the cluster, did some logging in and out, VdsUpdateRunTimeInfo was run several times (to get the updated host info, vms, status, etc.).
>>
>> Hope I was helpful,
>
> Sure, thanks.
>
>> Oved
>>
>>>
>>> Thanks,
>>>
>>>
>>> --
>>> Sandro Bonazzola
>>> Better technology. Faster innovation. Powered by community collaboration.
>>> See how it works at redhat.com
>>> _______________________________________________
>>> Devel mailing list
>>> Devel at ovirt.org
>>> http://lists.ovirt.org/mailman/listinfo/devel
>>>
>
>