[ovirt-devel] Help debugging engine.log
Greg Padgett
gpadgett at redhat.com
Mon May 12 14:25:05 UTC 2014
On 05/12/2014 09:59 AM, Sandro Bonazzola wrote:
> Il 12/05/2014 15:43, Greg Padgett ha scritto:
>> 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.
>
> Shouldn't we say it's engine "system" which is doing this import automatically?
>
Agreed, that would be better. I opened bug 1096854 for investigation.
>>
>>>
>>>>> 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?
>
> Sadly no, I don't have them anymore. I'll try to provide them if I'm able to reproduce.
Thanks.
> Anybody else seeing this?
>
>>
>>>
>>>>> 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
>>>>>
>>>
>>>
>>
>
>
More information about the Devel
mailing list