Re: [ovirt-devel] Help debugging engine.log

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(a)redhat.com&gt; >>>> To: devel(a)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?

> >> >>>> 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.

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@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@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@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(a)ovirt.org >>>> http://lists.ovirt.org/mailman/listinfo/devel >>>> >> >> >