so i had done another test... i have disabled datastore heartbeating and reinstalled the ha-agents on the hosts... now the logs are a little bit better: 2012-03-20T15:03:33.815Z [461D7B9...
See more...
so i had done another test... i have disabled datastore heartbeating and reinstalled the ha-agents on the hosts... now the logs are a little bit better: 2012-03-20T15:03:33.815Z [461D7B90 info 'Election' opID=SWI-ba420ecc] Slave timed out 2012-03-20T15:03:33.816Z [461D7B90 info 'Election' opID=SWI-ba420ecc] [ClusterElection::ChangeState] Slave => Startup : Lost master 2012-03-20T15:03:33.816Z [461D7B90 info 'Cluster' opID=SWI-ba420ecc] Change state to Startup:0 2012-03-20T15:03:33.816Z [4631CB90 verbose 'Cluster' opID=SWI-3b1a98a4] [ClusterManagerImpl::CheckElectionState] Transitioned from Slave to Startup 2012-03-20T15:03:33.817Z [4631CB90 info 'Invt' opID=SWI-3b1a98a4] [InventoryManagerImpl::NotifyDatastoreUnlockedLocally] Invoked for datastore (/vmfs/volumes/4f1fe1be-5c192c43-c0c9-0025b30272a2). 2012-03-20T15:03:33.817Z [4631CB90 info 'Cluster' opID=SWI-3b1a98a4] Releasing datastore /vmfs/volumes/4f0d8e48-cc6fcf66-a20a-68b599722822 2012-03-20T15:03:33.818Z [4631CB90 error 'Message' opID=SWI-3b1a98a4] AsyncWrite: Error sending asynch message: N7Vmacore21InvalidStateExceptionE(Invalid state) 2012-03-20T15:03:33.818Z [4631CB90 warning 'Cluster' opID=SWI-3b1a98a4] [ClusterDatastore::SendDatastoreReleasedMsg] Exception sending to host-22: N7Vmacore21InvalidStateExceptionE(Invalid state) 2012-03-20T15:03:33.818Z [4631CB90 info 'Message' opID=SWI-3b1a98a4] Destroying connection 2012-03-20T15:03:33.818Z [4631CB90 info 'Invt' opID=SWI-3b1a98a4] [InventoryManagerImpl::NotifyDatastoreUnlockedLocally] Invoked for datastore (/vmfs/volumes/4f0d8e48-cc6fcf66-a20a-68b599722822). 2012-03-20T15:03:33.819Z [4631CB90 info 'Cluster' opID=SWI-3b1a98a4] [ClusterManagerImpl::MainLoop] curState 1 lastState 4 2012-03-20T15:03:33.819Z [4639EB90 info 'Invt' opID=SWI-e762e053] [InventoryManagerImpl::ProcessClusterChange] Cluster state changed to Startup 2012-03-20T15:03:33.820Z [4639EB90 verbose 'PropertyProvider' opID=SWI-e762e053] RecordOp ASSIGN: clusterState, fdmService 2012-03-20T15:03:33.820Z [4639EB90 verbose 'FDM' opID=SWI-e762e053] [FdmService::Handle::ClusterStateNotification] Cluster state changed: Slave -> Startup 2012-03-20T15:03:33.820Z [4639EB90 verbose 'Placement' opID=SWI-e762e053] [PlacementManagerImpl::ClusterStateListener::Handle] New cluster state is 1 2012-03-20T15:03:33.820Z [4639EB90 verbose 'Execution' opID=SWI-e762e053] [ExecutionManagerImpl::ClusterStateListener::Handle] New cluster state is 1 2012-03-20T15:03:33.820Z [4639EB90 verbose 'Policy' opID=SWI-e762e053] [PolicyManager::Handle(ClusterStateNotification)] Transitioning to startup (1). Disabling global policy and enabling local policy. 2012-03-20T15:03:33.820Z [4639EB90 verbose 'Monitor' opID=SWI-e762e053] [IsoAddressMonitor::Handle::ClusterStateNotification] Cluster state changed to 1 2012-03-20T15:03:33.820Z [4639EB90 verbose 'Monitor' opID=SWI-e762e053] [PingableAddressMonitor::Handle::ClusterStateNotification] Cluster state changed to 1 2012-03-20T15:03:33.820Z [4639EB90 verbose 'Monitor' opID=SWI-e762e053] [HostAccessMonitor::ClusterStateListener] Cluster state changed to 1 2012-03-20T15:03:38.818Z [461D7B90 info 'Election' opID=SWI-ba420ecc] [ClusterElection::ChangeState] Startup => Candidate : Startup Timeout 2012-03-20T15:03:38.818Z [461D7B90 info 'Cluster' opID=SWI-ba420ecc] Change state to Candidate:690781799707 2012-03-20T15:03:38.819Z [4631CB90 verbose 'Cluster' opID=SWI-3b1a98a4] [ClusterManagerImpl::CheckElectionState] Transitioned from Startup to Candidate 2012-03-20T15:03:38.819Z [4631CB90 info 'Invt' opID=SWI-3b1a98a4] [InventoryManagerImpl::NotifyDatastoreUnlockedLocally] Invoked for datastore (/vmfs/volumes/4f1fe1be-5c192c43-c0c9-0025b30272a2). 2012-03-20T15:03:38.819Z [4631CB90 info 'Invt' opID=SWI-3b1a98a4] [InventoryManagerImpl::NotifyDatastoreUnlockedLocally] Invoked for datastore (/vmfs/volumes/4f0d8e48-cc6fcf66-a20a-68b599722822). 2012-03-20T15:03:38.819Z [4631CB90 info 'Cluster' opID=SWI-3b1a98a4] [ClusterManagerImpl::MainLoop] curState 5 lastState 1 2012-03-20T15:03:44.732Z [FFF72B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:44.733Z [FFF72B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:44.733Z [FFF72B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:44.785Z [FFE0B400 verbose 'HttpConnectionPool'] HttpConnectionPoolImpl created. maxPoolConnections = 1; idleTimeout = 900000000; maxOpenConnections = 1; maxConnectionAge = 0 2012-03-20T15:03:44.791Z [FFF31B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:44.791Z [FFF31B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:44.791Z [FFF31B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:44.825Z [FFE0B400 info 'vmomi.soapStub[4]'] Resetting stub adapter for server TCP:localhost:443 : Closed 2012-03-20T15:03:44.826Z [FFE0B400 verbose 'HalCnx'] [HalCnx] Authenticate succeeded: userName=root 2012-03-20T15:03:44.827Z [FFE0B400 verbose 'DebugBrowser.HTTPService'] User agent is 'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0)' 2012-03-20T15:03:44.827Z [FFE0B400 verbose 'DebugBrowser'] MO fdmService: typeName: ManagedObjectReference:CsiFdmService, homeUrl: /mobfdm 2012-03-20T15:03:44.828Z [FFE0B400 verbose 'DebugBrowser'] MO fdmLogServiceManager: typeName: ManagedObjectReference:CsiLogsvcManager, homeUrl: /mobfdm 2012-03-20T15:03:44.829Z [FFE0B400 verbose 'DebugBrowser.HTTPService'] HTTP Response: Complete (processed 11766 bytes) 2012-03-20T15:03:45.709Z [46218B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:45.710Z [46218B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:45.710Z [46218B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:45.761Z [4629AB90 verbose 'HttpConnectionPool'] HttpConnectionPoolImpl created. maxPoolConnections = 1; idleTimeout = 900000000; maxOpenConnections = 1; maxConnectionAge = 0 2012-03-20T15:03:45.766Z [4639EB90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:45.767Z [4639EB90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:45.767Z [4639EB90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:45.800Z [4629AB90 info 'vmomi.soapStub[5]'] Resetting stub adapter for server TCP:localhost:443 : Closed 2012-03-20T15:03:45.802Z [4629AB90 verbose 'HalCnx'] [HalCnx] Authenticate succeeded: userName=root 2012-03-20T15:03:45.802Z [4629AB90 verbose 'DebugBrowser.HTTPService'] User agent is 'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0)' 2012-03-20T15:03:45.802Z [4629AB90 verbose 'DebugBrowser'] MO fdmService: typeName: ManagedObjectReference:CsiFdmService, homeUrl: /mobfdm 2012-03-20T15:03:45.804Z [4629AB90 verbose 'DebugBrowser'] MO fdmLogServiceManager: typeName: ManagedObjectReference:CsiLogsvcManager, homeUrl: /mobfdm 2012-03-20T15:03:45.804Z [4629AB90 verbose 'DebugBrowser.HTTPService'] HTTP Response: Complete (processed 11766 bytes) 2012-03-20T15:03:46.547Z [FFE0B400 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:46.547Z [FFE0B400 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:46.548Z [FFE0B400 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:46.600Z [FFEF0B90 verbose 'HttpConnectionPool'] HttpConnectionPoolImpl created. maxPoolConnections = 1; idleTimeout = 900000000; maxOpenConnections = 1; maxConnectionAge = 0 2012-03-20T15:03:46.608Z [462DBB90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:46.608Z [462DBB90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:46.608Z [462DBB90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:46.634Z [FFEF0B90 info 'vmomi.soapStub[6]'] Resetting stub adapter for server TCP:localhost:443 : Closed 2012-03-20T15:03:46.636Z [FFEF0B90 verbose 'HalCnx'] [HalCnx] Authenticate succeeded: userName=root 2012-03-20T15:03:46.636Z [FFEF0B90 verbose 'DebugBrowser.HTTPService'] User agent is 'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0)' 2012-03-20T15:03:46.636Z [FFEF0B90 verbose 'DebugBrowser'] MO fdmService: typeName: ManagedObjectReference:CsiFdmService, homeUrl: /mobfdm 2012-03-20T15:03:46.638Z [FFEF0B90 verbose 'DebugBrowser'] MO fdmLogServiceManager: typeName: ManagedObjectReference:CsiLogsvcManager, homeUrl: /mobfdm 2012-03-20T15:03:46.638Z [FFEF0B90 verbose 'DebugBrowser.HTTPService'] HTTP Response: Complete (processed 11766 bytes) 2012-03-20T15:03:47.347Z [46155B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:47.348Z [46155B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:47.348Z [46155B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:47.401Z [4639EB90 verbose 'HttpConnectionPool'] HttpConnectionPoolImpl created. maxPoolConnections = 1; idleTimeout = 900000000; maxOpenConnections = 1; maxConnectionAge = 0 2012-03-20T15:03:47.406Z [FFFF4B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:47.406Z [FFFF4B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:47.407Z [FFFF4B90 warning 'Libs'] SSL_VerifyX509: Certificate verification is disabled, so connection will proceed despite the error 2012-03-20T15:03:47.441Z [4639EB90 info 'vmomi.soapStub[7]'] Resetting stub adapter for server TCP:localhost:443 : Closed 2012-03-20T15:03:47.442Z [4639EB90 verbose 'HalCnx'] [HalCnx] Authenticate succeeded: userName=root 2012-03-20T15:03:47.443Z [4639EB90 verbose 'DebugBrowser.HTTPService'] User agent is 'Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; WOW64; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0)' 2012-03-20T15:03:47.443Z [4639EB90 verbose 'DebugBrowser'] MO fdmService: typeName: ManagedObjectReference:CsiFdmService, homeUrl: /mobfdm 2012-03-20T15:03:47.444Z [4639EB90 verbose 'DebugBrowser'] MO fdmLogServiceManager: typeName: ManagedObjectReference:CsiLogsvcManager, homeUrl: /mobfdm 2012-03-20T15:03:47.445Z [4639EB90 verbose 'DebugBrowser.HTTPService'] HTTP Response: Complete (processed 11766 bytes) 2012-03-20T15:03:48.819Z [461D7B90 info 'Election' opID=SWI-ba420ecc] [ClusterElection::ChangeState] Candidate => Master : Master selected 2012-03-20T15:03:48.819Z [461D7B90 info 'Cluster' opID=SWI-ba420ecc] Change state to Master:690781799707 2012-03-20T15:03:48.820Z [4631CB90 verbose 'Cluster' opID=SWI-3b1a98a4] [ClusterManagerImpl::CheckElectionState] Transitioned from Candidate to Master 2012-03-20T15:03:48.820Z [4631CB90 info 'Invt' opID=SWI-3b1a98a4] [InventoryManagerImpl::NotifyDatastoreUnlockedLocally] Invoked for datastore (/vmfs/volumes/4f1fe1be-5c192c43-c0c9-0025b30272a2). 2012-03-20T15:03:48.820Z [4631CB90 info 'Invt' opID=SWI-3b1a98a4] [InventoryManagerImpl::NotifyDatastoreUnlockedLocally] Invoked for datastore (/vmfs/volumes/4f0d8e48-cc6fcf66-a20a-68b599722822). 2012-03-20T15:03:48.820Z [4631CB90 info 'Cluster' opID=SWI-3b1a98a4] [ClusterManagerImpl::MainLoop] curState 6 lastState 5 2012-03-20T15:03:48.821Z [4631CB90 info 'Cluster' opID=SWI-3b1a98a4] [ClusterManagerImpl::MainLoop] Am now master 2012-03-20T15:03:48.821Z [FFFB3B90 info 'Invt' opID=SWI-c4db588c] [InventoryManagerImpl::ProcessClusterChange] Cluster state changed to Master 2012-03-20T15:03:48.821Z [4631CB90 verbose 'Cluster' opID=SWI-3b1a98a4] [ClusterManagerImpl::CheckHostNetworkIsolation] Waited 5 seconds for isolation icmp ping reply. Isolated 2012-03-20T15:03:48.821Z [FFFB3B90 verbose 'PropertyProvider' opID=SWI-c4db588c] RecordOp ASSIGN: clusterState, fdmService 2012-03-20T15:03:48.822Z [4631CB90 info 'Policy' opID=SWI-3b1a98a4] [LocalIsolationPolicy::Handle(IsolationNotification)] host isolated is true 2012-03-20T15:03:48.822Z [FFFB3B90 verbose 'FDM' opID=SWI-c4db588c] [FdmService::Handle::ClusterStateNotification] Cluster state changed: Startup -> Master 2012-03-20T15:03:48.822Z [FFFB3B90 verbose 'Notifications' opID=SWI-c4db588c] [Notification::AddListener] Adding listener of type Csi::Notifications::HostStateChange: FdmService (listeners = 2) 2012-03-20T15:03:48.822Z [FFFB3B90 verbose 'Notifications' opID=SWI-c4db588c] [Notification::AddListener] Adding listener of type Csi::Notifications::VmStateChange: FdmService (listeners = 2) 2012-03-20T15:03:48.822Z [FFFB3B90 verbose 'Notifications' opID=SWI-c4db588c] [Notification::AddListener] Adding listener of type Csi::Notifications::DsStateChange: FdmService (listeners = 2) 2012-03-20T15:03:48.823Z [FFFB3B90 verbose 'Notifications' opID=SWI-c4db588c] [Notification::AddListener] Adding listener of type Csi::Notifications::InitialProtectedList: FdmService (listeners = 1) 2012-03-20T15:03:48.822Z [FFF31B90 verbose 'Policy' opID=SWI-832b39dc] [LocalIsolationPolicy::GetIsolationResponseInfo] Cluster default isolation response is shutdown 2012-03-20T15:03:48.823Z [FFFB3B90 verbose 'Placement' opID=SWI-c4db588c] [PlacementManagerImpl::ClusterStateListener::Handle] New cluster state is 3 2012-03-20T15:03:48.823Z [FFFB3B90 verbose 'Execution' opID=SWI-c4db588c] [ExecutionManagerImpl::ClusterStateListener::Handle] New cluster state is 3 2012-03-20T15:03:48.823Z [FFF31B90 verbose 'Policy' opID=SWI-832b39dc] [LocalIsolationPolicy::LogIsolationResponseInfo] Logging IsolationResponseInfo 2012-03-20T15:03:48.824Z [FFF31B90 verbose 'Policy' opID=SWI-832b39dc] [LocalIsolationPolicy::LogIsolationResponseInfo] Datastore /vmfs/volumes/4f0d8e48-cc6fcf66-a20a-68b599722822 2012-03-20T15:03:48.824Z [FFF31B90 verbose 'Policy' opID=SWI-832b39dc] [LocalIsolationPolicy::LogIsolationResponseInfo] VM /vmfs/volumes/4f0d8e48-cc6fcf66-a20a-68b599722822/SvSAN ESX1/SvSAN ESX1.vmx isolation response shutdown 2012-03-20T15:03:48.824Z [FFFB3B90 verbose 'Policy' opID=SWI-c4db588c] [PolicyManager::Handle(ClusterStateNotification)] Transitioning to master (3). Enabling global and local policies. 2012-03-20T15:03:48.824Z [FFFB3B90 verbose 'Policy' opID=SWI-c4db588c] [GlobalPolicy::OnEnable] Enabling global failure processing policy. 2012-03-20T15:03:48.824Z [FFFB3B90 verbose 'Notifications' opID=SWI-c4db588c] [Notification::AddListener] Adding listener of type Csi::Notifications::VmStateChange: Csi::Policies::GlobalPolicy (listeners = 3) 2012-03-20T15:03:48.825Z [FFFB3B90 verbose 'Monitor' opID=SWI-c4db588c] [IsoAddressMonitor::Handle::ClusterStateNotification] Cluster state changed to 3 2012-03-20T15:03:48.825Z [FFFB3B90 verbose 'Monitor' opID=SWI-c4db588c] [PingableAddressMonitor::Handle::ClusterStateNotification] Cluster state changed to 3 2012-03-20T15:03:48.825Z [FFFB3B90 verbose 'Monitor' opID=SWI-c4db588c] [HostAccessMonitor::ClusterStateListener] Cluster state changed to 3 2012-03-20T15:03:48.827Z [46155B90 verbose 'Placement' opID=SWI-1b0b4dc2] [PlacementManagerImpl::CancelVmPlacement] removed 0 of 8 vms 2012-03-20T15:03:49.819Z [461D7B90 verbose 'Election' opID=SWI-ba420ecc] [ClusterElection::MasterStateFunc] Am isolated! Dropping to STARTUP! as we can see on 15:03:48.821 --> the host wants to ping the isolation address and get no reply. he is isolated... on 15:03:48.824 everything seen to be fine, he wants to shutdown the "SvSAN ESX1.vmx" virtual maschine... but he dont do that... why??? everything would be allright when he would shutdown this VM...