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

No Test Failures!


Error lines from build-log.txt

... skipping 777 lines ...
I0723 20:07:19.151731    8503 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0723 20:07:19.152249    8503 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0723 20:07:19.154128    8503 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0723 20:07:19.154879    8503 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0723 20:07:19.155299    8503 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=46621
I0723 20:07:19.679909    8503 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" 
•E0723 20:07:19.726136    8503 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:07:19.726172    8503 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-246769422/tls.crt: no such file or directory"  
I0723 20:07:19.726360    8503 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 13.191 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.19s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	60.507s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 310 lines ...
=== RUN   Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined
--- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s)
=== RUN   Test_clusterctlClient_GetProviderComponents
=== RUN   Test_clusterctlClient_GetProviderComponents/Pass
=== RUN   Test_clusterctlClient_GetProviderComponents/Fail
--- PASS: Test_clusterctlClient_GetProviderComponents (0.02s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.02s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s)
=== RUN   Test_getComponentsByName_withEmptyVariables
--- PASS: Test_getComponentsByName_withEmptyVariables (0.00s)
=== RUN   Test_clusterctlClient_templateOptionsToVariables
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts)
... skipping 1398 lines ...
I0723 20:06:52.449259   10538 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinehealthcheck" 
I0723 20:06:52.449289   10538 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
I0723 20:06:52.449616   10538 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
I0723 20:06:52.450045   10538 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0723 20:06:52.450092   10538 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
I0723 20:06:52.451267   10538 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machine" "worker count"=1
2021/07/23 20:06:52 http: TLS handshake error from 127.0.0.1:37424: EOF
=== RUN   TestClusterReconcilePhases
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I0723 20:06:52.753671   10538 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"
I0723 20:06:52.756726   10538 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
... skipping 105 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0723 20:06:52.794447   10538 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
I0723 20:06:52.826100   10538 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"
E0723 20:06:52.826496   10538 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
I0723 20:06:52.828522   10538 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.04s)
    --- PASS: TestReconcileInfrastructure/new_machine,_infrastructure_config_ready (0.03s)
    --- 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
I0723 20:06:53.056251   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0723 20:06:53.059993   10538 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0723 20:06:53.070269   10538 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-4pq55" "namespace"="test-machine-watches-65dt8" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0723 20:06:53.070408   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0723 20:06:53.178936   10538 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-4pq55" "namespace"="test-machine-watches-65dt8" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0723 20:06:53.179019   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0723 20:06:53.279570   10538 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-4pq55" "namespace"="test-machine-watches-65dt8" "noderef"="node-1"
E0723 20:06:53.292827   10538 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0723 20:06:53.292878   10538 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0723 20:06:53.342307   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-4pq55\" in namespace \"test-machine-watches-65dt8\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-4pq55" "namespace"="test-machine-watches-65dt8"
E0723 20:06:54.346116   10538 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-4pq55\" in namespace \"test-machine-watches-65dt8\", requeuing: requeue in 1s"  
E0723 20:06:54.354080   10538 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-4pq55\" in namespace \"test-machine-watches-65dt8\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-4pq55\" in namespace \"test-machine-watches-65dt8\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-4pq55" "namespace"="test-machine-watches-65dt8"
--- PASS: TestWatches (1.55s)
=== 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
I0723 20:06:54.576842   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-66vvl" "namespace"="test-machine-watches-65dt8" "count"=1
I0723 20:06:54.576915   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-66vvl" "namespace"="test-machine-watches-65dt8" "descendants"="Worker machines: machine-created-4pq55" "indirect descendants count"=0
I0723 20:06:54.592637   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-66vvl" "namespace"="test-machine-watches-65dt8" "count"=1
I0723 20:06:54.592702   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-66vvl" "namespace"="test-machine-watches-65dt8" "descendants"="Worker machines: machine-created-4pq55" "indirect descendants count"=0
I0723 20:06:55.354623   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-66vvl" "machine"="machine-created-4pq55" "namespace"="test-machine-watches-65dt8" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"6d5550fc-e878-4689-9fb1-bc36a564f246","apiVersion":"v1"}
E0723 20:06:55.415989   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-4pq55\" not found" "controller"="machine" "name"="machine-created-4pq55" "namespace"="test-machine-watches-65dt8"
E0723 20:06:56.465075   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-8j5nz\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-b9slx\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-b9slx: secrets \"machine-reconcile-b9slx-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-8j5nz" "namespace"="default"
I0723 20:06:57.466407   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-b9slx" "machine"="machine-created-8j5nz" "namespace"="default" "cause"="noderef is nil" "node"=null
I0723 20:06:57.504229   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-b9slx" "machine"="machine-created-8j5nz" "namespace"="default" "cause"="noderef is nil" "node"=null
I0723 20:06:57.546661   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-b9slx" "machine"="machine-created-8j5nz" "namespace"="default" "cause"="noderef is nil" "node"=null
E0723 20:06:57.582568   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-8j5nz\" not found" "controller"="machine" "name"="machine-created-8j5nz" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.21s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.21s)
=== 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
I0723 20:06:57.605335   10538 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"
I0723 20:06:57.605454   10538 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
I0723 20:06:57.613060   10538 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"
I0723 20:06:57.613234   10538 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" 
E0723 20:06:57.613862   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-b9slx\" not found" "controller"="cluster" "name"="machine-reconcile-b9slx" "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.01s)
    --- 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 119 lines ...
    --- PASS: TestMachineDeploymentSyncStatus/all_machines_are_running (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0723 20:06:57.744137   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pvwnd" "namespace"="test-mhc-xs5cs" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
I0723 20:06:57.779377   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0723 20:06:57.779455   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-ss7lk\" not found"  "cluster"="test-mhc-xs5cs/test-cluster-ss7lk"
E0723 20:06:57.884254   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-pvwnd\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-pvwnd\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-pvwnd" "namespace"="test-mhc-xs5cs"
=== 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
I0723 20:06:58.884551   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gtqs6" "namespace"="test-mhc-7n96k" 
I0723 20:06:58.884658   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-pvwnd" "namespace"="test-mhc-xs5cs" 
I0723 20:06:58.884704   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bnwfk" "namespace"="test-mhc-827px" 
I0723 20:06:58.884738   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jmp5c" "namespace"="test-mhc-n7qtd" 
I0723 20:06:58.906324   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0723 20:06:59.022000   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jmp5c" "namespace"="test-mhc-n7qtd" 
I0723 20:06:59.022529   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jmp5c" "namespace"="test-mhc-n7qtd" 
I0723 20:06:59.033824   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-jmp5c" "namespace"="test-mhc-n7qtd" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
E0723 20:06:59.049174   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-n7qtd/test-cluster-fb9n4"
E0723 20:06:59.053830   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-fb9n4\" not found" "controller"="cluster" "name"="test-cluster-fb9n4" "namespace"="test-mhc-n7qtd"
I0723 20:06:59.061909   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7vjsh" "namespace"="test-mhc-2klwk" 
I0723 20:06:59.079900   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0723 20:06:59.204166   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7vjsh" "namespace"="test-mhc-2klwk" 
E0723 20:06:59.268488   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-2klwk/test-cluster-24bhp"
I0723 20:06:59.275162   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7vjsh" "namespace"="test-mhc-2klwk" 
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0723 20:06:59.296900   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
inframachine created: test-mhc-machine-infra-jmzl6
I0723 20:06:59.330740   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-69f66
I0723 20:06:59.361085   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.361437   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
I0723 20:06:59.376833   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.377142   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
I0723 20:06:59.382868   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.383276   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
I0723 20:06:59.391213   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.391580   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
I0723 20:06:59.396309   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.396610   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
I0723 20:06:59.413231   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.413720   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
I0723 20:06:59.419179   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.419464   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
E0723 20:06:59.451051   10538 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-mjvj2"
E0723 20:06:59.451299   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mjvj2, got []"  "node"="test-mhc-node-mjvj2"
node created: test-mhc-node-mjvj2
I0723 20:06:59.455898   10538 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-69f66" "namespace"="test-mhc-rnplq" "noderef"="test-mhc-node-mjvj2"
I0723 20:06:59.460555   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
inframachine created: test-mhc-machine-infra-8d9kv
machine created: test-mhc-machine-qd5r5
I0723 20:06:59.480452   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
... skipping 70 lines ...
I0723 20:06:59.668339   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.669470   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.670474   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.672709   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.675173   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.676470   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.676921   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-qd5r5/"
E0723 20:06:59.683224   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t5rqg, got []"  "node"="test-mhc-node-t5rqg"
node created: test-mhc-node-t5rqg
E0723 20:06:59.683678   10538 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-t5rqg"
I0723 20:06:59.687528   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.688035   10538 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-rnplq/test-mhc-mccrk/test-mhc-machine-qd5r5/"
I0723 20:06:59.692363   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.711751   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
Cleaning up nodes, machines and infra machines.
I0723 20:06:59.721308   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.724705   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.725071   10538 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
I0723 20:06:59.748708   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-9nvvr" "machine"="test-mhc-machine-69f66" "namespace"="test-mhc-rnplq" "cause"="no control plane members" "node"={"kind":"Node","name":"test-mhc-node-mjvj2","uid":"a7b195b5-461e-47cd-8fe6-dc7c189e9905","apiVersion":"v1"}
I0723 20:06:59.761819   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:06:59.763282   10538 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-rnplq/test-mhc-mccrk/test-mhc-machine-69f66/"
I0723 20:06:59.763888   10538 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-rnplq/test-mhc-mccrk/test-mhc-machine-qd5r5/"
E0723 20:06:59.765714   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-rnplq/test-cluster-9nvvr"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E0723 20:06:59.784392   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-mccrk\" not found" "controller"="machinehealthcheck" "name"="test-mhc-mccrk" "namespace"="test-mhc-rnplq"
E0723 20:06:59.800179   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-69f66\" not found" "controller"="machine" "name"="test-mhc-machine-69f66" "namespace"="test-mhc-rnplq"
inframachine created: test-mhc-machine-infra-wfpd9
machine created: test-mhc-machine-kwqfp
E0723 20:07:00.068258   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-65dt8/machine-reconcile-66vvl"
I0723 20:07:00.784766   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mccrk" "namespace"="test-mhc-rnplq" 
I0723 20:07:00.784860   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
E0723 20:07:00.800473   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:00.801382   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0723 20:07:00.817889   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:00.819003   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:00.820815   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:00.827347   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:00.829815   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
... skipping 424 lines ...
I0723 20:07:01.797948   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.807001   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.810264   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.812061   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.812616   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.813725   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
E0723 20:07:01.820004   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:01.820298   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.820530   10538 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-6pfl5/test-mhc-cd98q/test-mhc-machine-kwqfp/"
E0723 20:07:01.829319   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-rc2xt, got []"  "node"="test-mhc-node-rc2xt"
node created: test-mhc-node-rc2xt
I0723 20:07:01.832660   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.832933   10538 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-6pfl5/test-mhc-cd98q/test-mhc-machine-kwqfp/"
I0723 20:07:01.835549   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
inframachine created: test-mhc-machine-infra-fgj22
machine created: test-mhc-machine-vpcn9
I0723 20:07:01.860920   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.865913   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:01.870751   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
... skipping 389 lines ...
I0723 20:07:02.857469   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.859523   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.860597   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.861667   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.862692   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.863651   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
E0723 20:07:02.864187   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:02.865102   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.866112   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.868251   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.870465   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.876690   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:02.879311   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
... skipping 328 lines ...
I0723 20:07:03.863835   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.867114   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.869300   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.871518   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.876036   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.878052   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.878556   10538 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-6pfl5/test-mhc-cd98q/test-mhc-machine-vpcn9/"
I0723 20:07:03.891701   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.892098   10538 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-6pfl5/test-mhc-cd98q/test-mhc-machine-vpcn9/"
E0723 20:07:03.892551   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tm5l4, got []"  "node"="test-mhc-node-tm5l4"
node created: test-mhc-node-tm5l4
I0723 20:07:03.893035   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
E0723 20:07:03.893272   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:03.893360   10538 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-6pfl5/test-mhc-cd98q/test-mhc-machine-vpcn9/"
I0723 20:07:03.900073   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
inframachine created: test-mhc-machine-infra-lpjf9
machine created: test-mhc-machine-jvgrf
I0723 20:07:03.917712   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.924107   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:03.925745   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
... skipping 327 lines ...
I0723 20:07:04.929076   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:04.935344   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:04.937144   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:04.944836   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:04.951235   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:04.956677   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
E0723 20:07:04.958626   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:04.959699   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:04.961123   10538 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-6pfl5/test-mhc-cd98q/test-mhc-machine-jvgrf/"
I0723 20:07:04.972855   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:04.973328   10538 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-6pfl5/test-mhc-cd98q/test-mhc-machine-jvgrf/"
E0723 20:07:05.030767   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7twlk, got []"  "node"="test-mhc-node-7twlk"
node created: test-mhc-node-7twlk
I0723 20:07:05.044561   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:05.045131   10538 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-6pfl5/test-mhc-cd98q/test-mhc-machine-jvgrf/test-mhc-node-7twlk"
Cleaning up nodes, machines and infra machines.
I0723 20:07:05.057606   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cd98q" "namespace"="test-mhc-6pfl5" 
I0723 20:07:05.058111   10538 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-6pfl5/test-mhc-cd98q/test-mhc-machine-jvgrf/"
Cleaning up nodes, machines and infra machines.
I0723 20:07:05.110876   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-qkjsj" "namespace"="test-mhc-6pfl5" "count"=2
I0723 20:07:05.110955   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-qkjsj" "namespace"="test-mhc-6pfl5" "descendants"="Worker machines: test-mhc-machine-jvgrf,test-mhc-machine-kwqfp,test-mhc-machine-vpcn9" "indirect descendants count"=1
I0723 20:07:05.115021   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-qkjsj" "namespace"="test-mhc-6pfl5" "count"=2
I0723 20:07:05.115073   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-qkjsj" "namespace"="test-mhc-6pfl5" "descendants"="Worker machines: test-mhc-machine-vpcn9,test-mhc-machine-jvgrf,test-mhc-machine-kwqfp" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
... skipping 7 lines ...
I0723 20:07:05.312834   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:05.353813   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:05.434766   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:05.595710   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:05.916711   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:05.959177   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-qkjsj" "machine"="test-mhc-machine-vpcn9" "namespace"="test-mhc-6pfl5" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-tm5l4"}
E0723 20:07:06.001538   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-vpcn9\" not found" "controller"="machine" "name"="test-mhc-machine-vpcn9" "namespace"="test-mhc-6pfl5"
I0723 20:07:06.557717   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:07.002061   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-qkjsj" "machine"="test-mhc-machine-jvgrf" "namespace"="test-mhc-6pfl5" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-7twlk"}
E0723 20:07:07.040930   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-jvgrf\" not found" "controller"="machine" "name"="test-mhc-machine-jvgrf" "namespace"="test-mhc-6pfl5"
I0723 20:07:07.838796   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
E0723 20:07:08.041307   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:09.041900   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-qkjsj" "machine"="test-mhc-machine-kwqfp" "namespace"="test-mhc-6pfl5" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-rc2xt"}
E0723 20:07:09.088294   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-kwqfp\" not found" "controller"="machine" "name"="test-mhc-machine-kwqfp" "namespace"="test-mhc-6pfl5"
I0723 20:07:10.102506   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:10.106520   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
E0723 20:07:10.107010   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:10.128334   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
E0723 20:07:10.131579   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-6pfl5/test-cluster-qkjsj"
E0723 20:07:10.204910   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-5mrvm, got []"  "node"="test-mhc-node-5mrvm"
node created: test-mhc-node-5mrvm
I0723 20:07:10.211858   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
inframachine created: test-mhc-machine-infra-mlxh6
machine created: test-mhc-machine-pc8sq
I0723 20:07:10.229069   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:10.247260   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
... skipping 5 lines ...
I0723 20:07:10.878912   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:11.129889   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:11.140193   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:11.149484   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:11.165834   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:11.173886   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
E0723 20:07:11.179027   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:11.179367   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:11.196056   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
node created: test-mhc-node-9mnzp
E0723 20:07:11.242911   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-9mnzp, got []"  "node"="test-mhc-node-9mnzp"
I0723 20:07:11.250709   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
inframachine created: test-mhc-machine-infra-7hlxw
I0723 20:07:11.260616   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:11.262351   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
machine created: test-mhc-machine-p57fr
I0723 20:07:11.271503   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:11.520343   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.190123   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.201610   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.207158   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.249131   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.255559   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.279934   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
E0723 20:07:12.286694   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:12.286988   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.317220   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
E0723 20:07:12.369865   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hfzng, got []"  "node"="test-mhc-node-hfzng"
node created: test-mhc-node-hfzng
Cleaning up nodes, machines and infra machines.
I0723 20:07:12.377285   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.387421   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.399157   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.410571   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
Cleaning up nodes, machines and infra machines.
I0723 20:07:12.420415   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:12.441233   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-l5ttn" "namespace"="test-mhc-4f5lt" "count"=2
I0723 20:07:12.441301   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-l5ttn" "namespace"="test-mhc-4f5lt" "descendants"="Worker machines: test-mhc-machine-74djl,test-mhc-machine-pc8sq,test-mhc-machine-p57fr" "indirect descendants count"=1
I0723 20:07:12.448591   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-l5ttn" "namespace"="test-mhc-4f5lt" "count"=2
I0723 20:07:12.448654   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-l5ttn" "namespace"="test-mhc-4f5lt" "descendants"="Worker machines: test-mhc-machine-74djl,test-mhc-machine-pc8sq,test-mhc-machine-p57fr" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout
E0723 20:07:12.466469   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-vl545\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-vl545\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-vl545" "namespace"="test-mhc-4f5lt"
inframachine created: test-mhc-machine-infra-ddmdd
machine created: test-mhc-machine-sbt6v
I0723 20:07:13.287248   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-l5ttn" "machine"="test-mhc-machine-74djl" "namespace"="test-mhc-4f5lt" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-5mrvm"}
E0723 20:07:13.336016   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-74djl\" not found" "controller"="machine" "name"="test-mhc-machine-74djl" "namespace"="test-mhc-4f5lt"
I0723 20:07:13.466703   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vl545" "namespace"="test-mhc-4f5lt" 
I0723 20:07:13.466807   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:13.495143   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0723 20:07:13.612903   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:13.622796   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:14.336521   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-l5ttn" "machine"="test-mhc-machine-pc8sq" "namespace"="test-mhc-4f5lt" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-9mnzp"}
E0723 20:07:14.374369   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-pc8sq\" not found" "controller"="machine" "name"="test-mhc-machine-pc8sq" "namespace"="test-mhc-4f5lt"
I0723 20:07:15.374826   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-l5ttn" "machine"="test-mhc-machine-p57fr" "namespace"="test-mhc-4f5lt" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-hfzng"}
E0723 20:07:15.413839   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-p57fr\" not found" "controller"="machine" "name"="test-mhc-machine-p57fr" "namespace"="test-mhc-4f5lt"
I0723 20:07:16.423274   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:16.432618   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
E0723 20:07:16.433572   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
E0723 20:07:16.507018   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cpq6p, got []"  "node"="test-mhc-node-cpq6p"
node created: test-mhc-node-cpq6p
E0723 20:07:16.507945   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cpq6p, got []"  "node"="test-mhc-node-cpq6p"
I0723 20:07:16.517818   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
inframachine created: test-mhc-machine-infra-7stzd
machine created: test-mhc-machine-b4rh5
I0723 20:07:16.541389   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:16.547152   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.445534   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.455832   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.465574   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
E0723 20:07:17.466602   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-4f5lt/test-cluster-l5ttn"
I0723 20:07:17.471386   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.477620   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.481401   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.490844   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.505419   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.520079   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.532414   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
E0723 20:07:17.540808   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-qtwhz, got []"  "node"="test-mhc-node-qtwhz"
node created: test-mhc-node-qtwhz
I0723 20:07:17.545493   10538 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-b4rh5" "namespace"="test-mhc-5rrf9" "noderef"="test-mhc-node-qtwhz"
I0723 20:07:17.549933   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
inframachine created: test-mhc-machine-infra-6h4lt
machine created: test-mhc-machine-klhm4
I0723 20:07:17.568808   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
... skipping 8 lines ...
I0723 20:07:17.748617   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.759653   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
Cleaning up nodes, machines and infra machines.
I0723 20:07:17.774563   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
Cleaning up nodes, machines and infra machines.
I0723 20:07:17.784099   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:17.784655   10538 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-5rrf9/test-mhc-b4pp8/test-mhc-machine-sbt6v/"
I0723 20:07:17.785748   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-k756p" "machine"="test-mhc-machine-klhm4" "namespace"="test-mhc-5rrf9" "cause"="noderef is nil" "node"=null
I0723 20:07:17.832752   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
E0723 20:07:17.833176   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-klhm4\" not found" "controller"="machine" "name"="test-mhc-machine-klhm4" "namespace"="test-mhc-5rrf9"
I0723 20:07:17.833262   10538 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-5rrf9/test-mhc-b4pp8/test-mhc-machine-sbt6v/"
I0723 20:07:17.833895   10538 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-5rrf9/test-mhc-b4pp8/test-mhc-machine-b4rh5/"
I0723 20:07:17.835881   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-k756p" "namespace"="test-mhc-5rrf9" "count"=2
I0723 20:07:17.835967   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-k756p" "namespace"="test-mhc-5rrf9" "descendants"="Worker machines: test-mhc-machine-sbt6v,test-mhc-machine-b4rh5" "indirect descendants count"=0
I0723 20:07:17.844324   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-k756p" "namespace"="test-mhc-5rrf9" "count"=2
I0723 20:07:17.844390   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-k756p" "namespace"="test-mhc-5rrf9" "descendants"="Worker machines: test-mhc-machine-b4rh5,test-mhc-machine-sbt6v" "indirect descendants count"=0
=== 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
E0723 20:07:17.855640   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-b4pp8\" not found" "controller"="machinehealthcheck" "name"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9"
inframachine created: test-mhc-machine-infra-hs27f
machine created: test-mhc-machine-8knzc
I0723 20:07:18.833694   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-k756p" "machine"="test-mhc-machine-sbt6v" "namespace"="test-mhc-5rrf9" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-cpq6p"}
I0723 20:07:18.855858   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b4pp8" "namespace"="test-mhc-5rrf9" 
I0723 20:07:18.855947   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:18.891350   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0723 20:07:18.904903   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-sbt6v\" not found" "controller"="machine" "name"="test-mhc-machine-sbt6v" "namespace"="test-mhc-5rrf9"
I0723 20:07:19.011705   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.019576   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.023024   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.024822   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.026631   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.028367   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
... skipping 417 lines ...
I0723 20:07:19.971788   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.973503   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.975296   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.977166   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.978839   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.980621   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
E0723 20:07:19.981239   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-b4rh5\" not found" "controller"="machine" "name"="test-mhc-machine-b4rh5" "namespace"="test-mhc-5rrf9"
I0723 20:07:19.982356   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.984020   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.985772   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.987460   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.989142   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:19.990822   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
... skipping 463 lines ...
I0723 20:07:20.984952   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:20.986778   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:20.988572   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:20.990364   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:20.990930   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:20.994370   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:20.994609   10538 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-fbwls/test-mhc-9ths4/test-mhc-machine-8knzc/"
E0723 20:07:20.995868   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:21.012691   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.013042   10538 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-fbwls/test-mhc-9ths4/test-mhc-machine-8knzc/"
E0723 20:07:21.027770   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hczv2, got []"  "node"="test-mhc-node-hczv2"
E0723 20:07:21.027984   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hczv2, got []"  "node"="test-mhc-node-hczv2"
node created: test-mhc-node-hczv2
I0723 20:07:21.035577   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.052075   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.058448   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.059928   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.060208   10538 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-fbwls/test-mhc-9ths4/test-mhc-machine-8knzc/test-mhc-node-hczv2"
I0723 20:07:21.086931   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.087360   10538 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-fbwls/test-mhc-9ths4/test-mhc-machine-8knzc/test-mhc-node-hczv2"
Cleaning up nodes, machines and infra machines.
I0723 20:07:21.092169   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.092579   10538 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-fbwls/test-mhc-9ths4/test-mhc-machine-8knzc/test-mhc-node-hczv2"
I0723 20:07:21.095896   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.096208   10538 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-fbwls/test-mhc-9ths4/test-mhc-machine-8knzc/"
I0723 20:07:21.110349   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2mwt2" "namespace"="test-mhc-fbwls" "descendants"="Worker machines: test-mhc-machine-8knzc" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0723 20:07:21.115468   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2mwt2" "namespace"="test-mhc-fbwls" "descendants"="Worker machines: test-mhc-machine-8knzc" "indirect descendants count"=1
I0723 20:07:21.202238   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" "creating"=1 "need"=1
I0723 20:07:21.202297   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" 
I0723 20:07:21.213389   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-vtxzq-qmzxh\"" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" 
I0723 20:07:21.284063   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9ths4" "namespace"="test-mhc-fbwls" 
I0723 20:07:21.292347   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:21.315259   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0723 20:07:21.324378   10538 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" 
I0723 20:07:21.437091   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:21.996574   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-2mwt2" "machine"="test-mhc-machine-8knzc" "namespace"="test-mhc-fbwls" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-hczv2"}
E0723 20:07:22.044341   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-8knzc\" not found" "controller"="machine" "name"="test-mhc-machine-8knzc" "namespace"="test-mhc-fbwls"
I0723 20:07:22.437307   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
E0723 20:07:22.858059   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-5rrf9/test-cluster-k756p"
I0723 20:07:23.053121   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:23.053931   10538 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" 
I0723 20:07:23.058784   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:23.059476   10538 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" 
I0723 20:07:23.069225   10538 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:23.069272   10538 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
... skipping 6 lines ...
I0723 20:07:23.096204   10538 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:23.096450   10538 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:23.438313   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:24.089890   10538 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:24.089948   10538 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.000643   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.001090   10538 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-wllhn/test-mhc-8265h/mhc-ms-vtxzq-qmzxh/"
I0723 20:07:25.012140   10538 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.021180   10538 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.021233   10538 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.032858   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.033212   10538 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-wllhn/test-mhc-8265h/mhc-ms-vtxzq-qmzxh/"
I0723 20:07:25.036070   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.036408   10538 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-wllhn/test-mhc-8265h/mhc-ms-vtxzq-qmzxh/"
I0723 20:07:25.036892   10538 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.045808   10538 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.045853   10538 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.052495   10538 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-pgrzf" "namespace"="test-mhc-wllhn" "count"=1
I0723 20:07:25.052580   10538 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-pgrzf" "namespace"="test-mhc-wllhn" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-vtxzq"
I0723 20:07:25.054396   10538 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" "machine"="mhc-ms-vtxzq-qmzxh"
I0723 20:07:25.057229   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-pgrzf" "namespace"="test-mhc-wllhn" "descendants"="Machine sets: mhc-ms-vtxzq;Worker machines: mhc-ms-vtxzq-qmzxh" "indirect descendants count"=1
I0723 20:07:25.059849   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.060234   10538 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-wllhn/test-mhc-8265h/mhc-ms-vtxzq-qmzxh/"
I0723 20:07:25.060431   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-pgrzf" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" "cause"="cluster is being deleted" "node"=null
I0723 20:07:25.061089   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8265h" "namespace"="test-mhc-wllhn" 
I0723 20:07:25.061129   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-pgrzf" "namespace"="test-mhc-wllhn" "descendants"="Worker machines: mhc-ms-vtxzq-qmzxh" "indirect descendants count"=1
E0723 20:07:25.069328   10538 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-vtxzq\" not found" "machineset"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn" 
E0723 20:07:25.069413   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-vtxzq\" not found" "controller"="machineset" "name"="mhc-ms-vtxzq" "namespace"="test-mhc-wllhn"
=== 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
I0723 20:07:25.241083   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
inframachine created: test-mhc-machine-infra-nzx9w
machine created: test-mhc-machine-kgtd6
I0723 20:07:25.262933   10538 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0723 20:07:25.290898   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.292854   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-pgrzf" "machine"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn" "cause"="cluster is being deleted" "node"=null
I0723 20:07:25.306584   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
E0723 20:07:25.330281   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-vtxzq-qmzxh\" not found" "controller"="machine" "name"="mhc-ms-vtxzq-qmzxh" "namespace"="test-mhc-wllhn"
I0723 20:07:25.354002   10538 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-kgtd6" "target"="test-mhc-fx6b6/test-mhc-9c8l5/test-mhc-machine-kgtd6/"
E0723 20:07:25.366896   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-74b6h, got []"  "node"="test-mhc-node-74b6h"
E0723 20:07:25.367110   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-74b6h, got []"  "node"="test-mhc-node-74b6h"
node created: test-mhc-node-74b6h
E0723 20:07:25.367376   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-74b6h, got []"  "node"="test-mhc-node-74b6h"
I0723 20:07:25.367832   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.374644   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.392137   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.398718   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.400850   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.403863   10538 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-kgtd6" "target"="test-mhc-fx6b6/test-mhc-9c8l5/test-mhc-machine-kgtd6/test-mhc-node-74b6h"
I0723 20:07:25.425718   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
Cleaning up nodes, machines and infra machines.
I0723 20:07:25.440262   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.443129   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.451590   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9c8l5" "namespace"="test-mhc-fx6b6" 
I0723 20:07:25.458439   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-l6x8z" "namespace"="test-mhc-fx6b6" "descendants"="Worker machines: test-mhc-machine-kgtd6" "indirect descendants count"=1
... skipping 270 lines ...
I0723 20:07:26.116048   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.117787   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.119506   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.122033   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.123762   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.125514   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
E0723 20:07:26.127076   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-fbwls/test-cluster-2mwt2"
I0723 20:07:26.127166   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.128830   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.130505   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.132181   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.133835   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.135414   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
... skipping 104 lines ...
I0723 20:07:26.380592   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.382927   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.384571   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.388562   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.390400   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.392079   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
E0723 20:07:26.393337   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-kgtd6\" not found" "controller"="machine" "name"="test-mhc-machine-kgtd6" "namespace"="test-mhc-fx6b6"
I0723 20:07:26.393826   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.395522   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.397283   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.398973   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.400638   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:26.402331   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
... skipping 467 lines ...
I0723 20:07:27.397190   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.399062   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.400730   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.402477   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.403016   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.404693   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
E0723 20:07:27.406193   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
I0723 20:07:27.406505   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.411482   10538 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-gvkqp" "target"="test-mhc-xfgk2/test-mhc-7s57j/test-mhc-machine-gvkqp/"
E0723 20:07:27.411981   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t2h7w, got []"  "node"="test-mhc-node-t2h7w"
E0723 20:07:27.412207   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t2h7w, got []"  "node"="test-mhc-node-t2h7w"
node created: test-mhc-node-t2h7w
E0723 20:07:27.412811   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t2h7w, got []"  "node"="test-mhc-node-t2h7w"
I0723 20:07:27.560265   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.588177   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.595080   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.599437   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.609830   10538 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-gvkqp" "target"="test-mhc-xfgk2/test-mhc-7s57j/test-mhc-machine-gvkqp/test-mhc-node-t2h7w"
I0723 20:07:27.635740   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.645550   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.669211   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
Cleaning up nodes, machines and infra machines.
I0723 20:07:27.674873   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.678821   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:27.691704   10538 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-gvkqp" "target"="test-mhc-xfgk2/test-mhc-7s57j/test-mhc-machine-gvkqp/"
I0723 20:07:27.706994   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-g7pkn" "namespace"="test-mhc-xfgk2" "descendants"="Worker machines: test-mhc-machine-gvkqp" "indirect descendants count"=1
I0723 20:07:27.713788   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-g7pkn" "namespace"="test-mhc-xfgk2" "descendants"="Worker machines: test-mhc-machine-gvkqp" "indirect descendants count"=1
--- PASS: TestMachineHealthCheck_Reconcile (30.01s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.04s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.13s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.20s)
... 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 (0.39s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (2.26s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0723 20:07:27.727658   10538 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
E0723 20:07:27.729845   10538 machinehealthcheck_controller.go:445]  "msg"="expected a Machine" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace
=== RUN   TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace
--- PASS: TestMachineToMachineHealthCheck (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_the_object_passed_isn't_a_machine (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_2_MachineHealthChecks_match_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_does_not_match_labels_for_the_Machine_in_the_same_namespace (0.00s)
    --- PASS: TestMachineToMachineHealthCheck/when_a_MachineHealthCheck_matches_labels_for_the_Machine_in_another_namespace (0.00s)
=== RUN   TestNodeToMachineHealthCheck
=== RUN   TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node
E0723 20:07:27.731700   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-7s57j\" not found" "controller"="machinehealthcheck" "name"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2"
E0723 20:07:27.732006   10538 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0723 20:07:27.732301   10538 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
E0723 20:07:27.732910   10538 machinehealthcheck_controller.go:480]  "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node node1, got [machine1 machine2]"  "node"="node1"
=== RUN   TestNodeToMachineHealthCheck/when_no_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_two_MachineHealthChecks_exist_for_the_Node_in_the_Machine's_namespace
=== RUN   TestNodeToMachineHealthCheck/when_a_MachineHealthCheck_exists_for_the_Node,_but_not_in_the_Machine's_cluster
--- PASS: TestNodeToMachineHealthCheck (0.00s)
    --- PASS: TestNodeToMachineHealthCheck/when_the_object_passed_isn't_a_Node (0.00s)
... skipping 31 lines ...
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_nil (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_not_an_int_or_percentage (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_an_int (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_a_40%_(of_5) (0.00s)
    --- PASS: TestGetMaxUnhealthy/when_maxUnhealthy_is_a_60%_(of_7) (0.00s)
=== RUN   TestPatchTargets
I0723 20:07:27.741252   10538 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0723 20:07:27.742012   10538 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0723 20:07:27.743837   10538 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
E0723 20:07:27.767377   10538 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
E0723 20:07:27.769759   10538 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 ...
I0723 20:07:27.975043   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-9fgzh-jt52d\"" "machineset"="ms-9fgzh" "namespace"="ms-test" 
I0723 20:07:27.975106   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-9fgzh" "namespace"="ms-test" 
I0723 20:07:27.989771   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-9fgzh-l8mzr\"" "machineset"="ms-9fgzh" "namespace"="ms-test" 
I0723 20:07:28.091372   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-9fgzh" "namespace"="ms-test" "creating"=1 "need"=2
I0723 20:07:28.091448   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-9fgzh" "namespace"="ms-test" 
I0723 20:07:28.118615   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-9fgzh-pwvc6\"" "machineset"="ms-9fgzh" "namespace"="ms-test" 
E0723 20:07:28.222814   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.222836   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.223114   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.326678   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.326747   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.326679   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.326781   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.326847   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.326898   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-pwvc6-nj42x, got []"  "node"="ms-9fgzh-pwvc6-nj42x"
E0723 20:07:28.372186   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.372309   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.372378   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.375112   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.375161   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.375342   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.375372   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.375526   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.375551   10538 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-9fgzh-l8mzr-mn5hr, got []"  "node"="ms-9fgzh-l8mzr-mn5hr"
E0723 20:07:28.381152   10538 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-9fgzh-pwvc6-nj42x for machine ms-test/ms-9fgzh-pwvc6: the cache is not started, can not read objects" "machineset"="ms-9fgzh" "namespace"="ms-test" 
I0723 20:07:28.406682   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-g7pkn" "machine"="test-mhc-machine-gvkqp" "namespace"="test-mhc-xfgk2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-t2h7w"}
E0723 20:07:28.444141   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-gvkqp\" not found" "controller"="machine" "name"="test-mhc-machine-gvkqp" "namespace"="test-mhc-xfgk2"
I0723 20:07:28.501836   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-9fgzh-l8mzr,ms-9fgzh-pwvc6" "indirect descendants count"=2
I0723 20:07:28.506423   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-9fgzh-pwvc6,ms-9fgzh-l8mzr" "indirect descendants count"=2
•I0723 20:07:28.507824   10538 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"
I0723 20:07:28.508941   10538 machine_controller_phases.go:219]  "msg"="Bootstrap provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0723 20:07:28.509008   10538 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"
I0723 20:07:28.509904   10538 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
... skipping 15 lines ...
I0723 20:07:28.530861   10538 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"
•I0723 20:07:28.533048   10538 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"
I0723 20:07:28.533986   10538 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"
I0723 20:07:28.534855   10538 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0723 20:07:28.535188   10538 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0723 20:07:28.535903   10538 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0723 20:07:28.537980   10538 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" 
••E0723 20:07:28.667943   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-r2nch\" not found" "controller"="cluster" "name"="test1-r2nch" "namespace"="default"
I0723 20:07:28.731964   10538 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-7s57j" "namespace"="test-mhc-xfgk2" 
I0723 20:07:29.874625   10538 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-mlx2p" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
•I0723 20:07:29.994214   10538 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-mlx2p" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0723 20:07:29.998666   10538 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-mlx2p" "namespace"="default"
E0723 20:07:31.015165   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-mlx2p: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-mlx2p" "namespace"="default"
•E0723 20:07:32.030978   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-wllhn/test-cluster-pgrzf"
E0723 20:07:32.042324   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-fx6b6/test-cluster-l6x8z"
E0723 20:07:32.056795   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-rkhb5\" not found" "controller"="cluster" "name"="test3-rkhb5" "namespace"="default"
E0723 20:07:33.057613   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-mlx2p: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-mlx2p" "namespace"="default"
E0723 20:07:34.082497   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-xfgk2/test-cluster-g7pkn"
E0723 20:07:34.083110   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-mlx2p: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-mlx2p" "namespace"="default"
•I0723 20:07:35.083605   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-9fgzh-pwvc6,ms-9fgzh-l8mzr" "indirect descendants count"=2
E0723 20:07:35.088037   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-lwwmb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-lwwmb" "namespace"="default"
E0723 20:07:36.088721   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-mlx2p: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-mlx2p" "namespace"="default"
E0723 20:07:37.097578   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-lwwmb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-lwwmb" "namespace"="default"
•E0723 20:07:37.646589   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-9nvvr\" for machine \"test-mhc-machine-qd5r5\" in namespace \"test-mhc-rnplq\": Cluster.cluster.x-k8s.io \"test-cluster-9nvvr\" not found" "controller"="machine" "name"="test-mhc-machine-qd5r5" "namespace"="test-mhc-rnplq"
E0723 20:07:38.098203   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-mlx2p: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-mlx2p" "namespace"="default"
E0723 20:07:39.098855   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-lwwmb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-lwwmb" "namespace"="default"
E0723 20:07:40.107780   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-mlx2p: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-mlx2p" "namespace"="default"
I0723 20:07:40.232132   10538 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-6qxqp" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0723 20:07:40.241339   10538 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-6qxqp" "namespace"="default" 
E0723 20:07:40.254320   10538 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-6qxqp" "namespace"="default"
E0723 20:07:41.108679   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-lwwmb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-lwwmb" "namespace"="default"
I0723 20:07:41.275879   10538 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-6qxqp" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0723 20:07:41.276092   10538 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-6qxqp" "namespace"="default" "noderef"="id-node-1"
E0723 20:07:41.290527   10538 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-6qxqp" "namespace"="default"
I0723 20:07:42.109305   10538 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-9fgzh-pwvc6,ms-9fgzh-l8mzr" "indirect descendants count"=2
E0723 20:07:42.114020   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-mlx2p: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-mlx2p" "namespace"="default"
•I0723 20:07:42.175189   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0723 20:07:42.175234   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.187667   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-fqspw-6657c7fddb-sx282\"" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.187734   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.199823   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-fqspw-6657c7fddb-r5ctk\"" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.266539   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0723 20:07:42.266580   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.277319   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-fqspw-6657c7fddb-2c7rr\"" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.277375   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.286179   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-fqspw-6657c7fddb-2zdrr\"" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.290922   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-8j6vf" "machine"="test6-6qxqp" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"54e8bf89-8f91-4396-9f18-69d0f563e7a5","apiVersion":"v1"}
E0723 20:07:42.312345   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-6qxqp\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-6qxqp" "namespace"="default"
I0723 20:07:42.394872   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0723 20:07:42.394916   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.408560   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-fqspw-6657c7fddb-lpxl2\"" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" 
I0723 20:07:42.482404   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0723 20:07:42.482449   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" 
I0723 20:07:42.500772   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-fqspw-cdfc6fd6c-zbp94\"" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" 
E0723 20:07:42.620795   10538 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-fqspw-cdfc6fd6c-zbp94-bqs5j for machine md-test/md-fqspw-cdfc6fd6c-zbp94: the cache is not started, can not read objects" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" 
I0723 20:07:42.652101   10538 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0723 20:07:42.652156   10538 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0723 20:07:42.658419   10538 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "machine"="md-fqspw-6657c7fddb-2c7rr"
I0723 20:07:42.669256   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0723 20:07:42.669379   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" 
I0723 20:07:42.680414   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-fqspw-cdfc6fd6c-cfgmf\"" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" 
... skipping 5 lines ...
I0723 20:07:42.883596   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-fqspw-cdfc6fd6c-qn4lm\"" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" 
I0723 20:07:43.014654   10538 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0723 20:07:43.014689   10538 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0723 20:07:43.018760   10538 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-fqspw-6657c7fddb" "namespace"="md-test" "machine"="md-fqspw-6657c7fddb-lpxl2"
I0723 20:07:43.109371   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0723 20:07:43.109407   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
E0723 20:07:43.114630   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-lwwmb: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-lwwmb" "namespace"="default"
I0723 20:07:43.118247   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-fqspw-74d45c49c5-5w2qr\"" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
I0723 20:07:43.338956   10538 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2
I0723 20:07:43.339007   10538 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0723 20:07:43.342769   10538 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-8j6vf" "machine"="test6-6qxqp" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"54e8bf89-8f91-4396-9f18-69d0f563e7a5","apiVersion":"v1"}
E0723 20:07:43.343606   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-6qxqp\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-6qxqp" "namespace"="default"
I0723 20:07:43.345303   10538 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" "machine"="md-fqspw-cdfc6fd6c-cfgmf"
I0723 20:07:43.455696   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=2
I0723 20:07:43.455736   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
I0723 20:07:43.466368   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-fqspw-74d45c49c5-5jkml\"" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
I0723 20:07:43.596509   10538 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0723 20:07:43.596579   10538 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0723 20:07:43.600486   10538 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-fqspw-cdfc6fd6c" "namespace"="md-test" "machine"="md-fqspw-cdfc6fd6c-zbp94"
I0723 20:07:43.708828   10538 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0723 20:07:43.708874   10538 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
I0723 20:07:43.717412   10538 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-fqspw-74d45c49c5-md58v\"" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
E0723 20:07:43.807923   10538 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="md-test/test-cluster"
•

Ran 16 of 16 Specs in 16.039 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.04s)
PASS
Tearing down test suite
E0723 20:07:43.811639   10538 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:07:43.811683   10538 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-010732667/tls.crt: no such file or directory"  
E0723 20:07:43.811695   10538 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:07:43.811708   10538 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-010732667/tls.crt: no such file or directory"  
I0723 20:07:43.811830   10538 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0723 20:07:43.811875   10538 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0723 20:07:43.811906   10538 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0723 20:07:43.811935   10538 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0723 20:07:43.812135   10538 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0723 20:07:43.812164   10538 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0723 20:07:43.811831   10538 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
E0723 20:07:43.818226   10538 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error creating client and cache for remote cluster: error creating dynamic rest mapper for remote cluster \"md-test/test-cluster\": Get http://127.0.0.1:40421/api?timeout=10s: dial tcp 127.0.0.1:40421: connect: connection refused" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
E0723 20:07:43.818663   10538 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"md-test/test-cluster\": failed to retrieve kubeconfig secret for Cluster md-test/test-cluster: Get http://127.0.0.1:40421/api/v1/namespaces/md-test/secrets/test-cluster-kubeconfig: dial tcp 127.0.0.1:40421: connect: connection refused" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
E0723 20:07:43.819003   10538 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"md-test/test-cluster\": failed to retrieve kubeconfig secret for Cluster md-test/test-cluster: Get http://127.0.0.1:40421/api/v1/namespaces/md-test/secrets/test-cluster-kubeconfig: dial tcp 127.0.0.1:40421: connect: connection refused" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
E0723 20:07:43.819597   10538 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to patch MachineSet's Status: Patch http://127.0.0.1:40421/apis/cluster.x-k8s.io/v1alpha3/namespaces/md-test/machinesets/md-fqspw-74d45c49c5/status: dial tcp 127.0.0.1:40421: connect: connection refused" "machineset"="md-fqspw-74d45c49c5" "namespace"="md-test" 
E0723 20:07:43.819664   10538 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: Patch http://127.0.0.1:40421/apis/cluster.x-k8s.io/v1alpha3/namespaces/md-test/machinesets/md-fqspw-74d45c49c5/status: dial tcp 127.0.0.1:40421: connect: connection refused" "controller"="machineset" "name"="md-fqspw-74d45c49c5" "namespace"="md-test"
E0723 20:07:43.819982   10538 event.go:272] Unable to write event: 'Post http://127.0.0.1:40421/api/v1/namespaces/md-test/events: dial tcp 127.0.0.1:40421: connect: connection refused' (may retry after sleeping)
E0723 20:07:43.843954   10538 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:40421/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1242&timeout=10s&timeoutSeconds=579&watch=true: dial tcp 127.0.0.1:40421: connect: connection refused
E0723 20:07:43.844206   10538 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:40421/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1242&timeout=10s&timeoutSeconds=522&watch=true: dial tcp 127.0.0.1:40421: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	64.564s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.01s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 260 lines ...
I0723 20:06:54.937017   11026 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0723 20:06:54.937128   11026 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=43107
I0723 20:06:54.946914   11026 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}}}
I0723 20:06:55.047252   11026 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0723 20:06:55.147588   11026 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I0723 20:06:55.290069   11026 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0723 20:06:57.325204   11026 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-pdvkg/test-cluster"
•E0723 20:06:57.794390   11026 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-c26vc/test-cluster"
•E0723 20:06:58.370185   11026 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:44611/?timeout=50ms: dial tcp 127.0.0.1:44611: connect: connection refused"  "cluster"="cluster-cache-test-mkzpb/test-cluster"
•I0723 20:06:58.590204   11026 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":{}}}
I0723 20:06:58.790612   11026 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0723 20:06:58.790683   11026 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0723 20:06:58.790774   11026 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•E0723 20:06:59.320047   11026 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:06:59.320098   11026 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-186893920/tls.crt: no such file or directory"  
E0723 20:06:59.320130   11026 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:06:59.320158   11026 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-186893920/tls.crt: no such file or directory"  
I0723 20:06:59.320380   11026 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0723 20:06:59.320464   11026 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0723 20:06:59.389949   11026 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:33147/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:33147: connect: connection refused


Ran 5 of 5 Specs in 17.963 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (17.96s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	18.099s
?   	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
I0723 20:07:04.141563   11586 controller.go:131]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.00s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0723 20:07:04.142875   11586 controller.go:127]  "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
I0723 20:07:04.143539   11586 controller.go:137]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0723 20:07:04.143713   11586 controller.go:137]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 6 lines ...
=== RUN   TestKubeadmControlPlaneReconciler_adoption/adopts_v1alpha2_cluster_secrets
I0723 20:07:07.186007   11586 controller.go:247]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-wosiif" "kubeadmControlPlane"="kcp-foo-wosiif" "namespace"="test" 
=== RUN   TestKubeadmControlPlaneReconciler_adoption/Deleted_KubeadmControlPlanes_don't_adopt_machines
I0723 20:07:07.186630   11586 controller.go:247]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-t3oees" "kubeadmControlPlane"="kcp-foo-t3oees" "namespace"="test" 
=== RUN   TestKubeadmControlPlaneReconciler_adoption/refuses_to_adopt_Machines_that_are_more_than_one_version_old
I0723 20:07:07.187246   11586 controller.go:247]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-egm5vn" "kubeadmControlPlane"="kcp-foo-egm5vn" "namespace"="test" 
--- FAIL: TestKubeadmControlPlaneReconciler_adoption (2.45s)
    --- FAIL: TestKubeadmControlPlaneReconciler_adoption/adopts_existing_Machines (0.00s)
        controller_test.go:501: 
            Unexpected non-nil/non-zero extra argument at index 1:
            	<*errors.withStack>: failed to check if Kubernetes version is supported: failed to retrieve kubeconfig secret for Cluster test/kcp-foo-pumkui: secrets "kcp-foo-pumkui-kubeconfig" not found
    --- FAIL: TestKubeadmControlPlaneReconciler_adoption/adopts_v1alpha2_cluster_secrets (0.00s)
        controller_test.go:597: 
            Unexpected non-nil/non-zero extra argument at index 1:
            	<*errors.withStack>: failed to check if Kubernetes version is supported: failed to retrieve kubeconfig secret for Cluster test/kcp-foo-wosiif: secrets "kcp-foo-wosiif-kubeconfig" not found
    --- FAIL: TestKubeadmControlPlaneReconciler_adoption/Deleted_KubeadmControlPlanes_don't_adopt_machines (0.00s)
        controller_test.go:685: 
            Expected
                <string>: failed to check if Kubernetes version is supported: failed to retrieve kubeconfig secret for Cluster test/kcp-foo-t3oees: secrets "kcp-foo-t3oees-kubeconfig" not found
            to contain substring
                <string>: has just been deleted
    --- PASS: TestKubeadmControlPlaneReconciler_adoption/refuses_to_adopt_Machines_that_are_more_than_one_version_old (2.45s)
=== RUN   TestReconcileInitializeControlPlane
I0723 20:07:09.642407   11586 controller.go:247]  "msg"="Reconcile KubeadmControlPlane" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0723 20:07:13.244605   11586 controller.go:362]  "msg"="Initializing control plane" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" "Desired"=1 "Existing"=0
... skipping 172 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
I0723 20:07:16.218162   11586 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
I0723 20:07:16.218278   11586 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: 1627070811
Will run 1 of 1 specs

E0723 20:07:16.250831   11586 controller.go:127]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-f1xqmn\" not found" "kubeadmControlPlane"="kcp-foo-f1xqmn" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.029 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0723 20:07:16.252182   11586 controller.go:247]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-swowvn" "kubeadmControlPlane"="kcp-foo-swowvn" "namespace"="test" 
I0723 20:07:19.338326   11586 controller.go:342]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-swowvn" "kubeadmControlPlane"="kcp-foo-swowvn" "namespace"="test" "needRollout"=["kcp-foo-swowvn-5f6gb"]
I0723 20:07:19.338440   11586 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-swowvn" "kubeadmControlPlane"="kcp-foo-swowvn" "namespace"="test" "failures"="[machine kcp-foo-swowvn-d5fk2 does not have APIServerPodHealthy condition, machine kcp-foo-swowvn-d5fk2 does not have ControllerManagerPodHealthy condition, machine kcp-foo-swowvn-d5fk2 does not have SchedulerPodHealthy condition, machine kcp-foo-swowvn-d5fk2 does not have EtcdPodHealthy condition, machine kcp-foo-swowvn-d5fk2 does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (3.09s)
FAIL
I0723 20:07:19.339089   11586 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
FAIL	sigs.k8s.io/cluster-api/controlplane/kubeadm/controllers	28.381s
I0723 20:07:03.685971   11536 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0723 20:07:03.686097   11536 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0723 20:07:03.686130   11536 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0723 20:07:03.686145   11536 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0723 20:07:03.686221   11536 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Machine"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
I0723 20:07:03.686237   11536 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
... skipping 51 lines ...
==================================
Random Seed: 1627070810
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: 1627070810
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.001 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestMachineCollection (0.00s)
=== RUN   TestUpdateEtcdConditions
=== RUN   TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines
=== RUN   TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition
... skipping 297 lines ...
    --- PASS: TestUpdateKubeProxyImageInfo/returns_error_if_image_repository_is_invalid (0.00s)
    --- PASS: TestUpdateKubeProxyImageInfo/does_not_update_image_repository_when_no_kube-proxy_update_is_requested (0.00s)
=== RUN   TestRemoveMachineFromKubeadmConfigMap
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_find_kubeadm-config_for_Kubernetes_version_<_1.22.0
E0723 20:07:06.282896   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:07:14.605978   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:07:23.594445   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:07:34.724678   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:07:51.197907   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:08:04.206635   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:08:21.854025   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:08:42.777352   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:09:13.793926   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0723 20:09:58.951117   11536 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0
--- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s)
... skipping 371 lines ...
I0723 20:07:12.219419   11817 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0723 20:07:12.219843   11817 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0723 20:07:12.320289   11817 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0723 20:07:12.420695   11817 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0723 20:07:12.420757   11817 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0723 20:07:12.500644   11817 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-0vhbgh"} 
E0723 20:07:12.529856   11817 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"
•I0723 20:07:13.593586   11817 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-d27e5a"} 
E0723 20:07:13.678975   11817 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"
•E0723 20:07:14.745473   11817 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"
E0723 20:07:15.769596   11817 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"
•E0723 20:07:16.913868   11817 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"
E0723 20:07:17.939510   11817 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"
•E0723 20:07:18.954967   11817 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"
•E0723 20:07:18.963434   11817 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:07:18.963473   11817 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-690947461/tls.crt: no such file or directory"  
E0723 20:07:18.963490   11817 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:07:18.963506   11817 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-690947461/tls.crt: no such file or directory"  
I0723 20:07:18.963527   11817 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0723 20:07:18.963577   11817 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0723 20:07:18.963645   11817 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 5 of 5 Specs in 20.669 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (20.67s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/addons/controllers	20.711s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
... skipping 61 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0723 20:07:06.248771   12116 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 91 lines ...
I0723 20:07:19.025206   12116 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0723 20:07:19.059029   12116 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0723 20:07:19.081412   12116 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0723 20:07:19.083440   12116 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0723 20:07:19.119870   12116 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0723 20:07:19.151588   12116 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••E0723 20:07:19.154414   12116 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:07:19.154470   12116 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-171513158/tls.crt: no such file or directory"  
E0723 20:07:19.154494   12116 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0723 20:07:19.154514   12116 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-171513158/tls.crt: no such file or directory"  
I0723 20:07:19.154520   12116 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 9 of 9 Specs in 12.874 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (12.87s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	13.102s
?   	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 200 lines ...
I0723 20:07:41.815207   15055 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"
I0723 20:07:41.815229   15055 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0723 20:07:41.815413   15055 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0723 20:07:41.816114   15055 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0723 20:07:41.816264   15055 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=46397
I0723 20:07:41.816331   15055 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••E0723 20:07:42.982764   15055 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
I0723 20:07:42.982813   15055 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0723 20:07:42.982821   15055 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-654220193/tls.crt: no such file or directory"  


Ran 14 of 14 Specs in 8.060 seconds
SUCCESS! -- 14 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestPatch (8.06s)
=== 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.033s
FAIL
make: *** [Makefile:116: test] Error 1
+ EXIT_VALUE=2
+ set +o xtrace