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@redhat.com> To: devel@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@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@ovirt.org http://lists.ovirt.org/mailman/listinfo/devel