ESXiで構築した仮想マシンが起動しない。
snapshotをいくつか作ってある仮想マシンの電源を入れようとしたら以下のメッセージが出て起動しない。
——-日本語表記———————
ESXiホスト名 上の 仮想マシン名 をパワーオンでき
ません。 一般的なシステム エラーが発生しました:
エラー
2013/04/25 19:30:36
仮想マシン名
root
——-英語表記———————
Cannot power on 仮想マシン名 on ESXiホスト名
. A general system error occurred:
error
2013/04/25 19:30:36
仮想マシン名
root
—————————-
上記の出力から検索したところ近い事例が2つ
・vCenter 5.0 (Appliance) Issues (Stack Error & Migration Issues)
・RedoLog Corrupt Error and “Failed to clone disk : Bad file descriptor (589833).” when trying to clone
上記2つの内容を簡単に言えば「ESXiを再インストールして治った」とか、「他のデータストアにコピーして治った」とか
VMwareのKnowledgeからは以下の事例が見付かった
・Investigating disk space on an ESX or ESXi host
・ESX, ESXiのディスクスペースの容量調査 (↑の日本語版。ただし版が古い)
これは、起動しない、という対処の一般的な事例として、データストア(ディスク)の空き容量が足らない、という可能性がある、という話。
では、検証。
・データストア(ディスク)の空き容量が足らない可能性について
snapshotデータを統合する場合の作業領域を考えると若干足らない可能性があったので、空き容量をさらに広げた。
→ でも起動せず。(状況変わらず)
・ESXi側の問題について
別のESXiに仮想マシンイメージ全体をコピーして、起動試験。
→ 正常起動
どういうことかな?と考えて見ると、このESXiのサーバって、テスト用サーバで、結構適当な管理をされており、設置場所の都合上、いきなり電源offされたりすることがあった。
どうやら、その時に、ESXiのブートイメージがおかしくなったんじゃないかと想定される。
「hostd-vix-worke: access denied:: dom:appDom(2), obj:vmxSys(66), mode:syscall_allow(2)」とか、怪しすぎる。
まぁ、そんな感じで、結果としては、ESXiの再インストールとなりました。
ただ・・・起動しなくなったのは、とりあえず、仮想マシン1つだけで、他は起動してたんだよね。
その理由はよくわかりませんでした。
# cat /var/log/vmkernel.log 2013-04-25T19:36:46.504Z cpu6:5025)Config: 347: "SIOControlFlag2" = 9, Old Value: 8, (Status: 0x0) 2013-04-25T19:36:46.543Z cpu6:5621)VmkAccess: 637: hostd-vix-worke: access denied:: dom:appDom(2), obj:vmxSys(66), mode:syscall_allow(2) 2013-04-25T19:36:46.543Z cpu6:5621)VmkAccess: 922: VMkernel syscall invalid (1059) 2013-04-25T19:36:46.544Z cpu6:5621)VmkAccess: 637: hostd-vix-worke: access denied:: dom:appDom(2), obj:forkExecSys(88), mode:syscall_allow(2) 2013-04-25T19:36:46.544Z cpu6:5621)VmkAccess: 922: VMkernel syscall invalid (1025) 2013-04-25T19:36:46.608Z cpu2:187170)Config: 347: "SIOControlFlag2" = 8, Old Value: 9, (Status: 0x0) #
# cat /var/log/hostd.log 2013-04-25T19:36:39.811Z [50F40B90 verbose 'DvsManager'] PersistAllDvsInfo called 2013-04-25T19:36:46.503Z [4FFDCB90 info 'TaskManager' opID=22A33D0D-00000409] Task Created : haTask-24-vim.VirtualMachine.powerOn-500539340 2013-04-25T19:36:46.503Z [FFD81D20 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] Power on request recieved 2013-04-25T19:36:46.504Z [FFD81D20 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] Reconfigure ethernet backing if required 2013-04-25T19:36:46.504Z [FFD81D20 info 'ha-eventmgr' opID=22A33D0D-00000409] Event 164 : linuxvm1 on host adminserver in ha-datacenter is starting 2013-04-25T19:36:46.504Z [FFD81D20 info 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] State Transition (VM_STATE_OFF -> VM_STATE_POWERING_ON) 2013-04-25T19:36:46.504Z [FFD81D20 verbose 'ha-host' opID=22A33D0D-00000409] ModeMgr::Begin: op = normal, current = normal, count = 1 2013-04-25T19:36:46.504Z [FFD81D20 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] Invoking interceptor:3-ha-vmsvc 2013-04-25T19:36:46.504Z [FFD81D20 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] Done invoking interceptor:3-ha-vmsvc 2013-04-25T19:36:46.505Z [FFD81D20 verbose 'ServiceSystem' opID=22A33D0D-00000409] Invoking command /bin/sh /etc/init.d/xorg status 2013-04-25T19:36:46.506Z [FFD81D20 info 'SysCommandPosix' opID=22A33D0D-00000409] ForkExec(/bin/sh) 191986 2013-04-25T19:36:46.539Z [FFD81D20 verbose 'ServiceSystem' opID=22A33D0D-00000409] Command finished with status 3 2013-04-25T19:36:46.541Z [FFD81D20 verbose 'HostsvcPlugin' opID=22A33D0D-00000409] Security domain hostd24 not found 2013-04-25T19:36:46.541Z [FFD81D20 info 'Libs' opID=22A33D0D-00000409] Vix: [5025 foundryHandleProperties.c:3359]: Error VIX_E_NOT_FOUND in Vix_GetPropertiesImpl(): Unable to get bool property 107. 2013-04-25T19:36:46.541Z [FFD81D20 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] PowerOn request queued 2013-04-25T19:36:46.542Z [4F6C2B90 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] Retrieved current VM state from foundry 7, 6 2013-04-25T19:36:46.542Z [4FC43B90 info 'vm:VMHSVMCbPower: /vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] Setting state of VM to powerOn with option soft 2013-04-25T19:36:46.543Z [4FC43B90 info 'Libs'] Starting vmx as /bin/vmx 2013-04-25T19:36:46.543Z [4FC43B90 info 'Libs'] Starting vmx as /bin/vmx 2013-04-25T19:36:46.544Z [4FC43B90 info 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] VMHS: VM /vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx in directory /vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1 2013-04-25T19:36:46.544Z [4FC43B90 info 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] VMHS: Exec()'ing /bin/vmx. 2013-04-25T19:36:46.544Z [4FC43B90 info 'Libs'] VMHS: VMKernel_ForkExec(/bin/vmx, detached=1): rc=195887383 pid=132863664 2013-04-25T19:36:46.544Z [4FC43B90 warning 'Libs'] VMHSSpawnVMXUW: unable to spawn /bin/vmx: Operation not permitted 2013-04-25T19:36:46.544Z [4FC43B90 info 'Libs'] VigorClient_StartAndConnect Failed: Failed to launch peer process 2013-04-25T19:36:46.545Z [4FC43B90 info 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] Reloading config state. 2013-04-25T19:36:46.595Z [4FC43B90 info 'Libs'] VMHS: Transitioned vmx/execState/val to poweredOff 2013-04-25T19:36:46.607Z [4F681B90 info 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] Upgrade is required for virtual machine, version: 8 2013-04-25T19:36:46.607Z [4F681B90 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] Running status of tools changed to: 0 2013-04-25T19:36:46.607Z [4FC43B90 info 'vm:FoundryVMDBPowerOpCallback: VMDB reports power op failed for VM /vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] with error msg = "The virtual machine could not start. Make sure VMware ESX is installed correctly. You must also have rights to run the software and access all directories 2013-04-25T19:36:46.607Z [4FB40B90 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] Retrieved current VM state from foundry 5, 2 2013-04-25T19:36:46.607Z [513C3B90 info 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] Failed to do Power Op: Error: (3041) The virtual machine could not start 2013-04-25T19:36:46.608Z [513C3B90 info 'HostsvcPlugin' opID=22A33D0D-00000409] Decremented SIOC Injector Flag2 2013-04-25T19:36:46.641Z [4FC43B90 info 'vm:Vix: [5621 foundryVMPowerOps.c:980]: FoundryVMPowerStateChangeCallback: /vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx'] vmx/execState/val = poweredOff. 2013-04-25T19:36:46.641Z [513C3B90 warning 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] Failed operation 2013-04-25T19:36:46.642Z [513C3B90 info 'ha-eventmgr' opID=22A33D0D-00000409] Event 165 : Cannot power on linuxvm1 on adminserver in ha-datacenter. A general system error occurred: 2013-04-25T19:36:46.642Z [513C3B90 info 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] State Transition (VM_STATE_POWERING_ON -> VM_STATE_OFF) 2013-04-25T19:36:46.642Z [513C3B90 verbose 'ha-host' opID=22A33D0D-00000409] ModeMgr::End: op = normal, current = normal, count = 2 2013-04-25T19:36:46.677Z [513C3B90 info 'ha-host' opID=22A33D0D-00000409] vmxSwapEnabled = true vmmOvhd.anonymous: 25934 vmmOvhd.paged: 50002 vmmOvhd.nonpaged: 12519 2013-04-25T19:36:46.677Z [513C3B90 info 'ha-host' opID=22A33D0D-00000409] vmkOvhd.fixd = 303104 vmkOvhd.variable: 2050 vmkOvhd.selfSwap: 3145728 2013-04-25T19:36:46.677Z [513C3B90 info 'ha-host' opID=22A33D0D-00000409] Computed from lib overhead: 157503488 for (memPages: 1048576, fbSize: 1024, #vcpus: 1, #lsiscsi: 1, #pvscsi: 0, #passthru: 0, #network: 2) vmkOverhead: 11845632 2013-04-25T19:36:46.677Z [513C3B90 info 'ha-host' opID=22A33D0D-00000409] overhead result (no CBRC): 169349120 2013-04-25T19:36:46.677Z [513C3B90 info 'ha-host' opID=22A33D0D-00000409] Predicted overhead: 169349120 for (memory: 4294967296, video: 4194304, #vcpus: 1, autodetect: false, enable3D: false, svgaPtFbSize: 4194304, cbrcOverhead: 0 2013-04-25T19:36:46.677Z [513C3B90 verbose 'vm:/vmfs/volumes/4f8dXXXX-8d9cXXXX-XXXX-XXXXXXXXXXXX/linuxvm1/linuxvm1.vmx' opID=22A33D0D-00000409] Time to gather config: 35 (msecs) 2013-04-25T19:36:46.678Z [4FB81B90 verbose 'Hbrsvc'] Replicator: ReconfigListener triggered for config VM 24 2013-04-25T19:36:46.678Z [513C3B90 info 'HostsvcPlugin' opID=22A33D0D-00000409] Lookupvm: World ID not set for VM 24 2013-04-25T19:36:46.689Z [513C3B90 info 'TaskManager' opID=22A33D0D-00000409] Task Completed : haTask-24-vim.VirtualMachine.powerOn-500539340 Status error 2013-04-25T19:36:46.689Z [4FB81B90 verbose 'Hbrsvc'] Replicator: VmReconfig ignoring VM 24 not configured for replication 2013-04-25T19:36:46.689Z [4FB81B90 info 'Snmpsvc'] VmConfigListener: vm state change received, queueing reload request 2013-04-25T19:36:46.712Z [50FC2B90 warning 'Locale' opID=6E461CB0-00001066] FormatField: Invalid (vim.vm.Message.1) 2013-04-25T19:36:46.712Z [50FC2B90 warning 'Locale' opID=6E461CB0-00001066] FormatField: Invalid (vim.vm.Message.2) 2013-04-25T19:36:46.712Z [50FC2B90 warning 'Locale' opID=6E461CB0-00001066] FormatField: Invalid (vim.vm.Message.3) 2013-04-25T19:36:46.952Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.prov.ProvisioningManager.queryVmLocation.label' expected in module 'task'. 2013-04-25T19:36:46.952Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.prov.ProvisioningManager.queryVmLocation.summary' expected in module 'task'. 2013-04-25T19:36:46.952Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.prov.ProvisioningManager.createShadowVm.label' expected in module 'task'. 2013-04-25T19:36:46.952Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.prov.ProvisioningManager.createShadowVm.summary' expected in module 'task'. 2013-04-25T19:36:46.953Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.NetworkSystem.invokeHostTransactionCall.label' expected in module 'task'. 2013-04-25T19:36:46.953Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.NetworkSystem.invokeHostTransactionCall.summary' expected in module 'task'. 2013-04-25T19:36:46.953Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.NetworkSystem.commitTransaction.label' expected in module 'task'. 2013-04-25T19:36:46.953Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.NetworkSystem.commitTransaction.summary' expected in module 'task'. 2013-04-25T19:36:46.954Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'profile.host.HostProfile.validate.label' expected in module 'task'. 2013-04-25T19:36:46.954Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'profile.host.HostProfile.validate.summary' expected in module 'task'. 2013-04-25T19:36:46.955Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'DistributedVirtualSwitch.lookupPortgroup.label' expected in module 'task'. 2013-04-25T19:36:46.955Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'DistributedVirtualSwitch.lookupPortgroup.summary' expected in module 'task'. 2013-04-25T19:36:46.956Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'HostSystem.queryTpmAttestationReport.label' expected in module 'task'. 2013-04-25T19:36:46.956Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'HostSystem.queryTpmAttestationReport.summary' expected in module 'task'. 2013-04-25T19:36:46.957Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'IpPoolManager.allocateIpv4Address.label' expected in module 'task'. 2013-04-25T19:36:46.957Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'IpPoolManager.allocateIpv4Address.summary' expected in module 'task'. 2013-04-25T19:36:46.957Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'IpPoolManager.allocateIpv6Address.label' expected in module 'task'. 2013-04-25T19:36:46.957Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'IpPoolManager.allocateIpv6Address.summary' expected in module 'task'. 2013-04-25T19:36:46.957Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'IpPoolManager.releaseIpAllocation.label' expected in module 'task'. 2013-04-25T19:36:46.957Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'IpPoolManager.releaseIpAllocation.summary' expected in module 'task'. 2013-04-25T19:36:46.957Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'IpPoolManager.queryIPAllocations.label' expected in module 'task'. 2013-04-25T19:36:46.957Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'IpPoolManager.queryIPAllocations.summary' expected in module 'task'. 2013-04-25T19:36:46.958Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'dvs.DistributedVirtualSwitchManager.lookupPortgroup.label' expected in module 'task'. 2013-04-25T19:36:46.958Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'dvs.DistributedVirtualSwitchManager.lookupPortgroup.summary' expected in module 'task'. 2013-04-25T19:36:46.958Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'profile.host.ProfileManager.retrieveAnswerFileForProfile.label' expected in module 'task'. 2013-04-25T19:36:46.958Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'profile.host.ProfileManager.retrieveAnswerFileForProfile.summary' expected in module 'task'. 2013-04-25T19:36:46.959Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'Datacenter.queryConfigOptionDescriptor.label' expected in module 'task'. 2013-04-25T19:36:46.959Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'Datacenter.queryConfigOptionDescriptor.summary' expected in module 'task'. 2013-04-25T19:36:46.959Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.DatastoreNamespaceManager.CreateDirectory.label' expected in module 'task'. 2013-04-25T19:36:46.959Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.DatastoreNamespaceManager.CreateDirectory.summary' expected in module 'task'. 2013-04-25T19:36:46.959Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.DatastoreNamespaceManager.DeleteDirectory.label' expected in module 'task'. 2013-04-25T19:36:46.959Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.DatastoreNamespaceManager.DeleteDirectory.summary' expected in module 'task'. 2013-04-25T19:36:46.960Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.retrieveVmRecoveryInfo.label' expected in module 'task'. 2013-04-25T19:36:46.960Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.retrieveVmRecoveryInfo.summary' expected in module 'task'. 2013-04-25T19:36:46.960Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.retrieveLastVmMigrationStatus.label' expected in module 'task'. 2013-04-25T19:36:46.960Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.retrieveLastVmMigrationStatus.summary' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.reserveFiles.label' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.reserveFiles.summary' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.deleteFiles.label' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.deleteFiles.summary' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.extractNvramContent.label' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'host.LowLevelProvisioningManager.extractNvramContent.summary' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.retrieveConfigValue.label' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.retrieveConfigValue.summary' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.updateConfigValue.label' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.updateConfigValue.summary' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.initiateProductInfoQuery.label' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.initiateProductInfoQuery.summary' expected in module 'task'. 2013-04-25T19:36:46.961Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.initiateProductInstall.label' expected in module 'task'. 2013-04-25T19:36:46.962Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.initiateProductInstall.summary' expected in module 'task'. 2013-04-25T19:36:46.962Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.retrieveJobStatus.label' expected in module 'task'. 2013-04-25T19:36:46.962Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.retrieveJobStatus.summary' expected in module 'task'. 2013-04-25T19:36:46.962Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.retrieveJobResults.label' expected in module 'task'. 2013-04-25T19:36:46.962Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'vm.guest.GuestUpdateAgent.retrieveJobResults.summary' expected in module 'task'. 2013-04-25T19:36:46.962Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'dvs.VmwareDistributedVirtualSwitch.lookupPortgroup.label' expected in module 'task'. 2013-04-25T19:36:46.962Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'dvs.VmwareDistributedVirtualSwitch.lookupPortgroup.summary' expected in module 'task'. 2013-04-25T19:36:46.963Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'ExtensionManager.queryExtensionIpAllocationUsage.label' expected in module 'task'. 2013-04-25T19:36:46.963Z [4FF5BB90 verbose 'Locale' opID=22A33D0D-0000040E] Default resource used for 'ExtensionManager.queryExtensionIpAllocationUsage.summary' expected in module 'task'. 2013-04-25T19:36:51.691Z [4F6C2B90 info 'Snmpsvc'] DoReport: VM Poll State cache - report starting 2013-04-25T19:36:51.694Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 8 2013-04-25T19:36:51.697Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 9 2013-04-25T19:36:51.700Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 14 2013-04-25T19:36:51.703Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 18 2013-04-25T19:36:51.706Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 19 2013-04-25T19:36:51.709Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 21 2013-04-25T19:36:51.712Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 24 2013-04-25T19:36:51.714Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 27 2013-04-25T19:36:51.718Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 28 2013-04-25T19:36:51.721Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 30 2013-04-25T19:36:51.723Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 31 2013-04-25T19:36:51.726Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 34 2013-04-25T19:36:51.729Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 41 2013-04-25T19:36:51.732Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 43 2013-04-25T19:36:51.734Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 45 2013-04-25T19:36:51.737Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 46 2013-04-25T19:36:51.740Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 47 2013-04-25T19:36:51.743Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 48 2013-04-25T19:36:51.746Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 49 2013-04-25T19:36:51.749Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 58 2013-04-25T19:36:51.752Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 59 2013-04-25T19:36:51.755Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 60 2013-04-25T19:36:51.758Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 62 2013-04-25T19:36:51.761Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 65 2013-04-25T19:36:51.764Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 71 2013-04-25T19:36:51.767Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 81 2013-04-25T19:36:51.770Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 83 2013-04-25T19:36:51.773Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 84 2013-04-25T19:36:51.777Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 86 2013-04-25T19:36:51.780Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 87 2013-04-25T19:36:51.783Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 88 2013-04-25T19:36:51.786Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 89 2013-04-25T19:36:51.789Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 91 2013-04-25T19:36:51.792Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 94 2013-04-25T19:36:51.794Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 95 2013-04-25T19:36:51.797Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 96 2013-04-25T19:36:51.800Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 97 2013-04-25T19:36:51.802Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 98 2013-04-25T19:36:51.815Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 101 2013-04-25T19:36:51.828Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 102 2013-04-25T19:36:51.837Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 103 2013-04-25T19:36:51.841Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 104 2013-04-25T19:36:51.844Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 105 2013-04-25T19:36:51.847Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 106 2013-04-25T19:36:51.850Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 107 2013-04-25T19:36:51.853Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 110 2013-04-25T19:36:51.857Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 111 2013-04-25T19:36:51.860Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 112 2013-04-25T19:36:51.864Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 114 2013-04-25T19:36:51.867Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 115 2013-04-25T19:36:51.869Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 116 2013-04-25T19:36:51.872Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 117 2013-04-25T19:36:51.875Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 118 2013-04-25T19:36:51.878Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 119 2013-04-25T19:36:51.881Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 120 2013-04-25T19:36:51.883Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 121 2013-04-25T19:36:51.887Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 122 2013-04-25T19:36:51.890Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 123 2013-04-25T19:36:51.893Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 124 2013-04-25T19:36:51.897Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 125 2013-04-25T19:36:51.900Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 126 2013-04-25T19:36:51.903Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 127 2013-04-25T19:36:51.906Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 128 2013-04-25T19:36:51.909Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 129 2013-04-25T19:36:51.912Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 130 2013-04-25T19:36:51.915Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 131 2013-04-25T19:36:51.918Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: processing vm 132 2013-04-25T19:36:51.918Z [4F6C2B90 info 'Snmpsvc'] ReportVMs: serialized 67 out of 67 vms 2013-04-25T19:36:51.918Z [4F6C2B90 info 'Snmpsvc'] GenerateFullReport: report file /tmp/.vm-report.xml generated, size 2310 bytes. 2013-04-25T19:36:51.918Z [4F6C2B90 info 'Snmpsvc'] PublishReport: file /tmp/.vm-report.xml published as /tmp/vm-report.xml 2013-04-25T19:36:51.918Z [4F6C2B90 info 'Snmpsvc'] NotifyAgent: write(73, /var/run/snmp.ctl, V) 1 bytes to snmpd 2013-04-25T19:36:51.918Z [4F6C2B90 info 'Snmpsvc'] GenerateFullReport: notified snmpd to update vm cache 2013-04-25T19:36:51.918Z [4F6C2B90 info 'Snmpsvc'] DoReport: VM Poll State cache - report completed ok 2013-04-25T19:36:53.007Z [5001DB90 trivia 'Snmpsvc:http.HTTPService'] HTTP Response: Setting Content-Length: -1 2013-04-25T19:36:53.007Z [5001DB90 verbose 'Snmpsvc:http.HTTPService.HttpConnection'] User agent is 'No-User-Agent' 2013-04-25T19:36:53.007Z [5001DB90 trivia 'Snmpsvc:http.HTTPService.HttpConnection'] User agent 'No-User-Agent' is non-chunking: false 2013-04-25T19:36:53.007Z [5001DB90 trivia 'Snmpsvc:http.HTTPService.HttpConnection'] User agent 'No-User-Agent' needs Content-Length: false 2013-04-25T19:36:53.007Z [5001DB90 trivia 'Snmpsvc:http.HTTPService.HttpConnection'] Lookup handler by prefix for: / 2013-04-25T19:36:53.007Z [5001DB90 trivia 'Snmpsvc:http.HTTPService.HttpConnection'] Inspecting path: / 2013-04-25T19:36:53.007Z [5001DB90 trivia 'Snmpsvc:http.HTTPService.HttpConnection'] No match found for: / 2013-04-25T19:36:53.007Z [5001DB90 trivia 'Snmpsvc:http.HTTPService.HttpConnection'] ProcessRequest: using default handler 2013-04-25T19:36:53.007Z [5001DB90 verbose 'Snmpsvc-env'] HandlePost 2013-04-25T19:36:53.007Z [5001DB90 verbose 'Snmpsvc-env'] HandleRequest 2013-04-25T19:36:53.007Z [5001DB90 verbose 'Snmpsvc-env'] Push starting indication parser 2013-04-25T19:36:53.008Z [5001DB90 verbose 'Snmpsvc-env'] ProcessIndications started threadid=1342299024 2013-04-25T19:36:54.009Z [5001DB90 verbose 'Snmpsvc-env'] FetchClassDef: connect to cimom @ 127.0.0.1:5988 2013-04-25T19:36:54.010Z [5001DB90 verbose 'Snmpsvc-env'] FetchClassDef: making request class VMware_CIMHeartbeat, ns root/cimv2 2013-04-25T19:36:54.014Z [5001DB90 verbose 'Snmpsvc-env'] FetchClassDef: got response from cimom 2013-04-25T19:36:54.014Z [5001DB90 verbose 'Snmpsvc-env'] FetchClassDef: http response code from cimom: 200 OK 2013-04-25T19:36:54.014Z [5001DB90 error 'Snmpsvc-env'] OnEndElement: no _props to update value, skipping 2013-04-25T19:36:54.014Z [5001DB90 verbose 'Snmpsvc-env'] parse class definition msg ok: WBEMHandler @0x62a0670 = {_state: 3, _mode: 5, _className: VMware_CIMHeartbeat, _identifier: MIB.IETF| 1.3.6.1.4.1.6876.4.90.0.401, _props = { (IndicationTime,datetime,MIB.IETF|1| 1.3.6.1.4.1.6876.4.30.3.0,0), }} 2013-04-25T19:36:54.014Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='stamp', value='922', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='hostname', value='adminserver', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='SequenceNumber', value='', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='SequenceContext', value='', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='IndicationFilterName', value='com.vmware:vim.snmpagent-root/cimv2', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='OtherSeverity', value='', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='PerceivedSeverity', value='', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='CorrelatedIndications', value='', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds skipping property name='IndicationIdentifier', value='', no oid info from class def keys:(IndicationTime, ) 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc-env'] GenerateVarbinds indication VMware_CIMHeartbeat(1.3.6.1.4.1.6876.4.90.0.401) has 1 properties with mapping qualifiers. Indication had 10, ClassDef had 1 props each. 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc'] GenEvent: oid: 1.3.6.1.4.1.6876.4.90.0.401 2013-04-25T19:36:54.015Z [5001DB90 verbose 'Snmpsvc'] ConvertId: ent:1.3.6.1.4.1.6876.4.90 spec 401 2013-04-25T19:36:54.015Z [5001DB90 info 'Snmpsvc'] ConvertVarbinds: convert id=1.3.6.1.4.1.6876.4.30.3.0: type=dateTimeTC, value=20130422101653.000000+000 2013-04-25T19:36:54.015Z [5001DB90 info 'Snmpsvc'] GenEvent: sending trap (generic=6 specific=401 ent_sz=9) with id: 1.3.6.1.4.1.6876.4.90., vbs: 1 2013-04-25T19:36:54.015Z [5001DB90 info 'Snmpsvc'] WriteV1Trap: generic 6 specific 401 2013-04-25T19:36:54.015Z [5001DB90 info 'Snmpsvc'] WriteV1Trap: serialized 1 varbinds 2013-04-25T19:36:54.016Z [5001DB90 info 'Snmpsvc'] WriteV1Trap: wrote 88 bytes 2013-04-25T19:36:54.016Z [5001DB90 info 'Snmpsvc'] NotifyAgent: write(88, /var/run/snmp.ctl, N) 1 bytes to snmpd 2013-04-25T19:36:54.016Z [5001DB90 info 'Snmpsvc'] WriteV1Trap: agent was notified 2013-04-25T19:36:54.016Z [5001DB90 verbose 'Snmpsvc:http.HTTPService'] HTTP Response: Complete (processed 0 bytes) 2013-04-25T19:36:54.016Z [5001DB90 trivia 'Snmpsvc:http.HTTPService'] HTTP Response: Flush(lastBlock = true) 2013-04-25T19:36:54.016Z [5001DB90 trivia 'Snmpsvc:http.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) 2013-04-25T19:36:54.016Z [5001DB90 trivia 'Snmpsvc:http.HTTPService'] HTTP Response: SetKeepAlive(true) 2013-04-25T19:36:54.016Z [5001DB90 trivia 'Snmpsvc:http.HTTPService'] HTTP Response: Setting Content-Length: 0 2013-04-25T19:36:54.016Z [5001DB90 trivia 'Snmpsvc:http.HTTPService'] HTTP Response: Header size is 163 2013-04-25T19:36:54.016Z [5001DB90 trivia 'Snmpsvc:http.HTTPService'] HTTP Response: Writing 163 bytes to stream 2013-04-25T19:36:54.016Z [5001DB90 trivia 'Snmpsvc:http.HTTPService.HttpConnection'] ResponseCompleted(false), request keep alive true, closeStream false 2013-04-25T19:36:54.016Z [5001DB90 verbose 'Snmpsvc-env'] ProcessIndications completed, 1 indication(s) processed 2013-04-25T19:36:54.016Z [4FE99B90 trivia 'Snmpsvc:http.HTTPService'] HTTP Response: Setting Content-Length: -1 2013-04-25T19:36:55.016Z [500E0B90 verbose 'HttpConnectionPool-000000'] [RemoveConnection] Connection removed; cnx: TCPClientSocket(this=50d773d0, state=CLOSED, _connectSocket=TCP(null), error=(null)) TCP(<null>); pooled: 0 #