This job view page is being replaced by Spyglass soon. Check out the new job view.
PRsbueringer: ✨ v0.3.x: KCP: block mgmt cluster updates to v1.22.0
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2021-07-26 15:22
Elapsed4m12s
Revision0ea76dfd28bec8f5ad0cf2d96e3731b656540ba3
Refs 5013

No Test Failures!


Error lines from build-log.txt

... skipping 777 lines ...
I0726 15:24:12.926990    8354 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0726 15:24:12.927174    8354 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0726 15:24:12.927998    8354 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0726 15:24:12.928172    8354 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=44357
I0726 15:24:12.928777    8354 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0726 15:24:13.701788    8354 kubeadmconfig_controller.go:223]  "msg"="Cluster infrastructure is not ready, waiting" "kind"="Machine" "kubeadmconfig"={"Namespace":"default","Name":"my-machine-config"} "name"="my-machine" "version"="109" 
•E0726 15:24:13.720386    8354 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0726 15:24:13.720459    8354 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-969221468/tls.crt: no such file or directory"  
E0726 15:24:13.720475    8354 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0726 15:24:13.720489    8354 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-969221468/tls.crt: no such file or directory"  
I0726 15:24:13.720573    8354 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 10.216 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (10.22s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	35.269s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 310 lines ...
=== RUN   Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined
--- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s)
=== RUN   Test_clusterctlClient_GetProviderComponents
=== RUN   Test_clusterctlClient_GetProviderComponents/Pass
=== RUN   Test_clusterctlClient_GetProviderComponents/Fail
--- PASS: Test_clusterctlClient_GetProviderComponents (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s)
=== RUN   Test_getComponentsByName_withEmptyVariables
--- PASS: Test_getComponentsByName_withEmptyVariables (0.00s)
=== RUN   Test_clusterctlClient_templateOptionsToVariables
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts)
... skipping 1398 lines ...
I0726 15:24:04.076408   10408 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
I0726 15:24:04.076436   10408 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0726 15:24:04.076443   10408 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
I0726 15:24:04.076461   10408 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0726 15:24:04.076532   10408 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
I0726 15:24:04.076551   10408 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machine" "worker count"=1
2021/07/26 15:24:04 http: TLS handshake error from 127.0.0.1:43034: EOF
=== RUN   TestClusterReconcilePhases
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I0726 15:24:04.470659   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test-cluster" "namespace"="test-namespace" "err"="cannot create a metadata client without a rest config"
I0726 15:24:04.473210   10408 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
... skipping 105 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0726 15:24:04.496615   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
=== RUN   TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed
I0726 15:24:04.497953   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
E0726 15:24:04.498262   10408 machine_controller_phases.go:246]  "msg"="Machine infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine \"infra-config1\" for Machine \"machine-test\" in namespace \"default\", requeuing: requeue in 1s"  
=== RUN   TestReconcileInfrastructure/infrastructure_ref_is_paused
I0726 15:24:04.498612   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
--- PASS: TestReconcileInfrastructure (0.00s)
    --- PASS: TestReconcileInfrastructure/new_machine,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestWatches
I0726 15:24:04.914236   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0726 15:24:04.916590   10408 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0726 15:24:04.928419   10408 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-55l2g" "namespace"="test-machine-watches-8z9sn" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0726 15:24:04.928521   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0726 15:24:05.036959   10408 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-55l2g" "namespace"="test-machine-watches-8z9sn" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0726 15:24:05.037028   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0726 15:24:05.137462   10408 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-55l2g" "namespace"="test-machine-watches-8z9sn" "noderef"="node-1"
E0726 15:24:05.144619   10408 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0726 15:24:05.144664   10408 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0726 15:24:05.192552   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-55l2g\" in namespace \"test-machine-watches-8z9sn\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-55l2g" "namespace"="test-machine-watches-8z9sn"
E0726 15:24:06.197353   10408 machine_controller_phases.go:246] controllers/Machine "msg"="Machine infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine \"infra-config1\" for Machine \"machine-created-55l2g\" in namespace \"test-machine-watches-8z9sn\", requeuing: requeue in 1s"  
E0726 15:24:06.203182   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine \"infra-config1\" for Machine \"machine-created-55l2g\" in namespace \"test-machine-watches-8z9sn\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-55l2g\" in namespace \"test-machine-watches-8z9sn\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-55l2g" "namespace"="test-machine-watches-8z9sn"
--- PASS: TestWatches (1.78s)
=== RUN   TestIndexMachineByNodeName
=== RUN   TestIndexMachineByNodeName/when_the_machine_has_no_NodeRef
=== RUN   TestIndexMachineByNodeName/when_the_machine_has_valid_a_NodeRef
--- PASS: TestIndexMachineByNodeName (0.00s)
    --- PASS: TestIndexMachineByNodeName/when_the_machine_has_no_NodeRef (0.00s)
... skipping 2 lines ...
=== RUN   TestMachine_Reconcile/reconcile_create
I0726 15:24:06.449579   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-slwgf" "namespace"="test-machine-watches-8z9sn" "count"=1
I0726 15:24:06.449641   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-slwgf" "namespace"="test-machine-watches-8z9sn" "descendants"="Worker machines: machine-created-55l2g" "indirect descendants count"=0
I0726 15:24:06.462895   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-slwgf" "namespace"="test-machine-watches-8z9sn" "count"=1
I0726 15:24:06.462975   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-slwgf" "namespace"="test-machine-watches-8z9sn" "descendants"="Worker machines: machine-created-55l2g" "indirect descendants count"=0
I0726 15:24:07.203792   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-slwgf" "machine"="machine-created-55l2g" "namespace"="test-machine-watches-8z9sn" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"dd3e260c-bb97-4380-9563-5f1ad7a1d20f","apiVersion":"v1"}
E0726 15:24:07.257831   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-55l2g\" not found" "controller"="machine" "name"="machine-created-55l2g" "namespace"="test-machine-watches-8z9sn"
E0726 15:24:08.306177   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-mrsk4\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-m52z2\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-m52z2: secrets \"machine-reconcile-m52z2-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-mrsk4" "namespace"="default"
I0726 15:24:09.306754   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-m52z2" "machine"="machine-created-mrsk4" "namespace"="default" "cause"="noderef is nil" "node"=null
I0726 15:24:09.339272   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-m52z2" "machine"="machine-created-mrsk4" "namespace"="default" "cause"="noderef is nil" "node"=null
I0726 15:24:09.363272   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-m52z2" "machine"="machine-created-mrsk4" "namespace"="default" "cause"="noderef is nil" "node"=null
E0726 15:24:09.401460   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-mrsk4\" not found" "controller"="machine" "name"="machine-created-mrsk4" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.13s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.13s)
=== RUN   TestMachineFinalizer
=== RUN   TestMachineFinalizer/should_add_a_machine_finalizer_to_the_machine_if_it_doesn't_have_one
=== RUN   TestMachineFinalizer/should_append_the_machine_finalizer_to_the_machine_if_it_already_has_a_finalizer
--- PASS: TestMachineFinalizer (0.00s)
... skipping 14 lines ...
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set (0.00s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.00s)
=== RUN   TestReconcileRequest
=== RUN   TestReconcileRequest/machine_should_be_created
I0726 15:24:09.425004   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="created" "namespace"="default" "err"="cannot create a metadata client without a rest config"
=== RUN   TestReconcileRequest/machine_should_be_updated
E0726 15:24:09.433152   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-m52z2\" not found" "controller"="cluster" "name"="machine-reconcile-m52z2" "namespace"="default"
I0726 15:24:09.433348   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="updated" "namespace"="default" "err"="cannot create a metadata client without a rest config"
=== RUN   TestReconcileRequest/machine_should_be_deleted
I0726 15:24:09.436740   10408 machine_controller.go:305]  "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="deleted" "namespace"="default" "cause"="noderef is nil" "node"=null
--- PASS: TestReconcileRequest (0.02s)
    --- PASS: TestReconcileRequest/machine_should_be_created (0.01s)
    --- PASS: TestReconcileRequest/machine_should_be_updated (0.00s)
... skipping 111 lines ...
    --- PASS: TestMachineDeploymentSyncStatus/scaling_up (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0726 15:24:09.569135   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f9sct" "namespace"="test-mhc-gq6c8" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
I0726 15:24:09.624057   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0726 15:24:09.624151   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-5gntt\" not found"  "cluster"="test-mhc-gq6c8/test-cluster-5gntt"
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present
E0726 15:24:09.743956   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-f9sct\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-f9sct\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-f9sct" "namespace"="test-mhc-gq6c8"
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist
error cannot retrieve mhc in ctx: MachineHealthCheck.cluster.x-k8s.io "test-mhc-rltgx" not foundI0726 15:24:10.744384   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qfc6p" "namespace"="test-mhc-s96jn" 
I0726 15:24:10.744512   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f9sct" "namespace"="test-mhc-gq6c8" 
I0726 15:24:10.744552   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fpfzd" "namespace"="test-mhc-wtdl6" 
I0726 15:24:10.744580   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rltgx" "namespace"="test-mhc-khj5p" 
I0726 15:24:10.761696   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0726 15:24:10.880553   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rltgx" "namespace"="test-mhc-khj5p" 
I0726 15:24:10.900990   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rltgx" "namespace"="test-mhc-khj5p" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
E0726 15:24:10.922362   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-khj5p/test-cluster-rk6g4"
E0726 15:24:10.922686   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-rk6g4\" not found" "controller"="cluster" "name"="test-cluster-rk6g4" "namespace"="test-mhc-khj5p"
I0726 15:24:11.028786   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fqb8b" "namespace"="test-mhc-ctr6f" 
I0726 15:24:11.082684   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0726 15:24:11.099535   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fqb8b" "namespace"="test-mhc-ctr6f" 
E0726 15:24:11.133718   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-ctr6f/test-cluster-gwr2d"
I0726 15:24:11.139232   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fqb8b" "namespace"="test-mhc-ctr6f" 
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0726 15:24:11.158498   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bxjhv" "namespace"="test-mhc-vplz6" 
inframachine created: test-mhc-machine-infra-fz252
I0726 15:24:11.173634   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-qjb4r
I0726 15:24:11.274324   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-vplz6/test-mhc-bxjhv/test-mhc-machine-qjb4r/"
E0726 15:24:11.284958   10408 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-7zzdh"
node created: test-mhc-node-7zzdh
E0726 15:24:11.285667   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7zzdh, got []"  "node"="test-mhc-node-7zzdh"
inframachine created: test-mhc-machine-infra-4dqb6
machine created: test-mhc-machine-tgs75
node created: test-mhc-node-hvfcf
E0726 15:24:11.432023   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hvfcf, got []"  "node"="test-mhc-node-hvfcf"
E0726 15:24:11.432630   10408 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-hvfcf"
I0726 15:24:11.445082   10408 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6" "noderef"="test-mhc-node-hvfcf"
I0726 15:24:11.506130   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bxjhv" "namespace"="test-mhc-vplz6" 
I0726 15:24:11.540011   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bxjhv" "namespace"="test-mhc-vplz6" 
Cleaning up nodes, machines and infra machines.
I0726 15:24:11.549496   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bxjhv" "namespace"="test-mhc-vplz6" 
I0726 15:24:11.549964   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vplz6/test-mhc-bxjhv/test-mhc-machine-qjb4r/"
I0726 15:24:11.592229   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bxjhv" "namespace"="test-mhc-vplz6" 
I0726 15:24:11.592761   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vplz6/test-mhc-bxjhv/test-mhc-machine-qjb4r/"
I0726 15:24:11.593155   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vplz6/test-mhc-bxjhv/test-mhc-machine-tgs75/"
I0726 15:24:11.621482   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bxjhv" "namespace"="test-mhc-vplz6" 
I0726 15:24:11.622019   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vplz6/test-mhc-bxjhv/test-mhc-machine-qjb4r/"
I0726 15:24:11.622401   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vplz6/test-mhc-bxjhv/test-mhc-machine-tgs75/"
I0726 15:24:11.623028   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bxjhv" "namespace"="test-mhc-vplz6" 
I0726 15:24:11.623379   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vplz6/test-mhc-bxjhv/test-mhc-machine-qjb4r/"
I0726 15:24:11.623716   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vplz6/test-mhc-bxjhv/test-mhc-machine-tgs75/"
E0726 15:24:11.624422   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-vplz6/test-cluster-7gp87"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
I0726 15:24:11.637902   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bxjhv" "namespace"="test-mhc-vplz6" 
I0726 15:24:11.745726   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
inframachine created: test-mhc-machine-infra-fcwlz
E0726 15:24:11.767844   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:11.794005   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-cwphs
I0726 15:24:11.827000   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.834019   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.835190   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.837242   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 43 lines ...
I0726 15:24:11.935536   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.937600   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.939273   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.940900   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.943004   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.944829   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
E0726 15:24:11.945608   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-8z9sn/machine-reconcile-slwgf"
I0726 15:24:11.946660   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.948498   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.950109   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.951756   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.953382   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:11.955069   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 396 lines ...
I0726 15:24:12.758615   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.760415   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.762247   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.764148   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.766113   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.767861   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
E0726 15:24:12.768358   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:12.769779   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.771743   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.773886   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.788520   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.790545   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:12.792438   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 469 lines ...
I0726 15:24:13.759635   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.761301   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.762862   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.764496   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.766105   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.767642   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
E0726 15:24:13.768621   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:13.769184   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.770733   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.772469   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.774037   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.775567   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:13.777189   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 494 lines ...
I0726 15:24:14.776421   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:14.777642   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:14.778289   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:14.779506   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:14.781150   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:14.781580   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:14.781754   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-m9l4r/test-mhc-94bh8/test-mhc-machine-cwphs/"
E0726 15:24:14.781826   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:14.790647   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:14.790899   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-m9l4r/test-mhc-94bh8/test-mhc-machine-cwphs/"
E0726 15:24:14.821386   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tmt7p, got []"  "node"="test-mhc-node-tmt7p"
node created: test-mhc-node-tmt7p
I0726 15:24:14.830362   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
inframachine created: test-mhc-machine-infra-nxqwq
I0726 15:24:14.845443   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
machine created: test-mhc-machine-ws8cr
I0726 15:24:14.850075   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 367 lines ...
I0726 15:24:15.749467   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.756286   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.758786   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.762397   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.765730   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.779178   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
E0726 15:24:15.784816   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:15.787399   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.791226   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.793542   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.795765   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.797789   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:15.808197   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 416 lines ...
I0726 15:24:16.869503   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.870740   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.872610   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.874472   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.876369   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.877480   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
E0726 15:24:16.877485   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:16.878614   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.880942   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.883212   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.885228   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.887462   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:16.889494   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 373 lines ...
I0726 15:24:17.876699   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:17.878797   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:17.889585   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:17.890718   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:17.891706   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:17.892964   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
E0726 15:24:17.894176   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:17.894217   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:17.894489   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-m9l4r/test-mhc-94bh8/test-mhc-machine-ws8cr/"
I0726 15:24:17.906544   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:17.906916   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-m9l4r/test-mhc-94bh8/test-mhc-machine-ws8cr/"
E0726 15:24:17.962696   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-9cw5n, got []"  "node"="test-mhc-node-9cw5n"
node created: test-mhc-node-9cw5n
I0726 15:24:17.976984   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
inframachine created: test-mhc-machine-infra-hrjgr
I0726 15:24:17.993106   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
machine created: test-mhc-machine-rw5c7
I0726 15:24:17.996015   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 266 lines ...
I0726 15:24:18.882923   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.885609   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.896150   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.899774   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.904513   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.907152   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
E0726 15:24:18.907478   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:18.908651   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.910277   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.911752   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.913035   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.914302   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:18.915318   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 303 lines ...
I0726 15:24:19.943419   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.944681   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.945809   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.946935   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.948029   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.950583   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
E0726 15:24:19.952419   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:19.953040   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.954190   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.955267   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.957429   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.959795   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:19.962150   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
... skipping 306 lines ...
I0726 15:24:20.953028   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:20.957383   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:20.960136   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:20.969225   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:20.970570   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:20.972660   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:20.973032   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-m9l4r/test-mhc-94bh8/test-mhc-machine-rw5c7/"
E0726 15:24:20.984854   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:20.985758   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:20.986450   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-m9l4r/test-mhc-94bh8/test-mhc-machine-rw5c7/"
E0726 15:24:21.039461   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-w2fl2, got []"  "node"="test-mhc-node-w2fl2"
node created: test-mhc-node-w2fl2
I0726 15:24:21.046195   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:21.046688   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "target"="test-mhc-m9l4r/test-mhc-94bh8/test-mhc-machine-rw5c7/test-mhc-node-w2fl2"
Cleaning up nodes, machines and infra machines.
I0726 15:24:21.058796   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-94bh8" "namespace"="test-mhc-m9l4r" 
I0726 15:24:21.059248   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-m9l4r/test-mhc-94bh8/test-mhc-machine-rw5c7/"
Cleaning up nodes, machines and infra machines.
I0726 15:24:21.125646   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-xg7wh" "namespace"="test-mhc-m9l4r" "count"=2
I0726 15:24:21.125735   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-xg7wh" "namespace"="test-mhc-m9l4r" "descendants"="Worker machines: test-mhc-machine-cwphs,test-mhc-machine-ws8cr,test-mhc-machine-rw5c7" "indirect descendants count"=1
I0726 15:24:21.129725   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-xg7wh" "namespace"="test-mhc-m9l4r" "count"=2
I0726 15:24:21.129781   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-xg7wh" "namespace"="test-mhc-m9l4r" "descendants"="Worker machines: test-mhc-machine-rw5c7,test-mhc-machine-cwphs,test-mhc-machine-ws8cr" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
... skipping 7 lines ...
I0726 15:24:21.413857   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:21.456218   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:21.537199   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:21.703853   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:21.985705   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-xg7wh" "machine"="test-mhc-machine-ws8cr" "namespace"="test-mhc-m9l4r" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-9cw5n"}
I0726 15:24:22.024974   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:22.031666   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-ws8cr\" not found" "controller"="machine" "name"="test-mhc-machine-ws8cr" "namespace"="test-mhc-m9l4r"
I0726 15:24:22.665912   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:23.032190   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:23.946845   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:24.032828   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-xg7wh" "machine"="test-mhc-machine-rw5c7" "namespace"="test-mhc-m9l4r" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-w2fl2"}
E0726 15:24:24.089631   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-rw5c7\" not found" "controller"="machine" "name"="test-mhc-machine-rw5c7" "namespace"="test-mhc-m9l4r"
E0726 15:24:25.090073   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:26.090697   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-xg7wh" "machine"="test-mhc-machine-cwphs" "namespace"="test-mhc-m9l4r" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-tmt7p"}
I0726 15:24:26.130162   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-xg7wh" "namespace"="test-mhc-m9l4r" "count"=1
I0726 15:24:26.130258   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-xg7wh" "namespace"="test-mhc-m9l4r" "descendants"="Worker machines: test-mhc-machine-cwphs" "indirect descendants count"=0
E0726 15:24:26.152772   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-cwphs\" not found" "controller"="machine" "name"="test-mhc-machine-cwphs" "namespace"="test-mhc-m9l4r"
I0726 15:24:26.507807   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.172521   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:27.179011   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:27.179419   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.202546   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:27.229399   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pgkhb, got []"  "node"="test-mhc-node-pgkhb"
node created: test-mhc-node-pgkhb
E0726 15:24:27.229765   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pgkhb, got []"  "node"="test-mhc-node-pgkhb"
I0726 15:24:27.237329   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
inframachine created: test-mhc-machine-infra-szxww
machine created: test-mhc-machine-jhjwm
I0726 15:24:27.264684   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.278176   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.283450   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.305098   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.346349   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.427669   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.590775   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:27.911945   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:28.179540   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:28.553348   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.196747   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.197592   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.204758   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.214280   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.237572   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.252851   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.258950   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:29.259251   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
node created: test-mhc-node-htpjg
E0726 15:24:29.267566   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-htpjg, got []"  "node"="test-mhc-node-htpjg"
E0726 15:24:29.268321   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-htpjg, got []"  "node"="test-mhc-node-htpjg"
inframachine created: test-mhc-machine-infra-sb467
I0726 15:24:29.293930   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.305578   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.309061   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
machine created: test-mhc-machine-tzhf5
I0726 15:24:29.322274   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:29.834611   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:30.259851   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
E0726 15:24:31.147156   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-m9l4r/test-cluster-xg7wh"
I0726 15:24:31.273753   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.292849   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.305773   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.327903   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.337695   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.357537   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:31.364903   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:31.365434   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.390514   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
E0726 15:24:31.451556   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pkfxn, got []"  "node"="test-mhc-node-pkfxn"
node created: test-mhc-node-pkfxn
I0726 15:24:31.461208   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
Cleaning up nodes, machines and infra machines.
I0726 15:24:31.484348   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.498874   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.500485   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
... skipping 2 lines ...
I0726 15:24:31.543556   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:31.561329   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-b6spx" "namespace"="test-mhc-p9hm7" "count"=2
I0726 15:24:31.561403   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-b6spx" "namespace"="test-mhc-p9hm7" "descendants"="Worker machines: test-mhc-machine-f7pls,test-mhc-machine-jhjwm,test-mhc-machine-tzhf5" "indirect descendants count"=1
I0726 15:24:31.565764   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-b6spx" "namespace"="test-mhc-p9hm7" "count"=2
I0726 15:24:31.565820   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-b6spx" "namespace"="test-mhc-p9hm7" "descendants"="Worker machines: test-mhc-machine-f7pls,test-mhc-machine-jhjwm,test-mhc-machine-tzhf5" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout
E0726 15:24:31.684898   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-c5xzz\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-c5xzz\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7"
inframachine created: test-mhc-machine-infra-rpjqd
machine created: test-mhc-machine-fkm57
E0726 15:24:32.372392   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:32.685207   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c5xzz" "namespace"="test-mhc-p9hm7" 
I0726 15:24:32.685328   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:32.705238   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0726 15:24:32.743204   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:33.373690   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-b6spx" "machine"="test-mhc-machine-f7pls" "namespace"="test-mhc-p9hm7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-pgkhb"}
E0726 15:24:33.422521   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-f7pls\" not found" "controller"="machine" "name"="test-mhc-machine-f7pls" "namespace"="test-mhc-p9hm7"
I0726 15:24:34.423200   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-b6spx" "machine"="test-mhc-machine-jhjwm" "namespace"="test-mhc-p9hm7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-htpjg"}
E0726 15:24:34.469485   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-jhjwm\" not found" "controller"="machine" "name"="test-mhc-machine-jhjwm" "namespace"="test-mhc-p9hm7"
I0726 15:24:35.470060   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-b6spx" "machine"="test-mhc-machine-tzhf5" "namespace"="test-mhc-p9hm7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-pkfxn"}
E0726 15:24:35.516473   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-tzhf5\" not found" "controller"="machine" "name"="test-mhc-machine-tzhf5" "namespace"="test-mhc-p9hm7"
I0726 15:24:36.525273   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:36.532857   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
E0726 15:24:36.533998   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
E0726 15:24:36.547006   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ckx9w, got []"  "node"="test-mhc-node-ckx9w"
node created: test-mhc-node-ckx9w
E0726 15:24:36.547709   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ckx9w, got []"  "node"="test-mhc-node-ckx9w"
I0726 15:24:36.555283   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
inframachine created: test-mhc-machine-infra-h4c8x
I0726 15:24:36.571827   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
machine created: test-mhc-machine-qrmtj
I0726 15:24:36.582080   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
E0726 15:24:36.583721   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-p9hm7/test-cluster-b6spx"
I0726 15:24:36.589535   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
E0726 15:24:37.534468   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:38.549343   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.556644   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.567263   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.574012   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.584634   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.588610   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.632111   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.648845   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.657789   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.665371   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.689651   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
node created: test-mhc-node-p8shn
E0726 15:24:38.692499   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-p8shn, got []"  "node"="test-mhc-node-p8shn"
I0726 15:24:38.702663   10408 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-qrmtj" "namespace"="test-mhc-jlmvw" "noderef"="test-mhc-node-p8shn"
I0726 15:24:38.707067   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
inframachine created: test-mhc-machine-infra-tk29r
I0726 15:24:38.728249   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
machine created: test-mhc-machine-28s8c
I0726 15:24:38.735467   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
... skipping 4 lines ...
Cleaning up nodes, machines and infra machines.
I0726 15:24:38.939527   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.940256   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-5m98x" "machine"="test-mhc-machine-28s8c" "namespace"="test-mhc-jlmvw" "cause"="noderef is nil" "node"=null
Cleaning up nodes, machines and infra machines.
I0726 15:24:38.950894   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.957716   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.958447   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-fkm57/"
I0726 15:24:38.988939   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:38.989658   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-fkm57/"
I0726 15:24:38.990680   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-qrmtj/"
I0726 15:24:39.014881   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:39.015535   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-qrmtj/"
I0726 15:24:39.016029   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-fkm57/"
I0726 15:24:39.017198   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-5m98x" "namespace"="test-mhc-jlmvw" "count"=2
I0726 15:24:39.017286   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5m98x" "namespace"="test-mhc-jlmvw" "descendants"="Worker machines: test-mhc-machine-fkm57,test-mhc-machine-qrmtj,test-mhc-machine-28s8c" "indirect descendants count"=1
I0726 15:24:39.023250   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-5m98x" "namespace"="test-mhc-jlmvw" "count"=2
I0726 15:24:39.023393   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5m98x" "namespace"="test-mhc-jlmvw" "descendants"="Worker machines: test-mhc-machine-fkm57,test-mhc-machine-qrmtj,test-mhc-machine-28s8c" "indirect descendants count"=1
I0726 15:24:39.024256   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:39.024882   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-fkm57/"
I0726 15:24:39.025285   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-qrmtj/"
I0726 15:24:39.028188   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:39.028660   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-fkm57/"
I0726 15:24:39.029021   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-jlmvw/test-mhc-pg8mg/test-mhc-machine-qrmtj/"
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_longer_than_the_NodeStartupTimeout
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine's_Node_has_gone_away
=== RUN   TestMachineHealthCheck_Reconcile/should_react_when_a_Node_transitions_to_unhealthy
E0726 15:24:39.033619   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-28s8c\" not found" "controller"="machine" "name"="test-mhc-machine-28s8c" "namespace"="test-mhc-jlmvw"
E0726 15:24:39.033716   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-pg8mg\" not found" "controller"="machinehealthcheck" "name"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw"
inframachine created: test-mhc-machine-infra-4lhvn
machine created: test-mhc-machine-kfq69
I0726 15:24:40.034108   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pg8mg" "namespace"="test-mhc-jlmvw" 
I0726 15:24:40.034203   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.034370   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-5m98x" "machine"="test-mhc-machine-fkm57" "namespace"="test-mhc-jlmvw" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-ckx9w"}
I0726 15:24:40.047280   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0726 15:24:40.076183   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.081341   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.082398   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.084125   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.085975   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
E0726 15:24:40.087555   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-fkm57\" not found" "controller"="machine" "name"="test-mhc-machine-fkm57" "namespace"="test-mhc-jlmvw"
I0726 15:24:40.087859   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.089560   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.091299   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.092978   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.094960   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:40.097002   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
... skipping 490 lines ...
I0726 15:24:41.122690   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.126411   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.128600   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.130840   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.133410   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.135295   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
E0726 15:24:41.135839   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-qrmtj\" not found" "controller"="machine" "name"="test-mhc-machine-qrmtj" "namespace"="test-mhc-jlmvw"
I0726 15:24:41.137430   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.139429   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.141358   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.143100   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.144882   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:41.146779   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
... skipping 501 lines ...
I0726 15:24:42.125263   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.127210   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.129523   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.131490   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.133328   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.135149   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
E0726 15:24:42.136448   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:42.136883   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.138382   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.140415   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.142360   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.143989   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:42.145772   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
... skipping 511 lines ...
I0726 15:24:43.142326   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.143828   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.145335   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.145922   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.147095   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.148986   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
E0726 15:24:43.149193   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:43.149342   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-cldhq/test-mhc-4hk85/test-mhc-machine-kfq69/"
I0726 15:24:43.160302   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.160535   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "target"="test-mhc-cldhq/test-mhc-4hk85/test-mhc-machine-kfq69/"
E0726 15:24:43.239483   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c5wvb, got []"  "node"="test-mhc-node-c5wvb"
node created: test-mhc-node-c5wvb
E0726 15:24:43.239940   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c5wvb, got []"  "node"="test-mhc-node-c5wvb"
I0726 15:24:43.248081   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.264080   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.272599   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.272889   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "target"="test-mhc-cldhq/test-mhc-4hk85/test-mhc-machine-kfq69/test-mhc-node-c5wvb"
I0726 15:24:43.288022   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.288413   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "target"="test-mhc-cldhq/test-mhc-4hk85/test-mhc-machine-kfq69/test-mhc-node-c5wvb"
I0726 15:24:43.288909   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.289080   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "target"="test-mhc-cldhq/test-mhc-4hk85/test-mhc-machine-kfq69/test-mhc-node-c5wvb"
Cleaning up nodes, machines and infra machines.
I0726 15:24:43.299166   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.299514   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-cldhq/test-mhc-4hk85/test-mhc-machine-kfq69/"
I0726 15:24:43.316746   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-t6drt" "namespace"="test-mhc-cldhq" "descendants"="Worker machines: test-mhc-machine-kfq69" "indirect descendants count"=1
I0726 15:24:43.321777   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-t6drt" "namespace"="test-mhc-cldhq" "descendants"="Worker machines: test-mhc-machine-kfq69" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0726 15:24:43.388773   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-bs7tj" "namespace"="test-mhc-9kwgz" "creating"=1 "need"=1
I0726 15:24:43.388823   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-bs7tj" "namespace"="test-mhc-9kwgz" 
I0726 15:24:43.401293   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-bs7tj-m2khb\"" "machineset"="mhc-ms-bs7tj" "namespace"="test-mhc-9kwgz" 
I0726 15:24:43.473343   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4hk85" "namespace"="test-mhc-cldhq" 
I0726 15:24:43.478556   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:43.492998   10408 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0726 15:24:43.509532   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:43.517122   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
E0726 15:24:44.038282   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-jlmvw/test-cluster-5m98x"
I0726 15:24:44.149800   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-t6drt" "machine"="test-mhc-machine-kfq69" "namespace"="test-mhc-cldhq" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-c5wvb"}
E0726 15:24:44.192821   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-kfq69\" not found" "controller"="machine" "name"="test-mhc-machine-kfq69" "namespace"="test-mhc-cldhq"
I0726 15:24:44.509819   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:45.202231   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:45.202828   10408 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-bs7tj" "namespace"="test-mhc-9kwgz" 
I0726 15:24:45.207025   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:45.207348   10408 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-bs7tj" "namespace"="test-mhc-9kwgz" 
I0726 15:24:45.218107   10408 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
... skipping 7 lines ...
I0726 15:24:45.237959   10408 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
I0726 15:24:45.238003   10408 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
I0726 15:24:45.510920   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:46.233822   10408 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
I0726 15:24:46.233882   10408 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.000926   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.001399   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1s" "reason"="NodeStartupTimeout" "target"="test-mhc-9kwgz/test-mhc-kcfth/mhc-ms-bs7tj-m2khb/"
I0726 15:24:47.008201   10408 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-bs7tj" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.013759   10408 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.013803   10408 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.014282   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.014583   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1s" "reason"="NodeStartupTimeout" "target"="test-mhc-9kwgz/test-mhc-kcfth/mhc-ms-bs7tj-m2khb/"
I0726 15:24:47.020248   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.020488   10408 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-bs7tj" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.020859   10408 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="Node failed to report startup in 1s" "reason"="NodeStartupTimeout" "target"="test-mhc-9kwgz/test-mhc-kcfth/mhc-ms-bs7tj-m2khb/"
I0726 15:24:47.033404   10408 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.033468   10408 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" 
I0726 15:24:47.118986   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-2bzdn" "namespace"="test-mhc-9kwgz" "count"=1
I0726 15:24:47.119043   10408 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-2bzdn" "namespace"="test-mhc-9kwgz" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-bs7tj"
I0726 15:24:47.120477   10408 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-bs7tj" "namespace"="test-mhc-9kwgz" "machine"="mhc-ms-bs7tj-m2khb"
I0726 15:24:47.124458   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kcfth" "namespace"="test-mhc-9kwgz" 
... skipping 11 lines ...
I0726 15:24:47.326775   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.328233   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.329490   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.330030   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.331215   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.333213   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
E0726 15:24:47.333923   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
I0726 15:24:47.363865   10408 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "remediation request name"="test-mhc-machine-zcbdp" "target"="test-mhc-cv9g7/test-mhc-vnc42/test-mhc-machine-zcbdp/"
I0726 15:24:47.377804   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
E0726 15:24:47.412633   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gnjqx, got []"  "node"="test-mhc-node-gnjqx"
E0726 15:24:47.413076   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gnjqx, got []"  "node"="test-mhc-node-gnjqx"
E0726 15:24:47.413110   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gnjqx, got []"  "node"="test-mhc-node-gnjqx"
node created: test-mhc-node-gnjqx
I0726 15:24:47.423166   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.448962   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.458779   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.463600   10408 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request"  "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "remediation request name"="test-mhc-machine-zcbdp" "target"="test-mhc-cv9g7/test-mhc-vnc42/test-mhc-machine-zcbdp/test-mhc-node-gnjqx"
I0726 15:24:47.515395   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
Cleaning up nodes, machines and infra machines.
I0726 15:24:47.536561   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.539613   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.543785   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnc42" "namespace"="test-mhc-cv9g7" 
I0726 15:24:47.551943   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-l8s9m" "namespace"="test-mhc-cv9g7" "descendants"="Worker machines: test-mhc-machine-zcbdp" "indirect descendants count"=1
... skipping 322 lines ...
I0726 15:24:48.327621   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.329607   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.331275   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.333187   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.334306   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-2bzdn" "machine"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz" "cause"="cluster is being deleted" "node"=null
I0726 15:24:48.335088   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
E0726 15:24:48.337134   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-cldhq/test-cluster-t6drt"
I0726 15:24:48.337407   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.341657   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.344182   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.345871   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.347564   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.349643   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
... skipping 3 lines ...
I0726 15:24:48.357998   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.359701   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.361670   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.363427   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.365581   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.367686   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
E0726 15:24:48.370115   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-bs7tj-m2khb\" not found" "controller"="machine" "name"="mhc-ms-bs7tj-m2khb" "namespace"="test-mhc-9kwgz"
I0726 15:24:48.370257   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.372182   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.374143   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.376340   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.378052   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:48.380109   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
... skipping 541 lines ...
I0726 15:24:49.427432   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.429294   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.431137   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.433274   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.435184   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.436988   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
E0726 15:24:49.437445   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-zcbdp\" not found" "controller"="machine" "name"="test-mhc-machine-zcbdp" "namespace"="test-mhc-cv9g7"
I0726 15:24:49.438648   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.440263   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.441824   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.443639   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.445309   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:49.446774   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
... skipping 516 lines ...
I0726 15:24:50.444384   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.445833   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.446215   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.447808   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.449759   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.451123   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
E0726 15:24:50.451462   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
I0726 15:24:50.455432   10408 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request"  "message"="Node failed to report startup in 1ms" "reason"="NodeStartupTimeout" "remediation request name"="test-mhc-machine-5qn9b" "target"="test-mhc-94vgk/test-mhc-v89nm/test-mhc-machine-5qn9b/"
I0726 15:24:50.467874   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
E0726 15:24:50.521214   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jcp5v, got []"  "node"="test-mhc-node-jcp5v"
E0726 15:24:50.521591   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jcp5v, got []"  "node"="test-mhc-node-jcp5v"
E0726 15:24:50.521646   10408 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jcp5v, got []"  "node"="test-mhc-node-jcp5v"
node created: test-mhc-node-jcp5v
I0726 15:24:50.530137   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.552439   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.567096   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.572570   10408 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request"  "message"="Condition Ready on node is reporting status Unknown for more than 5m0s" "reason"="UnhealthyNode" "remediation request name"="test-mhc-machine-5qn9b" "target"="test-mhc-94vgk/test-mhc-v89nm/test-mhc-machine-5qn9b/test-mhc-node-jcp5v"
I0726 15:24:50.596872   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.605374   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.628814   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
Cleaning up nodes, machines and infra machines.
I0726 15:24:50.639905   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
I0726 15:24:50.645422   10408 machinehealthcheck_controller.go:379] controllers/MachineHealthCheck "msg"="Target has failed health check, creating an external remediation request"  "message"="" "reason"="NodeNotFound" "remediation request name"="test-mhc-machine-5qn9b" "target"="test-mhc-94vgk/test-mhc-v89nm/test-mhc-machine-5qn9b/"
I0726 15:24:50.659126   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-xtz5m" "namespace"="test-mhc-94vgk" "descendants"="Worker machines: test-mhc-machine-5qn9b" "indirect descendants count"=1
I0726 15:24:50.665347   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-xtz5m" "namespace"="test-mhc-94vgk" "descendants"="Worker machines: test-mhc-machine-5qn9b" "indirect descendants count"=1
I0726 15:24:50.665605   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
E0726 15:24:50.673032   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-v89nm\" not found" "controller"="machinehealthcheck" "name"="test-mhc-v89nm" "namespace"="test-mhc-94vgk"
--- PASS: TestMachineHealthCheck_Reconcile (41.13s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.07s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.03s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.20s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist (1.05s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones (0.24s)
... skipping 10 lines ...
    --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s)
        machinehealthcheck_controller_test.go:933: skipping until made stable
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (0.43s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (3.11s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0726 15:24:50.677861   10408 machinehealthcheck_controller.go:416]  "msg"="expected a Cluster" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Cluster_in_the_same_namespace
=== RUN   TestClusterToMachineHealthCheck/when_2_MachineHealthChecks_exists_for_the_Cluster_in_the_same_namespace
=== RUN   TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_the_same_namespace
=== RUN   TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_another_namespace
--- PASS: TestClusterToMachineHealthCheck (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Cluster_in_the_same_namespace (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_2_MachineHealthChecks_exists_for_the_Cluster_in_the_same_namespace (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_the_same_namespace (0.00s)
    --- PASS: TestClusterToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_another_Cluster_in_another_namespace (0.00s)
=== RUN   TestMachineToMachineHealthCheck
=== RUN   TestMachineToMachineHealthCheck/when_the_object_passed_isn't_a_machine
E0726 15:24:50.678909   10408 machinehealthcheck_controller.go:445]  "msg"="expected a Machine" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace
--- PASS: TestMachineToMachineHealthCheck (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_the_object_passed_isn't_a_machine (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace (0.00s)
=== RUN   TestNodeToMachineHealthCheck
=== RUN   TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node
E0726 15:24:50.680026   10408 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0726 15:24:50.680184   10408 machinehealthcheck_controller.go:480]  "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node node1, got []"  "node"="node1"
=== RUN   TestNodeToMachineHealthCheck/when_two_Machines_exist_for_the_Node
E0726 15:24:50.680463   10408 machinehealthcheck_controller.go:480]  "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node node1, got [machine1 machine2]"  "node"="node1"
=== RUN   TestNodeToMachineHealthCheck/when_no_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_two_MachineHealthChecks_exist_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node,_but_not_in_the_Machine's_cluster
--- PASS: TestNodeToMachineHealthCheck (0.00s)
    --- PASS: TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node (0.00s)
... skipping 31 lines ...
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_nil (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_not_an_int_or_percentage (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_an_int (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_a_40%_(of_5) (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_a_60%_(of_7) (0.00s)
=== RUN   TestPatchTargets
I0726 15:24:50.682175   10408 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0726 15:24:50.682546   10408 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0726 15:24:50.683727   10408 machinehealthcheck_controller.go:320]  "msg"="failed to patch healthy machine status for machine" "error"="machines.cluster.x-k8s.io \"machine1\" not found"  "machine"="machine1"
--- PASS: TestPatchTargets (0.00s)
=== RUN   TestGetTargetsFromMHC
=== RUN   TestGetTargetsFromMHC/with_no_matching_machines
=== RUN   TestGetTargetsFromMHC/when_a_machine's_node_is_missing
=== RUN   TestGetTargetsFromMHC/when_a_machine's_labels_do_not_match_the_selector
=== RUN   TestGetTargetsFromMHC/with_multiple_machines,_should_match_correct_nodes
... skipping 26 lines ...
--- PASS: TestMachineSetOwnerReference (0.00s)
    --- PASS: TestMachineSetOwnerReference/should_add_cluster_owner_reference_to_machine_set (0.00s)
    --- PASS: TestMachineSetOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_deployment (0.00s)
=== RUN   TestMachineSetReconcile
=== RUN   TestMachineSetReconcile/ignore_machine_sets_marked_for_deletion
=== RUN   TestMachineSetReconcile/records_event_if_reconcile_fails
E0726 15:24:50.690652   10408 machineset_controller.go:151]  "msg"="Failed to reconcile MachineSet" "error"="failed to calculate MachineSet's Status: failed to calculate status for MachineSet default/machineset1: invalid label key \"--$-invalid\": name part must consist of alphanumeric characters, '-', '_' or '.', and must start and end with an alphanumeric character (e.g. 'MyName',  or 'my.name',  or '123-abc', regex used for validation is '([A-Za-z0-9][-A-Za-z0-9_.]*)?[A-Za-z0-9]')" "machineset"="machineset1" "namespace"="default" 
--- PASS: TestMachineSetReconcile (0.00s)
    --- PASS: TestMachineSetReconcile/ignore_machine_sets_marked_for_deletion (0.00s)
    --- PASS: TestMachineSetReconcile/records_event_if_reconcile_fails (0.00s)
=== RUN   TestMachineSetToMachines
=== RUN   TestMachineSetToMachines/should_return_empty_request_when_controller_is_set
=== RUN   TestMachineSetToMachines/should_return_nil_if_machine_has_no_owner_reference
... skipping 8 lines ...
--- PASS: TestAdoptOrphan (0.00s)
=== RUN   TestHasMatchingLabels
=== RUN   TestHasMatchingLabels/machine_set_and_machine_have_matching_labels
=== RUN   TestHasMatchingLabels/machine_set_and_machine_do_not_have_matching_labels
=== RUN   TestHasMatchingLabels/machine_set_has_empty_selector
=== RUN   TestHasMatchingLabels/machine_set_has_bad_selector
E0726 15:24:50.692307   10408 machineset_controller.go:569]  "msg"="Unable to convert selector" "error"="\"bad-operator\" is not a valid pod selector operator" "machine"="match" "machineset"="" "namespace"="" 
--- PASS: TestHasMatchingLabels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_do_not_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_empty_selector (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_bad_selector (0.00s)
=== RUN   TestMachineToDelete
... skipping 57 lines ...
=== RUN   TestGinkgoSuite
Running Suite: Controllers Suite
================================
Random Seed: 1627313034
Will run 16 of 16 specs

•E0726 15:24:50.822084   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-chkhz\" not found" "controller"="cluster" "name"="test1-chkhz" "namespace"="default"
I0726 15:24:51.452186   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-xtz5m" "machine"="test-mhc-machine-5qn9b" "namespace"="test-mhc-94vgk" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-jcp5v"}
E0726 15:24:51.493979   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-5qn9b\" not found" "controller"="machine" "name"="test-mhc-machine-5qn9b" "namespace"="test-mhc-94vgk"
I0726 15:24:51.673397   10408 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v89nm" "namespace"="test-mhc-94vgk" 
•I0726 15:24:51.939137   10408 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-rlbdd" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0726 15:24:52.053772   10408 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-rlbdd" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0726 15:24:52.058801   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to find a CustomResourceDefinition for /, Kind= with contract \"cluster.x-k8s.io/v1alpha3\"" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"
E0726 15:24:53.075878   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-rlbdd: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"
•E0726 15:24:54.093149   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-9kwgz/test-cluster-2bzdn"
E0726 15:24:54.107104   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-cv9g7/test-cluster-l8s9m"
E0726 15:24:54.119883   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-tg7zb\" not found" "controller"="cluster" "name"="test3-tg7zb" "namespace"="default"
E0726 15:24:55.120724   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-rlbdd: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"
E0726 15:24:56.132634   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-rlbdd: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"
•E0726 15:24:57.146452   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-94vgk/test-cluster-xtz5m"
E0726 15:24:57.151372   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-hn79x: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-hn79x" "namespace"="default"
E0726 15:24:57.574512   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-qjb4r\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-qjb4r" "namespace"="test-mhc-vplz6"
E0726 15:24:58.152406   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-rlbdd: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"
E0726 15:24:59.166191   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-hn79x: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-hn79x" "namespace"="default"
•E0726 15:25:00.166985   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-rlbdd: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"
E0726 15:25:00.691947   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-7gp87\" for machine \"test-mhc-machine-tgs75\" in namespace \"test-mhc-vplz6\": Cluster.cluster.x-k8s.io \"test-cluster-7gp87\" not found" "controller"="machine" "name"="test-mhc-machine-tgs75" "namespace"="test-mhc-vplz6"
E0726 15:25:01.168038   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-hn79x: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-hn79x" "namespace"="default"
E0726 15:25:02.178433   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-rlbdd: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"
I0726 15:25:02.262368   10408 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-8mzwh" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0726 15:25:02.377953   10408 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-8mzwh" "namespace"="default" "noderef"="id-node-1"
E0726 15:25:02.401809   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to find a CustomResourceDefinition for /, Kind= with contract \"cluster.x-k8s.io/v1alpha3\"" "controller"="machine" "name"="test6-8mzwh" "namespace"="default"
E0726 15:25:03.179326   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-hn79x: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-hn79x" "namespace"="default"
I0726 15:25:03.416181   10408 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-8mzwh" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0726 15:25:03.416816   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to find a CustomResourceDefinition for /, Kind= with contract \"cluster.x-k8s.io/v1alpha3\"" "controller"="machine" "name"="test6-8mzwh" "namespace"="default"
E0726 15:25:04.185256   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-rlbdd: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"

------------------------------
• [SLOW TEST:5.046 seconds]
Cluster Reconciler
/home/prow/go/src/sigs.k8s.io/cluster-api/controllers/cluster_controller_test.go:45
  Should successfully set Status.ControlPlaneInitialized on the cluster object if controlplane is ready
... skipping 2 lines ...
I0726 15:25:04.332269   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-nqlzk" "namespace"="ms-test" "creating"=2 "need"=2
I0726 15:25:04.332320   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-nqlzk" "namespace"="ms-test" 
I0726 15:25:04.350660   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-nqlzk-nxpq5\"" "machineset"="ms-nqlzk" "namespace"="ms-test" 
I0726 15:25:04.350741   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-nqlzk" "namespace"="ms-test" 
I0726 15:25:04.370504   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-nqlzk-p8dkc\"" "machineset"="ms-nqlzk" "namespace"="ms-test" 
I0726 15:25:04.417478   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-g498r" "machine"="test6-8mzwh" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"76405b9c-d452-4d38-a716-0080c01e63e3","apiVersion":"v1"}
E0726 15:25:04.445200   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-8mzwh\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-8mzwh" "namespace"="default"
I0726 15:25:04.479267   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-nqlzk" "namespace"="ms-test" "creating"=1 "need"=2
I0726 15:25:04.479338   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-nqlzk" "namespace"="ms-test" 
I0726 15:25:04.497118   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-nqlzk-r7xw6\"" "machineset"="ms-nqlzk" "namespace"="ms-test" 
E0726 15:25:04.741747   10408 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-nqlzk-r7xw6-4qzkx for machine ms-test/ms-nqlzk-r7xw6: the cache is not started, can not read objects" "machineset"="ms-nqlzk" "namespace"="ms-test" 
E0726 15:25:04.872107   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="ms-test/test-cluster"
•I0726 15:25:04.878208   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0726 15:25:04.878950   10408 machine_controller_phases.go:219]  "msg"="Bootstrap provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0726 15:25:04.878993   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0726 15:25:04.879466   10408 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0726 15:25:04.879493   10408 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0726 15:25:04.879890   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
... skipping 13 lines ...
I0726 15:25:04.886834   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
•I0726 15:25:04.888015   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0726 15:25:04.888550   10408 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0726 15:25:04.889034   10408 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0726 15:25:04.889083   10408 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0726 15:25:04.889461   10408 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0726 15:25:04.890531   10408 machine_controller.go:494]  "msg"="Error creating a remote client while deleting Machine, won't retry" "error"="failed to create REST configuration for Cluster default/test-cluster: invalid configuration: no configuration has been provided" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node" 
•I0726 15:25:04.964653   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0726 15:25:04.964719   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:04.974992   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-2bj6z-6657c7fddb-nrp85\"" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:04.975063   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:04.992091   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-2bj6z-6657c7fddb-ff87r\"" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:05.057174   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0726 15:25:05.057221   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:05.072802   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-2bj6z-6657c7fddb-8rq5j\"" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:05.072884   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:05.086823   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-2bj6z-6657c7fddb-spffx\"" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:05.158864   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0726 15:25:05.158929   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
I0726 15:25:05.169537   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-2bj6z-6657c7fddb-wm2mc\"" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" 
E0726 15:25:05.186214   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-hn79x: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-hn79x" "namespace"="default"
I0726 15:25:05.258079   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0726 15:25:05.258132   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" 
I0726 15:25:05.276320   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-2bj6z-cdfc6fd6c-lv9zj\"" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" 
E0726 15:25:05.445843   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster\" for machine \"ms-nqlzk-p8dkc\" in namespace \"ms-test\": Cluster.cluster.x-k8s.io \"test-cluster\" not found" "controller"="machine" "name"="ms-nqlzk-p8dkc" "namespace"="ms-test"
E0726 15:25:05.489143   10408 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-2bj6z-cdfc6fd6c-lv9zj-qr956 for machine md-test/md-2bj6z-cdfc6fd6c-lv9zj: the cache is not started, can not read objects" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" 
I0726 15:25:05.525921   10408 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0726 15:25:05.526088   10408 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0726 15:25:05.535128   10408 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "machine"="md-2bj6z-6657c7fddb-spffx"
I0726 15:25:05.647743   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0726 15:25:05.647799   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" 
I0726 15:25:05.660838   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-2bj6z-cdfc6fd6c-6zhm5\"" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" 
... skipping 5 lines ...
I0726 15:25:05.985488   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-2bj6z-cdfc6fd6c-4tc8r\"" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" 
I0726 15:25:06.116077   10408 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0726 15:25:06.116135   10408 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0726 15:25:06.122262   10408 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-2bj6z-6657c7fddb" "namespace"="md-test" "machine"="md-2bj6z-6657c7fddb-wm2mc"
I0726 15:25:06.186840   10408 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-g498r" "namespace"="default" "count"=1
I0726 15:25:06.186916   10408 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-g498r" "namespace"="default" "descendants"="Control plane machines: test6-8mzwh" "indirect descendants count"=0
E0726 15:25:06.192181   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-rlbdd: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-rlbdd" "namespace"="default"
I0726 15:25:06.285521   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0726 15:25:06.285584   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" 
I0726 15:25:06.311284   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-2bj6z-74d45c49c5-d9wzg\"" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" 
I0726 15:25:06.446638   10408 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-g498r" "machine"="test6-8mzwh" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"76405b9c-d452-4d38-a716-0080c01e63e3","apiVersion":"v1"}
E0726 15:25:06.447341   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-8mzwh\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-8mzwh" "namespace"="default"
I0726 15:25:06.521400   10408 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2
I0726 15:25:06.521448   10408 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0726 15:25:06.526284   10408 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "machine"="md-2bj6z-cdfc6fd6c-lv9zj"
I0726 15:25:06.550449   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=2
I0726 15:25:06.550516   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" 
I0726 15:25:06.567786   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-2bj6z-74d45c49c5-5sl4m\"" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" 
I0726 15:25:06.775405   10408 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0726 15:25:06.775475   10408 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0726 15:25:06.780814   10408 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "machine"="md-2bj6z-cdfc6fd6c-4tc8r"
I0726 15:25:06.892939   10408 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0726 15:25:06.893004   10408 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" 
I0726 15:25:06.906223   10408 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-2bj6z-74d45c49c5-fbcmd\"" "machineset"="md-2bj6z-74d45c49c5" "namespace"="md-test" 
E0726 15:25:07.020717   10408 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinedeployments.cluster.x-k8s.io \"md-2bj6z\" not found" "controller"="machinedeployment" "name"="md-2bj6z" "namespace"="md-test"
I0726 15:25:07.025068   10408 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=0
I0726 15:25:07.025123   10408 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
E0726 15:25:07.027398   10408 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="md-test/test-cluster"
•

Ran 16 of 16 Specs in 16.336 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.34s)
PASS
Tearing down test suite
E0726 15:25:07.030485   10408 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0726 15:25:07.030564   10408 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-582224467/tls.crt: no such file or directory"  
I0726 15:25:07.030499   10408 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0726 15:25:07.030603   10408 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0726 15:25:07.030646   10408 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0726 15:25:07.030675   10408 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0726 15:25:07.030696   10408 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0726 15:25:07.030729   10408 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0726 15:25:07.030749   10408 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0726 15:25:07.032248   10408 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-2bj6z-cdfc6fd6c" "namespace"="md-test" "machine"="md-2bj6z-cdfc6fd6c-6zhm5"
E0726 15:25:07.032749   10408 event.go:272] Unable to write event: 'Post http://127.0.0.1:35199/api/v1/namespaces/md-test/events: dial tcp 127.0.0.1:35199: connect: connection refused' (may retry after sleeping)
E0726 15:25:07.062875   10408 reflector.go:309] pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:105: Failed to watch *v1.Node: Get http://127.0.0.1:35199/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1204&timeout=10s&timeoutSeconds=540&watch=true: dial tcp 127.0.0.1:35199: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	72.432s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 265 lines ...
I0726 15:24:07.304130   10771 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0726 15:24:07.851715   10771 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0726 15:24:07.865555   10771 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="cluster" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0726 15:24:07.965929   10771 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0726 15:24:07.965991   10771 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I0726 15:24:08.113604   10771 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0726 15:24:10.151116   10771 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-l8vhs/test-cluster"
•E0726 15:24:10.620106   10771 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-zslqj/test-cluster"
•E0726 15:24:11.168042   10771 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:33983/?timeout=50ms: dial tcp 127.0.0.1:33983: connect: connection refused"  "cluster"="cluster-cache-test-lg2ff/test-cluster"
•E0726 15:24:11.378185   10771 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0726 15:24:11.378252   10771 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-669851058/tls.crt: no such file or directory"  
I0726 15:24:11.378336   10771 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0726 15:24:11.417976   10771 reflector.go:309] pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:105: Failed to watch *v1alpha3.Cluster: Get http://127.0.0.1:43699/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:43699: connect: connection refused


Ran 5 of 5 Specs in 15.346 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (15.35s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	15.487s
?   	sigs.k8s.io/cluster-api/controllers/remote/fake	[no test files]
?   	sigs.k8s.io/cluster-api/controlplane/kubeadm	[no test files]
=== RUN   TestKubeadmControlPlaneDefault
... skipping 208 lines ...
=== RUN   TestReconcileNoClusterOwnerRef
I0726 15:24:16.642517   11574 controller.go:133]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.00s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0726 15:24:16.643457   11574 controller.go:129]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="clusters.cluster.x-k8s.io \"foo\" not found" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoCluster (0.00s)
=== RUN   TestReconcilePaused
I0726 15:24:16.643874   11574 controller.go:139]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0726 15:24:16.644026   11574 controller.go:139]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
--- FAIL: TestReconcileClusterNoEndpoints (0.00s)
    controller_test.go:427: 
        Unexpected error:
            <*errors.withStack | 0xc000773420>: {
                error: {
                    cause: {
                        error: {
                            cause: {
                                ErrStatus: {
                                    TypeMeta: {Kind: "", APIVersion: ""},
                                    ListMeta: {
                                        SelfLink: "",
                                        ResourceVersion: "",
... skipping 11 lines ...
                                        Causes: nil,
                                        RetryAfterSeconds: 0,
                                    },
                                    Code: 404,
                                },
                            },
                            msg: "failed to retrieve kubeconfig secret for Cluster test/foo",
                        },
                        stack: [0x1464401, 0x1734009, 0x172d97f, 0x174564c, 0x50fb29, 0x461751],
                    },
                    msg: "failed to create metadata only client",
                },
                stack: [0x172dc2b, 0x174564c, 0x50fb29, 0x461751],
            }
            failed to create metadata only client: failed to retrieve kubeconfig secret for Cluster test/foo: secrets "foo-kubeconfig" not found
        occurred
=== RUN   TestKubeadmControlPlaneReconciler_adoption
=== RUN   TestKubeadmControlPlaneReconciler_adoption/adopts_existing_Machines
I0726 15:24:16.647588   11574 controller.go:263]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-7ywoyy" "kubeadmControlPlane"="kcp-foo-7ywoyy" "namespace"="test" 
=== RUN   TestKubeadmControlPlaneReconciler_adoption/adopts_v1alpha2_cluster_secrets
I0726 15:24:19.157381   11574 controller.go:263]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-mg5tej" "kubeadmControlPlane"="kcp-foo-mg5tej" "namespace"="test" 
... skipping 4 lines ...
--- PASS: TestKubeadmControlPlaneReconciler_adoption (7.28s)
    --- PASS: TestKubeadmControlPlaneReconciler_adoption/adopts_existing_Machines (2.51s)
    --- PASS: TestKubeadmControlPlaneReconciler_adoption/adopts_v1alpha2_cluster_secrets (1.83s)
    --- PASS: TestKubeadmControlPlaneReconciler_adoption/Deleted_KubeadmControlPlanes_don't_adopt_machines (1.46s)
    --- PASS: TestKubeadmControlPlaneReconciler_adoption/refuses_to_adopt_Machines_that_are_more_than_one_version_old (1.47s)
=== RUN   TestReconcileInitializeControlPlane
--- FAIL: TestReconcileInitializeControlPlane (0.00s)
    controller_test.go:897: 
        Unexpected error:
            <*errors.withStack | 0xc0008ca880>: {
                error: {
                    cause: {
                        error: {
                            cause: {
                                ErrStatus: {
                                    TypeMeta: {Kind: "", APIVersion: ""},
                                    ListMeta: {
                                        SelfLink: "",
                                        ResourceVersion: "",
... skipping 11 lines ...
                                        Causes: nil,
                                        RetryAfterSeconds: 0,
                                    },
                                    Code: 404,
                                },
                            },
                            msg: "failed to retrieve kubeconfig secret for Cluster test/foo",
                        },
                        stack: [0x1464401, 0x1734009, 0x172d97f, 0x174838b, 0x50fb29, 0x461751],
                    },
                    msg: "failed to create metadata only client",
                },
                stack: [0x172dc2b, 0x174838b, 0x50fb29, 0x461751],
            }
            failed to create metadata only client: failed to retrieve kubeconfig secret for Cluster test/foo: secrets "foo-kubeconfig" not found
        occurred
=== RUN   TestKubeadmControlPlaneReconciler_updateCoreDNS
=== RUN   TestKubeadmControlPlaneReconciler_updateCoreDNS/updates_configmaps_and_deployments_successfully
=== RUN   TestKubeadmControlPlaneReconciler_updateCoreDNS/returns_no_error_when_no_ClusterConfiguration_is_specified
=== RUN   TestKubeadmControlPlaneReconciler_updateCoreDNS/should_not_return_an_error_when_there_is_no_CoreDNS_configmap
=== RUN   TestKubeadmControlPlaneReconciler_updateCoreDNS/should_not_return_an_error_when_there_is_no_CoreDNS_deployment
... skipping 178 lines ...
    --- PASS: TestSelectMachineForScaleDown/when_there_is_an_up_to_date_machine_with_delete_annotation,_while_there_are_any_outdated_machines_without_annotatio_that_still_exist,_it_returns_oldest_marked_machine_first (0.00s)
=== RUN   TestPreflightChecks
=== RUN   TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass
=== RUN   TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue
I0726 15:24:27.336439   11574 scale.go:173]  "msg"="Waiting for machines to be deleted" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "Machines"=""
=== RUN   TestPreflightChecks/control_plane_with_an_unhealthy_machine_condition_should_requeue
I0726 15:24:27.336623   11574 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "failures"="machine  reports APIServerPodHealthy condition is false (Error, )"
=== RUN   TestPreflightChecks/control_plane_with_an_healthy_machine_and_an_healthy_kcp_condition_should_pass
--- PASS: TestPreflightChecks (0.00s)
    --- PASS: TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass (0.00s)
    --- PASS: TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue (0.00s)
    --- PASS: TestPreflightChecks/control_plane_with_an_unhealthy_machine_condition_should_requeue (0.00s)
    --- PASS: TestPreflightChecks/control_plane_with_an_healthy_machine_and_an_healthy_kcp_condition_should_pass (0.00s)
... skipping 18 lines ...
=== RUN   TestAPIs
Running Suite: Controller Suite
===============================
Random Seed: 1627313045
Will run 1 of 1 specs

E0726 15:24:27.382015   11574 controller.go:129]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-nba754\" not found" "kubeadmControlPlane"="kcp-foo-nba754" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.042 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.04s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0726 15:24:27.383335   11574 controller.go:263]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-m9spah" "kubeadmControlPlane"="kcp-foo-m9spah" "namespace"="test" 
I0726 15:24:28.899498   11574 controller.go:348]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-m9spah" "kubeadmControlPlane"="kcp-foo-m9spah" "namespace"="test" "needRollout"=["kcp-foo-m9spah-dcf2d"]
I0726 15:24:28.899692   11574 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-m9spah" "kubeadmControlPlane"="kcp-foo-m9spah" "namespace"="test" "failures"="[machine kcp-foo-m9spah-fdqlk does not have APIServerPodHealthy condition, machine kcp-foo-m9spah-fdqlk does not have ControllerManagerPodHealthy condition, machine kcp-foo-m9spah-fdqlk does not have SchedulerPodHealthy condition, machine kcp-foo-m9spah-fdqlk does not have EtcdPodHealthy condition, machine kcp-foo-m9spah-fdqlk does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (1.52s)
FAIL
I0726 15:24:28.900558   11574 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0726 15:24:28.900795   11574 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0726 15:24:28.900866   11574 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-911829154/tls.crt: no such file or directory"  
FAIL	sigs.k8s.io/cluster-api/controlplane/kubeadm/controllers	23.663s
I0726 15:24:14.614573   11511 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0726 15:24:14.614677   11511 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0726 15:24:14.614702   11511 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0726 15:24:14.614714   11511 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0726 15:24:14.614771   11511 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Machine"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
I0726 15:24:14.614784   11511 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
... skipping 51 lines ...
==================================
Random Seed: 1627313044
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.001 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestControlPlane (0.00s)
=== RUN   TestHasUnhealthyMachine
--- PASS: TestHasUnhealthyMachine (0.00s)
=== RUN   TestNewFailureDomainPicker
=== RUN   TestNewFailureDomainPicker/simple
=== RUN   TestNewFailureDomainPicker/no_machines
... skipping 111 lines ...
=======================================
Random Seed: 1627313044
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.001 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestMachineCollection (0.00s)
=== RUN   TestUpdateEtcdConditions
=== RUN   TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines
=== RUN   TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition
... skipping 297 lines ...
    --- PASS: TestUpdateKubeProxyImageInfo/returns_error_if_image_repository_is_invalid (0.00s)
    --- PASS: TestUpdateKubeProxyImageInfo/does_not_update_image_repository_when_no_kube-proxy_update_is_requested (0.00s)
=== RUN   TestRemoveMachineFromKubeadmConfigMap
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_find_kubeadm-config_for_Kubernetes_version_<_1.22.0
E0726 15:24:17.040092   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:24:25.363171   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:24:34.349202   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:24:45.479522   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:25:01.952757   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:25:14.961412   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:25:32.608963   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:25:53.532375   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:26:24.549010   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0726 15:27:09.706467   11511 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0
--- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s)
... skipping 72 lines ...
=== RUN   TestClusterStatus/returns_cluster_status_with_kubeadm_config
--- PASS: TestClusterStatus (0.00s)
    --- PASS: TestClusterStatus/returns_cluster_status (0.00s)
    --- PASS: TestClusterStatus/returns_cluster_status_with_kubeadm_config (0.00s)
PASS
I0726 15:27:09.713424   11511 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0726 15:27:09.713515   11511 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0726 15:27:09.713538   11511 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-076556361/tls.crt: no such file or directory"  
E0726 15:27:09.713765   11511 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0726 15:27:09.713804   11511 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-076556361/tls.crt: no such file or directory"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	184.872s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
PASS
... skipping 287 lines ...
I0726 15:24:23.875516   11835 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0726 15:24:23.876717   11835 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0726 15:24:23.977182   11835 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0726 15:24:24.078384   11835 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0726 15:24:24.078450   11835 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0726 15:24:24.178896   11835 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-pke7y3"} 
E0726 15:24:24.215315   11835 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
•I0726 15:24:25.295661   11835 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-xkpyuq"} 
E0726 15:24:25.347675   11835 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
•E0726 15:24:26.422106   11835 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get data field from the resource" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
E0726 15:24:27.453540   11835 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
•E0726 15:24:28.594808   11835 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
•E0726 15:24:29.655079   11835 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset2\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset2" "namespace"="default"
•I0726 15:24:30.669568   11835 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0726 15:24:30.669703   11835 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0726 15:24:30.669710   11835 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0726 15:24:30.669744   11835 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0726 15:24:30.669786   11835 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-859929757/tls.crt: no such file or directory"  
E0726 15:24:30.672100   11835 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="Patch http://127.0.0.1:44177/apis/addons.cluster.x-k8s.io/v1alpha3/namespaces/default/clusterresourcesets/test-clusterresourceset/status: read tcp 127.0.0.1:59514-\u003e127.0.0.1:44177: read: connection reset by peer" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"


Ran 5 of 5 Specs in 18.236 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (18.24s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/addons/controllers	18.334s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
... skipping 61 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0726 15:24:17.556926   12168 machinepool_controller_phases.go:237]  "msg"="MachinePool infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureConfig \"infra-config1\" for MachinePool \"machinepool-test\" in namespace \"default\", requeuing: failed to retrieve InfrastructureConfig external object \"default\"/\"infra-config1\": infrastructureconfigs.infrastructure.cluster.x-k8s.io \"infra-config1\" not found" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
=== RUN   TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused
--- PASS: TestReconcileMachinePoolInfrastructure (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestMachinePoolFinalizer
... skipping 92 lines ...
I0726 15:24:27.720172   12168 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0726 15:24:27.736773   12168 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0726 15:24:27.738575   12168 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0726 15:24:27.767458   12168 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0726 15:24:27.793001   12168 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinepool" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0726 15:24:27.800447   12168 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••E0726 15:24:27.802923   12168 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0726 15:24:27.802952   12168 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-132227378/tls.crt: no such file or directory"  
E0726 15:24:27.802964   12168 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0726 15:24:27.802975   12168 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-132227378/tls.crt: no such file or directory"  
I0726 15:24:27.803198   12168 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 9 of 9 Specs in 10.314 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (10.31s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	10.524s
?   	sigs.k8s.io/cluster-api/exp/util	[no test files]
?   	sigs.k8s.io/cluster-api/feature	[no test files]
?   	sigs.k8s.io/cluster-api/hack/boilerplate/test	[no test files]
... skipping 266 lines ...
--- PASS: TestGetFirstReasonAndMessage (0.00s)
=== RUN   TestNewConditionsGroup
--- PASS: TestNewConditionsGroup (0.00s)
=== RUN   TestMergeRespectPriority
=== RUN   TestMergeRespectPriority/aggregate_nil_list_return_nil
=== RUN   TestMergeRespectPriority/aggregate_empty_list_return_nil
=== RUN   TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error
=== RUN   TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning
=== RUN   TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info
=== RUN   TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info
=== RUN   TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown
=== RUN   TestMergeRespectPriority/nil_conditions_are_ignored
--- PASS: TestMergeRespectPriority (0.00s)
    --- PASS: TestMergeRespectPriority/aggregate_nil_list_return_nil (0.00s)
    --- PASS: TestMergeRespectPriority/aggregate_empty_list_return_nil (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown (0.00s)
    --- PASS: TestMergeRespectPriority/nil_conditions_are_ignored (0.00s)
=== RUN   TestNewPatch
=== RUN   TestNewPatch/No_changes_return_empty_patch
... skipping 204 lines ...
I0726 15:24:44.710682   15000 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=39403
I0726 15:24:44.710919   15000 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••I0726 15:24:45.692111   15000 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 14 of 14 Specs in 6.412 seconds
SUCCESS! -- 14 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestPatch (6.41s)
=== RUN   TestToUnstructured
=== RUN   TestToUnstructured/with_a_typed_object
=== RUN   TestToUnstructured/with_an_unstructured_object
--- PASS: TestToUnstructured (0.00s)
    --- PASS: TestToUnstructured/with_a_typed_object (0.00s)
... skipping 105 lines ...
    --- PASS: TestToUnstructured/returns_error_for_invalid_yaml#01 (0.00s)
    --- PASS: TestToUnstructured/returns_error_for_invalid_yaml#02 (0.00s)
=== RUN   TestFromUnstructured
--- PASS: TestFromUnstructured (0.00s)
PASS
ok  	sigs.k8s.io/cluster-api/util/yaml	0.032s
FAIL
make: *** [Makefile:116: test] Error 1
+ EXIT_VALUE=2
+ set +o xtrace