ESXi上でsnapshotをとってあった仮想マシンが起動しない

Tweet

Check

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

上記の出力から検索したところ近い事例が２つ
・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

上記２つの内容を簡単に言えば「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の再インストールとなりました。
ただ・・・起動しなくなったのは、とりあえず、仮想マシン１つだけで、他は起動してたんだよね。
その理由はよくわかりませんでした。

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