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

No Test Failures!


Error lines from build-log.txt

... skipping 781 lines ...
I0728 16:36:03.630192    8579 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0728 16:36:04.263206    8579 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" 
•I0728 16:36:04.277868    8579 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 13.930 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.93s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	62.607s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 310 lines ...
=== RUN   Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined
--- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s)
=== RUN   Test_clusterctlClient_GetProviderComponents
=== RUN   Test_clusterctlClient_GetProviderComponents/Pass
=== RUN   Test_clusterctlClient_GetProviderComponents/Fail
--- PASS: Test_clusterctlClient_GetProviderComponents (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s)
=== RUN   Test_getComponentsByName_withEmptyVariables
--- PASS: Test_getComponentsByName_withEmptyVariables (0.00s)
=== RUN   Test_clusterctlClient_templateOptionsToVariables
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts)
... skipping 1399 lines ...
I0728 16:35:36.828574   10585 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0728 16:35:36.828631   10585 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0728 16:35:36.828675   10585 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0728 16:35:36.829085   10585 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
I0728 16:35:36.832360   10585 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
=== RUN   TestClusterReconcilePhases
2021/07/28 16:35:37 http: TLS handshake error from 127.0.0.1:44332: EOF
=== 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
I0728 16:35:37.023764   10585 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"
I0728 16:35:37.026927   10585 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infra_config_is_marked_for_deletion
... skipping 104 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0728 16:35:37.080296   10585 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
I0728 16:35:37.085055   10585 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"
E0728 16:35:37.086062   10585 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
I0728 16:35:37.087400   10585 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.00s)
    --- PASS: TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestWatches
I0728 16:35:37.424756   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0728 16:35:37.525550   10585 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0728 16:35:37.534439   10585 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-kgkdj" "namespace"="test-machine-watches-4wqxd" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0728 16:35:37.534528   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0728 16:35:37.644366   10585 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-kgkdj" "namespace"="test-machine-watches-4wqxd" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0728 16:35:37.644463   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0728 16:35:37.745085   10585 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-kgkdj" "namespace"="test-machine-watches-4wqxd" "noderef"="node-1"
E0728 16:35:37.757837   10585 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0728 16:35:37.757892   10585 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0728 16:35:37.845707   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-kgkdj\" in namespace \"test-machine-watches-4wqxd\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-kgkdj" "namespace"="test-machine-watches-4wqxd"
E0728 16:35:38.850462   10585 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-kgkdj\" in namespace \"test-machine-watches-4wqxd\", requeuing: requeue in 1s"  
E0728 16:35:38.857711   10585 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-kgkdj\" in namespace \"test-machine-watches-4wqxd\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-kgkdj\" in namespace \"test-machine-watches-4wqxd\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-kgkdj" "namespace"="test-machine-watches-4wqxd"
--- PASS: TestWatches (1.79s)
=== 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
I0728 16:35:39.076432   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-tng9c" "namespace"="test-machine-watches-4wqxd" "count"=1
I0728 16:35:39.076521   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-tng9c" "namespace"="test-machine-watches-4wqxd" "descendants"="Worker machines: machine-created-kgkdj" "indirect descendants count"=0
I0728 16:35:39.093149   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-tng9c" "namespace"="test-machine-watches-4wqxd" "count"=1
I0728 16:35:39.093216   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-tng9c" "namespace"="test-machine-watches-4wqxd" "descendants"="Worker machines: machine-created-kgkdj" "indirect descendants count"=0
I0728 16:35:39.858342   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-tng9c" "machine"="machine-created-kgkdj" "namespace"="test-machine-watches-4wqxd" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"f2457a8c-d7d9-456d-8f87-7bcbebb36be1","apiVersion":"v1"}
E0728 16:35:39.905373   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-kgkdj\" not found" "controller"="machine" "name"="machine-created-kgkdj" "namespace"="test-machine-watches-4wqxd"
E0728 16:35:40.959601   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-zrvb7\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-892bw\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-892bw: secrets \"machine-reconcile-892bw-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-zrvb7" "namespace"="default"
I0728 16:35:41.960113   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-892bw" "machine"="machine-created-zrvb7" "namespace"="default" "cause"="noderef is nil" "node"=null
I0728 16:35:41.994752   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-892bw" "machine"="machine-created-zrvb7" "namespace"="default" "cause"="noderef is nil" "node"=null
I0728 16:35:42.020806   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-892bw" "machine"="machine-created-zrvb7" "namespace"="default" "cause"="noderef is nil" "node"=null
E0728 16:35:42.058346   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-zrvb7\" not found" "controller"="machine" "name"="machine-created-zrvb7" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.19s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.19s)
=== 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.01s)
... skipping 15 lines ...
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.01s)
=== RUN   TestReconcileRequest
=== RUN   TestReconcileRequest/machine_should_be_created
I0728 16:35:42.107127   10585 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="created" "namespace"="default" "err"="cannot create a metadata client without a rest config"
=== RUN   TestReconcileRequest/machine_should_be_updated
I0728 16:35:42.132384   10585 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"
E0728 16:35:42.137776   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-892bw\" not found" "controller"="cluster" "name"="machine-reconcile-892bw" "namespace"="default"
=== RUN   TestReconcileRequest/machine_should_be_deleted
I0728 16:35:42.138824   10585 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.04s)
    --- PASS: TestReconcileRequest/machine_should_be_created (0.03s)
    --- PASS: TestReconcileRequest/machine_should_be_updated (0.01s)
    --- PASS: TestReconcileRequest/machine_should_be_deleted (0.00s)
... skipping 109 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
I0728 16:35:42.359855   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8ds78" "namespace"="test-mhc-s95j8" 
I0728 16:35:42.374764   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0728 16:35:42.380367   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-s95j8/test-cluster-p7l2b"
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
E0728 16:35:42.388787   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-8ds78\" not found" "controller"="machinehealthcheck" "name"="test-mhc-8ds78" "namespace"="test-mhc-s95j8"
=== 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
I0728 16:35:43.389191   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-8ds78" "namespace"="test-mhc-s95j8" 
I0728 16:35:43.389316   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4pl7f" "namespace"="test-mhc-qtprx" 
I0728 16:35:43.389349   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rprg2" "namespace"="test-mhc-fcxvb" 
I0728 16:35:43.389376   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chtlh" "namespace"="test-mhc-dtr98" 
I0728 16:35:43.405937   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 16:35:43.526630   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chtlh" "namespace"="test-mhc-dtr98" 
I0728 16:35:43.531706   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chtlh" "namespace"="test-mhc-dtr98" 
I0728 16:35:43.579893   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-chtlh" "namespace"="test-mhc-dtr98" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
E0728 16:35:43.605976   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-dtr98/test-cluster-z7749"
E0728 16:35:43.610696   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-z7749\" not found" "controller"="cluster" "name"="test-cluster-z7749" "namespace"="test-mhc-dtr98"
I0728 16:35:43.716426   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hzwfq" "namespace"="test-mhc-b6v9d" 
I0728 16:35:43.742499   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 16:35:43.763656   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hzwfq" "namespace"="test-mhc-b6v9d" 
E0728 16:35:43.822641   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-b6v9d/test-cluster-5cq8c"
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0728 16:35:43.827977   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hzwfq" "namespace"="test-mhc-b6v9d" 
I0728 16:35:43.862540   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6znbk" "namespace"="test-mhc-gb4l5" 
inframachine created: test-mhc-machine-infra-wn7t4
I0728 16:35:43.886552   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-hgf5n
I0728 16:35:43.987545   10585 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-gb4l5/test-mhc-6znbk/test-mhc-machine-hgf5n/"
E0728 16:35:43.993475   10585 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-7gk76"
E0728 16:35:43.993771   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-7gk76, got []"  "node"="test-mhc-node-7gk76"
node created: test-mhc-node-7gk76
inframachine created: test-mhc-machine-infra-9w2zs
machine created: test-mhc-machine-lzwxm
E0728 16:35:44.139798   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-whz5v, got []"  "node"="test-mhc-node-whz5v"
E0728 16:35:44.140027   10585 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-whz5v"
node created: test-mhc-node-whz5v
I0728 16:35:44.228782   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6znbk" "namespace"="test-mhc-gb4l5" 
I0728 16:35:44.301017   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6znbk" "namespace"="test-mhc-gb4l5" 
Cleaning up nodes, machines and infra machines.
I0728 16:35:44.313200   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6znbk" "namespace"="test-mhc-gb4l5" 
I0728 16:35:44.313686   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-gb4l5/test-mhc-6znbk/test-mhc-machine-hgf5n/"
I0728 16:35:44.333670   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6znbk" "namespace"="test-mhc-gb4l5" 
I0728 16:35:44.334207   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-gb4l5/test-mhc-6znbk/test-mhc-machine-hgf5n/"
I0728 16:35:44.334682   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-gb4l5/test-mhc-6znbk/test-mhc-machine-lzwxm/"
E0728 16:35:44.356613   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-gb4l5/test-cluster-f65gt"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
inframachine created: test-mhc-machine-infra-s2qp5
machine created: test-mhc-machine-bpfdm
E0728 16:35:44.470643   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
E0728 16:35:44.558324   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-6znbk\" not found" "controller"="machinehealthcheck" "name"="test-mhc-6znbk" "namespace"="test-mhc-gb4l5"
E0728 16:35:44.644788   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-4wqxd/machine-reconcile-tng9c"
E0728 16:35:45.471100   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:35:45.558669   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:45.586435   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 16:35:45.709029   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6znbk" "namespace"="test-mhc-gb4l5" 
I0728 16:35:45.709287   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:45.710078   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:45.711915   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
... skipping 315 lines ...
I0728 16:35:46.479548   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.481088   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.481949   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.489174   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.490506   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.491672   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
E0728 16:35:46.493504   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:35:46.494114   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.494644   10585 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-qpwc2/test-mhc-njwtd/test-mhc-machine-bpfdm/"
I0728 16:35:46.508991   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.509376   10585 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-qpwc2/test-mhc-njwtd/test-mhc-machine-bpfdm/"
node created: test-mhc-node-rj7p6
E0728 16:35:46.535764   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-rj7p6, got []"  "node"="test-mhc-node-rj7p6"
I0728 16:35:46.545143   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
inframachine created: test-mhc-machine-infra-kxlds
machine created: test-mhc-machine-zh28b
I0728 16:35:46.579896   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.586377   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:46.587858   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
... skipping 349 lines ...
I0728 16:35:47.480819   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.482921   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.484973   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.487138   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.489794   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.492081   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
E0728 16:35:47.493842   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:35:47.494303   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.496432   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.498460   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.500496   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.502506   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:47.504513   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
... skipping 350 lines ...
I0728 16:35:48.522883   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.524230   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.525366   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.526919   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.528834   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.530480   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
E0728 16:35:48.538490   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:35:48.538723   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.541731   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.544665   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.547214   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.549508   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:48.551779   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
... skipping 339 lines ...
I0728 16:35:49.549850   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.552037   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.555016   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.559855   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.562242   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.564394   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
E0728 16:35:49.573103   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:35:49.573350   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.573892   10585 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-qpwc2/test-mhc-njwtd/test-mhc-machine-zh28b/"
node created: test-mhc-node-k52j8
E0728 16:35:49.611360   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-k52j8, got []"  "node"="test-mhc-node-k52j8"
I0728 16:35:49.612222   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.612650   10585 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-qpwc2/test-mhc-njwtd/test-mhc-machine-zh28b/"
I0728 16:35:49.619551   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
inframachine created: test-mhc-machine-infra-7xttt
machine created: test-mhc-machine-chdt6
I0728 16:35:49.653562   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.688910   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:49.696706   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
... skipping 263 lines ...
I0728 16:35:50.565059   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.567764   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.570269   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.572981   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.575867   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.578365   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
E0728 16:35:50.586088   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:35:50.586273   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.591460   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.595607   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.598328   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.601261   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:50.604255   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
... skipping 230 lines ...
I0728 16:35:51.634874   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.645767   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.648599   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.652116   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.655607   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.657329   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
E0728 16:35:51.661099   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:35:51.661569   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.664247   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.670580   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.673021   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.676805   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:51.679936   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
... skipping 222 lines ...
I0728 16:35:52.664436   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:52.668521   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:52.672073   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:52.674692   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:52.676834   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:52.680723   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:52.681257   10585 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-qpwc2/test-mhc-njwtd/test-mhc-machine-chdt6/"
E0728 16:35:52.685827   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-6tcwp, got []"  "node"="test-mhc-node-6tcwp"
node created: test-mhc-node-6tcwp
E0728 16:35:52.688942   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:35:52.692461   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
Cleaning up nodes, machines and infra machines.
I0728 16:35:52.699684   10585 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-qpwc2/test-mhc-njwtd/test-mhc-machine-chdt6/test-mhc-node-6tcwp"
I0728 16:35:52.718452   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-njwtd" "namespace"="test-mhc-qpwc2" 
I0728 16:35:52.719241   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-qpwc2/test-mhc-njwtd/test-mhc-machine-chdt6/"
Cleaning up nodes, machines and infra machines.
I0728 16:35:52.769712   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-f584s" "namespace"="test-mhc-qpwc2" "count"=2
I0728 16:35:52.769800   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-f584s" "namespace"="test-mhc-qpwc2" "descendants"="Worker machines: test-mhc-machine-bpfdm,test-mhc-machine-zh28b,test-mhc-machine-chdt6" "indirect descendants count"=1
I0728 16:35:52.782485   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-f584s" "namespace"="test-mhc-qpwc2" "count"=2
I0728 16:35:52.782568   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-f584s" "namespace"="test-mhc-qpwc2" "descendants"="Worker machines: test-mhc-machine-bpfdm,test-mhc-machine-zh28b,test-mhc-machine-chdt6" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
... skipping 7 lines ...
I0728 16:35:53.006167   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:53.047233   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:53.128348   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:53.289507   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:53.610581   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:53.689567   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-f584s" "machine"="test-mhc-machine-zh28b" "namespace"="test-mhc-qpwc2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-k52j8"}
E0728 16:35:53.734937   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-zh28b\" not found" "controller"="machine" "name"="test-mhc-machine-zh28b" "namespace"="test-mhc-qpwc2"
I0728 16:35:54.251710   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
E0728 16:35:54.735365   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:35:55.532857   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:55.735892   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-f584s" "machine"="test-mhc-machine-chdt6" "namespace"="test-mhc-qpwc2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-6tcwp"}
E0728 16:35:55.799694   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-chdt6\" not found" "controller"="machine" "name"="test-mhc-machine-chdt6" "namespace"="test-mhc-qpwc2"
I0728 16:35:56.800462   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-f584s" "machine"="test-mhc-machine-bpfdm" "namespace"="test-mhc-qpwc2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-rj7p6"}
E0728 16:35:56.850336   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-bpfdm\" not found" "controller"="machine" "name"="test-mhc-machine-bpfdm" "namespace"="test-mhc-qpwc2"
E0728 16:35:57.800638   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-qpwc2/test-cluster-f584s"
E0728 16:35:57.850751   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:35:58.094536   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:58.862745   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:58.868129   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
E0728 16:35:58.868131   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:35:58.893539   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
E0728 16:35:58.956689   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jjq5t, got []"  "node"="test-mhc-node-jjq5t"
node created: test-mhc-node-jjq5t
I0728 16:35:58.964673   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
inframachine created: test-mhc-machine-infra-xfvpp
machine created: test-mhc-machine-j96w6
I0728 16:35:59.004412   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:59.134060   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:59.139207   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:59.160424   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:59.201928   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:59.284003   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:59.445751   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:35:59.767213   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
E0728 16:35:59.868779   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:36:00.412745   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:00.885666   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:00.900290   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:00.920185   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:00.925601   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:00.936808   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:00.961535   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
E0728 16:36:00.963251   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:36:00.998289   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
E0728 16:36:01.024440   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-crmvg, got []"  "node"="test-mhc-node-crmvg"
node created: test-mhc-node-crmvg
inframachine created: test-mhc-machine-infra-6qjlb
machine created: test-mhc-machine-qsn8p
I0728 16:36:01.192122   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:01.230785   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:01.694221   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
E0728 16:36:01.963690   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:36:02.977161   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:03.002346   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:03.015246   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:03.027897   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:03.039558   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:03.055308   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
E0728 16:36:03.063874   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:36:03.067137   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:03.092726   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
node created: test-mhc-node-sx4v5
E0728 16:36:03.168426   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-sx4v5, got []"  "node"="test-mhc-node-sx4v5"
I0728 16:36:03.180187   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
Cleaning up nodes, machines and infra machines.
I0728 16:36:03.197629   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
Cleaning up nodes, machines and infra machines.
I0728 16:36:03.267717   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-54bvm" "namespace"="test-mhc-r69vd" "count"=2
I0728 16:36:03.267801   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-54bvm" "namespace"="test-mhc-r69vd" "descendants"="Worker machines: test-mhc-machine-qsn8p,test-mhc-machine-d7696,test-mhc-machine-j96w6" "indirect descendants count"=1
... skipping 4 lines ...
machine created: test-mhc-machine-9vbsp
I0728 16:36:03.392996   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:03.413667   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 16:36:03.542177   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6ms58" "namespace"="test-mhc-r69vd" 
I0728 16:36:03.542248   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:03.550051   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
E0728 16:36:04.064375   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:36:05.065298   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-54bvm" "machine"="test-mhc-machine-d7696" "namespace"="test-mhc-r69vd" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-jjq5t"}
E0728 16:36:05.126764   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-d7696\" not found" "controller"="machine" "name"="test-mhc-machine-d7696" "namespace"="test-mhc-r69vd"
I0728 16:36:06.127399   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-54bvm" "machine"="test-mhc-machine-j96w6" "namespace"="test-mhc-r69vd" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-crmvg"}
E0728 16:36:06.177277   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-j96w6\" not found" "controller"="machine" "name"="test-mhc-machine-j96w6" "namespace"="test-mhc-r69vd"
I0728 16:36:07.177873   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-54bvm" "machine"="test-mhc-machine-qsn8p" "namespace"="test-mhc-r69vd" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-sx4v5"}
E0728 16:36:07.235530   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-qsn8p\" not found" "controller"="machine" "name"="test-mhc-machine-qsn8p" "namespace"="test-mhc-r69vd"
I0728 16:36:08.245029   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:08.251070   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
E0728 16:36:08.251372   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
E0728 16:36:08.288061   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-r69vd/test-cluster-54bvm"
E0728 16:36:08.352649   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bnd4z, got []"  "node"="test-mhc-node-bnd4z"
node created: test-mhc-node-bnd4z
I0728 16:36:08.360662   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
inframachine created: test-mhc-machine-infra-fphwp
machine created: test-mhc-machine-m8wjc
I0728 16:36:08.380982   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:08.388742   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
E0728 16:36:09.251834   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:36:10.270385   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:10.275767   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:10.290262   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:10.301299   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:10.308942   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:10.314648   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
E0728 16:36:10.316371   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
E0728 16:36:10.385354   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-8rg4z, got []"  "node"="test-mhc-node-8rg4z"
node created: test-mhc-node-8rg4z
I0728 16:36:10.394569   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
inframachine created: test-mhc-machine-infra-bt2fn
machine created: test-mhc-machine-5xczq
I0728 16:36:10.419149   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:10.426567   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
... skipping 7 lines ...
Cleaning up nodes, machines and infra machines.
I0728 16:36:11.427341   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:11.430189   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
Cleaning up nodes, machines and infra machines.
I0728 16:36:11.449885   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="test-mhc-machine-5xczq" "namespace"="test-mhc-lvm44" 
I0728 16:36:11.459553   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:11.460147   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-lvm44/test-mhc-flrsn/test-mhc-machine-m8wjc/"
I0728 16:36:11.481465   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-lvm44/test-mhc-flrsn/test-mhc-machine-9vbsp/"
E0728 16:36:11.490598   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="infrastructuremachines.infrastructure.cluster.x-k8s.io \"test-mhc-machine-infra-bt2fn\" not found" "controller"="machine" "name"="test-mhc-machine-5xczq" "namespace"="test-mhc-lvm44"
I0728 16:36:11.503005   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-m5zzf" "namespace"="test-mhc-lvm44" "count"=3
I0728 16:36:11.503129   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-m5zzf" "namespace"="test-mhc-lvm44" "descendants"="Worker machines: test-mhc-machine-5xczq,test-mhc-machine-9vbsp,test-mhc-machine-m8wjc" "indirect descendants count"=0
I0728 16:36:11.504206   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
I0728 16:36:11.505043   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-lvm44/test-mhc-flrsn/test-mhc-machine-9vbsp/"
I0728 16:36:11.505641   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-lvm44/test-mhc-flrsn/test-mhc-machine-m8wjc/"
I0728 16:36:11.508535   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-m5zzf" "namespace"="test-mhc-lvm44" "count"=3
I0728 16:36:11.508743   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-m5zzf" "namespace"="test-mhc-lvm44" "descendants"="Worker machines: test-mhc-machine-9vbsp,test-mhc-machine-m8wjc,test-mhc-machine-5xczq" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_longer_than_the_NodeStartupTimeout
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine's_Node_has_gone_away
=== RUN   TestMachineHealthCheck_Reconcile/should_react_when_a_Node_transitions_to_unhealthy
I0728 16:36:11.511176   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-flrsn" "namespace"="test-mhc-lvm44" 
... skipping 402 lines ...
I0728 16:36:12.566978   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.573427   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.575473   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.578575   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.580466   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.582369   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
E0728 16:36:12.583130   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-m8wjc\" not found" "controller"="machine" "name"="test-mhc-machine-m8wjc" "namespace"="test-mhc-lvm44"
I0728 16:36:12.584456   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.588681   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.590662   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.596990   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.598949   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:12.600761   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
... skipping 466 lines ...
I0728 16:36:13.631956   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.633983   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.636132   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.638659   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.642235   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.644138   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
E0728 16:36:13.646790   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9vbsp\" not found" "controller"="machine" "name"="test-mhc-machine-9vbsp" "namespace"="test-mhc-lvm44"
I0728 16:36:13.646943   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.648801   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.650777   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.652613   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.654230   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:13.655950   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
... skipping 470 lines ...
I0728 16:36:14.680321   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.682272   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.685548   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.688574   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.690606   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.692434   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
E0728 16:36:14.694276   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-5xczq\" not found" "controller"="machine" "name"="test-mhc-machine-5xczq" "namespace"="test-mhc-lvm44"
I0728 16:36:14.694397   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.696751   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.698591   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.700400   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.702316   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:14.704143   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
... skipping 416 lines ...
I0728 16:36:15.711684   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.713582   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.715382   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.717106   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.718858   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.720630   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
E0728 16:36:15.721654   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:36:15.721822   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.722084   10585 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-6bfhw/test-mhc-fhwpc/test-mhc-machine-cdw9v/"
I0728 16:36:15.736154   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.736551   10585 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-6bfhw/test-mhc-fhwpc/test-mhc-machine-cdw9v/"
E0728 16:36:15.790081   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-z69dh, got []"  "node"="test-mhc-node-z69dh"
E0728 16:36:15.790416   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-z69dh, got []"  "node"="test-mhc-node-z69dh"
node created: test-mhc-node-z69dh
I0728 16:36:15.799080   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.820370   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.848324   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.848812   10585 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-6bfhw/test-mhc-fhwpc/test-mhc-machine-cdw9v/test-mhc-node-z69dh"
I0728 16:36:15.867562   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.867990   10585 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-6bfhw/test-mhc-fhwpc/test-mhc-machine-cdw9v/test-mhc-node-z69dh"
Cleaning up nodes, machines and infra machines.
I0728 16:36:15.880415   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.880830   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-6bfhw/test-mhc-fhwpc/test-mhc-machine-cdw9v/"
I0728 16:36:15.901514   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
I0728 16:36:15.901928   10585 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-6bfhw/test-mhc-fhwpc/test-mhc-machine-cdw9v/"
I0728 16:36:15.904336   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-spxks" "namespace"="test-mhc-6bfhw" "descendants"="Worker machines: test-mhc-machine-cdw9v" "indirect descendants count"=1
I0728 16:36:15.908950   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-fhwpc" "namespace"="test-mhc-6bfhw" 
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0728 16:36:15.911462   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-spxks" "namespace"="test-mhc-6bfhw" "descendants"="Worker machines: test-mhc-machine-cdw9v" "indirect descendants count"=1
I0728 16:36:16.139348   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" "creating"=1 "need"=1
I0728 16:36:16.139417   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
I0728 16:36:16.172722   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-pfm4j-nfhr9\"" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
I0728 16:36:16.223377   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:16.245723   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 16:36:16.272289   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:16.278574   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:16.282517   10585 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
E0728 16:36:16.525471   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-lvm44/test-cluster-m5zzf"
E0728 16:36:16.722168   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:36:17.272593   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:17.722955   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-spxks" "machine"="test-mhc-machine-cdw9v" "namespace"="test-mhc-6bfhw" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-z69dh"}
E0728 16:36:17.777871   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-cdw9v\" not found" "controller"="machine" "name"="test-mhc-machine-cdw9v" "namespace"="test-mhc-6bfhw"
I0728 16:36:18.273695   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.787965   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.788840   10585 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.792932   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.793188   10585 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.802567   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
... skipping 4 lines ...
I0728 16:36:18.825641   10585 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.829047   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.829101   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.841190   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
I0728 16:36:18.841242   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.274805   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.275272   10585 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-2kwh7/test-mhc-cv5jw/mhc-ms-pfm4j-nfhr9/"
I0728 16:36:19.285755   10585 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.291504   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.291555   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.297391   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.297920   10585 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-2kwh7/test-mhc-cv5jw/mhc-ms-pfm4j-nfhr9/"
I0728 16:36:19.318823   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.319257   10585 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.319296   10585 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-2kwh7/test-mhc-cv5jw/mhc-ms-pfm4j-nfhr9/"
I0728 16:36:19.344367   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.344434   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.373643   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-sfkpb" "namespace"="test-mhc-2kwh7" "count"=1
I0728 16:36:19.373720   10585 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-sfkpb" "namespace"="test-mhc-2kwh7" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-pfm4j"
I0728 16:36:19.373959   10585 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" "machine"="mhc-ms-pfm4j-nfhr9"
I0728 16:36:19.402720   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-sfkpb" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" "cause"="cluster is being deleted" "node"=null
I0728 16:36:19.403482   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.403818   10585 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-2kwh7/test-mhc-cv5jw/mhc-ms-pfm4j-nfhr9/"
I0728 16:36:19.469550   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-sfkpb" "namespace"="test-mhc-2kwh7" "descendants"="Machine sets: mhc-ms-pfm4j;Worker machines: mhc-ms-pfm4j-nfhr9" "indirect descendants count"=1
I0728 16:36:19.470237   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-cv5jw" "namespace"="test-mhc-2kwh7" 
I0728 16:36:19.475926   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-sfkpb" "namespace"="test-mhc-2kwh7" "descendants"="Worker machines: mhc-ms-pfm4j-nfhr9" "indirect descendants count"=1
E0728 16:36:19.477876   10585 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-pfm4j\" not found" "machineset"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7" 
E0728 16:36:19.477959   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-pfm4j\" not found" "controller"="machineset" "name"="mhc-ms-pfm4j" "namespace"="test-mhc-2kwh7"
=== RUN   TestMachineHealthCheck_Reconcile/when_a_machine_is_paused
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created
I0728 16:36:19.506360   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-sfkpb" "machine"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7" "cause"="cluster is being deleted" "node"=null
E0728 16:36:19.554348   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-pfm4j-nfhr9\" not found" "controller"="machine" "name"="mhc-ms-pfm4j-nfhr9" "namespace"="test-mhc-2kwh7"
I0728 16:36:19.660652   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
inframachine created: test-mhc-machine-infra-bbpzf
machine created: test-mhc-machine-wbvtf
I0728 16:36:19.688981   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0728 16:36:19.713616   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:19.714382   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
... skipping 385 lines ...
I0728 16:36:20.561955   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.562732   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.565255   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.567486   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.569349   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.571196   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
E0728 16:36:20.602102   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c5cgn, got []"  "node"="test-mhc-node-c5cgn"
E0728 16:36:20.602102   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c5cgn, got []"  "node"="test-mhc-node-c5cgn"
node created: test-mhc-node-c5cgn
E0728 16:36:20.602278   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c5cgn, got []"  "node"="test-mhc-node-c5cgn"
I0728 16:36:20.656260   10585 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-wbvtf" "target"="test-mhc-wq5vz/test-mhc-f87c6/test-mhc-machine-wbvtf/"
I0728 16:36:20.671635   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.706340   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.710949   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.715950   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.720393   10585 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-wbvtf" "target"="test-mhc-wq5vz/test-mhc-f87c6/test-mhc-machine-wbvtf/test-mhc-node-c5cgn"
I0728 16:36:20.750129   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.760290   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
Cleaning up nodes, machines and infra machines.
I0728 16:36:20.774806   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.781388   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-nr98v" "machine"="test-mhc-machine-wbvtf" "namespace"="test-mhc-wq5vz" "cause"="no control plane members" "node"={"name":"test-mhc-node-c5cgn"}
I0728 16:36:20.781596   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.793962   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
I0728 16:36:20.798976   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nr98v" "namespace"="test-mhc-wq5vz" "count"=1
I0728 16:36:20.799049   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nr98v" "namespace"="test-mhc-wq5vz" "descendants"="Worker machines: test-mhc-machine-wbvtf" "indirect descendants count"=0
I0728 16:36:20.804014   10585 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-nr98v" "namespace"="test-mhc-wq5vz" "count"=1
I0728 16:36:20.804103   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-nr98v" "namespace"="test-mhc-wq5vz" "descendants"="Worker machines: test-mhc-machine-wbvtf" "indirect descendants count"=0
I0728 16:36:20.805689   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-f87c6" "namespace"="test-mhc-wq5vz" 
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted
E0728 16:36:20.850228   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-wbvtf\" not found" "controller"="machine" "name"="test-mhc-machine-wbvtf" "namespace"="test-mhc-wq5vz"
E0728 16:36:20.924746   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-6bfhw/test-cluster-spxks"
I0728 16:36:20.949644   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
inframachine created: test-mhc-machine-infra-hc9c7
I0728 16:36:20.969621   10585 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-km6k2
I0728 16:36:21.106320   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.123653   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
... skipping 292 lines ...
I0728 16:36:21.840174   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.841920   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.843665   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.845355   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.847047   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.848848   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
E0728 16:36:21.850672   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
I0728 16:36:21.850892   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.852727   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.854536   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.856417   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.858425   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:21.860167   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
... skipping 450 lines ...
I0728 16:36:22.859722   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.860560   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.862548   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.864368   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.866232   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.866853   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
E0728 16:36:22.867101   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
I0728 16:36:22.870587   10585 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-km6k2" "target"="test-mhc-7j5pl/test-mhc-hsb67/test-mhc-machine-km6k2/"
node created: test-mhc-node-28vk6
E0728 16:36:22.904149   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-28vk6, got []"  "node"="test-mhc-node-28vk6"
E0728 16:36:22.904548   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-28vk6, got []"  "node"="test-mhc-node-28vk6"
E0728 16:36:22.905091   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-28vk6, got []"  "node"="test-mhc-node-28vk6"
I0728 16:36:22.920820   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.925981   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.963988   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.975653   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:22.979519   10585 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-km6k2" "target"="test-mhc-7j5pl/test-mhc-hsb67/test-mhc-machine-km6k2/test-mhc-node-28vk6"
I0728 16:36:23.000598   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:23.009622   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:23.013355   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:23.040426   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
Cleaning up nodes, machines and infra machines.
I0728 16:36:23.056825   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
I0728 16:36:23.067692   10585 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-km6k2" "target"="test-mhc-7j5pl/test-mhc-hsb67/test-mhc-machine-km6k2/"
I0728 16:36:23.086734   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-jj5jj" "namespace"="test-mhc-7j5pl" "descendants"="Worker machines: test-mhc-machine-km6k2" "indirect descendants count"=1
I0728 16:36:23.093715   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-jj5jj" "namespace"="test-mhc-7j5pl" "descendants"="Worker machines: test-mhc-machine-km6k2" "indirect descendants count"=1
I0728 16:36:23.094903   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
E0728 16:36:23.105754   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-hsb67\" not found" "controller"="machinehealthcheck" "name"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl"
--- PASS: TestMachineHealthCheck_Reconcile (40.87s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.15s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.19s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.06s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist (0.94s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones (0.25s)
... skipping 10 lines ...
    --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s)
        machinehealthcheck_controller_test.go:933: skipping until made stable
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (1.34s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (2.28s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0728 16:36:23.109042   10585 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
E0728 16:36:23.110754   10585 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
E0728 16:36:23.112698   10585 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0728 16:36:23.113024   10585 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
E0728 16:36:23.113450   10585 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
I0728 16:36:23.115767   10585 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0728 16:36:23.116173   10585 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0728 16:36:23.117548   10585 machinehealthcheck_controller.go:320]  "msg"="failed to patch healthy machine status for machine" "error"="machines.cluster.x-k8s.io \"machine1\" not found"  "machine"="machine1"
--- PASS: TestPatchTargets (0.00s)
=== RUN   TestGetTargetsFromMHC
=== RUN   TestGetTargetsFromMHC/with_no_matching_machines
=== RUN   TestGetTargetsFromMHC/when_a_machine's_node_is_missing
=== RUN   TestGetTargetsFromMHC/when_a_machine's_labels_do_not_match_the_selector
=== RUN   TestGetTargetsFromMHC/with_multiple_machines,_should_match_correct_nodes
... skipping 26 lines ...
--- PASS: TestMachineSetOwnerReference (0.00s)
    --- PASS: TestMachineSetOwnerReference/should_add_cluster_owner_reference_to_machine_set (0.00s)
    --- PASS: TestMachineSetOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_deployment (0.00s)
=== RUN   TestMachineSetReconcile
=== RUN   TestMachineSetReconcile/ignore_machine_sets_marked_for_deletion
=== RUN   TestMachineSetReconcile/records_event_if_reconcile_fails
E0728 16:36:23.127949   10585 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
E0728 16:36:23.130357   10585 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 73 lines ...
I0728 16:36:23.531609   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0728 16:36:23.532354   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" 
I0728 16:36:23.547632   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-dbp2k-6657c7fddb-clrq6\"" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" 
I0728 16:36:23.628026   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0728 16:36:23.628076   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" 
I0728 16:36:23.647258   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-dbp2k-cdfc6fd6c-27cw6\"" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" 
E0728 16:36:23.726059   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
E0728 16:36:23.726245   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
E0728 16:36:23.726588   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
E0728 16:36:23.829664   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
E0728 16:36:23.829715   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
E0728 16:36:23.829865   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
E0728 16:36:23.829906   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
E0728 16:36:23.829958   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
E0728 16:36:23.830000   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-27cw6-9t5b8, got []"  "node"="md-dbp2k-cdfc6fd6c-27cw6-9t5b8"
I0728 16:36:23.869092   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-jj5jj" "machine"="test-mhc-machine-km6k2" "namespace"="test-mhc-7j5pl" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-28vk6"}
E0728 16:36:23.869366   10585 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-dbp2k-cdfc6fd6c-27cw6-9t5b8 for machine md-test/md-dbp2k-cdfc6fd6c-27cw6: the cache is not started, can not read objects" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" 
I0728 16:36:23.924053   10585 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0728 16:36:23.924137   10585 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0728 16:36:23.934856   10585 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "machine"="md-dbp2k-6657c7fddb-lst4t"
E0728 16:36:23.942735   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-km6k2\" not found" "controller"="machine" "name"="test-mhc-machine-km6k2" "namespace"="test-mhc-7j5pl"
I0728 16:36:23.953642   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0728 16:36:23.953702   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" 
I0728 16:36:23.970410   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-dbp2k-cdfc6fd6c-jmv8v\"" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" 
E0728 16:36:24.075068   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
E0728 16:36:24.075296   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
E0728 16:36:24.075473   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
I0728 16:36:24.106176   10585 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hsb67" "namespace"="test-mhc-7j5pl" 
E0728 16:36:24.178784   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
E0728 16:36:24.178840   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
E0728 16:36:24.178961   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
E0728 16:36:24.179042   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
E0728 16:36:24.179063   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
E0728 16:36:24.179124   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-jmv8v-778ln, got []"  "node"="md-dbp2k-cdfc6fd6c-jmv8v-778ln"
I0728 16:36:24.229573   10585 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1
I0728 16:36:24.229621   10585 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0728 16:36:24.235985   10585 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "machine"="md-dbp2k-6657c7fddb-jfb7c"
I0728 16:36:24.350990   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0728 16:36:24.351048   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" 
I0728 16:36:24.391728   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-dbp2k-cdfc6fd6c-dn7dn\"" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" 
E0728 16:36:24.458202   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.458403   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.458568   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.462447   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.462504   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.462499   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.462547   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.462654   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.462684   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-cdfc6fd6c-dn7dn-tdhdr, got []"  "node"="md-dbp2k-cdfc6fd6c-dn7dn-tdhdr"
E0728 16:36:24.514915   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-2kwh7/test-cluster-sfkpb"
I0728 16:36:24.521502   10585 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0728 16:36:24.521550   10585 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0728 16:36:24.528559   10585 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-dbp2k-6657c7fddb" "namespace"="md-test" "machine"="md-dbp2k-6657c7fddb-clrq6"
I0728 16:36:24.663186   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0728 16:36:24.663252   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" 
I0728 16:36:24.681299   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-dbp2k-74d45c49c5-mmwkl\"" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" 
E0728 16:36:24.756730   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-mmwkl-tcvlq, got []"  "node"="md-dbp2k-74d45c49c5-mmwkl-tcvlq"
E0728 16:36:24.756950   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-mmwkl-tcvlq, got []"  "node"="md-dbp2k-74d45c49c5-mmwkl-tcvlq"
E0728 16:36:24.760492   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-mmwkl-tcvlq, got []"  "node"="md-dbp2k-74d45c49c5-mmwkl-tcvlq"
E0728 16:36:24.760568   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-mmwkl-tcvlq, got []"  "node"="md-dbp2k-74d45c49c5-mmwkl-tcvlq"
E0728 16:36:24.760506   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-mmwkl-tcvlq, got []"  "node"="md-dbp2k-74d45c49c5-mmwkl-tcvlq"
E0728 16:36:24.760601   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-mmwkl-tcvlq, got []"  "node"="md-dbp2k-74d45c49c5-mmwkl-tcvlq"
I0728 16:36:24.814348   10585 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2
I0728 16:36:24.814392   10585 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0728 16:36:24.820790   10585 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "machine"="md-dbp2k-cdfc6fd6c-dn7dn"
I0728 16:36:24.847752   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=2
I0728 16:36:24.847896   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" 
I0728 16:36:24.902648   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-dbp2k-74d45c49c5-49z7m\"" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" 
I0728 16:36:25.055704   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:25.055751   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
E0728 16:36:25.067253   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-49z7m-92vhj, got []"  "node"="md-dbp2k-74d45c49c5-49z7m-92vhj"
E0728 16:36:25.067456   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-49z7m-92vhj, got []"  "node"="md-dbp2k-74d45c49c5-49z7m-92vhj"
E0728 16:36:25.072448   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-49z7m-92vhj, got []"  "node"="md-dbp2k-74d45c49c5-49z7m-92vhj"
E0728 16:36:25.072546   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-49z7m-92vhj, got []"  "node"="md-dbp2k-74d45c49c5-49z7m-92vhj"
E0728 16:36:25.072741   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-49z7m-92vhj, got []"  "node"="md-dbp2k-74d45c49c5-49z7m-92vhj"
E0728 16:36:25.072787   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-49z7m-92vhj, got []"  "node"="md-dbp2k-74d45c49c5-49z7m-92vhj"
I0728 16:36:25.090585   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
I0728 16:36:25.090632   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
I0728 16:36:25.142445   10585 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0728 16:36:25.142496   10585 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0728 16:36:25.149002   10585 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-dbp2k-cdfc6fd6c" "namespace"="md-test" "machine"="md-dbp2k-cdfc6fd6c-jmv8v"
E0728 16:36:25.153821   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-cdfc6fd6c-27cw6\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-cdfc6fd6c-27cw6" "namespace"="md-test"
I0728 16:36:25.177800   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0728 16:36:25.177869   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" 
I0728 16:36:25.192413   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-dbp2k-74d45c49c5-b6tmp\"" "machineset"="md-dbp2k-74d45c49c5" "namespace"="md-test" 
E0728 16:36:25.352796   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-b6tmp-vjb9x, got []"  "node"="md-dbp2k-74d45c49c5-b6tmp-vjb9x"
E0728 16:36:25.352800   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-b6tmp-vjb9x, got []"  "node"="md-dbp2k-74d45c49c5-b6tmp-vjb9x"
E0728 16:36:25.456568   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-b6tmp-vjb9x, got []"  "node"="md-dbp2k-74d45c49c5-b6tmp-vjb9x"
E0728 16:36:25.456642   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-b6tmp-vjb9x, got []"  "node"="md-dbp2k-74d45c49c5-b6tmp-vjb9x"
E0728 16:36:25.456753   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-b6tmp-vjb9x, got []"  "node"="md-dbp2k-74d45c49c5-b6tmp-vjb9x"
E0728 16:36:25.456807   10585 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-dbp2k-74d45c49c5-b6tmp-vjb9x, got []"  "node"="md-dbp2k-74d45c49c5-b6tmp-vjb9x"
I0728 16:36:25.482085   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-dbp2k-74d45c49c5,md-dbp2k-cdfc6fd6c;Worker machines: md-dbp2k-74d45c49c5-b6tmp,md-dbp2k-6657c7fddb-czs5h,md-dbp2k-6657c7fddb-pqq94,md-dbp2k-cdfc6fd6c-jmv8v,md-dbp2k-74d45c49c5-49z7m,md-dbp2k-74d45c49c5-mmwkl,md-dbp2k-cdfc6fd6c-27cw6" "indirect descendants count"=9
•I0728 16:36:25.487570   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-dbp2k-74d45c49c5,md-dbp2k-cdfc6fd6c;Worker machines: md-dbp2k-6657c7fddb-czs5h,md-dbp2k-6657c7fddb-pqq94,md-dbp2k-cdfc6fd6c-jmv8v,md-dbp2k-74d45c49c5-49z7m,md-dbp2k-74d45c49c5-mmwkl,md-dbp2k-cdfc6fd6c-27cw6,md-dbp2k-74d45c49c5-b6tmp" "indirect descendants count"=9
•E0728 16:36:25.614919   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-2gfzv\" not found" "controller"="cluster" "name"="test1-2gfzv" "namespace"="default"
I0728 16:36:26.154394   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-dbp2k-cdfc6fd6c-jmv8v" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-dbp2k-cdfc6fd6c-jmv8v-778ln"}
E0728 16:36:26.222926   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-mmwkl\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-mmwkl" "namespace"="md-test"
E0728 16:36:26.640292   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-wq5vz/test-cluster-nr98v"
•I0728 16:36:26.737358   10585 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-z4v4j" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0728 16:36:26.860436   10585 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-z4v4j" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0728 16:36:26.864733   10585 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-z4v4j" "namespace"="default"
E0728 16:36:27.257687   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-49z7m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-49z7m" "namespace"="md-test"
E0728 16:36:27.880039   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
•I0728 16:36:28.263210   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:28.263272   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:28.267523   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
I0728 16:36:28.267567   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
E0728 16:36:28.279353   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-cdfc6fd6c-27cw6\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-cdfc6fd6c-27cw6" "namespace"="md-test"
E0728 16:36:28.894701   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-pjvtn\" not found" "controller"="cluster" "name"="test3-pjvtn" "namespace"="default"
I0728 16:36:29.293150   10585 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-dbp2k-cdfc6fd6c-jmv8v" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-dbp2k-cdfc6fd6c-jmv8v-778ln"}
E0728 16:36:29.321158   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"md-dbp2k-cdfc6fd6c-jmv8v\" not found" "controller"="machine" "name"="md-dbp2k-cdfc6fd6c-jmv8v" "namespace"="md-test"
E0728 16:36:29.895613   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
E0728 16:36:30.326441   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-mmwkl\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-mmwkl" "namespace"="md-test"
E0728 16:36:30.915276   10585 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-7j5pl/test-cluster-jj5jj"
E0728 16:36:30.915579   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
•E0728 16:36:31.331650   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-49z7m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-49z7m" "namespace"="md-test"
I0728 16:36:31.916252   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-dbp2k-74d45c49c5,md-dbp2k-cdfc6fd6c;Worker machines: md-dbp2k-74d45c49c5-mmwkl,md-dbp2k-cdfc6fd6c-27cw6,md-dbp2k-74d45c49c5-b6tmp,md-dbp2k-6657c7fddb-czs5h,md-dbp2k-6657c7fddb-pqq94,md-dbp2k-74d45c49c5-49z7m" "indirect descendants count"=8
E0728 16:36:31.920764   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
E0728 16:36:32.338848   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-cdfc6fd6c-27cw6\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-cdfc6fd6c-27cw6" "namespace"="md-test"
E0728 16:36:32.921550   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
I0728 16:36:33.344447   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:33.344514   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:33.349689   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
I0728 16:36:33.349737   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
E0728 16:36:33.381133   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-mmwkl\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-mmwkl" "namespace"="md-test"
E0728 16:36:33.933809   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
•E0728 16:36:34.386743   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-49z7m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-49z7m" "namespace"="md-test"
E0728 16:36:34.934707   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
E0728 16:36:35.387210   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-hgf5n\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-hgf5n" "namespace"="test-mhc-gb4l5"
E0728 16:36:35.935399   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
E0728 16:36:36.392320   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-cdfc6fd6c-27cw6\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-cdfc6fd6c-27cw6" "namespace"="md-test"
E0728 16:36:36.945195   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
E0728 16:36:37.392819   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-f65gt\" for machine \"test-mhc-machine-lzwxm\" in namespace \"test-mhc-gb4l5\": Cluster.cluster.x-k8s.io \"test-cluster-f65gt\" not found" "controller"="machine" "name"="test-mhc-machine-lzwxm" "namespace"="test-mhc-gb4l5"
E0728 16:36:37.945987   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
E0728 16:36:38.401978   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-mmwkl\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-mmwkl" "namespace"="md-test"
I0728 16:36:38.946688   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-dbp2k-74d45c49c5,md-dbp2k-cdfc6fd6c;Worker machines: md-dbp2k-6657c7fddb-czs5h,md-dbp2k-6657c7fddb-pqq94,md-dbp2k-74d45c49c5-b6tmp,md-dbp2k-74d45c49c5-49z7m,md-dbp2k-74d45c49c5-mmwkl,md-dbp2k-cdfc6fd6c-27cw6" "indirect descendants count"=8
E0728 16:36:38.947304   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
I0728 16:36:39.406890   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:39.406933   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:39.410475   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
I0728 16:36:39.410515   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
E0728 16:36:39.415241   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-49z7m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-49z7m" "namespace"="md-test"
E0728 16:36:39.948172   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
E0728 16:36:40.422463   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-cdfc6fd6c-27cw6\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-cdfc6fd6c-27cw6" "namespace"="md-test"
E0728 16:36:40.949104   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
E0728 16:36:41.443632   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-mmwkl\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-mmwkl" "namespace"="md-test"
E0728 16:36:41.950209   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
E0728 16:36:42.449036   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-49z7m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-49z7m" "namespace"="md-test"
E0728 16:36:42.951032   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
I0728 16:36:43.453913   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:43.453961   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:43.458799   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
I0728 16:36:43.458838   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
E0728 16:36:43.464433   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-cdfc6fd6c-27cw6\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-cdfc6fd6c-27cw6" "namespace"="md-test"
E0728 16:36:43.951793   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
I0728 16:36:44.481045   10585 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-bmvn2" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0728 16:36:44.491070   10585 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-bmvn2" "namespace"="default" 
E0728 16:36:44.510775   10585 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-bmvn2" "namespace"="default"
E0728 16:36:44.952701   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
E0728 16:36:45.516647   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-mmwkl\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-mmwkl" "namespace"="md-test"
I0728 16:36:45.953363   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-dbp2k-74d45c49c5,md-dbp2k-cdfc6fd6c;Worker machines: md-dbp2k-74d45c49c5-b6tmp,md-dbp2k-74d45c49c5-49z7m,md-dbp2k-74d45c49c5-mmwkl,md-dbp2k-cdfc6fd6c-27cw6,md-dbp2k-6657c7fddb-czs5h,md-dbp2k-6657c7fddb-pqq94" "indirect descendants count"=8
E0728 16:36:45.953853   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
E0728 16:36:46.521842   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-49z7m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-49z7m" "namespace"="md-test"
E0728 16:36:46.954603   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-z4v4j: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-z4v4j" "namespace"="default"
E0728 16:36:47.527408   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-cdfc6fd6c-27cw6\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-cdfc6fd6c-27cw6" "namespace"="md-test"
E0728 16:36:47.955427   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-9z8fg: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-9z8fg" "namespace"="default"
I0728 16:36:48.532544   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:48.532592   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-czs5h" "namespace"="md-test" 
I0728 16:36:48.536289   10585 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
I0728 16:36:48.536329   10585 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-dbp2k-6657c7fddb-pqq94" "namespace"="md-test" 
I0728 16:36:48.550602   10585 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-bmvn2" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0728 16:36:48.550826   10585 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-bmvn2" "namespace"="default" "noderef"="id-node-1"
E0728 16:36:48.565513   10585 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-bmvn2" "namespace"="default"

------------------------------
• [SLOW TEST:15.068 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 25 lines ...
I0728 16:36:49.073415   10585 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"
•I0728 16:36:49.075117   10585 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"
I0728 16:36:49.075881   10585 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"
I0728 16:36:49.076550   10585 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0728 16:36:49.076584   10585 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0728 16:36:49.077096   10585 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0728 16:36:49.078379   10585 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" 
•I0728 16:36:49.149704   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-5hpw9" "namespace"="ms-test" "creating"=2 "need"=2
I0728 16:36:49.149746   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-5hpw9" "namespace"="ms-test" 
I0728 16:36:49.164156   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-5hpw9-cr4jc\"" "machineset"="ms-5hpw9" "namespace"="ms-test" 
I0728 16:36:49.164254   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-5hpw9" "namespace"="ms-test" 
I0728 16:36:49.180383   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-5hpw9-njv8w\"" "machineset"="ms-5hpw9" "namespace"="ms-test" 
I0728 16:36:49.279472   10585 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-5hpw9" "namespace"="ms-test" "creating"=1 "need"=2
I0728 16:36:49.279522   10585 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-5hpw9" "namespace"="ms-test" 
I0728 16:36:49.297565   10585 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-5hpw9-68nfc\"" "machineset"="ms-5hpw9" "namespace"="ms-test" 
E0728 16:36:49.527836   10585 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-5hpw9-njv8w-fsf2w for machine ms-test/ms-5hpw9-njv8w: the cache is not started, can not read objects" "machineset"="ms-5hpw9" "namespace"="ms-test" 
E0728 16:36:49.569617   10585 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-dbp2k-74d45c49c5-mmwkl\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-dbp2k-74d45c49c5-mmwkl" "namespace"="md-test"
I0728 16:36:49.661146   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-5hpw9-68nfc,ms-5hpw9-njv8w" "indirect descendants count"=2
•

Ran 16 of 16 Specs in 26.531 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (26.53s)
PASS
Tearing down test suite
I0728 16:36:49.665158   10585 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-5hpw9-68nfc,ms-5hpw9-njv8w" "indirect descendants count"=2
I0728 16:36:49.665363   10585 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0728 16:36:49.665434   10585 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0728 16:36:49.665377   10585 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0728 16:36:49.665392   10585 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0728 16:36:49.665407   10585 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0728 16:36:49.665441   10585 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0728 16:36:49.665621   10585 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
E0728 16:36:49.696622   10585 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:44987/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1263&timeout=10s&timeoutSeconds=519&watch=true: dial tcp 127.0.0.1:44987: connect: connection refused
E0728 16:36:49.696622   10585 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:44987/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1263&timeout=10s&timeoutSeconds=540&watch=true: dial tcp 127.0.0.1:44987: connect: connection refused
E0728 16:36:49.697691   10585 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:44987/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1263&timeout=10s&timeoutSeconds=354&watch=true: dial tcp 127.0.0.1:44987: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	86.568s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 265 lines ...
•I0728 16:35:38.144765   11116 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0728 16:35:38.185285   11116 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":{}}}
I0728 16:35:38.386190   11116 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0728 16:35:38.386260   11116 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0728 16:35:38.386335   11116 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0728 16:35:38.919223   11116 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0728 16:35:40.979021   11116 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-7jlvc/test-cluster"
•E0728 16:35:41.434187   11116 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-tttr6/test-cluster"
•E0728 16:35:41.976873   11116 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:38153/?timeout=50ms: dial tcp 127.0.0.1:38153: connect: connection refused"  "cluster"="cluster-cache-test-2blqp/test-cluster"
•I0728 16:35:42.186228   11116 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0728 16:35:42.245267   11116 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:43185/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:43185: connect: connection refused


Ran 5 of 5 Specs in 16.455 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.46s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	16.635s
?   	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
I0728 16:35:51.908888   11674 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
E0728 16:35:51.910167   11674 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
I0728 16:35:51.911054   11674 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0728 16:35:51.911324   11674 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 94 lines ...
I0728 16:36:07.625981   11674 remediation.go:248]  "msg"="etcd cluster projected after remediation of m1-unhealthy-w78c8" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "canSafelyRemediate"=true "healthyMembers"=["node-m3-healthy-pjjhn (m3-healthy-pjjhn)","node-m2-healthy-brsxs (m2-healthy-brsxs)"] "targetQuorum"=2 "targetTotalMembers"=2 "targetUnhealthyMembers"=0 "unhealthyMembers"=[]
I0728 16:36:07.630573   11674 remediation.go:154]  "msg"="Remediating unhealthy machine" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "UnhealthyMachine"="m1-unhealthy-w78c8"
=== RUN   TestReconcileUnhealthyMachines/Remediation_deletes_unhealthy_machine_-_4_CP_(during_3_CP_rolling_upgrade)
I0728 16:36:07.768833   11674 remediation.go:195]  "msg"="etcd cluster before remediation" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "currentMembers"=["node-m1-unhealthy-2wmz8","node-m2-healthy-4qkkf","node-m3-healthy-zspp5","node-m4-healthy-j99lk"] "currentTotalMembers"=4
I0728 16:36:07.768922   11674 remediation.go:248]  "msg"="etcd cluster projected after remediation of m1-unhealthy-2wmz8" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "canSafelyRemediate"=true "healthyMembers"=["node-m2-healthy-4qkkf (m2-healthy-4qkkf)","node-m3-healthy-zspp5 (m3-healthy-zspp5)","node-m4-healthy-j99lk (m4-healthy-j99lk)"] "targetQuorum"=2 "targetTotalMembers"=3 "targetUnhealthyMembers"=0 "unhealthyMembers"=[]
I0728 16:36:07.773574   11674 remediation.go:154]  "msg"="Remediating unhealthy machine" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "UnhealthyMachine"="m1-unhealthy-2wmz8"
--- FAIL: TestReconcileUnhealthyMachines (0.87s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_are_no_unhealthy_machines (0.00s)
    --- PASS: TestReconcileUnhealthyMachines/reconcileUnhealthyMachines_return_early_if_the_machine_to_be_remediated_is_marked_for_deletion (0.00s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_desired_replicas_<=_1 (0.04s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_number_of_machines_lower_than_desired (0.05s)
    --- FAIL: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_is_a_deleting_machine (0.05s)
        remediation_test.go:841: 
            Expected
                <string>: 
            to equal
                <string>: KCP waiting for control plane machine deletion to complete before triggering remediation
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_is_at_least_one_additional_unhealthy_etcd_member_on_a_3_machine_CP (0.08s)
... skipping 85 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
I0728 16:36:11.445667   11674 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
I0728 16:36:11.445785   11674 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: 1627490136
Will run 1 of 1 specs

E0728 16:36:11.478796   11674 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-ssog13\" not found" "kubeadmControlPlane"="kcp-foo-ssog13" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.029 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0728 16:36:11.480417   11674 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-oromfk" "kubeadmControlPlane"="kcp-foo-oromfk" "namespace"="test" 
I0728 16:36:13.642852   11674 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-oromfk" "kubeadmControlPlane"="kcp-foo-oromfk" "namespace"="test" "needRollout"=["kcp-foo-oromfk-pp5ms"]
I0728 16:36:13.642996   11674 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-oromfk" "kubeadmControlPlane"="kcp-foo-oromfk" "namespace"="test" "failures"="[machine kcp-foo-oromfk-sqlbh does not have APIServerPodHealthy condition, machine kcp-foo-oromfk-sqlbh does not have ControllerManagerPodHealthy condition, machine kcp-foo-oromfk-sqlbh does not have SchedulerPodHealthy condition, machine kcp-foo-oromfk-sqlbh does not have EtcdPodHealthy condition, machine kcp-foo-oromfk-sqlbh does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (2.16s)
FAIL
I0728 16:36:13.644000   11674 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
FAIL	sigs.k8s.io/cluster-api/controlplane/kubeadm/controllers	37.224s
I0728 16:35:48.869703   11640 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0728 16:35:48.869809   11640 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0728 16:35:48.869840   11640 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0728 16:35:48.869855   11640 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0728 16:35:48.869935   11640 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Machine"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
I0728 16:35:48.869950   11640 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
... skipping 51 lines ...
==================================
Random Seed: 1627490135
Will run 7 of 7 specs

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

•••••••
Ran 7 of 7 Specs in 0.001 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestMachineCollection (0.00s)
=== RUN   TestUpdateEtcdConditions
=== RUN   TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines
=== RUN   TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition
... skipping 247 lines ...
        --- PASS: TestForwardEtcdLeadership/move_etcd_leader/returns_error_if_failed_to_move_to_the_leader_candidate (0.00s)
        --- PASS: TestForwardEtcdLeadership/move_etcd_leader/returns_error_if_the_leader_candidate_doesn't_exist_in_etcd (0.00s)
=== RUN   TestReconcileEtcdMembers
=== RUN   TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_and_removes_the_node_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_for_Kubernetes_version_>=_1.22.0
=== RUN   TestReconcileEtcdMembers/return_error_if_there_aren't_enough_control_plane_nodes
--- FAIL: TestReconcileEtcdMembers (0.21s)
    --- PASS: TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_and_removes_the_node_from_kubeadm_config_for_Kubernetes_version_<_1.22.0 (0.15s)
    --- FAIL: TestReconcileEtcdMembers/successfully_removes_the_etcd_member_without_a_node_for_Kubernetes_version_>=_1.22.0 (0.03s)
        workload_cluster_etcd_test.go:608: 
            Unexpected error:
                <errors.aggregate | len:2, cap:2>: [
                    {
                        msg: "cluster has fewer than 2 control plane nodes; removing an etcd member is not supported",
                        stack: [0x1740de6, 0x43f42a, 0x43f3f7, 0x432e62, 0x461351],
                    },
                    {
... skipping 47 lines ...
    --- PASS: TestUpdateKubeProxyImageInfo/returns_error_if_image_repository_is_invalid (0.00s)
    --- PASS: TestUpdateKubeProxyImageInfo/does_not_update_image_repository_when_no_kube-proxy_update_is_requested (0.00s)
=== RUN   TestRemoveMachineFromKubeadmConfigMap
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_find_kubeadm-config_for_Kubernetes_version_<_1.22.0
E0728 16:35:51.718414   11640 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"  
E0728 16:36:00.041452   11640 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"  
E0728 16:36:09.027508   11640 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"  
E0728 16:36:20.157788   11640 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"  
E0728 16:36:36.631012   11640 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"  
E0728 16:36:49.639767   11640 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"  
E0728 16:37:07.287173   11640 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"  
E0728 16:37:28.210585   11640 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"  
E0728 16:37:59.227057   11640 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"  
E0728 16:38:44.384234   11640 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0
--- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s)
... skipping 82 lines ...
--- PASS: TestIsKubernetesVersionSupported (0.01s)
    --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_<_v1.22.0 (0.01s)
    --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_<_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.23.0 (0.00s)
FAIL
I0728 16:38:44.400667   11640 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0728 16:38:44.404441   11640 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0728 16:38:44.404587   11640 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-229973754/tls.crt: no such file or directory"  
FAIL	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	189.097s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
PASS
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal/etcd	0.073s
... skipping 286 lines ...
I0728 16:36:01.428177   11961 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourcesetbinding" 
I0728 16:36:01.428249   11961 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0728 16:36:01.437802   11961 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0728 16:36:01.540726   11961 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0728 16:36:01.540810   11961 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0728 16:36:01.739490   11961 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-15kw8h"} 
E0728 16:36:01.781329   11961 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"
•I0728 16:36:02.841886   11961 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-2r07ud"} 
E0728 16:36:02.877649   11961 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"
•E0728 16:36:03.964361   11961 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get data field from the resource" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
•E0728 16:36:04.996747   11961 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"
E0728 16:36:06.137341   11961 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"
E0728 16:36:07.162860   11961 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"
••E0728 16:36:08.180349   11961 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 16:36:08.180416   11961 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-793851826/tls.crt: no such file or directory"  
E0728 16:36:08.180439   11961 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 16:36:08.180460   11961 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-793851826/tls.crt: no such file or directory"  
I0728 16:36:08.180533   11961 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0728 16:36:08.180617   11961 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0728 16:36:08.180791   11961 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0728 16:36:08.181767   11961 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"


Ran 5 of 5 Specs in 22.669 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (22.67s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/addons/controllers	22.746s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
... skipping 61 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0728 16:35:50.909114   12110 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 ...
•I0728 16:36:05.159526   12110 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0728 16:36:05.195321   12110 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0728 16:36:05.234396   12110 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0728 16:36:05.237846   12110 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0728 16:36:05.259646   12110 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0728 16:36:05.280365   12110 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••E0728 16:36:05.286912   12110 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 16:36:05.286966   12110 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-101975110/tls.crt: no such file or directory"  
E0728 16:36:05.287092   12110 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 16:36:05.287128   12110 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-101975110/tls.crt: no such file or directory"  
I0728 16:36:05.288673   12110 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 9 of 9 Specs in 14.162 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (14.16s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	14.584s
?   	sigs.k8s.io/cluster-api/exp/util	[no test files]
?   	sigs.k8s.io/cluster-api/feature	[no test files]
?   	sigs.k8s.io/cluster-api/hack/boilerplate/test	[no test files]
... skipping 266 lines ...
--- PASS: TestGetFirstReasonAndMessage (0.00s)
=== RUN   TestNewConditionsGroup
--- PASS: TestNewConditionsGroup (0.00s)
=== RUN   TestMergeRespectPriority
=== RUN   TestMergeRespectPriority/aggregate_nil_list_return_nil
=== RUN   TestMergeRespectPriority/aggregate_empty_list_return_nil
=== RUN   TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error
=== RUN   TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning
=== RUN   TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info
=== RUN   TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info
=== RUN   TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown
=== RUN   TestMergeRespectPriority/nil_conditions_are_ignored
--- PASS: TestMergeRespectPriority (0.00s)
    --- PASS: TestMergeRespectPriority/aggregate_nil_list_return_nil (0.00s)
    --- PASS: TestMergeRespectPriority/aggregate_empty_list_return_nil (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown (0.00s)
    --- PASS: TestMergeRespectPriority/nil_conditions_are_ignored (0.00s)
=== RUN   TestNewPatch
=== RUN   TestNewPatch/No_changes_return_empty_patch
... skipping 200 lines ...
I0728 16:36:33.236467   15194 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1alpha3","Kind":"ClusterResourceSet"} "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0728 16:36:33.236508   15194 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0728 16:36:33.236708   15194 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0728 16:36:33.237593   15194 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0728 16:36:33.237896   15194 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=41065
I0728 16:36:33.237997   15194 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••E0728 16:36:34.212861   15194 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 16:36:34.212899   15194 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-987199690/tls.crt: no such file or directory"  
E0728 16:36:34.212915   15194 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0728 16:36:34.212929   15194 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-987199690/tls.crt: no such file or directory"  
I0728 16:36:34.212998   15194 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


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