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

No Test Failures!


Error lines from build-log.txt

... skipping 777 lines ...
I0615 14:43:53.630714    8551 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0615 14:43:54.331356    8551 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" 
•I0615 14:43:54.341368    8551 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 13.302 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.30s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	43.962s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 316 lines ...
=== RUN   Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined
--- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s)
=== RUN   Test_clusterctlClient_GetProviderComponents
=== RUN   Test_clusterctlClient_GetProviderComponents/Pass
=== RUN   Test_clusterctlClient_GetProviderComponents/Fail
--- PASS: Test_clusterctlClient_GetProviderComponents (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s)
=== RUN   Test_getComponentsByName_withEmptyVariables
--- PASS: Test_getComponentsByName_withEmptyVariables (0.00s)
=== RUN   Test_clusterctlClient_templateOptionsToVariables
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts)
... skipping 1398 lines ...
I0615 14:43:44.675141   10505 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"clusterName":"","bootstrap":{},"infrastructureRef":{}},"status":{"bootstrapReady":false,"infrastructureReady":false}}}
I0615 14:43:44.675218   10505 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0615 14:43:44.675249   10505 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinehealthcheck" 
I0615 14:43:44.675282   10505 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
I0615 14:43:44.682871   10505 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
I0615 14:43:44.682944   10505 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
2022/06/15 14:43:44 http: TLS handshake error from 127.0.0.1:43978: 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
I0615 14:43:44.872563   10505 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"
I0615 14:43:44.879948   10505 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
I0615 14:43:44.928825   10505 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
I0615 14:43:44.934409   10505 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"
E0615 14:43:44.934827   10505 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
I0615 14:43:44.935528   10505 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.01s)
    --- PASS: TestReconcileInfrastructure/new_machine,_infrastructure_config_ready (0.01s)
    --- 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
I0615 14:43:45.230252   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0615 14:43:45.331026   10505 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0615 14:43:45.356387   10505 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-nx8mt" "namespace"="test-machine-watches-cpmfj" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0615 14:43:45.356481   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0615 14:43:45.468846   10505 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-nx8mt" "namespace"="test-machine-watches-cpmfj" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0615 14:43:45.469009   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0615 14:43:45.569814   10505 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-nx8mt" "namespace"="test-machine-watches-cpmfj" "noderef"="node-1"
E0615 14:43:45.588914   10505 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0615 14:43:45.588989   10505 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0615 14:43:45.654310   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-nx8mt\" in namespace \"test-machine-watches-cpmfj\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-nx8mt" "namespace"="test-machine-watches-cpmfj"
E0615 14:43:46.659327   10505 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-nx8mt\" in namespace \"test-machine-watches-cpmfj\", requeuing: requeue in 1s"  
E0615 14:43:46.667171   10505 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-nx8mt\" in namespace \"test-machine-watches-cpmfj\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-nx8mt\" in namespace \"test-machine-watches-cpmfj\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-nx8mt" "namespace"="test-machine-watches-cpmfj"
--- PASS: TestWatches (1.76s)
=== 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
I0615 14:43:46.783577   10505 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-2f74m" "namespace"="test-machine-watches-cpmfj" "count"=1
I0615 14:43:46.783650   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-2f74m" "namespace"="test-machine-watches-cpmfj" "descendants"="Worker machines: machine-created-nx8mt" "indirect descendants count"=0
I0615 14:43:46.800276   10505 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-2f74m" "namespace"="test-machine-watches-cpmfj" "count"=1
I0615 14:43:46.800358   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-2f74m" "namespace"="test-machine-watches-cpmfj" "descendants"="Worker machines: machine-created-nx8mt" "indirect descendants count"=0
I0615 14:43:47.667730   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-2f74m" "machine"="machine-created-nx8mt" "namespace"="test-machine-watches-cpmfj" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"72c9e09c-8738-4999-a7e8-16bf547d2b41","apiVersion":"v1"}
E0615 14:43:47.712748   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-nx8mt\" not found" "controller"="machine" "name"="machine-created-nx8mt" "namespace"="test-machine-watches-cpmfj"
E0615 14:43:48.808720   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-kqqt6\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-fb5sz\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-fb5sz: secrets \"machine-reconcile-fb5sz-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-kqqt6" "namespace"="default"
I0615 14:43:49.809369   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fb5sz" "machine"="machine-created-kqqt6" "namespace"="default" "cause"="noderef is nil" "node"=null
I0615 14:43:49.859749   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fb5sz" "machine"="machine-created-kqqt6" "namespace"="default" "cause"="noderef is nil" "node"=null
I0615 14:43:49.882832   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fb5sz" "machine"="machine-created-kqqt6" "namespace"="default" "cause"="noderef is nil" "node"=null
E0615 14:43:49.934968   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-kqqt6\" not found" "controller"="machine" "name"="machine-created-kqqt6" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.26s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.26s)
=== 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 13 lines ...
    --- PASS: TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta (0.00s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set (0.00s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.01s)
=== RUN   TestReconcileRequest
=== RUN   TestReconcileRequest/machine_should_be_created
I0615 14:43:49.970434   10505 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="created" "namespace"="default" "err"="cannot create a metadata client without a rest config"
E0615 14:43:49.974425   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-fb5sz\" not found" "controller"="cluster" "name"="machine-reconcile-fb5sz" "namespace"="default"
=== RUN   TestReconcileRequest/machine_should_be_updated
I0615 14:43:49.977482   10505 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="updated" "namespace"="default" "err"="cannot create a metadata client without a rest config"
=== RUN   TestReconcileRequest/machine_should_be_deleted
I0615 14:43:49.982588   10505 machine_controller.go:305]  "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="deleted" "namespace"="default" "cause"="noderef is nil" "node"=null
--- PASS: TestReconcileRequest (0.02s)
    --- PASS: TestReconcileRequest/machine_should_be_created (0.01s)
... skipping 111 lines ...
    --- PASS: TestMachineDeploymentSyncStatus/scaling_down (0.00s)
    --- PASS: TestMachineDeploymentSyncStatus/machine_set_failed (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0615 14:43:50.098056   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n59cp" "namespace"="test-mhc-pcg7w" 
I0615 14:43:50.144174   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0615 14:43:50.145454   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-wdtj9\" not found"  "cluster"="test-mhc-pcg7w/test-cluster-wdtj9"
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
E0615 14:43:50.182126   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-n59cp\" not found" "controller"="machinehealthcheck" "name"="test-mhc-n59cp" "namespace"="test-mhc-pcg7w"
=== 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
error cannot retrieve mhc in ctx: MachineHealthCheck.cluster.x-k8s.io "test-mhc-6txcs" not foundI0615 14:43:51.182420   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n59cp" "namespace"="test-mhc-pcg7w" 
I0615 14:43:51.182527   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-2nk9d" "namespace"="test-mhc-czg7t" 
I0615 14:43:51.182549   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6wr26" "namespace"="test-mhc-jcmch" 
I0615 14:43:51.182575   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6txcs" "namespace"="test-mhc-49mf9" 
I0615 14:43:51.230024   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0615 14:43:51.251025   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6txcs" "namespace"="test-mhc-49mf9" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
I0615 14:43:51.343165   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6txcs" "namespace"="test-mhc-49mf9" 
E0615 14:43:51.354652   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-49mf9/test-cluster-pn25v"
E0615 14:43:51.357119   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-pn25v\" not found" "controller"="cluster" "name"="test-cluster-pn25v" "namespace"="test-mhc-49mf9"
I0615 14:43:51.395926   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-db62h" "namespace"="test-mhc-fxcqn" 
I0615 14:43:51.429414   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0615 14:43:51.454263   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-db62h" "namespace"="test-mhc-fxcqn" 
E0615 14:43:51.513315   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-fxcqn/test-cluster-x4r5j"
I0615 14:43:51.521148   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-db62h" "namespace"="test-mhc-fxcqn" 
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0615 14:43:51.548040   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
inframachine created: test-mhc-machine-infra-hx647
I0615 14:43:51.584255   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-rgbx6
I0615 14:43:51.622478   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.622796   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-rgbx6/"
I0615 14:43:51.650285   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.650718   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-rgbx6/"
I0615 14:43:51.656444   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.657346   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-rgbx6/"
I0615 14:43:51.667924   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.668236   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-rgbx6/"
I0615 14:43:51.676035   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.676374   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-rgbx6/"
I0615 14:43:51.688985   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.689637   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-rgbx6/"
I0615 14:43:51.698987   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.699394   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-rgbx6/"
node created: test-mhc-node-svtkb
E0615 14:43:51.704815   10505 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-svtkb"
E0615 14:43:51.705044   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-svtkb, got []"  "node"="test-mhc-node-svtkb"
I0615 14:43:51.707730   10505 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p" "noderef"="test-mhc-node-svtkb"
E0615 14:43:51.714373   10505 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-svtkb"
E0615 14:43:51.714433   10505 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-svtkb"
E0615 14:43:51.716287   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-svtkb, got []"  "node"="test-mhc-node-svtkb"
E0615 14:43:51.716434   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-svtkb, got []"  "node"="test-mhc-node-svtkb"
I0615 14:43:51.716807   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
inframachine created: test-mhc-machine-infra-9qffq
machine created: test-mhc-machine-2fq5p
I0615 14:43:51.751375   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.758083   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.760208   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
... skipping 34 lines ...
I0615 14:43:51.880273   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.882881   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.886149   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.888424   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.890885   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.895035   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.897024   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-2fq5p/"
I0615 14:43:51.918260   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.918848   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-2fq5p/"
node created: test-mhc-node-q9fq4
E0615 14:43:51.942771   10505 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-q9fq4"
E0615 14:43:51.943037   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-q9fq4, got []"  "node"="test-mhc-node-q9fq4"
I0615 14:43:51.945350   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.953532   10505 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-7sz5p/test-mhc-r5hq5/test-mhc-machine-2fq5p/"
I0615 14:43:51.963285   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:51.992415   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
Cleaning up nodes, machines and infra machines.
I0615 14:43:52.009231   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:52.013251   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:52.013750   10505 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-7sz5p/test-mhc-r5hq5/test-mhc-machine-rgbx6/"
E0615 14:43:52.054617   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-7sz5p/test-cluster-6qcs5"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E0615 14:43:52.081074   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="nodes \"test-mhc-node-q9fq4\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
inframachine created: test-mhc-machine-infra-zcgs5
machine created: test-mhc-machine-qxrdj
E0615 14:43:52.260398   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-r5hq5\" not found" "controller"="machinehealthcheck" "name"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p"
E0615 14:43:52.372100   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-cpmfj/machine-reconcile-2f74m"
E0615 14:43:53.081459   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:43:53.260728   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:53.275766   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0615 14:43:53.403449   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r5hq5" "namespace"="test-mhc-7sz5p" 
I0615 14:43:53.403526   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:53.404670   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:53.406450   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
... skipping 301 lines ...
I0615 14:43:54.072692   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.074367   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.076091   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.077835   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.079574   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.081322   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
E0615 14:43:54.081778   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
I0615 14:43:54.083071   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.085352   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.087112   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.088938   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.090701   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:54.092426   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
... skipping 463 lines ...
I0615 14:43:55.084422   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.086060   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.087734   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.089921   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.090432   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.092035   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
E0615 14:43:55.093330   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:43:55.100736   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.101259   10505 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-q6k2z/test-mhc-vnvmv/test-mhc-machine-qxrdj/"
I0615 14:43:55.115009   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.115249   10505 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-q6k2z/test-mhc-vnvmv/test-mhc-machine-qxrdj/"
node created: test-mhc-node-xb2qb
E0615 14:43:55.155221   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-xb2qb, got []"  "node"="test-mhc-node-xb2qb"
I0615 14:43:55.164943   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
inframachine created: test-mhc-machine-infra-tt7xc
machine created: test-mhc-machine-hhqjt
I0615 14:43:55.184543   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.189770   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:55.197151   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
... skipping 328 lines ...
I0615 14:43:56.082048   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.084006   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.085970   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.088064   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.090075   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.092112   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
E0615 14:43:56.093870   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
I0615 14:43:56.094136   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.096134   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.098149   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.100187   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.105135   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:56.107953   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
... skipping 385 lines ...
I0615 14:43:57.132264   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.135412   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.137006   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.144492   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.147105   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.149738   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
E0615 14:43:57.152113   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:43:57.152308   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.153791   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.155508   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.157070   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.158672   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:57.160230   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
... skipping 290 lines ...
I0615 14:43:58.144966   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:58.147617   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:58.149818   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:58.152046   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:58.156401   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:58.161538   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
E0615 14:43:58.166569   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
I0615 14:43:58.168161   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:58.168832   10505 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-q6k2z/test-mhc-vnvmv/test-mhc-machine-hhqjt/"
I0615 14:43:58.187693   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:58.188058   10505 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-q6k2z/test-mhc-vnvmv/test-mhc-machine-hhqjt/"
E0615 14:43:58.202696   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-m9b4s, got []"  "node"="test-mhc-node-m9b4s"
node created: test-mhc-node-m9b4s
I0615 14:43:58.211253   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
inframachine created: test-mhc-machine-infra-ztc2r
machine created: test-mhc-machine-9cs5j
I0615 14:43:58.232430   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:58.244728   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
... skipping 264 lines ...
I0615 14:43:59.173578   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.176002   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.178454   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.180906   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.182998   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.184354   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
E0615 14:43:59.184935   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:43:59.186672   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.189190   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.191877   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.196296   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.199500   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:43:59.202202   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
... skipping 304 lines ...
I0615 14:44:00.224241   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:44:00.226201   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:44:00.228091   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:44:00.230826   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:44:00.236945   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:44:00.244219   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
E0615 14:44:00.256874   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
I0615 14:44:00.259392   10505 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-q6k2z/test-mhc-vnvmv/test-mhc-machine-9cs5j/"
node created: test-mhc-node-nbgzc
E0615 14:44:00.259460   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-nbgzc, got []"  "node"="test-mhc-node-nbgzc"
Cleaning up nodes, machines and infra machines.
I0615 14:44:00.277783   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vnvmv" "namespace"="test-mhc-q6k2z" 
I0615 14:44:00.278347   10505 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-q6k2z/test-mhc-vnvmv/test-mhc-machine-9cs5j/"
Cleaning up nodes, machines and infra machines.
I0615 14:44:00.337633   10505 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-t4knw" "namespace"="test-mhc-q6k2z" "count"=2
I0615 14:44:00.337720   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-t4knw" "namespace"="test-mhc-q6k2z" "descendants"="Worker machines: test-mhc-machine-qxrdj,test-mhc-machine-hhqjt,test-mhc-machine-9cs5j" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
I0615 14:44:00.345185   10505 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-t4knw" "namespace"="test-mhc-q6k2z" "count"=2
I0615 14:44:00.345255   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-t4knw" "namespace"="test-mhc-q6k2z" "descendants"="Worker machines: test-mhc-machine-qxrdj,test-mhc-machine-hhqjt,test-mhc-machine-9cs5j" "indirect descendants count"=1
... skipping 7 lines ...
I0615 14:44:00.636205   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:00.677415   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:00.758529   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:00.919644   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:01.241845   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:01.257432   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-t4knw" "machine"="test-mhc-machine-qxrdj" "namespace"="test-mhc-q6k2z" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-xb2qb"}
E0615 14:44:01.308905   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-qxrdj\" not found" "controller"="machine" "name"="test-mhc-machine-qxrdj" "namespace"="test-mhc-q6k2z"
I0615 14:44:01.886761   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
E0615 14:44:02.311614   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:44:03.167824   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:03.312216   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-t4knw" "machine"="test-mhc-machine-hhqjt" "namespace"="test-mhc-q6k2z" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-m9b4s"}
E0615 14:44:03.361281   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-hhqjt\" not found" "controller"="machine" "name"="test-mhc-machine-hhqjt" "namespace"="test-mhc-q6k2z"
I0615 14:44:04.362209   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-t4knw" "machine"="test-mhc-machine-9cs5j" "namespace"="test-mhc-q6k2z" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-nbgzc"}
E0615 14:44:04.412949   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9cs5j\" not found" "controller"="machine" "name"="test-mhc-machine-9cs5j" "namespace"="test-mhc-q6k2z"
E0615 14:44:05.358754   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-q6k2z/test-cluster-t4knw"
I0615 14:44:05.444695   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:05.470845   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
E0615 14:44:05.474766   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
E0615 14:44:05.568433   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-h77j7, got []"  "node"="test-mhc-node-h77j7"
I0615 14:44:05.568914   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
node created: test-mhc-node-h77j7
I0615 14:44:05.583844   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
inframachine created: test-mhc-machine-infra-dg2lf
machine created: test-mhc-machine-gfxls
I0615 14:44:05.632028   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:05.643790   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:05.651609   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:05.674025   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:05.723574   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:05.804955   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:05.966328   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:06.287750   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
E0615 14:44:06.475200   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:44:06.929200   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:07.489604   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:07.497281   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:07.509036   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:07.518482   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:07.526092   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
E0615 14:44:07.531895   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
I0615 14:44:07.532065   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:07.556635   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
node created: test-mhc-node-xwlxw
E0615 14:44:07.617415   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-xwlxw, got []"  "node"="test-mhc-node-xwlxw"
I0615 14:44:07.630949   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
inframachine created: test-mhc-machine-infra-l586q
I0615 14:44:07.650117   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:07.654371   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
machine created: test-mhc-machine-5vgt4
I0615 14:44:07.667065   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:08.211607   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
E0615 14:44:08.532346   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:44:09.544847   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:09.572806   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:09.582231   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:09.603805   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:09.610353   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:09.653484   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:09.660016   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
E0615 14:44:09.663313   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
E0615 14:44:09.671757   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-k5r94, got []"  "node"="test-mhc-node-k5r94"
node created: test-mhc-node-k5r94
Cleaning up nodes, machines and infra machines.
I0615 14:44:09.686172   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
I0615 14:44:09.704132   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
Cleaning up nodes, machines and infra machines.
I0615 14:44:09.742026   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6j8tj" "namespace"="test-mhc-rfj5q" 
... skipping 8 lines ...
I0615 14:44:09.821840   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
inframachine created: test-mhc-machine-infra-jcbjl
I0615 14:44:09.839099   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-c98fv
I0615 14:44:09.863160   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:09.869289   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
E0615 14:44:10.663992   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:44:11.664696   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-pzsgd" "machine"="test-mhc-machine-x7q6j" "namespace"="test-mhc-rfj5q" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-h77j7"}
E0615 14:44:11.729317   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-x7q6j\" not found" "controller"="machine" "name"="test-mhc-machine-x7q6j" "namespace"="test-mhc-rfj5q"
I0615 14:44:12.730101   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-pzsgd" "machine"="test-mhc-machine-gfxls" "namespace"="test-mhc-rfj5q" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-xwlxw"}
E0615 14:44:12.795968   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-gfxls\" not found" "controller"="machine" "name"="test-mhc-machine-gfxls" "namespace"="test-mhc-rfj5q"
I0615 14:44:13.796564   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-pzsgd" "machine"="test-mhc-machine-5vgt4" "namespace"="test-mhc-rfj5q" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-k5r94"}
E0615 14:44:13.847905   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-5vgt4\" not found" "controller"="machine" "name"="test-mhc-machine-5vgt4" "namespace"="test-mhc-rfj5q"
E0615 14:44:14.802966   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-rfj5q/test-cluster-pzsgd"
I0615 14:44:14.856545   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:14.861171   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
E0615 14:44:14.861536   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
node created: test-mhc-node-2zdfr
E0615 14:44:14.871849   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-2zdfr, got []"  "node"="test-mhc-node-2zdfr"
I0615 14:44:14.880180   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
inframachine created: test-mhc-machine-infra-mbsqf
I0615 14:44:14.897926   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
machine created: test-mhc-machine-skgh4
I0615 14:44:14.898992   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:14.912364   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
E0615 14:44:15.862147   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:44:16.878593   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.886082   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.899116   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.907096   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.919135   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.925253   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.942148   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.969467   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.979299   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:16.983630   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.000933   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
node created: test-mhc-node-7xnfc
E0615 14:44:17.010501   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7xnfc, got []"  "node"="test-mhc-node-7xnfc"
I0615 14:44:17.025328   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.030488   10505 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-skgh4" "namespace"="test-mhc-tgzwz" "noderef"="test-mhc-node-7xnfc"
inframachine created: test-mhc-machine-infra-kr2b5
machine created: test-mhc-machine-b6n2w
I0615 14:44:17.062578   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.070302   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.071931   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.075401   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.080300   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.105125   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.118515   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.128012   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
E0615 14:44:17.143797   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:44:17.143829   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
Cleaning up nodes, machines and infra machines.
I0615 14:44:17.168339   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
Cleaning up nodes, machines and infra machines.
I0615 14:44:17.177619   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.178287   10505 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-tgzwz/test-mhc-gljz6/test-mhc-machine-c98fv/"
I0615 14:44:17.203673   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.204923   10505 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-tgzwz/test-mhc-gljz6/test-mhc-machine-c98fv/"
I0615 14:44:17.206111   10505 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-tgzwz/test-mhc-gljz6/test-mhc-machine-skgh4/"
I0615 14:44:17.220482   10505 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-jxklv" "namespace"="test-mhc-tgzwz" "count"=3
I0615 14:44:17.220679   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-jxklv" "namespace"="test-mhc-tgzwz" "descendants"="Worker machines: test-mhc-machine-c98fv,test-mhc-machine-skgh4,test-mhc-machine-b6n2w" "indirect descendants count"=0
I0615 14:44:17.227545   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.227963   10505 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-jxklv" "namespace"="test-mhc-tgzwz" "count"=3
I0615 14:44:17.228019   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-jxklv" "namespace"="test-mhc-tgzwz" "descendants"="Worker machines: test-mhc-machine-b6n2w,test-mhc-machine-c98fv,test-mhc-machine-skgh4" "indirect descendants count"=0
I0615 14:44:17.228184   10505 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-tgzwz/test-mhc-gljz6/test-mhc-machine-c98fv/"
I0615 14:44:17.228620   10505 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-tgzwz/test-mhc-gljz6/test-mhc-machine-skgh4/"
=== 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
I0615 14:44:17.241312   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gljz6" "namespace"="test-mhc-tgzwz" 
I0615 14:44:17.275035   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
inframachine created: test-mhc-machine-infra-7v9qg
... skipping 398 lines ...
I0615 14:44:18.180044   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.181866   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.183625   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.185213   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.186863   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.188715   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
E0615 14:44:18.189857   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-b6n2w\" not found" "controller"="machine" "name"="test-mhc-machine-b6n2w" "namespace"="test-mhc-tgzwz"
I0615 14:44:18.190409   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.192003   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.193632   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.195227   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.196914   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:18.198764   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
... skipping 412 lines ...
I0615 14:44:19.227065   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.228885   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.230652   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.232853   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.234529   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.236314   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
E0615 14:44:19.237592   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-c98fv\" not found" "controller"="machine" "name"="test-mhc-machine-c98fv" "namespace"="test-mhc-tgzwz"
I0615 14:44:19.238230   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.239970   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.241744   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.243504   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.245311   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:19.247106   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
... skipping 468 lines ...
I0615 14:44:20.279051   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.280821   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.282732   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.284496   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.286281   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.288083   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
E0615 14:44:20.289566   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-skgh4\" not found" "controller"="machine" "name"="test-mhc-machine-skgh4" "namespace"="test-mhc-tgzwz"
I0615 14:44:20.289749   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.291470   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.293252   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.295020   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.296867   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:20.298713   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
... skipping 477 lines ...
I0615 14:44:21.295802   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.297536   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.298102   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.299228   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.300956   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.302709   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
E0615 14:44:21.302893   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
I0615 14:44:21.303288   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.303543   10505 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-xdcg8/test-mhc-htg9d/test-mhc-machine-j48hz/"
E0615 14:44:21.309436   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hn56m, got []"  "node"="test-mhc-node-hn56m"
E0615 14:44:21.309711   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hn56m, got []"  "node"="test-mhc-node-hn56m"
node created: test-mhc-node-hn56m
I0615 14:44:21.313277   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.313564   10505 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-xdcg8/test-mhc-htg9d/test-mhc-machine-j48hz/"
I0615 14:44:21.316443   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.331211   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.345063   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.345427   10505 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-xdcg8/test-mhc-htg9d/test-mhc-machine-j48hz/test-mhc-node-hn56m"
I0615 14:44:21.359596   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.359993   10505 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-xdcg8/test-mhc-htg9d/test-mhc-machine-j48hz/test-mhc-node-hn56m"
I0615 14:44:21.364651   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.365048   10505 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-xdcg8/test-mhc-htg9d/test-mhc-machine-j48hz/test-mhc-node-hn56m"
Cleaning up nodes, machines and infra machines.
I0615 14:44:21.374408   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.374801   10505 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-xdcg8/test-mhc-htg9d/test-mhc-machine-j48hz/"
I0615 14:44:21.386737   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-w56gv" "namespace"="test-mhc-xdcg8" "descendants"="Worker machines: test-mhc-machine-j48hz" "indirect descendants count"=1
I0615 14:44:21.391011   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-w56gv" "namespace"="test-mhc-xdcg8" "descendants"="Worker machines: test-mhc-machine-j48hz" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0615 14:44:21.499298   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-bpg9w" "namespace"="test-mhc-rkrg2" "creating"=1 "need"=1
I0615 14:44:21.499380   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-bpg9w" "namespace"="test-mhc-rkrg2" 
I0615 14:44:21.517927   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-bpg9w-98w4x\"" "machineset"="mhc-ms-bpg9w" "namespace"="test-mhc-rkrg2" 
I0615 14:44:21.534532   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-htg9d" "namespace"="test-mhc-xdcg8" 
I0615 14:44:21.584654   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:21.606589   10505 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0615 14:44:21.735670   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:21.736421   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
E0615 14:44:22.256720   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-tgzwz/test-cluster-jxklv"
E0615 14:44:22.303409   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:44:22.738786   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:23.304094   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-w56gv" "machine"="test-mhc-machine-j48hz" "namespace"="test-mhc-xdcg8" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-hn56m"}
E0615 14:44:23.350905   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-j48hz\" not found" "controller"="machine" "name"="test-mhc-machine-j48hz" "namespace"="test-mhc-xdcg8"
I0615 14:44:23.739828   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:24.359857   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:24.360761   10505 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-bpg9w" "namespace"="test-mhc-rkrg2" 
I0615 14:44:24.372895   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:24.372958   10505 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-bpg9w" "namespace"="test-mhc-rkrg2" 
I0615 14:44:24.413369   10505 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
... skipping 7 lines ...
I0615 14:44:24.442886   10505 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
I0615 14:44:24.442934   10505 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
I0615 14:44:24.740864   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:25.432347   10505 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
I0615 14:44:25.432398   10505 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.000583   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.001025   10505 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-rkrg2/test-mhc-n4jd6/mhc-ms-bpg9w-98w4x/"
I0615 14:44:26.009037   10505 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-bpg9w" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.015850   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.016202   10505 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-rkrg2/test-mhc-n4jd6/mhc-ms-bpg9w-98w4x/"
I0615 14:44:26.022150   10505 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.022470   10505 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.029321   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.029398   10505 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-bpg9w" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.029691   10505 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-rkrg2/test-mhc-n4jd6/mhc-ms-bpg9w-98w4x/"
I0615 14:44:26.045097   10505 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-bpg9w" "namespace"="test-mhc-rkrg2" "machine"="mhc-ms-bpg9w-98w4x"
I0615 14:44:26.046764   10505 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-xvq24" "namespace"="test-mhc-rkrg2" "count"=1
I0615 14:44:26.046814   10505 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-xvq24" "namespace"="test-mhc-rkrg2" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-bpg9w"
I0615 14:44:26.047596   10505 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.047693   10505 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" 
I0615 14:44:26.050462   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n4jd6" "namespace"="test-mhc-rkrg2" 
... skipping 47 lines ...
I0615 14:44:26.277190   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.278931   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.280742   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.282565   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.283996   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.284259   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-xvq24" "machine"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2" "cause"="cluster is being deleted" "node"=null
E0615 14:44:26.296204   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-kwfmr, got []"  "node"="test-mhc-node-kwfmr"
E0615 14:44:26.296204   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-kwfmr, got []"  "node"="test-mhc-node-kwfmr"
E0615 14:44:26.296289   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-kwfmr, got []"  "node"="test-mhc-node-kwfmr"
node created: test-mhc-node-kwfmr
E0615 14:44:26.416925   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-bpg9w-98w4x\" not found" "controller"="machine" "name"="mhc-ms-bpg9w-98w4x" "namespace"="test-mhc-rkrg2"
E0615 14:44:26.417366   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-xdcg8/test-cluster-w56gv"
I0615 14:44:26.429940   10505 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-tz8cb" "target"="test-mhc-gk4xr/test-mhc-bd2gd/test-mhc-machine-tz8cb/"
I0615 14:44:26.444979   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.486428   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.498606   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.502359   10505 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-tz8cb" "target"="test-mhc-gk4xr/test-mhc-bd2gd/test-mhc-machine-tz8cb/test-mhc-node-kwfmr"
I0615 14:44:26.529104   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
Cleaning up nodes, machines and infra machines.
I0615 14:44:26.544683   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.552403   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.563147   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bd2gd" "namespace"="test-mhc-gk4xr" 
I0615 14:44:26.572622   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-fmv68" "namespace"="test-mhc-gk4xr" "descendants"="Worker machines: test-mhc-machine-tz8cb" "indirect descendants count"=1
... skipping 386 lines ...
I0615 14:44:27.449448   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.451260   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.453094   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.454882   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.456727   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.458560   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
E0615 14:44:27.459706   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-tz8cb\" not found" "controller"="machine" "name"="test-mhc-machine-tz8cb" "namespace"="test-mhc-gk4xr"
I0615 14:44:27.460345   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.462148   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.463883   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.465640   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.467472   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:27.469205   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
... skipping 485 lines ...
I0615 14:44:28.448623   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.450473   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.452653   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.454424   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.456253   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.458091   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
E0615 14:44:28.460223   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
I0615 14:44:28.460343   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.462333   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.464435   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.467139   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.469090   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:28.471042   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
... skipping 512 lines ...
I0615 14:44:29.464449   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.466912   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.467628   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.468723   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.470461   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.471781   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
E0615 14:44:29.472147   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
I0615 14:44:29.475094   10505 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-6fjwh" "target"="test-mhc-qt6tq/test-mhc-j2fvq/test-mhc-machine-6fjwh/"
I0615 14:44:29.486299   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
node created: test-mhc-node-mp6v2
E0615 14:44:29.549702   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mp6v2, got []"  "node"="test-mhc-node-mp6v2"
E0615 14:44:29.549710   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mp6v2, got []"  "node"="test-mhc-node-mp6v2"
E0615 14:44:29.550092   10505 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-mp6v2, got []"  "node"="test-mhc-node-mp6v2"
I0615 14:44:29.557281   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.578854   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.583507   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.587257   10505 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-6fjwh" "target"="test-mhc-qt6tq/test-mhc-j2fvq/test-mhc-machine-6fjwh/test-mhc-node-mp6v2"
I0615 14:44:29.606234   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.622407   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.641986   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
Cleaning up nodes, machines and infra machines.
I0615 14:44:29.647139   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.649126   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:29.658077   10505 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-6fjwh" "target"="test-mhc-qt6tq/test-mhc-j2fvq/test-mhc-machine-6fjwh/"
I0615 14:44:29.658811   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-k2w58" "namespace"="test-mhc-qt6tq" "descendants"="Worker machines: test-mhc-machine-6fjwh" "indirect descendants count"=1
I0615 14:44:29.663846   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-k2w58" "namespace"="test-mhc-qt6tq" "descendants"="Worker machines: test-mhc-machine-6fjwh" "indirect descendants count"=1
--- PASS: TestMachineHealthCheck_Reconcile (39.59s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.07s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.11s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.04s)
... 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.52s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (3.09s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0615 14:44:29.667754   10505 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
E0615 14:44:29.668869   10505 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
E0615 14:44:29.670018   10505 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0615 14:44:29.670163   10505 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
E0615 14:44:29.670431   10505 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
I0615 14:44:29.672211   10505 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0615 14:44:29.672612   10505 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0615 14:44:29.673756   10505 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
=== RUN   TestGetTargetsFromMHC/with_machines_having_skip-remediation_or_paused_annotation
E0615 14:44:29.677524   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-j2fvq\" not found" "controller"="machinehealthcheck" "name"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq"
I0615 14:44:29.677700   10505 machinehealthcheck_targets.go:176]  "msg"="skipping remediation"  "machine"="machine5" "reason"="machine has \"cluster.x-k8s.io/skip-remediation\" annotation"
I0615 14:44:29.677731   10505 machinehealthcheck_targets.go:176]  "msg"="skipping remediation"  "machine"="machine6" "reason"="machine has \"cluster.x-k8s.io/paused\" annotation"
--- PASS: TestGetTargetsFromMHC (0.00s)
    --- PASS: TestGetTargetsFromMHC/with_no_matching_machines (0.00s)
    --- PASS: TestGetTargetsFromMHC/when_a_machine's_node_is_missing (0.00s)
    --- PASS: TestGetTargetsFromMHC/when_a_machine's_labels_do_not_match_the_selector (0.00s)
... skipping 19 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
E0615 14:44:29.680928   10505 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
E0615 14:44:29.682302   10505 machineset_controller.go:569]  "msg"="Unable to convert selector" "error"="\"bad-operator\" is not a valid pod selector operator" "machine"="match" "machineset"="" "namespace"="" 
--- PASS: TestHasMatchingLabels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_do_not_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_empty_selector (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_bad_selector (0.00s)
=== RUN   TestMachineToDelete
... skipping 57 lines ...
=== RUN   TestGinkgoSuite
Running Suite: Controllers Suite
================================
Random Seed: 1655304210
Will run 16 of 16 specs

•E0615 14:44:29.805914   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-9l8fk\" not found" "controller"="cluster" "name"="test1-9l8fk" "namespace"="default"
I0615 14:44:30.472724   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-k2w58" "machine"="test-mhc-machine-6fjwh" "namespace"="test-mhc-qt6tq" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-mp6v2"}
E0615 14:44:30.504657   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-6fjwh\" not found" "controller"="machine" "name"="test-mhc-machine-6fjwh" "namespace"="test-mhc-qt6tq"
I0615 14:44:30.677879   10505 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2fvq" "namespace"="test-mhc-qt6tq" 
I0615 14:44:30.923103   10505 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-57wrc" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
•I0615 14:44:31.038291   10505 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-57wrc" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0615 14:44:31.042059   10505 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-57wrc" "namespace"="default"
E0615 14:44:32.053967   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-57wrc: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-57wrc" "namespace"="default"
•E0615 14:44:33.065264   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-rkrg2/test-cluster-xvq24"
E0615 14:44:33.076177   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-gk4xr/test-cluster-fmv68"
E0615 14:44:33.088827   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-l8vph\" not found" "controller"="cluster" "name"="test3-l8vph" "namespace"="default"
E0615 14:44:34.089628   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-57wrc: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-57wrc" "namespace"="default"
E0615 14:44:35.100511   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-57wrc: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-57wrc" "namespace"="default"
•E0615 14:44:36.112822   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-qt6tq/test-cluster-k2w58"
E0615 14:44:36.116293   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-6gd88: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-6gd88" "namespace"="default"
E0615 14:44:37.117049   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-57wrc: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-57wrc" "namespace"="default"
E0615 14:44:38.128575   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-6gd88: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-6gd88" "namespace"="default"
•E0615 14:44:38.700623   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-2fq5p\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-2fq5p" "namespace"="test-mhc-7sz5p"
E0615 14:44:39.129331   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-57wrc: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-57wrc" "namespace"="default"
E0615 14:44:39.712458   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-6qcs5\" for machine \"test-mhc-machine-rgbx6\" in namespace \"test-mhc-7sz5p\": Cluster.cluster.x-k8s.io \"test-cluster-6qcs5\" not found" "controller"="machine" "name"="test-mhc-machine-rgbx6" "namespace"="test-mhc-7sz5p"
E0615 14:44:40.130140   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-6gd88: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-6gd88" "namespace"="default"
E0615 14:44:41.141086   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-57wrc: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-57wrc" "namespace"="default"
I0615 14:44:41.226508   10505 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-4hddq" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0615 14:44:41.235239   10505 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-4hddq" "namespace"="default" 
E0615 14:44:41.250025   10505 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-4hddq" "namespace"="default"
E0615 14:44:42.141854   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-6gd88: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-6gd88" "namespace"="default"
I0615 14:44:42.265117   10505 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-4hddq" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0615 14:44:42.265421   10505 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-4hddq" "namespace"="default" "noderef"="id-node-1"
E0615 14:44:42.278170   10505 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-4hddq" "namespace"="default"
E0615 14:44:43.146352   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-57wrc: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-57wrc" "namespace"="default"

------------------------------
• [SLOW TEST:5.043 seconds]
Cluster Reconciler
/home/prow/go/src/sigs.k8s.io/cluster-api/controllers/cluster_controller_test.go:45
  Should successfully set Status.ControlPlaneInitialized on the cluster object if controlplane is ready
... skipping 2 lines ...
I0615 14:44:43.268551   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0615 14:44:43.268592   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.277023   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-rzrkq-6657c7fddb-2lm2m\"" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.277094   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.278699   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-4f2fm" "machine"="test6-4hddq" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"39f804a0-1ac4-425a-9303-13c9660d68ab","apiVersion":"v1"}
I0615 14:44:43.292341   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-rzrkq-6657c7fddb-57xpw\"" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
E0615 14:44:43.298182   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-4hddq\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-4hddq" "namespace"="default"
I0615 14:44:43.401030   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0615 14:44:43.401084   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.410180   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-rzrkq-6657c7fddb-2552p\"" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.410257   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.421467   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-rzrkq-6657c7fddb-fzp4n\"" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.470046   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0615 14:44:43.470109   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.480303   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rzrkq-6657c7fddb-q9x4t\"" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" 
I0615 14:44:43.587403   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0615 14:44:43.587444   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" 
I0615 14:44:43.597007   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rzrkq-cdfc6fd6c-hr99n\"" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" 
E0615 14:44:43.795699   10505 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-rzrkq-cdfc6fd6c-hr99n-grbxw for machine md-test/md-rzrkq-cdfc6fd6c-hr99n: the cache is not started, can not read objects" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" 
I0615 14:44:43.821634   10505 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0615 14:44:43.821676   10505 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0615 14:44:43.825612   10505 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "machine"="md-rzrkq-6657c7fddb-2552p"
I0615 14:44:43.934842   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0615 14:44:43.934903   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" 
I0615 14:44:43.944291   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rzrkq-cdfc6fd6c-vwgxx\"" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" 
I0615 14:44:44.134043   10505 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1
I0615 14:44:44.134086   10505 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0615 14:44:44.138177   10505 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "machine"="md-rzrkq-6657c7fddb-fzp4n"
E0615 14:44:44.147198   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-6gd88: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-6gd88" "namespace"="default"
I0615 14:44:44.246250   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0615 14:44:44.246292   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" 
I0615 14:44:44.255533   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rzrkq-cdfc6fd6c-5nws9\"" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" 
I0615 14:44:44.318852   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-4f2fm" "machine"="test6-4hddq" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"39f804a0-1ac4-425a-9303-13c9660d68ab","apiVersion":"v1"}
E0615 14:44:44.319840   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-4hddq\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-4hddq" "namespace"="default"
I0615 14:44:44.507860   10505 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0615 14:44:44.507915   10505 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0615 14:44:44.512143   10505 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rzrkq-6657c7fddb" "namespace"="md-test" "machine"="md-rzrkq-6657c7fddb-q9x4t"
I0615 14:44:44.757613   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0615 14:44:44.757656   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" 
I0615 14:44:44.767038   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rzrkq-74d45c49c5-j87fd\"" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" 
... skipping 2 lines ...
I0615 14:44:44.992355   10505 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "machine"="md-rzrkq-cdfc6fd6c-hr99n"
I0615 14:44:45.101553   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=2
I0615 14:44:45.101595   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" 
I0615 14:44:45.111218   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rzrkq-74d45c49c5-tshjn\"" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" 
I0615 14:44:45.147652   10505 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test6-4f2fm" "namespace"="default" "count"=1
I0615 14:44:45.147737   10505 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test6-4f2fm" "namespace"="default" "descendants"="Control plane machines: test6-4hddq" "indirect descendants count"=0
E0615 14:44:45.163480   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-57wrc: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-57wrc" "namespace"="default"
I0615 14:44:45.340880   10505 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0615 14:44:45.340926   10505 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0615 14:44:45.345103   10505 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "machine"="md-rzrkq-cdfc6fd6c-vwgxx"
I0615 14:44:45.360116   10505 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-rzrkq-6657c7fddb-2lm2m" "namespace"="md-test" 
I0615 14:44:45.360151   10505 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-rzrkq-6657c7fddb-2lm2m" "namespace"="md-test" 
I0615 14:44:45.376215   10505 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-rzrkq-6657c7fddb-57xpw" "namespace"="md-test" 
I0615 14:44:45.376259   10505 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-rzrkq-6657c7fddb-57xpw" "namespace"="md-test" 
I0615 14:44:45.386946   10505 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test6-4f2fm" "machine"="test6-4hddq" "namespace"="default" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"id-node-1","uid":"39f804a0-1ac4-425a-9303-13c9660d68ab","apiVersion":"v1"}
E0615 14:44:45.387806   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get /, Kind= \"\" for Machine \"test6-4hddq\" in namespace \"default\": failed to retrieve  external object \"default\"/\"\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="machine" "name"="test6-4hddq" "namespace"="default"
I0615 14:44:45.454300   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0615 14:44:45.454418   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" 
I0615 14:44:45.464068   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-rzrkq-74d45c49c5-jg9wz\"" "machineset"="md-rzrkq-74d45c49c5" "namespace"="md-test" 
•I0615 14:44:45.686037   10505 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"
E0615 14:44:45.686421   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinedeployments.cluster.x-k8s.io \"md-rzrkq\" not found" "controller"="machinedeployment" "name"="md-rzrkq" "namespace"="md-test"
I0615 14:44:45.686878   10505 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=0
I0615 14:44:45.686909   10505 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-rzrkq-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0615 14:44:45.687006   10505 machine_controller_phases.go:219]  "msg"="Bootstrap provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0615 14:44:45.687065   10505 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"
I0615 14:44:45.688044   10505 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0615 14:44:45.688089   10505 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
... skipping 15 lines ...
I0615 14:44:45.700049   10505 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"
•I0615 14:44:45.701863   10505 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"
I0615 14:44:45.702852   10505 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"
I0615 14:44:45.703797   10505 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0615 14:44:45.703836   10505 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0615 14:44:45.704506   10505 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0615 14:44:45.705690   10505 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" 
•I0615 14:44:45.778756   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-8qt87" "namespace"="ms-test" "creating"=2 "need"=2
I0615 14:44:45.778806   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-8qt87" "namespace"="ms-test" 
I0615 14:44:45.795951   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-8qt87-ncf8m\"" "machineset"="ms-8qt87" "namespace"="ms-test" 
I0615 14:44:45.796009   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-8qt87" "namespace"="ms-test" 
I0615 14:44:45.813678   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-8qt87-9nhbj\"" "machineset"="ms-8qt87" "namespace"="ms-test" 
I0615 14:44:45.919314   10505 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-8qt87" "namespace"="ms-test" "creating"=1 "need"=2
I0615 14:44:45.919388   10505 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-8qt87" "namespace"="ms-test" 
I0615 14:44:45.933907   10505 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-8qt87-pd2mv\"" "machineset"="ms-8qt87" "namespace"="ms-test" 
E0615 14:44:46.161647   10505 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-8qt87-pd2mv-dmn9v for machine ms-test/ms-8qt87-pd2mv: the cache is not started, can not read objects" "machineset"="ms-8qt87" "namespace"="ms-test" 
E0615 14:44:46.164233   10505 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-6gd88: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-6gd88" "namespace"="default"
E0615 14:44:46.292821   10505 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="ms-test/test-cluster"
•

Ran 16 of 16 Specs in 16.612 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.61s)
PASS
Tearing down test suite
I0615 14:44:46.295836   10505 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0615 14:44:46.295898   10505 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0615 14:44:46.295922   10505 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0615 14:44:46.295945   10505 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0615 14:44:46.295946   10505 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0615 14:44:46.295967   10505 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0615 14:44:46.295841   10505 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0615 14:44:46.336326   10505 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:41393/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1273&timeout=10s&timeoutSeconds=372&watch=true: dial tcp 127.0.0.1:41393: connect: connection refused
E0615 14:44:46.337446   10505 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:41393/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1273&timeout=10s&timeoutSeconds=393&watch=true: dial tcp 127.0.0.1:41393: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	75.757s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 265 lines ...
•I0615 14:43:44.226471   11003 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0615 14:43:44.248186   11003 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":{}}}
I0615 14:43:44.448627   11003 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0615 14:43:44.448693   11003 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0615 14:43:44.448772   11003 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0615 14:43:44.982206   11003 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0615 14:43:47.017740   11003 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-lnjgp/test-cluster"
•E0615 14:43:47.578993   11003 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-qcxc5/test-cluster"
•E0615 14:43:48.140273   11003 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:40809/?timeout=50ms: dial tcp 127.0.0.1:40809: connect: connection refused"  "cluster"="cluster-cache-test-dzmjh/test-cluster"
•I0615 14:43:48.341685   11003 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0615 14:43:48.341686   11003 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0615 14:43:48.341758   11003 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-040150738/tls.crt: no such file or directory"  
E0615 14:43:48.341781   11003 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0615 14:43:48.341802   11003 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-040150738/tls.crt: no such file or directory"  
E0615 14:43:48.493479   11003 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:38005/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:38005: connect: connection refused


Ran 5 of 5 Specs in 15.654 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (15.65s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	15.892s
?   	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
I0615 14:43:58.401583   11655 controller.go:130]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.00s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0615 14:43:58.402858   11655 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="clusters.cluster.x-k8s.io \"foo\" not found" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoCluster (0.00s)
=== RUN   TestReconcilePaused
I0615 14:43:58.403503   11655 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0615 14:43:58.403662   11655 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 192 lines ...
    --- PASS: TestSelectMachineForScaleDown/when_there_is_an_up_to_date_machine_with_delete_annotation,_while_there_are_any_outdated_machines_without_annotatio_that_still_exist,_it_returns_oldest_marked_machine_first (0.00s)
=== RUN   TestPreflightChecks
=== RUN   TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass
=== RUN   TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue
I0615 14:44:14.970861   11655 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
I0615 14:44:14.970982   11655 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: 1655304223
Will run 1 of 1 specs

E0615 14:44:14.992866   11655 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-d88byx\" not found" "kubeadmControlPlane"="kcp-foo-d88byx" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.018 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.02s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0615 14:44:14.994378   11655 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-n68zae" "kubeadmControlPlane"="kcp-foo-n68zae" "namespace"="test" 
I0615 14:44:17.781905   11655 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-n68zae" "kubeadmControlPlane"="kcp-foo-n68zae" "namespace"="test" "needRollout"=["kcp-foo-n68zae-mgg4j"]
I0615 14:44:17.782075   11655 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-n68zae" "kubeadmControlPlane"="kcp-foo-n68zae" "namespace"="test" "failures"="[machine kcp-foo-n68zae-k4wcc does not have APIServerPodHealthy condition, machine kcp-foo-n68zae-k4wcc does not have ControllerManagerPodHealthy condition, machine kcp-foo-n68zae-k4wcc does not have SchedulerPodHealthy condition, machine kcp-foo-n68zae-k4wcc does not have EtcdPodHealthy condition, machine kcp-foo-n68zae-k4wcc does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (2.79s)
... skipping 60 lines ...
==================================
Random Seed: 1655304223
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: 1655304223
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.000 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestMachineCollection (0.00s)
=== RUN   TestUpdateEtcdConditions
=== RUN   TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines
=== RUN   TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition
... skipping 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
E0615 14:43:57.828581   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:44:06.151646   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:44:15.137700   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:44:26.267935   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:44:42.741149   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:44:55.749806   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:45:13.397322   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:45:34.320702   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:46:05.337300   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0615 14:46:50.494575   11601 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0
--- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s)
... skipping 84 lines ...
    --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_<_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.23.0 (0.00s)
PASS
I0615 14:46:50.503568   11601 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0615 14:46:50.503864   11601 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0615 14:46:50.503940   11601 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-804064433/tls.crt: no such file or directory"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	187.304s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
PASS
... skipping 287 lines ...
I0615 14:44:06.044957   11945 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourcesetbinding" 
I0615 14:44:06.147714   11945 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0615 14:44:06.147872   11945 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0615 14:44:06.248122   11945 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0615 14:44:06.248197   11945 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0615 14:44:06.341116   11945 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-ilgjo8"} 
E0615 14:44:06.373772   11945 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"
•I0615 14:44:07.423047   11945 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-cfywbm"} 
E0615 14:44:07.460959   11945 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"
•E0615 14:44:18.578888   11945 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"

------------------------------
• Failure [11.123 seconds]
ClusterResourceSet Reconciler
/home/prow/go/src/sigs.k8s.io/cluster-api/exp/addons/controllers/clusterresourceset_controller_test.go:40
  Should reconcile a ClusterResourceSet when a resource is created that is part of ClusterResourceSet resources [It]
... skipping 8 lines ...
------------------------------
STEP: Creating the Cluster
STEP: Creating the remote Cluster kubeconfig
STEP: Creating a Secret and a ConfigMap with ConfigMap in their data field
STEP: Verifying ClusterResourceSetBinding is created with cluster owner reference
STEP: Deleting the Kubeconfigsecret
E0615 14:44:19.737054   11945 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"
•E0615 14:44:20.759973   11945 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"
E0615 14:44:21.775635   11945 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"
•I0615 14:44:21.783574   11945 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0615 14:44:21.783768   11945 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0615 14:44:21.783778   11945 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
E0615 14:44:21.784620   11945 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0615 14:44:21.784697   11945 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-329127170/tls.crt: no such file or directory"  



Summarizing 1 Failure:

[Fail] ClusterResourceSet Reconciler [It] Should reconcile a ClusterResourceSet when a resource is created that is part of ClusterResourceSet resources 
/home/prow/go/src/sigs.k8s.io/cluster-api/exp/addons/controllers/clusterresourceset_controller_test.go:307

Ran 5 of 5 Specs in 28.328 seconds
FAIL! -- 4 Passed | 1 Failed | 0 Pending | 0 Skipped
--- FAIL: TestAPIs (28.33s)
FAIL
FAIL	sigs.k8s.io/cluster-api/exp/addons/controllers	28.512s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-create
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-update
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-delete
... skipping 58 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.01s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0615 14:43:57.971050   12188 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 ...
•I0615 14:44:10.386527   12188 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0615 14:44:10.416204   12188 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0615 14:44:10.449209   12188 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0615 14:44:10.452255   12188 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0615 14:44:10.475310   12188 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0615 14:44:10.526352   12188 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••E0615 14:44:10.530016   12188 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0615 14:44:10.530045   12188 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-294478526/tls.crt: no such file or directory"  
I0615 14:44:10.530071   12188 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0615 14:44:10.575038   12188 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinepool" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}


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


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