This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2022-06-18 14:44
Elapsed4m26s
Revisionrelease-0.3

No Test Failures!


Error lines from build-log.txt

... skipping 777 lines ...
I0618 14:46:05.807126    8428 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0618 14:46:06.492802    8428 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" 
•I0618 14:46:06.509118    8428 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 13.094 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.09s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	46.574s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 316 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 1408 lines ...
I0618 14:45:51.841373   10478 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"
I0618 14:45:51.844472   10478 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"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infra_config_is_marked_for_deletion
I0618 14:45:51.844942   10478 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"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_is_marked_ready_on_cluster
I0618 14:45:51.846523   10478 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"
2022/06/18 14:45:51 http: TLS handshake error from 127.0.0.1:50390: EOF
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_infrastructure_has_the_paused_annotation
I0618 14:45:51.848400   10478 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"
=== RUN   TestClusterReconcilePhases/reconcile_kubeconfig
=== RUN   TestClusterReconcilePhases/reconcile_kubeconfig/cluster_not_provisioned,_apiEndpoint_is_not_set
=== RUN   TestClusterReconcilePhases/reconcile_kubeconfig/kubeconfig_secret_found
=== RUN   TestClusterReconcilePhases/reconcile_kubeconfig/kubeconfig_secret_not_found,_should_requeue
... skipping 95 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0618 14:45:51.919165   10478 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
I0618 14:45:51.921304   10478 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"
E0618 14:45:51.921639   10478 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
I0618 14:45:51.922134   10478 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
I0618 14:45:52.163360   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0618 14:45:52.165460   10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0618 14:45:52.173361   10478 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0618 14:45:52.173442   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0618 14:45:52.283737   10478 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0618 14:45:52.283825   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0618 14:45:52.384339   10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "noderef"="node-1"
E0618 14:45:52.415849   10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0618 14:45:52.415919   10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0618 14:45:52.486948   10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "noderef"="node-1"
E0618 14:45:52.517203   10478 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-gbftz\" in namespace \"test-machine-watches-f7xsh\", requeuing: requeue in 1s"  
E0618 14:45:52.531302   10478 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-gbftz\" in namespace \"test-machine-watches-f7xsh\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-gbftz\" in namespace \"test-machine-watches-f7xsh\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh"
--- PASS: TestWatches (0.62s)
=== 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
I0618 14:45:52.742604   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-dk7sc" "namespace"="test-machine-watches-f7xsh" "count"=1
I0618 14:45:52.742671   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-dk7sc" "namespace"="test-machine-watches-f7xsh" "descendants"="Worker machines: machine-created-gbftz" "indirect descendants count"=0
I0618 14:45:52.760448   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-dk7sc" "namespace"="test-machine-watches-f7xsh" "count"=1
I0618 14:45:52.760515   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-dk7sc" "namespace"="test-machine-watches-f7xsh" "descendants"="Worker machines: machine-created-gbftz" "indirect descendants count"=0
I0618 14:45:53.531878   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-dk7sc" "machine"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"d70be0ff-e837-44e6-8dd0-95a9d8d778bc","apiVersion":"v1"}
E0618 14:45:53.587400   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-gbftz\" not found" "controller"="machine" "name"="machine-created-gbftz" "namespace"="test-machine-watches-f7xsh"
E0618 14:45:54.676578   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-djvlf\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-rvh8h\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-rvh8h: secrets \"machine-reconcile-rvh8h-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-djvlf" "namespace"="default"
I0618 14:45:55.679652   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rvh8h" "machine"="machine-created-djvlf" "namespace"="default" "cause"="noderef is nil" "node"=null
I0618 14:45:55.721291   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rvh8h" "machine"="machine-created-djvlf" "namespace"="default" "cause"="noderef is nil" "node"=null
I0618 14:45:55.745374   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rvh8h" "machine"="machine-created-djvlf" "namespace"="default" "cause"="noderef is nil" "node"=null
E0618 14:45:55.776815   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-djvlf\" not found" "controller"="machine" "name"="machine-created-djvlf" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.24s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.24s)
=== 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 6 lines ...
=== RUN   TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set
I0618 14:45:55.798920   10478 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine3" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0618 14:45:55.799004   10478 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine3" "namespace"="default" 
=== RUN   TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner
I0618 14:45:55.804026   10478 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine4" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0618 14:45:55.804143   10478 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" 
E0618 14:45:55.804322   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-rvh8h\" not found" "controller"="cluster" "name"="machine-reconcile-rvh8h" "namespace"="default"
--- PASS: TestMachineOwnerReference (0.02s)
    --- PASS: TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta (0.00s)
    --- 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.01s)
=== RUN   TestReconcileRequest
=== RUN   TestReconcileRequest/machine_should_be_created
... skipping 118 lines ...
    --- PASS: TestMachineDeploymentSyncStatus/scaling_down (0.00s)
    --- PASS: TestMachineDeploymentSyncStatus/machine_set_failed (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0618 14:45:55.974070   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j79zw" "namespace"="test-mhc-5wdzr" 
I0618 14:45:55.999013   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0618 14:45:55.999515   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-fwtvz\" not found"  "cluster"="test-mhc-5wdzr/test-cluster-fwtvz"
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist
E0618 14:45:56.105082   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-j79zw\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-j79zw\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-j79zw" "namespace"="test-mhc-5wdzr"
I0618 14:45:57.105379   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9x4q7" "namespace"="test-mhc-6pl6p" 
I0618 14:45:57.105494   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4gzqd" "namespace"="test-mhc-78fhk" 
I0618 14:45:57.105531   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j79zw" "namespace"="test-mhc-5wdzr" 
I0618 14:45:57.105564   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnljt" "namespace"="test-mhc-svfx5" 
I0618 14:45:57.158163   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0618 14:45:57.197502   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnljt" "namespace"="test-mhc-svfx5" 
I0618 14:45:57.198336   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnljt" "namespace"="test-mhc-svfx5" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
I0618 14:45:57.211345   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-nnljt" "namespace"="test-mhc-svfx5" 
E0618 14:45:57.217774   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-svfx5/test-cluster-rhddt"
E0618 14:45:57.220226   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-rhddt\" not found" "controller"="cluster" "name"="test-cluster-rhddt" "namespace"="test-mhc-svfx5"
I0618 14:45:57.349600   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdhrl" "namespace"="test-mhc-4fwhh" 
I0618 14:45:57.372817   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0618 14:45:57.492336   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdhrl" "namespace"="test-mhc-4fwhh" 
E0618 14:45:57.570638   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-4fwhh/test-cluster-h54ts"
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0618 14:45:57.602059   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdhrl" "namespace"="test-mhc-4fwhh" 
I0618 14:45:57.634947   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
inframachine created: test-mhc-machine-infra-7cbwz
I0618 14:45:57.649138   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-79z8r
I0618 14:45:57.749752   10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-79z8r/"
node created: test-mhc-node-p5qrk
E0618 14:45:57.763607   10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-p5qrk"
E0618 14:45:57.763610   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-p5qrk, got []"  "node"="test-mhc-node-p5qrk"
inframachine created: test-mhc-machine-infra-n994s
I0618 14:45:57.781494   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
machine created: test-mhc-machine-l4gnb
I0618 14:45:57.799051   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.804966   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.806027   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
... skipping 57 lines ...
I0618 14:45:57.966433   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.967969   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.971059   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.972724   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.973704   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.976522   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.976908   10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/"
I0618 14:45:57.992034   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.993065   10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/"
I0618 14:45:57.994400   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:57.994817   10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/"
I0618 14:45:58.000169   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:58.000825   10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/"
node created: test-mhc-node-9n5qg
E0618 14:45:58.003862   10478 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-9n5qg"
E0618 14:45:58.004047   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-9n5qg, got []"  "node"="test-mhc-node-9n5qg"
I0618 14:45:58.007769   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:58.008191   10478 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-5jr87/test-mhc-dhwgj/test-mhc-machine-l4gnb/"
I0618 14:45:58.014640   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:58.025690   10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87" "noderef"="test-mhc-node-9n5qg"
I0618 14:45:58.033425   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
Cleaning up nodes, machines and infra machines.
I0618 14:45:58.043868   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:58.044373   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-5jr87/test-mhc-dhwgj/test-mhc-machine-79z8r/"
I0618 14:45:58.053720   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-j7n9k" "machine"="test-mhc-machine-79z8r" "namespace"="test-mhc-5jr87" "cause"="no control plane members" "node"={"name":"test-mhc-node-p5qrk"}
E0618 14:45:58.081796   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-5jr87/test-cluster-j7n9k"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E0618 14:45:58.119949   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found" "controller"="machine" "name"="test-mhc-machine-79z8r" "namespace"="test-mhc-5jr87"
E0618 14:45:58.179469   10478 machinehealthcheck_controller.go:167] controllers/MachineHealthCheck "msg"="Failed to reconcile MachineHealthCheck" "error"="failed to patch unhealthy machine status for machine: test-mhc-5jr87/test-mhc-machine-79z8r: [Machine.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found, machines.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found]" "cluster"="test-cluster-j7n9k" 
E0618 14:45:58.182059   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[failed to patch unhealthy machine status for machine: test-mhc-5jr87/test-mhc-machine-79z8r: [Machine.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found, machines.cluster.x-k8s.io \"test-mhc-machine-79z8r\" not found], machinehealthchecks.cluster.x-k8s.io \"test-mhc-dhwgj\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87"
inframachine created: test-mhc-machine-infra-gzgmf
E0618 14:45:58.240887   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-f7xsh/machine-reconcile-dk7sc"
machine created: test-mhc-machine-2vvn5
E0618 14:45:59.120296   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:45:59.182310   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dhwgj" "namespace"="test-mhc-5jr87" 
I0618 14:45:59.182417   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:45:59.195578   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0618 14:45:59.215762   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:45:59.216845   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:45:59.217493   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
... skipping 417 lines ...
I0618 14:46:00.124615   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:00.126718   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:00.127804   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:00.128448   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:00.130123   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:00.131750   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:00.131981   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-2vvn5/"
E0618 14:46:00.132151   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:46:00.141189   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:00.141467   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-2vvn5/"
E0618 14:46:00.188780   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-fhrdq, got []"  "node"="test-mhc-node-fhrdq"
node created: test-mhc-node-fhrdq
I0618 14:46:00.196558   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
inframachine created: test-mhc-machine-infra-zfnrb
machine created: test-mhc-machine-fmpnv
I0618 14:46:00.216371   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:00.222897   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
... skipping 383 lines ...
I0618 14:46:01.169038   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.172291   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.173325   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.174341   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.176477   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.178701   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
E0618 14:46:01.180140   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:46:01.180366   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.181513   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.182661   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.184001   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.185537   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:01.187170   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
... skipping 351 lines ...
I0618 14:46:02.181115   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:02.184187   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:02.187319   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:02.188358   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:02.189371   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:02.191492   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:02.191874   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/"
I0618 14:46:02.204391   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:02.204860   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/"
E0618 14:46:02.205811   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:46:02.205845   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:02.206174   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/"
E0618 14:46:02.231603   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6274r, got []"  "node"="test-mhc-node-6274r"
node created: test-mhc-node-6274r
I0618 14:46:02.238851   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
inframachine created: test-mhc-machine-infra-zx5h7
I0618 14:46:02.253596   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
machine created: test-mhc-machine-zpqhv
I0618 14:46:02.259444   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
... skipping 297 lines ...
I0618 14:46:03.250616   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.252791   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.260175   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.262609   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.265457   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.271118   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
E0618 14:46:03.271884   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:46:03.272987   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.277246   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.280245   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.288833   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.294527   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:03.297515   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
... skipping 218 lines ...
I0618 14:46:04.282184   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.284976   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.287667   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.289183   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.290815   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.292978   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.293831   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/"
I0618 14:46:04.307255   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.307825   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/"
I0618 14:46:04.312579   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.313134   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/"
E0618 14:46:04.313417   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
node created: test-mhc-node-xl9xn
E0618 14:46:04.373696   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-xl9xn, got []"  "node"="test-mhc-node-xl9xn"
I0618 14:46:04.382289   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.383133   10478 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-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/test-mhc-node-xl9xn"
Cleaning up nodes, machines and infra machines.
Cleaning up nodes, machines and infra machines.
I0618 14:46:04.428827   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.429392   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/"
I0618 14:46:04.484384   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.485989   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-2vvn5/"
I0618 14:46:04.517493   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/"
I0618 14:46:04.541238   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nnnfc" "namespace"="test-mhc-s9c54" "count"=2
I0618 14:46:04.541321   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nnnfc" "namespace"="test-mhc-s9c54" "descendants"="Worker machines: test-mhc-machine-2vvn5,test-mhc-machine-fmpnv,test-mhc-machine-zpqhv" "indirect descendants count"=1
I0618 14:46:04.541814   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/"
I0618 14:46:04.545774   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nnnfc" "namespace"="test-mhc-s9c54" "count"=2
I0618 14:46:04.545842   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nnnfc" "namespace"="test-mhc-s9c54" "descendants"="Worker machines: test-mhc-machine-2vvn5,test-mhc-machine-fmpnv,test-mhc-machine-zpqhv" "indirect descendants count"=1
I0618 14:46:04.547485   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.548040   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-fmpnv/"
I0618 14:46:04.548474   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-zpqhv/"
I0618 14:46:04.548783   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-s9c54/test-mhc-vhff5/test-mhc-machine-2vvn5/"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
I0618 14:46:04.550665   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vhff5" "namespace"="test-mhc-s9c54" 
I0618 14:46:04.584140   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
inframachine created: test-mhc-machine-infra-qv65q
I0618 14:46:04.613524   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-hxhnt
... skipping 3 lines ...
I0618 14:46:04.673580   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:04.722642   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:04.803747   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:04.964740   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:05.285838   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:05.314063   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nnnfc" "machine"="test-mhc-machine-zpqhv" "namespace"="test-mhc-s9c54" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-xl9xn"}
E0618 14:46:05.516714   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-zpqhv\" not found" "controller"="machine" "name"="test-mhc-machine-zpqhv" "namespace"="test-mhc-s9c54"
I0618 14:46:05.926947   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:06.517257   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nnnfc" "machine"="test-mhc-machine-fmpnv" "namespace"="test-mhc-s9c54" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-6274r"}
E0618 14:46:06.566835   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-fmpnv\" not found" "controller"="machine" "name"="test-mhc-machine-fmpnv" "namespace"="test-mhc-s9c54"
I0618 14:46:07.208003   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:07.567389   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nnnfc" "machine"="test-mhc-machine-2vvn5" "namespace"="test-mhc-s9c54" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-fhrdq"}
E0618 14:46:07.624862   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2vvn5\" not found" "controller"="machine" "name"="test-mhc-machine-2vvn5" "namespace"="test-mhc-s9c54"
E0618 14:46:08.625283   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
E0618 14:46:09.558467   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-s9c54/test-cluster-nnnfc"
I0618 14:46:09.633442   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
E0618 14:46:09.639990   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:46:09.640349   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
E0618 14:46:09.660633   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-p9tq7, got []"  "node"="test-mhc-node-p9tq7"
node created: test-mhc-node-p9tq7
I0618 14:46:09.662511   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:09.667466   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
inframachine created: test-mhc-machine-infra-x57cc
machine created: test-mhc-machine-2tm9l
I0618 14:46:09.697565   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
... skipping 6 lines ...
I0618 14:46:10.349298   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:10.669573   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:10.678315   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:10.702602   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:10.712471   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:10.725762   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
E0618 14:46:10.732852   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:46:10.733065   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:10.756195   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
node created: test-mhc-node-kf48l
E0618 14:46:10.796761   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-kf48l, got []"  "node"="test-mhc-node-kf48l"
I0618 14:46:10.811158   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
inframachine created: test-mhc-machine-infra-8spmm
I0618 14:46:10.824535   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
machine created: test-mhc-machine-92ppt
I0618 14:46:10.831941   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:10.843188   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
... skipping 4 lines ...
I0618 14:46:11.777815   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:11.796216   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:11.800565   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:11.809786   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:11.814347   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:11.832240   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
E0618 14:46:11.841169   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-l4vng, got []"  "node"="test-mhc-node-l4vng"
node created: test-mhc-node-l4vng
I0618 14:46:11.848308   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:11.860776   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
Cleaning up nodes, machines and infra machines.
I0618 14:46:11.882408   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
Cleaning up nodes, machines and infra machines.
I0618 14:46:11.935669   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-lc4dp" "machine"="test-mhc-machine-2tm9l" "namespace"="test-mhc-j847l" "cause"="no control plane members" "node"={"name":"test-mhc-node-kf48l"}
I0618 14:46:11.936472   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:11.963973   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-lc4dp" "namespace"="test-mhc-j847l" "count"=3
I0618 14:46:11.964068   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-lc4dp" "namespace"="test-mhc-j847l" "descendants"="Worker machines: test-mhc-machine-2tm9l,test-mhc-machine-92ppt,test-mhc-machine-hxhnt" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout
I0618 14:46:11.977805   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-lc4dp" "namespace"="test-mhc-j847l" "count"=3
I0618 14:46:11.977867   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-lc4dp" "namespace"="test-mhc-j847l" "descendants"="Worker machines: test-mhc-machine-hxhnt,test-mhc-machine-2tm9l,test-mhc-machine-92ppt" "indirect descendants count"=0
E0618 14:46:11.982408   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-84wwp\" not found" "controller"="machinehealthcheck" "name"="test-mhc-84wwp" "namespace"="test-mhc-j847l"
inframachine created: test-mhc-machine-infra-849w5
E0618 14:46:12.001420   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2tm9l\" not found" "controller"="machine" "name"="test-mhc-machine-2tm9l" "namespace"="test-mhc-j847l"
machine created: test-mhc-machine-sc48x
I0618 14:46:12.986201   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84wwp" "namespace"="test-mhc-j847l" 
I0618 14:46:12.986313   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:13.001492   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0618 14:46:13.007397   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-lc4dp" "machine"="test-mhc-machine-hxhnt" "namespace"="test-mhc-j847l" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-p9tq7"}
I0618 14:46:13.024309   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:13.024983   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
E0618 14:46:13.056509   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-hxhnt\" not found" "controller"="machine" "name"="test-mhc-machine-hxhnt" "namespace"="test-mhc-j847l"
I0618 14:46:14.057071   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-lc4dp" "machine"="test-mhc-machine-92ppt" "namespace"="test-mhc-j847l" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-l4vng"}
E0618 14:46:14.126638   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-92ppt\" not found" "controller"="machine" "name"="test-mhc-machine-92ppt" "namespace"="test-mhc-j847l"
I0618 14:46:15.136154   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:15.143446   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
E0618 14:46:15.144336   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
E0618 14:46:15.245358   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-khsz9, got []"  "node"="test-mhc-node-khsz9"
E0618 14:46:15.245605   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-khsz9, got []"  "node"="test-mhc-node-khsz9"
node created: test-mhc-node-khsz9
I0618 14:46:15.254233   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
inframachine created: test-mhc-machine-infra-n6sl7
I0618 14:46:15.272997   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:15.278472   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
machine created: test-mhc-machine-z6dt7
... skipping 7 lines ...
I0618 14:46:16.200137   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.206491   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.221845   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.249444   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.260848   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.268792   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
E0618 14:46:16.296383   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bq9mq, got []"  "node"="test-mhc-node-bq9mq"
E0618 14:46:16.296605   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bq9mq, got []"  "node"="test-mhc-node-bq9mq"
node created: test-mhc-node-bq9mq
I0618 14:46:16.318560   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
inframachine created: test-mhc-machine-infra-vd7s8
I0618 14:46:16.340488   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
machine created: test-mhc-machine-x8gxm
I0618 14:46:16.345732   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
... skipping 8 lines ...
I0618 14:46:16.444882   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.450666   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
Cleaning up nodes, machines and infra machines.
I0618 14:46:16.466686   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.466948   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-8b58l" "machine"="test-mhc-machine-x8gxm" "namespace"="test-mhc-hp52r" "cause"="noderef is nil" "node"=null
I0618 14:46:16.468406   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.468915   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-hp52r/test-mhc-fdrgq/test-mhc-machine-sc48x/"
I0618 14:46:16.503586   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:16.504414   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-hp52r/test-mhc-fdrgq/test-mhc-machine-z6dt7/"
=== 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
I0618 14:46:16.532479   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-8b58l" "namespace"="test-mhc-hp52r" "count"=3
I0618 14:46:16.532550   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-8b58l" "namespace"="test-mhc-hp52r" "descendants"="Worker machines: test-mhc-machine-sc48x,test-mhc-machine-z6dt7,test-mhc-machine-x8gxm" "indirect descendants count"=0
I0618 14:46:16.540296   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-8b58l" "namespace"="test-mhc-hp52r" "count"=3
I0618 14:46:16.540468   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-8b58l" "namespace"="test-mhc-hp52r" "descendants"="Worker machines: test-mhc-machine-sc48x,test-mhc-machine-z6dt7,test-mhc-machine-x8gxm" "indirect descendants count"=0
E0618 14:46:16.548028   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-x8gxm\" not found" "controller"="machine" "name"="test-mhc-machine-x8gxm" "namespace"="test-mhc-hp52r"
I0618 14:46:16.635884   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-hp52r/test-mhc-fdrgq/test-mhc-machine-sc48x/"
E0618 14:46:16.638588   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-fdrgq\" not found" "controller"="machinehealthcheck" "name"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r"
inframachine created: test-mhc-machine-infra-ctdv5
machine created: test-mhc-machine-vc22m
E0618 14:46:16.991231   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-j847l/test-cluster-lc4dp"
I0618 14:46:17.548595   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-8b58l" "machine"="test-mhc-machine-sc48x" "namespace"="test-mhc-hp52r" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-khsz9"}
E0618 14:46:17.598877   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-sc48x\" not found" "controller"="machine" "name"="test-mhc-machine-sc48x" "namespace"="test-mhc-hp52r"
I0618 14:46:17.638894   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fdrgq" "namespace"="test-mhc-hp52r" 
I0618 14:46:17.639004   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:17.651823   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0618 14:46:17.678430   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:17.679418   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:17.681491   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
... skipping 433 lines ...
I0618 14:46:18.637186   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.638982   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.640844   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.642756   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.644894   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.646781   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
E0618 14:46:18.647002   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-z6dt7\" not found" "controller"="machine" "name"="test-mhc-machine-z6dt7" "namespace"="test-mhc-hp52r"
I0618 14:46:18.649965   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.652159   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.653980   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.656095   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.657848   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:18.659585   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
... skipping 461 lines ...
I0618 14:46:19.652473   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.654176   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.655854   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.656413   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.658915   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.660965   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.661216   10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/"
E0618 14:46:19.661322   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:46:19.670570   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.670895   10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/"
E0618 14:46:19.703717   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-97t7l, got []"  "node"="test-mhc-node-97t7l"
node created: test-mhc-node-97t7l
E0618 14:46:19.703977   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-97t7l, got []"  "node"="test-mhc-node-97t7l"
I0618 14:46:19.715823   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.740161   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.745306   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.745675   10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/test-mhc-node-97t7l"
I0618 14:46:19.760577   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.760963   10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/test-mhc-node-97t7l"
I0618 14:46:19.765576   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.765944   10478 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-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/test-mhc-node-97t7l"
Cleaning up nodes, machines and infra machines.
I0618 14:46:19.770881   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:19.771218   10478 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-ljjqd/test-mhc-vcnws/test-mhc-machine-vc22m/"
I0618 14:46:19.785941   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-p9bxg" "namespace"="test-mhc-ljjqd" "descendants"="Worker machines: test-mhc-machine-vc22m" "indirect descendants count"=1
I0618 14:46:19.789727   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-p9bxg" "namespace"="test-mhc-ljjqd" "descendants"="Worker machines: test-mhc-machine-vc22m" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0618 14:46:19.910316   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vcnws" "namespace"="test-mhc-ljjqd" 
I0618 14:46:20.008081   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" "creating"=1 "need"=1
I0618 14:46:20.008136   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
I0618 14:46:20.020341   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-gfj4m-w4mhl\"" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
I0618 14:46:20.090491   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
I0618 14:46:20.115008   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0618 14:46:20.128300   10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
I0618 14:46:20.241089   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
I0618 14:46:20.661915   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-p9bxg" "machine"="test-mhc-machine-vc22m" "namespace"="test-mhc-ljjqd" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-97t7l"}
E0618 14:46:20.711306   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-vc22m\" not found" "controller"="machine" "name"="test-mhc-machine-vc22m" "namespace"="test-mhc-ljjqd"
I0618 14:46:21.241321   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
E0618 14:46:21.553946   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-hp52r/test-cluster-8b58l"
I0618 14:46:21.720665   10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.720827   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.730161   10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.730327   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.745402   10478 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.745467   10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
... skipping 3 lines ...
I0618 14:46:21.765389   10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.767514   10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.767661   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.776094   10478 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
I0618 14:46:21.776138   10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.242349   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.242888   10478 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-vksgb/test-mhc-grqzq/mhc-ms-gfj4m-w4mhl/"
I0618 14:46:22.251284   10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.258859   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.259291   10478 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-vksgb/test-mhc-grqzq/mhc-ms-gfj4m-w4mhl/"
I0618 14:46:22.261666   10478 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.261701   10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.270051   10478 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.270149   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.270518   10478 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-vksgb/test-mhc-grqzq/mhc-ms-gfj4m-w4mhl/"
I0618 14:46:22.279745   10478 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.279803   10478 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" 
I0618 14:46:22.345060   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-r6n8p" "namespace"="test-mhc-vksgb" "count"=1
I0618 14:46:22.345124   10478 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-r6n8p" "namespace"="test-mhc-vksgb" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-gfj4m"
I0618 14:46:22.349792   10478 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" "machine"="mhc-ms-gfj4m-w4mhl"
I0618 14:46:22.350892   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-r6n8p" "namespace"="test-mhc-vksgb" "descendants"="Machine sets: mhc-ms-gfj4m;Worker machines: mhc-ms-gfj4m-w4mhl" "indirect descendants count"=1
I0618 14:46:22.354288   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-grqzq" "namespace"="test-mhc-vksgb" 
=== RUN   TestMachineHealthCheck_Reconcile/when_a_machine_is_paused
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created
I0618 14:46:22.363449   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-r6n8p" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" "cause"="cluster is being deleted" "node"=null
I0618 14:46:22.364141   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-r6n8p" "namespace"="test-mhc-vksgb" "descendants"="Worker machines: mhc-ms-gfj4m-w4mhl" "indirect descendants count"=1
E0618 14:46:22.381299   10478 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-gfj4m\" not found" "machineset"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb" 
E0618 14:46:22.381391   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-gfj4m\" not found" "controller"="machineset" "name"="mhc-ms-gfj4m" "namespace"="test-mhc-vksgb"
I0618 14:46:22.552594   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-r6n8p" "machine"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb" "cause"="cluster is being deleted" "node"=null
I0618 14:46:22.608921   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
E0618 14:46:22.609475   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-gfj4m-w4mhl\" not found" "controller"="machine" "name"="mhc-ms-gfj4m-w4mhl" "namespace"="test-mhc-vksgb"
inframachine created: test-mhc-machine-infra-7j5fq
I0618 14:46:22.624137   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-x977p
I0618 14:46:22.751098   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:22.752074   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:22.752717   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
... skipping 393 lines ...
I0618 14:46:23.620438   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.621670   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.622279   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.623432   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.625618   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.626486   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
E0618 14:46:23.641652   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
E0618 14:46:23.641653   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
node created: test-mhc-node-cv4q9
E0618 14:46:23.641888   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
I0618 14:46:23.641965   10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-x977p" "namespace"="test-mhc-4ccvs" "noderef"="test-mhc-node-cv4q9"
E0618 14:46:23.646752   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
E0618 14:46:23.646790   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
E0618 14:46:23.646915   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
E0618 14:46:23.646938   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
E0618 14:46:23.646973   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
E0618 14:46:23.647029   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cv4q9, got []"  "node"="test-mhc-node-cv4q9"
I0618 14:46:23.673464   10478 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-x977p" "target"="test-mhc-4ccvs/test-mhc-w9dqq/test-mhc-machine-x977p/"
I0618 14:46:23.692358   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.715375   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.721773   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.725553   10478 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-x977p" "target"="test-mhc-4ccvs/test-mhc-w9dqq/test-mhc-machine-x977p/test-mhc-node-cv4q9"
I0618 14:46:23.753999   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.757223   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
Cleaning up nodes, machines and infra machines.
I0618 14:46:23.770517   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.774173   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
I0618 14:46:23.777237   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w9dqq" "namespace"="test-mhc-4ccvs" 
... skipping 4 lines ...
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted
I0618 14:46:23.811818   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-mmw2c" "machine"="test-mhc-machine-x977p" "namespace"="test-mhc-4ccvs" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-cv4q9"}
I0618 14:46:23.834684   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
inframachine created: test-mhc-machine-infra-gnhb8
I0618 14:46:23.859593   10478 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-f6b7n
E0618 14:46:23.882746   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-x977p\" not found" "controller"="machine" "name"="test-mhc-machine-x977p" "namespace"="test-mhc-4ccvs"
I0618 14:46:23.977880   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:23.984009   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:23.985132   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:23.986946   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:23.988783   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:23.990568   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
... skipping 348 lines ...
I0618 14:46:24.801312   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.803012   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.804764   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.806475   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.808178   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.809903   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
E0618 14:46:24.810300   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-ljjqd/test-cluster-p9bxg"
I0618 14:46:24.811614   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.822088   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.824251   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.826582   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.828665   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.830691   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
... skipping 26 lines ...
I0618 14:46:24.883835   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.885536   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.888171   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.890558   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.892842   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.895850   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
E0618 14:46:24.898216   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
I0618 14:46:24.898637   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:24.902173   10478 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-f6b7n" "target"="test-mhc-r4hcf/test-mhc-m7c7p/test-mhc-machine-f6b7n/"
I0618 14:46:24.914434   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
E0618 14:46:24.971543   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bbr8n, got []"  "node"="test-mhc-node-bbr8n"
node created: test-mhc-node-bbr8n
E0618 14:46:24.971637   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bbr8n, got []"  "node"="test-mhc-node-bbr8n"
E0618 14:46:24.971987   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bbr8n, got []"  "node"="test-mhc-node-bbr8n"
I0618 14:46:24.979571   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:25.013522   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:25.026560   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:25.036624   10478 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-f6b7n" "target"="test-mhc-r4hcf/test-mhc-m7c7p/test-mhc-machine-f6b7n/test-mhc-node-bbr8n"
I0618 14:46:25.055551   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:25.067116   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:25.107314   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:25.110330   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
Cleaning up nodes, machines and infra machines.
I0618 14:46:25.137645   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:25.140416   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:25.146521   10478 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-f6b7n" "target"="test-mhc-r4hcf/test-mhc-m7c7p/test-mhc-machine-f6b7n/"
I0618 14:46:25.162913   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5h25r" "namespace"="test-mhc-r4hcf" "descendants"="Worker machines: test-mhc-machine-f6b7n" "indirect descendants count"=1
I0618 14:46:25.176399   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5h25r" "namespace"="test-mhc-r4hcf" "descendants"="Worker machines: test-mhc-machine-f6b7n" "indirect descendants count"=1
--- PASS: TestMachineHealthCheck_Reconcile (29.23s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.06s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.04s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.03s)
... skipping 12 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 (1.44s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (1.38s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0618 14:46:25.186656   10478 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
E0618 14:46:25.188256   10478 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
E0618 14:46:25.191543   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-m7c7p\" not found" "controller"="machinehealthcheck" "name"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf"
=== RUN   TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node
E0618 14:46:25.193756   10478 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0618 14:46:25.194242   10478 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
E0618 14:46:25.203120   10478 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.02s)
    --- 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
I0618 14:46:25.206677   10478 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0618 14:46:25.207319   10478 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0618 14:46:25.209257   10478 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
E0618 14:46:25.222618   10478 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
E0618 14:46:25.224670   10478 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 65 lines ...
I0618 14:46:25.361502   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-d5w72-c99mf\"" "machineset"="ms-d5w72" "namespace"="ms-test" 
I0618 14:46:25.361571   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-d5w72" "namespace"="ms-test" 
I0618 14:46:25.381432   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-d5w72-k8ftl\"" "machineset"="ms-d5w72" "namespace"="ms-test" 
I0618 14:46:25.452305   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-d5w72" "namespace"="ms-test" "creating"=1 "need"=2
I0618 14:46:25.452354   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-d5w72" "namespace"="ms-test" 
I0618 14:46:25.471835   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-d5w72-cv4rp\"" "machineset"="ms-d5w72" "namespace"="ms-test" 
E0618 14:46:25.569352   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.569512   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.569550   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.681041   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.681103   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.681532   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.681570   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.682330   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.682369   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-cv4rp-xrp2g, got []"  "node"="ms-d5w72-cv4rp-xrp2g"
E0618 14:46:25.748340   10478 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-d5w72-cv4rp-xrp2g for machine ms-test/ms-d5w72-cv4rp: the cache is not started, can not read objects" "machineset"="ms-d5w72" "namespace"="ms-test" 
E0618 14:46:25.751318   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
E0618 14:46:25.751572   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
E0618 14:46:25.751847   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
E0618 14:46:25.856057   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
E0618 14:46:25.856123   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
E0618 14:46:25.856125   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
E0618 14:46:25.856178   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
E0618 14:46:25.856301   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
E0618 14:46:25.856342   10478 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-d5w72-k8ftl-xbdv9, got []"  "node"="ms-d5w72-k8ftl-xbdv9"
I0618 14:46:25.898787   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-5h25r" "machine"="test-mhc-machine-f6b7n" "namespace"="test-mhc-r4hcf" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-bbr8n"}
E0618 14:46:25.943701   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-f6b7n\" not found" "controller"="machine" "name"="test-mhc-machine-f6b7n" "namespace"="test-mhc-r4hcf"
I0618 14:46:25.981112   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-d5w72-cv4rp,ms-d5w72-k8ftl" "indirect descendants count"=2
•I0618 14:46:25.985927   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-d5w72-cv4rp,ms-d5w72-k8ftl" "indirect descendants count"=2
•E0618 14:46:26.115688   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-s7cnh\" not found" "controller"="cluster" "name"="test1-s7cnh" "namespace"="default"
I0618 14:46:26.191795   10478 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-m7c7p" "namespace"="test-mhc-r4hcf" 
I0618 14:46:27.238277   10478 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-ssgl2" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
•I0618 14:46:27.358470   10478 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-ssgl2" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0618 14:46:27.363878   10478 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-ssgl2" "namespace"="default"
E0618 14:46:28.386595   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-vksgb/test-cluster-r6n8p"
E0618 14:46:28.391668   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default"
•E0618 14:46:29.416578   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-tpdc2\" not found" "controller"="cluster" "name"="test3-tpdc2" "namespace"="default"
E0618 14:46:30.417429   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default"
E0618 14:46:31.443082   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-4ccvs/test-cluster-mmw2c"
E0618 14:46:31.452604   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default"
E0618 14:46:31.453219   10478 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-r4hcf/test-cluster-5h25r"
•I0618 14:46:32.453168   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-d5w72-cv4rp,ms-d5w72-k8ftl" "indirect descendants count"=2
E0618 14:46:32.458776   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-cv89s: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default"
E0618 14:46:33.459596   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default"
E0618 14:46:34.470626   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-cv89s: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default"
•E0618 14:46:35.138531   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-j7n9k\" for machine \"test-mhc-machine-l4gnb\" in namespace \"test-mhc-5jr87\": Cluster.cluster.x-k8s.io \"test-cluster-j7n9k\" not found" "controller"="machine" "name"="test-mhc-machine-l4gnb" "namespace"="test-mhc-5jr87"
E0618 14:46:35.471280   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default"
E0618 14:46:36.472098   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-cv89s: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default"
E0618 14:46:37.485902   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default"
I0618 14:46:37.586858   10478 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-bqc6v" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0618 14:46:37.599147   10478 machine_controller_noderef.go:73] controllers/Machine "msg"="Failed to retrieve Node by ProviderID" "error"="the cache is not started, can not read objects" "machine"="test6-bqc6v" "namespace"="default" 
E0618 14:46:37.613231   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[failed to find a CustomResourceDefinition for /, Kind= with contract \"cluster.x-k8s.io/v1alpha3\", the cache is not started, can not read objects]" "controller"="machine" "name"="test6-bqc6v" "namespace"="default"
E0618 14:46:38.486592   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-cv89s: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default"
I0618 14:46:38.627511   10478 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-bqc6v" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0618 14:46:38.627726   10478 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-bqc6v" "namespace"="default" "noderef"="id-node-1"
E0618 14:46:38.639455   10478 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-bqc6v" "namespace"="default"
I0618 14:46:39.487177   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-d5w72-k8ftl,ms-d5w72-cv4rp" "indirect descendants count"=2
E0618 14:46:39.491208   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default"

------------------------------
• [SLOW TEST:5.042 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 21 lines ...
I0618 14:46:39.602645   10478 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"
•I0618 14:46:39.604169   10478 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"
I0618 14:46:39.604889   10478 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"
I0618 14:46:39.605572   10478 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0618 14:46:39.605645   10478 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0618 14:46:39.606307   10478 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0618 14:46:39.607773   10478 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" 
•I0618 14:46:39.639899   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fhw7d" "machine"="test6-bqc6v" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"876c9568-c74b-4a11-a87f-df1329f641f7","apiVersion":"v1"}
E0618 14:46:39.660097   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-bqc6v\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-bqc6v" "namespace"="default"
I0618 14:46:39.664046   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0618 14:46:39.664120   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" 
I0618 14:46:39.678792   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-b2dbw-6657c7fddb-g6ftt\"" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" 
I0618 14:46:39.678905   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" 
I0618 14:46:39.693787   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-b2dbw-6657c7fddb-v2s8t\"" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" 
I0618 14:46:39.807182   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
... skipping 4 lines ...
I0618 14:46:39.911741   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0618 14:46:39.911784   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" 
I0618 14:46:39.926144   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-6657c7fddb-x7jdb\"" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" 
I0618 14:46:40.010453   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0618 14:46:40.010508   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" 
I0618 14:46:40.020200   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-cdfc6fd6c-2gqwf\"" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" 
E0618 14:46:40.143310   10478 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-b2dbw-cdfc6fd6c-2gqwf-dwcnf for machine md-test/md-b2dbw-cdfc6fd6c-2gqwf: the cache is not started, can not read objects" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" 
I0618 14:46:40.178534   10478 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0618 14:46:40.178570   10478 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0618 14:46:40.183902   10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "machine"="md-b2dbw-6657c7fddb-w67kc"
I0618 14:46:40.203904   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0618 14:46:40.203986   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" 
I0618 14:46:40.213386   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-cdfc6fd6c-v7llc\"" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" 
I0618 14:46:40.403283   10478 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1
I0618 14:46:40.403317   10478 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0618 14:46:40.407020   10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "machine"="md-b2dbw-6657c7fddb-845qh"
E0618 14:46:40.491892   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-cv89s: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-cv89s" "namespace"="default"
I0618 14:46:40.557016   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0618 14:46:40.557092   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" 
I0618 14:46:40.570098   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-cdfc6fd6c-g8q8h\"" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" 
I0618 14:46:40.671454   10478 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-fhw7d" "machine"="test6-bqc6v" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"876c9568-c74b-4a11-a87f-df1329f641f7","apiVersion":"v1"}
E0618 14:46:40.672683   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-bqc6v\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-bqc6v" "namespace"="default"
I0618 14:46:40.730098   10478 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0618 14:46:40.730138   10478 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0618 14:46:40.734513   10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-6657c7fddb" "namespace"="md-test" "machine"="md-b2dbw-6657c7fddb-x7jdb"
I0618 14:46:40.869773   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0618 14:46:40.869828   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" 
I0618 14:46:40.881022   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-74d45c49c5-qlqj5\"" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" 
... skipping 8 lines ...
I0618 14:46:41.366114   10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "machine"="md-b2dbw-cdfc6fd6c-g8q8h"
I0618 14:46:41.477376   10478 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0618 14:46:41.477419   10478 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" 
I0618 14:46:41.488315   10478 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-b2dbw-74d45c49c5-wbxfm\"" "machineset"="md-b2dbw-74d45c49c5" "namespace"="md-test" 
I0618 14:46:41.492570   10478 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-fhw7d" "namespace"="default" "count"=1
I0618 14:46:41.492662   10478 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-fhw7d" "namespace"="default" "descendants"="Control plane machines: test6-bqc6v" "indirect descendants count"=0
E0618 14:46:41.509646   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-ssgl2: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-ssgl2" "namespace"="default"
•

Ran 16 of 16 Specs in 16.396 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.40s)
PASS
Tearing down test suite
I0618 14:46:41.622172   10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0618 14:46:41.622223   10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0618 14:46:41.622244   10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0618 14:46:41.622276   10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0618 14:46:41.622298   10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0618 14:46:41.622317   10478 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0618 14:46:41.622396   10478 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0618 14:46:41.622843   10478 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinedeployments.cluster.x-k8s.io \"md-b2dbw\" not found" "controller"="machinedeployment" "name"="md-b2dbw" "namespace"="md-test"
I0618 14:46:41.624141   10478 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=0
I0618 14:46:41.624180   10478 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0618 14:46:41.628781   10478 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-b2dbw-cdfc6fd6c" "namespace"="md-test" "machine"="md-b2dbw-cdfc6fd6c-2gqwf"
E0618 14:46:41.629296   10478 event.go:272] Unable to write event: 'Post http://127.0.0.1:42473/api/v1/namespaces/md-test/events: dial tcp 127.0.0.1:42473: connect: connection refused' (may retry after sleeping)
E0618 14:46:41.665045   10478 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:42473/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1267&timeout=10s&timeoutSeconds=522&watch=true: dial tcp 127.0.0.1:42473: connect: connection refused
E0618 14:46:41.665453   10478 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:42473/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1267&timeout=10s&timeoutSeconds=540&watch=true: dial tcp 127.0.0.1:42473: connect: connection refused
E0618 14:46:41.665453   10478 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:42473/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1267&timeout=10s&timeoutSeconds=519&watch=true: dial tcp 127.0.0.1:42473: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	61.929s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 256 lines ...
I0618 14:45:53.118113   10939 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1alpha3","Kind":"ClusterResourceSet"} "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0618 14:45:53.118134   10939 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0618 14:45:53.118323   10939 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0618 14:45:53.119381   10939 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0618 14:45:53.119625   10939 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=39913
I0618 14:45:53.119885   10939 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
E0618 14:45:55.489642   10939 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-h8nfg/test-cluster"
•E0618 14:45:55.955083   10939 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-k8t8p/test-cluster"
•E0618 14:45:56.490173   10939 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:46431/?timeout=50ms: dial tcp 127.0.0.1:46431: connect: connection refused"  "cluster"="cluster-cache-test-v49wc/test-cluster"
•I0618 14:45:56.739614   10939 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}}}
I0618 14:45:56.840546   10939 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0618 14:45:56.840612   10939 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I0618 14:45:57.019256   10939 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0618 14:45:57.029457   10939 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"clusterName":"","selector":{},"template":{"metadata":{},"spec":{"clusterName":"","bootstrap":{},"infrastructureRef":{}}}},"status":{}}}
I0618 14:45:57.229944   10939 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0618 14:45:57.230006   10939 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0618 14:45:57.230077   10939 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0618 14:45:57.756665   10939 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0618 14:45:57.756698   10939 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0618 14:45:57.816712   10939 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:42037/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:42037: connect: connection refused


Ran 5 of 5 Specs in 16.066 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.07s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	16.210s
?   	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
I0618 14:46:06.067180   11553 controller.go:130]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.00s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0618 14:46:06.068468   11553 controller.go:126]  "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
I0618 14:46:06.069062   11553 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0618 14:46:06.069212   11553 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 192 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
I0618 14:46:20.964811   11553 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
I0618 14:46:20.965000   11553 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: 1655563551
Will run 1 of 1 specs

E0618 14:46:20.996411   11553 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-ltuo3n\" not found" "kubeadmControlPlane"="kcp-foo-ltuo3n" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.027 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0618 14:46:20.998270   11553 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-8a5tv3" "kubeadmControlPlane"="kcp-foo-8a5tv3" "namespace"="test" 
I0618 14:46:22.699593   11553 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-8a5tv3" "kubeadmControlPlane"="kcp-foo-8a5tv3" "namespace"="test" "needRollout"=["kcp-foo-8a5tv3-cswtp"]
I0618 14:46:22.699755   11553 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-8a5tv3" "kubeadmControlPlane"="kcp-foo-8a5tv3" "namespace"="test" "failures"="[machine kcp-foo-8a5tv3-ns9jz does not have APIServerPodHealthy condition, machine kcp-foo-8a5tv3-ns9jz does not have ControllerManagerPodHealthy condition, machine kcp-foo-8a5tv3-ns9jz does not have SchedulerPodHealthy condition, machine kcp-foo-8a5tv3-ns9jz does not have EtcdPodHealthy condition, machine kcp-foo-8a5tv3-ns9jz does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (1.70s)
... skipping 60 lines ...
==================================
Random Seed: 1655563550
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.000 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: 1655563550
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.000 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 247 lines ...
        --- PASS: TestForwardEtcdLeadership/move_etcd_leader/returns_error_if_failed_to_move_to_the_leader_candidate (0.00s)
        --- PASS: TestForwardEtcdLeadership/move_etcd_leader/returns_error_if_the_leader_candidate_doesn't_exist_in_etcd (0.00s)
=== RUN   TestReconcileEtcdMembers
=== RUN   TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_and_removes_the_node_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_for_Kubernetes_version_>=_1.22.0
=== RUN   TestReconcileEtcdMembers/return_error_if_there_aren't_enough_control_plane_nodes
--- FAIL: TestReconcileEtcdMembers (0.22s)
    --- PASS: TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_and_removes_the_node_from_kubeadm_config_for_Kubernetes_version_<_1.22.0 (0.14s)
    --- FAIL: TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_for_Kubernetes_version_>=_1.22.0 (0.03s)
        workload_cluster_etcd_test.go:608: 
            Unexpected error:
                <errors.aggregate | len:2, cap:2>: [
                    {
                        msg: "cluster has fewer than 2 control plane nodes; removing an etcd member is not supported",
                        stack: [0x1740e76, 0x43f42a, 0x43f3f7, 0x432e62, 0x461351],
                    },
                    {
... skipping 47 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
E0618 14:46:05.897211   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:46:14.220299   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:46:23.211454   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:46:34.341762   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:46:50.814928   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:47:03.823501   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:47:21.470860   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:47:42.394238   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:48:13.410718   11495 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0618 14:48:58.567999   11495 workload_cluster.go:354]  "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 82 lines ...
--- PASS: TestIsKubernetesVersionSupported (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_<_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_<_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.23.0 (0.00s)
FAIL
I0618 14:48:58.578000   11495 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
FAIL	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	187.951s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
PASS
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal/etcd	0.091s
... skipping 286 lines ...
I0618 14:46:12.724737   11859 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourcesetbinding" 
I0618 14:46:12.824770   11859 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0618 14:46:12.925167   11859 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0618 14:46:12.925243   11859 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0618 14:46:12.925946   11859 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0618 14:46:13.061627   11859 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-3texwt"} 
E0618 14:46:13.122051   11859 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"
•I0618 14:46:14.200995   11859 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-t2nvg8"} 
E0618 14:46:14.231080   11859 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"
•E0618 14:46:15.354815   11859 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"
E0618 14:46:16.373698   11859 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"
•E0618 14:46:17.537217   11859 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"
•E0618 14:46:18.568466   11859 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"
E0618 14:46:19.603930   11859 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"
•I0618 14:46:19.607401   11859 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0618 14:46:19.607454   11859 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0618 14:46:19.607530   11859 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 5 of 5 Specs in 20.149 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (20.15s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/addons/controllers	20.233s
?   	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.01s)
=== 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
E0618 14:46:05.531808   12025 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 96 lines ...
I0618 14:46:16.811348   12025 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0618 14:46:16.849310   12025 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••I0618 14:46:16.851136   12025 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 9 of 9 Specs in 11.307 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (11.31s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	11.619s
?   	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 ...
I0618 14:46:40.614177   15005 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=43335
I0618 14:46:40.616123   15005 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••I0618 14:46:41.616080   15005 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 14 of 14 Specs in 8.243 seconds
SUCCESS! -- 14 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestPatch (8.24s)
=== 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.034s
FAIL
make: *** [Makefile:116: test] Error 1