This job view page is being replaced by Spyglass soon. Check out the new job view.
PRykakarap: 🐛 Fix the observedGeneration update
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2021-07-12 17:00
Elapsed4m22s
Revision74bfd71de19b58e83666133aa093b0f1387018be
Refs 4920

No Test Failures!


Error lines from build-log.txt

... skipping 777 lines ...
I0712 17:02:12.247277    8384 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0712 17:02:12.247447    8384 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0712 17:02:12.248334    8384 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0712 17:02:12.248552    8384 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=38605
I0712 17:02:12.248677    8384 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0712 17:02:12.740001    8384 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" 
•E0712 17:02:12.754309    8384 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 17:02:12.754375    8384 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-769308771/tls.crt: no such file or directory"  
E0712 17:02:12.754395    8384 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 17:02:12.754429    8384 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-769308771/tls.crt: no such file or directory"  
I0712 17:02:12.754544    8384 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 12.245 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (12.24s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	61.011s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 302 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.01s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.01s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s)
=== RUN   Test_getComponentsByName_withEmptyVariables
--- PASS: Test_getComponentsByName_withEmptyVariables (0.00s)
=== RUN   Test_clusterctlClient_templateOptionsToVariables
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts)
... skipping 1398 lines ...
I0712 17:01:43.845246   10588 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0712 17:01:43.845303   10588 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinehealthcheck" 
I0712 17:01:43.845353   10588 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
I0712 17:01:43.845404   10588 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machine" "worker count"=1
I0712 17:01:43.848665   10588 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
I0712 17:01:43.848666   10588 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
2021/07/12 17:01:44 http: TLS handshake error from 127.0.0.1:35112: EOF
=== RUN   TestClusterReconcilePhases
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I0712 17:01:44.244003   10588 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"
I0712 17:01:44.247345   10588 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
... skipping 105 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0712 17:01:44.330486   10588 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
I0712 17:01:44.332999   10588 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"
E0712 17:01:44.333485   10588 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
I0712 17:01:44.334069   10588 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
--- PASS: TestReconcileInfrastructure (0.00s)
    --- PASS: TestReconcileInfrastructure/new_machine,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestWatches
I0712 17:01:44.723930   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0712 17:01:44.824673   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0712 17:01:44.833122   10588 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-ht6jp" "namespace"="test-machine-watches-knrcf" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0712 17:01:44.833205   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0712 17:01:44.943250   10588 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-ht6jp" "namespace"="test-machine-watches-knrcf" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0712 17:01:44.943346   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0712 17:01:45.044099   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-ht6jp" "namespace"="test-machine-watches-knrcf" "noderef"="node-1"
E0712 17:01:45.051566   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0712 17:01:45.051627   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0712 17:01:45.108512   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-ht6jp\" in namespace \"test-machine-watches-knrcf\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-ht6jp" "namespace"="test-machine-watches-knrcf"
E0712 17:01:46.114651   10588 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-ht6jp\" in namespace \"test-machine-watches-knrcf\", requeuing: requeue in 1s"  
E0712 17:01:46.125295   10588 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-ht6jp\" in namespace \"test-machine-watches-knrcf\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-ht6jp\" in namespace \"test-machine-watches-knrcf\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-ht6jp" "namespace"="test-machine-watches-knrcf"
--- PASS: TestWatches (1.83s)
=== 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
I0712 17:01:46.353353   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-gvv9n" "namespace"="test-machine-watches-knrcf" "count"=1
I0712 17:01:46.353993   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-gvv9n" "namespace"="test-machine-watches-knrcf" "descendants"="Worker machines: machine-created-ht6jp" "indirect descendants count"=0
I0712 17:01:46.376029   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-gvv9n" "namespace"="test-machine-watches-knrcf" "count"=1
I0712 17:01:46.376089   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-gvv9n" "namespace"="test-machine-watches-knrcf" "descendants"="Worker machines: machine-created-ht6jp" "indirect descendants count"=0
I0712 17:01:47.125791   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-gvv9n" "machine"="machine-created-ht6jp" "namespace"="test-machine-watches-knrcf" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"37ad8f15-688f-42c5-a758-dffa081b3b68","apiVersion":"v1"}
E0712 17:01:47.174706   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-ht6jp\" not found" "controller"="machine" "name"="machine-created-ht6jp" "namespace"="test-machine-watches-knrcf"
E0712 17:01:48.226504   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-jv974\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-c8cf2\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-c8cf2: secrets \"machine-reconcile-c8cf2-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-jv974" "namespace"="default"
I0712 17:01:49.227063   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-c8cf2" "machine"="machine-created-jv974" "namespace"="default" "cause"="noderef is nil" "node"=null
I0712 17:01:49.256435   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-c8cf2" "machine"="machine-created-jv974" "namespace"="default" "cause"="noderef is nil" "node"=null
I0712 17:01:49.274532   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-c8cf2" "machine"="machine-created-jv974" "namespace"="default" "cause"="noderef is nil" "node"=null
E0712 17:01:49.303340   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-jv974\" not found" "controller"="machine" "name"="machine-created-jv974" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.15s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.15s)
=== RUN   TestMachineFinalizer
=== RUN   TestMachineFinalizer/should_add_a_machine_finalizer_to_the_machine_if_it_doesn't_have_one
=== RUN   TestMachineFinalizer/should_append_the_machine_finalizer_to_the_machine_if_it_already_has_a_finalizer
--- PASS: TestMachineFinalizer (0.00s)
... skipping 13 lines ...
    --- PASS: TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta (0.00s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set (0.00s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.00s)
=== RUN   TestReconcileRequest
=== RUN   TestReconcileRequest/machine_should_be_created
I0712 17:01:49.332393   10588 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"
E0712 17:01:49.341013   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-c8cf2\" not found" "controller"="cluster" "name"="machine-reconcile-c8cf2" "namespace"="default"
=== RUN   TestReconcileRequest/machine_should_be_updated
I0712 17:01:49.345722   10588 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="updated" "namespace"="default" "err"="cannot create a metadata client without a rest config"
=== RUN   TestReconcileRequest/machine_should_be_deleted
I0712 17:01:49.353090   10588 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.03s)
    --- PASS: TestReconcileRequest/machine_should_be_created (0.01s)
... skipping 112 lines ...
    --- 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
I0712 17:01:49.485982   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-89cwf" "namespace"="test-mhc-x6t6c" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
I0712 17:01:49.529304   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0712 17:01:49.530717   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-wlw99\" not found"  "cluster"="test-mhc-x6t6c/test-cluster-wlw99"
E0712 17:01:49.537339   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-89cwf\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-89cwf\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-89cwf" "namespace"="test-mhc-x6t6c"
=== 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
I0712 17:01:50.537671   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zlcpw" "namespace"="test-mhc-46vt8" 
I0712 17:01:50.537775   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-89cwf" "namespace"="test-mhc-x6t6c" 
I0712 17:01:50.537809   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g2svn" "namespace"="test-mhc-zpr4v" 
I0712 17:01:50.537836   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84lbz" "namespace"="test-mhc-8f6bm" 
I0712 17:01:50.553065   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 17:01:50.674220   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84lbz" "namespace"="test-mhc-8f6bm" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
I0712 17:01:50.716158   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-84lbz" "namespace"="test-mhc-8f6bm" 
E0712 17:01:50.722746   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-8f6bm/test-cluster-hmxrk"
E0712 17:01:50.723570   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-hmxrk\" not found" "controller"="cluster" "name"="test-cluster-hmxrk" "namespace"="test-mhc-8f6bm"
I0712 17:01:50.737078   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c927n" "namespace"="test-mhc-g6bzc" 
I0712 17:01:50.762564   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 17:01:50.781562   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c927n" "namespace"="test-mhc-g6bzc" 
E0712 17:01:50.842296   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-g6bzc/test-cluster-jjjhz"
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0712 17:01:50.848849   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-c927n" "namespace"="test-mhc-g6bzc" 
I0712 17:01:50.965241   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
inframachine created: test-mhc-machine-infra-mf7t2
machine created: test-mhc-machine-txfrb
I0712 17:01:50.994503   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
node created: test-mhc-node-hc7rc
E0712 17:01:51.094295   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-hc7rc"
I0712 17:01:51.095176   10588 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-krnlm/test-mhc-szmt5/test-mhc-machine-txfrb/"
E0712 17:01:51.095924   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hc7rc, got []"  "node"="test-mhc-node-hc7rc"
I0712 17:01:51.095991   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm" "noderef"="test-mhc-node-hc7rc"
E0712 17:01:51.103482   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-hc7rc"
E0712 17:01:51.103537   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-hc7rc"
E0712 17:01:51.103736   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hc7rc, got []"  "node"="test-mhc-node-hc7rc"
E0712 17:01:51.103766   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hc7rc, got []"  "node"="test-mhc-node-hc7rc"
inframachine created: test-mhc-machine-infra-rgcxp
machine created: test-mhc-machine-ml5tg
I0712 17:01:51.148430   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.162895   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.163979   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.165500   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
... skipping 56 lines ...
I0712 17:01:51.295289   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.298175   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.300120   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.301273   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.302418   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.303500   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.304924   10588 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-krnlm/test-mhc-szmt5/test-mhc-machine-ml5tg/"
I0712 17:01:51.336636   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.337049   10588 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-krnlm/test-mhc-szmt5/test-mhc-machine-ml5tg/"
I0712 17:01:51.343921   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.344361   10588 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-krnlm/test-mhc-szmt5/test-mhc-machine-ml5tg/"
node created: test-mhc-node-hxhpq
E0712 17:01:51.346070   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hxhpq, got []"  "node"="test-mhc-node-hxhpq"
E0712 17:01:51.346247   10588 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-hxhpq"
I0712 17:01:51.353713   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.354174   10588 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-krnlm/test-mhc-szmt5/test-mhc-machine-ml5tg/"
I0712 17:01:51.360244   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.559403   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.565699   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
Cleaning up nodes, machines and infra machines.
I0712 17:01:51.567264   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.570256   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.570687   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-krnlm/test-mhc-szmt5/test-mhc-machine-txfrb/"
I0712 17:01:51.588607   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:51.589053   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-krnlm/test-mhc-szmt5/test-mhc-machine-txfrb/"
I0712 17:01:51.589407   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-krnlm/test-mhc-szmt5/test-mhc-machine-ml5tg/"
E0712 17:01:51.606553   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
E0712 17:01:51.613640   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-krnlm/test-cluster-dpzj7"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E0712 17:01:51.743239   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-szmt5\" not found" "controller"="machinehealthcheck" "name"="test-mhc-szmt5" "namespace"="test-mhc-krnlm"
E0712 17:01:51.746525   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-knrcf/machine-reconcile-gvv9n"
inframachine created: test-mhc-machine-infra-l8hc2
machine created: test-mhc-machine-75zq8
E0712 17:01:52.606924   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:01:52.743566   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-szmt5" "namespace"="test-mhc-krnlm" 
I0712 17:01:52.743713   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:52.760017   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 17:01:52.882263   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:52.883375   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:52.885116   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
... skipping 340 lines ...
I0712 17:01:53.598103   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.600093   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.601816   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.603574   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.605243   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.606917   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
E0712 17:01:53.607249   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:01:53.608614   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.610327   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.612018   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.613763   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.615451   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:53.617122   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
... skipping 510 lines ...
I0712 17:01:54.611876   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:54.614531   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:54.615869   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:54.616450   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:54.618709   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:54.620497   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
E0712 17:01:54.620503   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:01:54.620792   10588 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-dnng2/test-mhc-wc8z8/test-mhc-machine-75zq8/"
I0712 17:01:54.632083   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:54.632363   10588 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-dnng2/test-mhc-wc8z8/test-mhc-machine-75zq8/"
E0712 17:01:54.685762   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-29smz, got []"  "node"="test-mhc-node-29smz"
node created: test-mhc-node-29smz
I0712 17:01:54.692923   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
inframachine created: test-mhc-machine-infra-nrz5p
machine created: test-mhc-machine-f7xgq
I0712 17:01:54.718668   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:54.724584   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
... skipping 346 lines ...
I0712 17:01:55.607202   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.609488   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.611499   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.613599   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.617112   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.620154   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
E0712 17:01:55.620884   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:01:55.622604   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.626683   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.628744   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.632007   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.634093   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:55.636253   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
... skipping 358 lines ...
I0712 17:01:56.652913   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.655533   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.656625   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.657880   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.659038   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.660316   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
E0712 17:01:56.660698   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:01:56.661541   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.664504   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.672298   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.674929   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.677642   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:56.683138   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
... skipping 373 lines ...
I0712 17:01:57.667999   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:57.670626   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:57.672266   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:57.673658   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:57.674764   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:57.675789   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
E0712 17:01:57.677654   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:01:57.678369   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:57.679990   10588 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-dnng2/test-mhc-wc8z8/test-mhc-machine-f7xgq/"
I0712 17:01:57.689967   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:57.690352   10588 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-dnng2/test-mhc-wc8z8/test-mhc-machine-f7xgq/"
node created: test-mhc-node-htf6g
E0712 17:01:57.757139   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-htf6g, got []"  "node"="test-mhc-node-htf6g"
I0712 17:01:57.792331   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
inframachine created: test-mhc-machine-infra-xnpz6
I0712 17:01:57.820262   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
machine created: test-mhc-machine-qm6kf
I0712 17:01:57.839939   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:57.848456   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
... skipping 250 lines ...
I0712 17:01:58.675219   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.678449   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.681157   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.683728   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.686267   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.688822   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
E0712 17:01:58.689910   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:01:58.690596   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.692200   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.693639   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.695022   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.696499   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:58.697997   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
... skipping 328 lines ...
I0712 17:01:59.739158   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.741315   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.742969   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.747151   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.749061   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.750413   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
E0712 17:01:59.752207   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:01:59.752346   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.753848   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.755340   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.756869   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.758316   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:01:59.760179   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
... skipping 286 lines ...
I0712 17:02:00.761132   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.762478   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.764343   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.765872   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.768488   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.769959   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.770416   10588 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-dnng2/test-mhc-wc8z8/test-mhc-machine-qm6kf/"
E0712 17:02:00.774640   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:02:00.782449   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.782858   10588 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-dnng2/test-mhc-wc8z8/test-mhc-machine-qm6kf/"
node created: test-mhc-node-kvkq7
E0712 17:02:00.848315   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-kvkq7, got []"  "node"="test-mhc-node-kvkq7"
Cleaning up nodes, machines and infra machines.
I0712 17:02:00.855594   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.856066   10588 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-dnng2/test-mhc-wc8z8/test-mhc-machine-qm6kf/test-mhc-node-kvkq7"
I0712 17:02:00.866587   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wc8z8" "namespace"="test-mhc-dnng2" 
I0712 17:02:00.867117   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-dnng2/test-mhc-wc8z8/test-mhc-machine-qm6kf/"
Cleaning up nodes, machines and infra machines.
I0712 17:02:00.900729   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-zn8mc" "namespace"="test-mhc-dnng2" "count"=2
I0712 17:02:00.900806   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-zn8mc" "namespace"="test-mhc-dnng2" "descendants"="Worker machines: test-mhc-machine-75zq8,test-mhc-machine-f7xgq,test-mhc-machine-qm6kf" "indirect descendants count"=1
I0712 17:02:00.904428   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-zn8mc" "namespace"="test-mhc-dnng2" "count"=2
I0712 17:02:00.904499   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-zn8mc" "namespace"="test-mhc-dnng2" "descendants"="Worker machines: test-mhc-machine-75zq8,test-mhc-machine-f7xgq,test-mhc-machine-qm6kf" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
... skipping 7 lines ...
I0712 17:02:01.078347   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:01.087096   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:01.167957   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:01.330327   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:01.651336   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:01.775238   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-zn8mc" "machine"="test-mhc-machine-f7xgq" "namespace"="test-mhc-dnng2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-htf6g"}
E0712 17:02:01.815157   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-f7xgq\" not found" "controller"="machine" "name"="test-mhc-machine-f7xgq" "namespace"="test-mhc-dnng2"
I0712 17:02:02.292295   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
E0712 17:02:02.815601   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:02:03.573794   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:03.816084   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-zn8mc" "machine"="test-mhc-machine-qm6kf" "namespace"="test-mhc-dnng2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-kvkq7"}
E0712 17:02:03.861564   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-qm6kf\" not found" "controller"="machine" "name"="test-mhc-machine-qm6kf" "namespace"="test-mhc-dnng2"
E0712 17:02:04.861964   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:02:05.862830   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-zn8mc" "machine"="test-mhc-machine-75zq8" "namespace"="test-mhc-dnng2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-29smz"}
E0712 17:02:05.906147   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-75zq8\" not found" "controller"="machine" "name"="test-mhc-machine-75zq8" "namespace"="test-mhc-dnng2"
E0712 17:02:05.918356   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-dnng2/test-cluster-zn8mc"
I0712 17:02:06.134800   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:06.914329   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:06.920744   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
E0712 17:02:06.921230   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:02:06.944891   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
E0712 17:02:06.969966   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-z8mx4, got []"  "node"="test-mhc-node-z8mx4"
node created: test-mhc-node-z8mx4
I0712 17:02:06.977646   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
inframachine created: test-mhc-machine-infra-kbn5w
machine created: test-mhc-machine-tjvzd
I0712 17:02:06.997342   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:07.009547   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:07.017495   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:07.027953   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:07.069476   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:07.150820   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:07.312154   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:07.633198   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
E0712 17:02:07.921603   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:02:08.274620   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:08.938100   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:08.944352   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:08.956310   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:08.962199   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:08.968775   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:08.972213   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
E0712 17:02:08.974212   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:02:08.993692   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
node created: test-mhc-node-87tsl
E0712 17:02:09.001435   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-87tsl, got []"  "node"="test-mhc-node-87tsl"
I0712 17:02:09.009585   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
inframachine created: test-mhc-machine-infra-687kj
I0712 17:02:09.023970   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
machine created: test-mhc-machine-wrwwr
I0712 17:02:09.029230   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:09.042200   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:09.053508   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:09.555926   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
E0712 17:02:09.974600   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:02:10.985434   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:10.994695   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:11.003092   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:11.011827   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:11.020151   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:11.028347   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
I0712 17:02:11.031469   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
E0712 17:02:11.031863   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
E0712 17:02:11.037350   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-97ft6, got []"  "node"="test-mhc-node-97ft6"
node created: test-mhc-node-97ft6
I0712 17:02:11.053644   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
Cleaning up nodes, machines and infra machines.
I0712 17:02:11.064674   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-z9nfc" "namespace"="test-mhc-dv7bp" 
Cleaning up nodes, machines and infra machines.
I0712 17:02:11.101417   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-jjdpv" "namespace"="test-mhc-dv7bp" "count"=2
... skipping 6 lines ...
inframachine created: test-mhc-machine-infra-7lkzj
I0712 17:02:11.246398   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-m959l
I0712 17:02:11.265015   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:11.269892   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:11.274671   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
E0712 17:02:12.032232   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:02:13.032843   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-jjdpv" "machine"="test-mhc-machine-kflnt" "namespace"="test-mhc-dv7bp" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-z8mx4"}
E0712 17:02:13.072391   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-kflnt\" not found" "controller"="machine" "name"="test-mhc-machine-kflnt" "namespace"="test-mhc-dv7bp"
I0712 17:02:14.072938   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-jjdpv" "machine"="test-mhc-machine-tjvzd" "namespace"="test-mhc-dv7bp" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-87tsl"}
E0712 17:02:14.114315   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-tjvzd\" not found" "controller"="machine" "name"="test-mhc-machine-tjvzd" "namespace"="test-mhc-dv7bp"
I0712 17:02:15.114838   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-jjdpv" "machine"="test-mhc-machine-wrwwr" "namespace"="test-mhc-dv7bp" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-97ft6"}
E0712 17:02:15.160028   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-wrwwr\" not found" "controller"="machine" "name"="test-mhc-machine-wrwwr" "namespace"="test-mhc-dv7bp"
E0712 17:02:16.119347   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-dv7bp/test-cluster-jjdpv"
I0712 17:02:16.169188   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
E0712 17:02:16.177674   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:02:16.177729   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
E0712 17:02:16.201103   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-srfbc, got []"  "node"="test-mhc-node-srfbc"
node created: test-mhc-node-srfbc
I0712 17:02:16.210916   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
inframachine created: test-mhc-machine-infra-kjsgd
machine created: test-mhc-machine-flvqc
I0712 17:02:16.225482   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:16.230506   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
E0712 17:02:17.178087   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:02:18.192982   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.210704   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.217550   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.226833   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.235610   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.240842   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.250280   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
E0712 17:02:18.252102   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-lbl2l, got []"  "node"="test-mhc-node-lbl2l"
node created: test-mhc-node-lbl2l
I0712 17:02:18.258582   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.259594   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-flvqc" "namespace"="test-mhc-m45dt" "noderef"="test-mhc-node-lbl2l"
inframachine created: test-mhc-machine-infra-fk7fn
machine created: test-mhc-machine-vx2hx
I0712 17:02:18.274295   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
... skipping 11 lines ...
Cleaning up nodes, machines and infra machines.
I0712 17:02:18.579753   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.579830   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-b44vt" "machine"="test-mhc-machine-vx2hx" "namespace"="test-mhc-m45dt" "cause"="noderef is nil" "node"=null
I0712 17:02:18.585373   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
Cleaning up nodes, machines and infra machines.
I0712 17:02:18.598060   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.598586   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-m45dt/test-mhc-bbgj7/test-mhc-machine-m959l/"
I0712 17:02:18.631122   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:18.631735   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-m45dt/test-mhc-bbgj7/test-mhc-machine-m959l/"
I0712 17:02:18.632339   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-m45dt/test-mhc-bbgj7/test-mhc-machine-flvqc/"
E0712 17:02:18.632719   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-vx2hx\" not found" "controller"="machine" "name"="test-mhc-machine-vx2hx" "namespace"="test-mhc-m45dt"
I0712 17:02:18.651002   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-b44vt" "namespace"="test-mhc-m45dt" "count"=2
I0712 17:02:18.651090   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-b44vt" "namespace"="test-mhc-m45dt" "descendants"="Worker machines: test-mhc-machine-m959l,test-mhc-machine-flvqc" "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
I0712 17:02:18.658910   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-b44vt" "namespace"="test-mhc-m45dt" "count"=2
I0712 17:02:18.658967   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-b44vt" "namespace"="test-mhc-m45dt" "descendants"="Worker machines: test-mhc-machine-m959l,test-mhc-machine-flvqc" "indirect descendants count"=0
inframachine created: test-mhc-machine-infra-rwbrn
E0712 17:02:18.787361   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-bbgj7\" not found" "controller"="machinehealthcheck" "name"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt"
machine created: test-mhc-machine-2jbql
I0712 17:02:19.633278   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-b44vt" "machine"="test-mhc-machine-m959l" "namespace"="test-mhc-m45dt" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-srfbc"}
E0712 17:02:19.709538   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-m959l\" not found" "controller"="machine" "name"="test-mhc-machine-m959l" "namespace"="test-mhc-m45dt"
I0712 17:02:19.787708   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:19.811968   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 17:02:19.945357   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bbgj7" "namespace"="test-mhc-m45dt" 
I0712 17:02:19.945436   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:19.946454   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:19.947087   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
... skipping 348 lines ...
I0712 17:02:20.752660   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.754628   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.756528   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.758408   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.760847   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.762814   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
E0712 17:02:20.763182   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-flvqc\" not found" "controller"="machine" "name"="test-mhc-machine-flvqc" "namespace"="test-mhc-m45dt"
I0712 17:02:20.764731   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.766928   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.768686   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.770468   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.772210   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:20.773974   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
... skipping 478 lines ...
I0712 17:02:21.754553   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.756237   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.757923   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.759600   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.761250   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.762913   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
E0712 17:02:21.763515   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:02:21.764648   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.766330   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.768042   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.769954   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.771647   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:21.773354   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
... skipping 499 lines ...
I0712 17:02:22.773511   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.775866   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.776598   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.778409   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.780234   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.781528   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.781759   10588 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-rn7zl/test-mhc-gxrqk/test-mhc-machine-2jbql/"
E0712 17:02:22.782531   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
I0712 17:02:22.790778   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.791087   10588 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-rn7zl/test-mhc-gxrqk/test-mhc-machine-2jbql/"
node created: test-mhc-node-9vgdm
E0712 17:02:22.832583   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-9vgdm, got []"  "node"="test-mhc-node-9vgdm"
E0712 17:02:22.832848   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-9vgdm, got []"  "node"="test-mhc-node-9vgdm"
I0712 17:02:22.840221   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.854480   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.859493   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.862765   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.863906   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.864178   10588 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-rn7zl/test-mhc-gxrqk/test-mhc-machine-2jbql/test-mhc-node-9vgdm"
I0712 17:02:22.877027   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.877355   10588 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-rn7zl/test-mhc-gxrqk/test-mhc-machine-2jbql/test-mhc-node-9vgdm"
I0712 17:02:22.881553   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.881923   10588 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-rn7zl/test-mhc-gxrqk/test-mhc-machine-2jbql/test-mhc-node-9vgdm"
Cleaning up nodes, machines and infra machines.
I0712 17:02:22.897349   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:22.897659   10588 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-rn7zl/test-mhc-gxrqk/test-mhc-machine-2jbql/"
I0712 17:02:22.912956   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-p7hrp" "namespace"="test-mhc-rn7zl" "descendants"="Worker machines: test-mhc-machine-2jbql" "indirect descendants count"=1
I0712 17:02:22.923343   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-p7hrp" "namespace"="test-mhc-rn7zl" "descendants"="Worker machines: test-mhc-machine-2jbql" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0712 17:02:23.024266   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-m6gkn" "namespace"="test-mhc-rh5cr" "creating"=1 "need"=1
I0712 17:02:23.024310   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-m6gkn" "namespace"="test-mhc-rh5cr" 
I0712 17:02:23.040146   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-m6gkn-7zstr\"" "machineset"="mhc-ms-m6gkn" "namespace"="test-mhc-rh5cr" 
I0712 17:02:23.046347   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-gxrqk" "namespace"="test-mhc-rn7zl" 
I0712 17:02:23.110890   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:23.137025   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0712 17:02:23.264045   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
E0712 17:02:23.673010   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-m45dt/test-cluster-b44vt"
I0712 17:02:23.783016   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-p7hrp" "machine"="test-mhc-machine-2jbql" "namespace"="test-mhc-rn7zl" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-9vgdm"}
E0712 17:02:23.888948   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2jbql\" not found" "controller"="machine" "name"="test-mhc-machine-2jbql" "namespace"="test-mhc-rn7zl"
I0712 17:02:24.264251   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.897901   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.898037   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-m6gkn" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.902554   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.902813   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-m6gkn" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.931069   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
... skipping 4 lines ...
I0712 17:02:24.946399   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.953788   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.953841   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.958521   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
I0712 17:02:24.958577   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.265272   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.265734   10588 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-rh5cr/test-mhc-rqvjj/mhc-ms-m6gkn-7zstr/"
I0712 17:02:25.282169   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-m6gkn" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.293150   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.293200   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.293326   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.293650   10588 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-rh5cr/test-mhc-rqvjj/mhc-ms-m6gkn-7zstr/"
I0712 17:02:25.300870   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.301232   10588 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-rh5cr/test-mhc-rqvjj/mhc-ms-m6gkn-7zstr/"
I0712 17:02:25.302128   10588 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-m6gkn" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.318244   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.318288   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.355157   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-5sgkk" "namespace"="test-mhc-rh5cr" "count"=1
I0712 17:02:25.355222   10588 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-5sgkk" "namespace"="test-mhc-rh5cr" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-m6gkn"
I0712 17:02:25.356539   10588 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-m6gkn" "namespace"="test-mhc-rh5cr" "machine"="mhc-ms-m6gkn-7zstr"
I0712 17:02:25.360013   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rqvjj" "namespace"="test-mhc-rh5cr" 
I0712 17:02:25.361279   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5sgkk" "namespace"="test-mhc-rh5cr" "descendants"="Machine sets: mhc-ms-m6gkn;Worker machines: mhc-ms-m6gkn-7zstr" "indirect descendants count"=1
I0712 17:02:25.362430   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-5sgkk" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" "cause"="cluster is being deleted" "node"=null
I0712 17:02:25.365590   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-5sgkk" "namespace"="test-mhc-rh5cr" "descendants"="Worker machines: mhc-ms-m6gkn-7zstr" "indirect descendants count"=1
=== 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
I0712 17:02:25.406673   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-5sgkk" "machine"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr" "cause"="cluster is being deleted" "node"=null
E0712 17:02:25.446080   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-m6gkn-7zstr\" not found" "controller"="machine" "name"="mhc-ms-m6gkn-7zstr" "namespace"="test-mhc-rh5cr"
I0712 17:02:25.467926   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
inframachine created: test-mhc-machine-infra-gpfnc
I0712 17:02:25.483285   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-wtmh6
I0712 17:02:25.502018   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:25.508100   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
... skipping 447 lines ...
I0712 17:02:26.462278   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.465496   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.466384   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.468054   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.469880   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.471262   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
E0712 17:02:26.505696   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bs7bc, got []"  "node"="test-mhc-node-bs7bc"
E0712 17:02:26.506048   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bs7bc, got []"  "node"="test-mhc-node-bs7bc"
node created: test-mhc-node-bs7bc
E0712 17:02:26.506816   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bs7bc, got []"  "node"="test-mhc-node-bs7bc"
I0712 17:02:26.513126   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-wtmh6" "namespace"="test-mhc-lcfmn" "noderef"="test-mhc-node-bs7bc"
I0712 17:02:26.543858   10588 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-wtmh6" "target"="test-mhc-lcfmn/test-mhc-6rcrb/test-mhc-machine-wtmh6/"
I0712 17:02:26.567295   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.776286   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.783182   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.787211   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.791082   10588 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-wtmh6" "target"="test-mhc-lcfmn/test-mhc-6rcrb/test-mhc-machine-wtmh6/test-mhc-node-bs7bc"
I0712 17:02:26.811453   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.814915   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
Cleaning up nodes, machines and infra machines.
I0712 17:02:26.823310   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.829139   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
I0712 17:02:26.866746   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-45brp" "namespace"="test-mhc-lcfmn" "count"=1
I0712 17:02:26.866828   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-45brp" "namespace"="test-mhc-lcfmn" "descendants"="Worker machines: test-mhc-machine-wtmh6" "indirect descendants count"=0
I0712 17:02:26.870850   10588 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-45brp" "namespace"="test-mhc-lcfmn" "count"=1
I0712 17:02:26.870916   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-45brp" "namespace"="test-mhc-lcfmn" "descendants"="Worker machines: test-mhc-machine-wtmh6" "indirect descendants count"=0
I0712 17:02:26.872890   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6rcrb" "namespace"="test-mhc-lcfmn" 
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted
E0712 17:02:26.999356   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-wtmh6\" in namespace \"test-mhc-lcfmn\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-wtmh6" "namespace"="test-mhc-lcfmn"
I0712 17:02:27.023765   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
inframachine created: test-mhc-machine-infra-x6zxd
I0712 17:02:27.042160   10588 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-lrkmv
I0712 17:02:27.062924   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.069606   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
... skipping 454 lines ...
I0712 17:02:27.927634   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.929350   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.931034   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.932765   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.934465   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.936132   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
E0712 17:02:27.936887   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-rn7zl/test-cluster-p7hrp"
I0712 17:02:27.937852   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.939578   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.948321   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.950860   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.952592   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.954610   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
... skipping 18 lines ...
I0712 17:02:27.988982   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.990951   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.992711   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.994455   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.996237   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:27.998011   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
E0712 17:02:27.999707   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
I0712 17:02:27.999763   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:28.001446   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:28.003250   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:28.005086   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:28.006900   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:28.008692   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
... skipping 551 lines ...
I0712 17:02:29.031431   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.033076   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.035245   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.036827   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.039579   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.041366   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
E0712 17:02:29.041919   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-wtmh6\" not found" "controller"="machine" "name"="test-mhc-machine-wtmh6" "namespace"="test-mhc-lcfmn"
I0712 17:02:29.043120   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.044816   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.046520   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.048319   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.050113   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:29.051700   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
... skipping 549 lines ...
I0712 17:02:30.057681   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.058864   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.060812   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.062625   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.064419   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.066143   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
E0712 17:02:30.066659   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
node created: test-mhc-node-fgwsg
E0712 17:02:30.094331   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-fgwsg, got []"  "node"="test-mhc-node-fgwsg"
E0712 17:02:30.094387   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-fgwsg, got []"  "node"="test-mhc-node-fgwsg"
E0712 17:02:30.094575   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-fgwsg, got []"  "node"="test-mhc-node-fgwsg"
I0712 17:02:30.096046   10588 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-lrkmv" "target"="test-mhc-s7mz2/test-mhc-kbjd9/test-mhc-machine-lrkmv/"
I0712 17:02:30.300381   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.318983   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.324237   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.328413   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.331690   10588 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-lrkmv" "target"="test-mhc-s7mz2/test-mhc-kbjd9/test-mhc-machine-lrkmv/test-mhc-node-fgwsg"
I0712 17:02:30.345502   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.351116   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.366969   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.371949   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
Cleaning up nodes, machines and infra machines.
E0712 17:02:30.375652   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-rh5cr/test-cluster-5sgkk"
I0712 17:02:30.376814   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.379453   10588 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-lrkmv" "target"="test-mhc-s7mz2/test-mhc-kbjd9/test-mhc-machine-lrkmv/"
I0712 17:02:30.394996   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hfl4f" "namespace"="test-mhc-s7mz2" "descendants"="Worker machines: test-mhc-machine-lrkmv" "indirect descendants count"=1
I0712 17:02:30.397692   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
I0712 17:02:30.399249   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-hfl4f" "namespace"="test-mhc-s7mz2" "descendants"="Worker machines: test-mhc-machine-lrkmv" "indirect descendants count"=1
I0712 17:02:30.403355   10588 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kbjd9" "namespace"="test-mhc-s7mz2" 
--- PASS: TestMachineHealthCheck_Reconcile (40.94s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.03s)
... skipping 14 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.50s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (3.53s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0712 17:02:30.406231   10588 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
E0712 17:02:30.407943   10588 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
E0712 17:02:30.409706   10588 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0712 17:02:30.409903   10588 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
E0712 17:02:30.410216   10588 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
I0712 17:02:30.412260   10588 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0712 17:02:30.412877   10588 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0712 17:02:30.414535   10588 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
E0712 17:02:30.421671   10588 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
E0712 17:02:30.422793   10588 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 ...
I0712 17:02:30.689114   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "creating"=1 "need"=3
I0712 17:02:30.689166   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" 
I0712 17:02:30.697366   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-4nwnd-6657c7fddb-kqqfh\"" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" 
I0712 17:02:30.809315   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=1
I0712 17:02:30.809353   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" 
I0712 17:02:30.821073   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-4nwnd-cdfc6fd6c-rttsn\"" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" 
E0712 17:02:30.892811   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-rttsn-bpp2s, got []"  "node"="md-4nwnd-cdfc6fd6c-rttsn-bpp2s"
E0712 17:02:30.893005   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-rttsn-bpp2s, got []"  "node"="md-4nwnd-cdfc6fd6c-rttsn-bpp2s"
E0712 17:02:30.996578   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-rttsn-bpp2s, got []"  "node"="md-4nwnd-cdfc6fd6c-rttsn-bpp2s"
E0712 17:02:30.996618   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-rttsn-bpp2s, got []"  "node"="md-4nwnd-cdfc6fd6c-rttsn-bpp2s"
E0712 17:02:30.996911   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-rttsn-bpp2s, got []"  "node"="md-4nwnd-cdfc6fd6c-rttsn-bpp2s"
E0712 17:02:30.996967   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-rttsn-bpp2s, got []"  "node"="md-4nwnd-cdfc6fd6c-rttsn-bpp2s"
E0712 17:02:31.017934   10588 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node md-4nwnd-cdfc6fd6c-rttsn-bpp2s for machine md-test/md-4nwnd-cdfc6fd6c-rttsn: the cache is not started, can not read objects" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" 
I0712 17:02:31.046963   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0712 17:02:31.047021   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0712 17:02:31.051993   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "machine"="md-4nwnd-6657c7fddb-kqqfh"
I0712 17:02:31.067175   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hfl4f" "machine"="test-mhc-machine-lrkmv" "namespace"="test-mhc-s7mz2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-fgwsg"}
E0712 17:02:31.094541   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-lrkmv\" not found" "controller"="machine" "name"="test-mhc-machine-lrkmv" "namespace"="test-mhc-s7mz2"
I0712 17:02:31.160667   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0712 17:02:31.160768   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" 
I0712 17:02:31.168861   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-4nwnd-cdfc6fd6c-7qgdz\"" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" 
E0712 17:02:31.224979   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-7qgdz-m6ckp, got []"  "node"="md-4nwnd-cdfc6fd6c-7qgdz-m6ckp"
E0712 17:02:31.225186   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-7qgdz-m6ckp, got []"  "node"="md-4nwnd-cdfc6fd6c-7qgdz-m6ckp"
E0712 17:02:31.227263   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-7qgdz-m6ckp, got []"  "node"="md-4nwnd-cdfc6fd6c-7qgdz-m6ckp"
E0712 17:02:31.227319   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-7qgdz-m6ckp, got []"  "node"="md-4nwnd-cdfc6fd6c-7qgdz-m6ckp"
E0712 17:02:31.227564   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-7qgdz-m6ckp, got []"  "node"="md-4nwnd-cdfc6fd6c-7qgdz-m6ckp"
E0712 17:02:31.227612   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-7qgdz-m6ckp, got []"  "node"="md-4nwnd-cdfc6fd6c-7qgdz-m6ckp"
I0712 17:02:31.258398   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1
I0712 17:02:31.258623   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0712 17:02:31.263937   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "machine"="md-4nwnd-6657c7fddb-55vmj"
I0712 17:02:31.371800   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0712 17:02:31.371837   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" 
I0712 17:02:31.381225   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-4nwnd-cdfc6fd6c-jwcjp\"" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" 
E0712 17:02:31.486744   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-jwcjp-56jlg, got []"  "node"="md-4nwnd-cdfc6fd6c-jwcjp-56jlg"
E0712 17:02:31.486814   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-jwcjp-56jlg, got []"  "node"="md-4nwnd-cdfc6fd6c-jwcjp-56jlg"
E0712 17:02:31.590206   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-jwcjp-56jlg, got []"  "node"="md-4nwnd-cdfc6fd6c-jwcjp-56jlg"
E0712 17:02:31.590271   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-jwcjp-56jlg, got []"  "node"="md-4nwnd-cdfc6fd6c-jwcjp-56jlg"
E0712 17:02:31.590400   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-jwcjp-56jlg, got []"  "node"="md-4nwnd-cdfc6fd6c-jwcjp-56jlg"
E0712 17:02:31.590442   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-cdfc6fd6c-jwcjp-56jlg, got []"  "node"="md-4nwnd-cdfc6fd6c-jwcjp-56jlg"
I0712 17:02:31.618312   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0712 17:02:31.618362   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0712 17:02:31.624180   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-4nwnd-6657c7fddb" "namespace"="md-test" "machine"="md-4nwnd-6657c7fddb-4xxsb"
E0712 17:02:31.890538   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-lcfmn/test-cluster-45brp"
I0712 17:02:31.912908   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0712 17:02:31.913057   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" 
I0712 17:02:31.939224   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-4nwnd-74d45c49c5-9vd56\"" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" 
E0712 17:02:32.011674   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-9vd56-jgb88, got []"  "node"="md-4nwnd-74d45c49c5-9vd56-jgb88"
E0712 17:02:32.115289   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-9vd56-jgb88, got []"  "node"="md-4nwnd-74d45c49c5-9vd56-jgb88"
E0712 17:02:32.115353   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-9vd56-jgb88, got []"  "node"="md-4nwnd-74d45c49c5-9vd56-jgb88"
I0712 17:02:32.157990   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2
I0712 17:02:32.158035   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0712 17:02:32.162195   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "machine"="md-4nwnd-cdfc6fd6c-jwcjp"
I0712 17:02:32.174073   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:32.174110   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:32.195621   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
I0712 17:02:32.195657   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
E0712 17:02:32.227343   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-cdfc6fd6c-rttsn\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-rttsn" "namespace"="md-test"
I0712 17:02:32.271662   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=2
I0712 17:02:32.271703   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" 
I0712 17:02:32.283827   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-4nwnd-74d45c49c5-fsm5t\"" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" 
E0712 17:02:32.343106   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-fsm5t-h9z74, got []"  "node"="md-4nwnd-74d45c49c5-fsm5t-h9z74"
E0712 17:02:32.446791   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-fsm5t-h9z74, got []"  "node"="md-4nwnd-74d45c49c5-fsm5t-h9z74"
E0712 17:02:32.446838   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-fsm5t-h9z74, got []"  "node"="md-4nwnd-74d45c49c5-fsm5t-h9z74"
I0712 17:02:32.480661   10588 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0712 17:02:32.480704   10588 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0712 17:02:32.484745   10588 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-4nwnd-cdfc6fd6c" "namespace"="md-test" "machine"="md-4nwnd-cdfc6fd6c-7qgdz"
I0712 17:02:32.592082   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0712 17:02:32.592128   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" 
I0712 17:02:32.603682   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-4nwnd-74d45c49c5-rnxwq\"" "machineset"="md-4nwnd-74d45c49c5" "namespace"="md-test" 
E0712 17:02:32.708282   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-rnxwq-4jgp2, got []"  "node"="md-4nwnd-74d45c49c5-rnxwq-4jgp2"
E0712 17:02:32.811710   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-rnxwq-4jgp2, got []"  "node"="md-4nwnd-74d45c49c5-rnxwq-4jgp2"
E0712 17:02:32.811757   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-4nwnd-74d45c49c5-rnxwq-4jgp2, got []"  "node"="md-4nwnd-74d45c49c5-rnxwq-4jgp2"
I0712 17:02:32.829342   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-4nwnd-cdfc6fd6c,md-4nwnd-74d45c49c5;Worker machines: md-4nwnd-cdfc6fd6c-rttsn,md-4nwnd-74d45c49c5-fsm5t,md-4nwnd-74d45c49c5-rnxwq,md-4nwnd-6657c7fddb-dt9q5,md-4nwnd-6657c7fddb-td4zn,md-4nwnd-cdfc6fd6c-jwcjp,md-4nwnd-74d45c49c5-9vd56,md-4nwnd-cdfc6fd6c-7qgdz" "indirect descendants count"=10
•I0712 17:02:32.833200   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-4nwnd-74d45c49c5,md-4nwnd-cdfc6fd6c;Worker machines: md-4nwnd-6657c7fddb-td4zn,md-4nwnd-cdfc6fd6c-jwcjp,md-4nwnd-74d45c49c5-9vd56,md-4nwnd-cdfc6fd6c-7qgdz,md-4nwnd-cdfc6fd6c-rttsn,md-4nwnd-74d45c49c5-fsm5t,md-4nwnd-74d45c49c5-rnxwq,md-4nwnd-6657c7fddb-dt9q5" "indirect descendants count"=10
I0712 17:02:32.895699   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-5mczg" "namespace"="ms-test" "creating"=2 "need"=2
I0712 17:02:32.895738   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-5mczg" "namespace"="ms-test" 
I0712 17:02:32.913171   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-5mczg-mxt7j\"" "machineset"="ms-5mczg" "namespace"="ms-test" 
I0712 17:02:32.913248   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-5mczg" "namespace"="ms-test" 
I0712 17:02:32.925095   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-5mczg-fqb5v\"" "machineset"="ms-5mczg" "namespace"="ms-test" 
I0712 17:02:33.036685   10588 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-5mczg" "namespace"="ms-test" "creating"=1 "need"=2
I0712 17:02:33.036733   10588 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-5mczg" "namespace"="ms-test" 
I0712 17:02:33.048752   10588 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-5mczg-cpk5h\"" "machineset"="ms-5mczg" "namespace"="ms-test" 
E0712 17:02:33.143158   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-5mczg-cpk5h-bjpx6, got []"  "node"="ms-5mczg-cpk5h-bjpx6"
I0712 17:02:33.227857   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-4nwnd-cdfc6fd6c-7qgdz" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-4nwnd-cdfc6fd6c-7qgdz-m6ckp"}
E0712 17:02:33.245942   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-5mczg-cpk5h-bjpx6, got []"  "node"="ms-5mczg-cpk5h-bjpx6"
E0712 17:02:33.246001   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-5mczg-cpk5h-bjpx6, got []"  "node"="ms-5mczg-cpk5h-bjpx6"
I0712 17:02:33.248734   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-4nwnd-cdfc6fd6c-jwcjp" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-4nwnd-cdfc6fd6c-jwcjp-56jlg"}
E0712 17:02:33.274006   10588 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-5mczg-cpk5h-bjpx6 for machine ms-test/ms-5mczg-cpk5h: the cache is not started, can not read objects" "machineset"="ms-5mczg" "namespace"="ms-test" 
E0712 17:02:33.276038   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-5mczg-fqb5v-sdn2r, got []"  "node"="ms-5mczg-fqb5v-sdn2r"
E0712 17:02:33.279501   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-5mczg-fqb5v-sdn2r, got []"  "node"="ms-5mczg-fqb5v-sdn2r"
E0712 17:02:33.279536   10588 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node ms-5mczg-fqb5v-sdn2r, got []"  "node"="ms-5mczg-fqb5v-sdn2r"
E0712 17:02:33.302473   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-9vd56\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-9vd56" "namespace"="md-test"
I0712 17:02:33.398322   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-5mczg-fqb5v,ms-5mczg-cpk5h" "indirect descendants count"=2
•I0712 17:02:33.402378   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-5mczg-cpk5h,ms-5mczg-fqb5v" "indirect descendants count"=2
•E0712 17:02:33.519404   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-bd48m\" not found" "controller"="cluster" "name"="test1-bd48m" "namespace"="default"
I0712 17:02:34.306848   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:34.306884   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:34.310552   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
I0712 17:02:34.310589   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
E0712 17:02:34.314606   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-cdfc6fd6c-rttsn\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-rttsn" "namespace"="md-test"
•I0712 17:02:34.637239   10588 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-h8dsr" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0712 17:02:34.754350   10588 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-h8dsr" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0712 17:02:34.758152   10588 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-h8dsr" "namespace"="default"
I0712 17:02:35.357267   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-4nwnd-cdfc6fd6c-7qgdz" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-4nwnd-cdfc6fd6c-7qgdz-m6ckp"}
E0712 17:02:35.382132   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"md-4nwnd-cdfc6fd6c-7qgdz\" not found" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-7qgdz" "namespace"="md-test"
E0712 17:02:35.771174   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
•I0712 17:02:36.382631   10588 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-4nwnd-cdfc6fd6c-jwcjp" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-4nwnd-cdfc6fd6c-jwcjp-56jlg"}
E0712 17:02:36.406145   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"md-4nwnd-cdfc6fd6c-jwcjp\" not found" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-jwcjp" "namespace"="md-test"
E0712 17:02:36.781574   10588 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-s7mz2/test-cluster-hfl4f"
E0712 17:02:36.790820   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-m9w7p\" not found" "controller"="cluster" "name"="test3-m9w7p" "namespace"="default"
E0712 17:02:37.411234   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-9vd56\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-9vd56" "namespace"="md-test"
E0712 17:02:37.791519   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
E0712 17:02:38.416147   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-cdfc6fd6c-rttsn\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-rttsn" "namespace"="md-test"
E0712 17:02:38.800393   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
•I0712 17:02:39.420408   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:39.420451   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:39.423965   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
I0712 17:02:39.423994   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
E0712 17:02:39.445934   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-fsm5t\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-fsm5t" "namespace"="md-test"
I0712 17:02:39.800982   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-4nwnd-74d45c49c5,md-4nwnd-cdfc6fd6c;Worker machines: md-4nwnd-74d45c49c5-rnxwq,md-4nwnd-6657c7fddb-dt9q5,md-4nwnd-6657c7fddb-td4zn,md-4nwnd-74d45c49c5-fsm5t,md-4nwnd-74d45c49c5-9vd56,md-4nwnd-cdfc6fd6c-rttsn" "indirect descendants count"=8
I0712 17:02:39.801334   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-5mczg-cpk5h,ms-5mczg-fqb5v" "indirect descendants count"=2
E0712 17:02:39.804985   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
E0712 17:02:40.528066   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-9vd56\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-9vd56" "namespace"="md-test"
E0712 17:02:40.805801   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
E0712 17:02:41.528439   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-txfrb\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-txfrb" "namespace"="test-mhc-krnlm"
E0712 17:02:41.815545   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
•E0712 17:02:42.533557   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-cdfc6fd6c-rttsn\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-rttsn" "namespace"="md-test"
E0712 17:02:42.816283   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
E0712 17:02:43.538369   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-fsm5t\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-fsm5t" "namespace"="md-test"
E0712 17:02:43.817019   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
E0712 17:02:44.538722   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-dpzj7\" for machine \"test-mhc-machine-ml5tg\" in namespace \"test-mhc-krnlm\": Cluster.cluster.x-k8s.io \"test-cluster-dpzj7\" not found" "controller"="machine" "name"="test-mhc-machine-ml5tg" "namespace"="test-mhc-krnlm"
E0712 17:02:44.826409   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
I0712 17:02:45.543253   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:45.543292   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:45.547755   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
I0712 17:02:45.547793   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
E0712 17:02:45.572978   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-9vd56\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-9vd56" "namespace"="md-test"
E0712 17:02:45.827181   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
E0712 17:02:46.577909   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-cdfc6fd6c-rttsn\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-rttsn" "namespace"="md-test"
I0712 17:02:46.827832   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-4nwnd-74d45c49c5,md-4nwnd-cdfc6fd6c;Worker machines: md-4nwnd-6657c7fddb-dt9q5,md-4nwnd-6657c7fddb-td4zn,md-4nwnd-74d45c49c5-fsm5t,md-4nwnd-74d45c49c5-9vd56,md-4nwnd-74d45c49c5-rnxwq,md-4nwnd-cdfc6fd6c-rttsn" "indirect descendants count"=8
I0712 17:02:46.828152   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-5mczg-cpk5h,ms-5mczg-fqb5v" "indirect descendants count"=2
E0712 17:02:46.828693   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
E0712 17:02:47.582714   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-fsm5t\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-fsm5t" "namespace"="md-test"
E0712 17:02:47.829437   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
E0712 17:02:48.605111   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-9vd56\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-9vd56" "namespace"="md-test"
E0712 17:02:48.830175   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
I0712 17:02:49.610035   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:49.610075   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:49.613918   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
I0712 17:02:49.613950   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
E0712 17:02:49.618087   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-cdfc6fd6c-rttsn\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-rttsn" "namespace"="md-test"
E0712 17:02:49.830936   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
E0712 17:02:50.622809   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-fsm5t\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-fsm5t" "namespace"="md-test"
E0712 17:02:50.831773   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
I0712 17:02:51.637698   10588 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-bx52x" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0712 17:02:51.663288   10588 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-bx52x" "namespace"="default" 
E0712 17:02:51.687650   10588 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-bx52x" "namespace"="default"
E0712 17:02:51.832432   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
E0712 17:02:52.692862   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-9vd56\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-9vd56" "namespace"="md-test"
E0712 17:02:52.833188   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
E0712 17:02:53.697923   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-cdfc6fd6c-rttsn\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-cdfc6fd6c-rttsn" "namespace"="md-test"
I0712 17:02:53.833947   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-4nwnd-74d45c49c5,md-4nwnd-cdfc6fd6c;Worker machines: md-4nwnd-6657c7fddb-td4zn,md-4nwnd-74d45c49c5-fsm5t,md-4nwnd-74d45c49c5-9vd56,md-4nwnd-74d45c49c5-rnxwq,md-4nwnd-cdfc6fd6c-rttsn,md-4nwnd-6657c7fddb-dt9q5" "indirect descendants count"=8
I0712 17:02:53.834299   10588 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-5mczg-cpk5h,ms-5mczg-fqb5v" "indirect descendants count"=2
E0712 17:02:53.834638   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
I0712 17:02:54.702464   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:54.702505   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-dt9q5" "namespace"="md-test" 
I0712 17:02:54.705975   10588 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
I0712 17:02:54.706009   10588 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-4nwnd-6657c7fddb-td4zn" "namespace"="md-test" 
E0712 17:02:54.709736   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-fsm5t\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-fsm5t" "namespace"="md-test"
E0712 17:02:54.835354   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-h8dsr: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-h8dsr" "namespace"="default"
I0712 17:02:55.725051   10588 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-bx52x" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0712 17:02:55.725314   10588 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-bx52x" "namespace"="default" "noderef"="id-node-1"
E0712 17:02:55.744617   10588 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-bx52x" "namespace"="default"
E0712 17:02:55.836098   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-rd85l: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-rd85l" "namespace"="default"
E0712 17:02:56.749833   10588 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-4nwnd-74d45c49c5-9vd56\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-4nwnd-74d45c49c5-9vd56" "namespace"="md-test"

------------------------------
• [SLOW TEST:14.861 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 ...
I0712 17:02:56.862497   10588 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"
•I0712 17:02:56.864028   10588 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"
I0712 17:02:56.864658   10588 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"
I0712 17:02:56.865276   10588 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0712 17:02:56.865307   10588 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0712 17:02:56.865759   10588 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0712 17:02:56.866902   10588 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" 
•

Ran 16 of 16 Specs in 26.444 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (26.44s)
PASS
Tearing down test suite
I0712 17:02:56.868443   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0712 17:02:56.868494   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
I0712 17:02:56.868533   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0712 17:02:56.868556   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0712 17:02:56.868579   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0712 17:02:56.868599   10588 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0712 17:02:56.868634   10588 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0712 17:02:56.868704   10588 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 17:02:56.868736   10588 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-851240232/tls.crt: no such file or directory"  
E0712 17:02:56.868754   10588 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 17:02:56.868770   10588 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-851240232/tls.crt: no such file or directory"  
E0712 17:02:56.914148   10588 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:40751/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1325&timeout=10s&timeoutSeconds=576&watch=true: dial tcp 127.0.0.1:40751: connect: connection refused
E0712 17:02:56.914145   10588 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:40751/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1325&timeout=10s&timeoutSeconds=593&watch=true: dial tcp 127.0.0.1:40751: connect: connection refused
E0712 17:02:56.914263   10588 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:40751/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1325&timeout=10s&timeoutSeconds=504&watch=true: dial tcp 127.0.0.1:40751: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	84.713s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 260 lines ...
I0712 17:01:46.144732   10881 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=36109
I0712 17:01:46.145007   10881 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0712 17:01:46.170624   10881 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="cluster" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0712 17:01:46.371669   10881 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0712 17:01:46.371731   10881 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I0712 17:01:46.665041   10881 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0712 17:01:48.689716   10881 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-xnr65/test-cluster"
•E0712 17:01:49.141829   10881 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-49dg8/test-cluster"
•E0712 17:01:49.681390   10881 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:43169/?timeout=50ms: dial tcp 127.0.0.1:43169: connect: connection refused"  "cluster"="cluster-cache-test-fzsp2/test-cluster"
•I0712 17:01:49.903370   10881 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":{}}}
I0712 17:01:50.103860   10881 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0712 17:01:50.103935   10881 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0712 17:01:50.104049   10881 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0712 17:01:50.635941   10881 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0712 17:01:50.636124   10881 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0712 17:01:50.712703   10881 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:34893/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:34893: connect: connection refused


Ran 5 of 5 Specs in 17.355 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (17.36s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	17.548s
?   	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
I0712 17:01:55.739108   11584 controller.go:129]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.00s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0712 17:01:55.740303   11584 controller.go:125]  "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
I0712 17:01:55.740891   11584 controller.go:135]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0712 17:01:55.741042   11584 controller.go:135]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 192 lines ...
    --- PASS: TestSelectMachineForScaleDown/when_there_is_an_up_to_date_machine_with_delete_annotation,_while_there_are_any_outdated_machines_without_annotatio_that_still_exist,_it_returns_oldest_marked_machine_first (0.00s)
=== RUN   TestPreflightChecks
=== RUN   TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass
=== RUN   TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue
I0712 17:02:12.727118   11584 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
I0712 17:02:12.727243   11584 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: 1626109303
Will run 1 of 1 specs

E0712 17:02:12.759126   11584 controller.go:125]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-bqox7b\" not found" "kubeadmControlPlane"="kcp-foo-bqox7b" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.028 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0712 17:02:12.760579   11584 controller.go:245]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-xsptz4" "kubeadmControlPlane"="kcp-foo-xsptz4" "namespace"="test" 
I0712 17:02:15.777815   11584 controller.go:330]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-xsptz4" "kubeadmControlPlane"="kcp-foo-xsptz4" "namespace"="test" "needRollout"=["kcp-foo-xsptz4-86d46"]
I0712 17:02:15.778075   11584 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-xsptz4" "kubeadmControlPlane"="kcp-foo-xsptz4" "namespace"="test" "failures"="[machine kcp-foo-xsptz4-4296f does not have APIServerPodHealthy condition, machine kcp-foo-xsptz4-4296f does not have ControllerManagerPodHealthy condition, machine kcp-foo-xsptz4-4296f does not have SchedulerPodHealthy condition, machine kcp-foo-xsptz4-4296f does not have EtcdPodHealthy condition, machine kcp-foo-xsptz4-4296f does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (3.02s)
... skipping 60 lines ...
==================================
Random Seed: 1626109302
Will run 7 of 7 specs

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

•••••••
Ran 7 of 7 Specs in 0.000 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestMachineCollection (0.00s)
=== RUN   TestUpdateEtcdConditions
=== RUN   TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines
=== RUN   TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition
... skipping 271 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
E0712 17:01:56.577609   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:02:04.900688   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:02:13.886665   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:02:25.016932   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:02:41.490067   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:02:54.498639   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:03:12.146098   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:03:33.069575   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:04:04.086119   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0712 17:04:49.243377   11516 workload_cluster.go:325]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0
--- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s)
... skipping 71 lines ...
=== RUN   TestClusterStatus/returns_cluster_status
=== RUN   TestClusterStatus/returns_cluster_status_with_kubeadm_config
--- PASS: TestClusterStatus (0.00s)
    --- PASS: TestClusterStatus/returns_cluster_status (0.00s)
    --- PASS: TestClusterStatus/returns_cluster_status_with_kubeadm_config (0.00s)
PASS
E0712 17:04:49.251826   11516 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 17:04:49.251875   11516 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-260155326/tls.crt: no such file or directory"  
E0712 17:04:49.251897   11516 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 17:04:49.251917   11516 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-260155326/tls.crt: no such file or directory"  
I0712 17:04:49.251982   11516 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	187.293s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
... skipping 288 lines ...
I0712 17:02:04.817671   11808 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0712 17:02:04.818049   11808 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0712 17:02:04.920368   11808 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0712 17:02:05.021161   11808 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0712 17:02:05.021226   11808 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0712 17:02:05.140394   11808 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-025tbj"} 
E0712 17:02:05.168139   11808 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"
•I0712 17:02:06.205514   11808 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-r52dx1"} 
E0712 17:02:06.235900   11808 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"
•E0712 17:02:17.322870   11808 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"

------------------------------
• Failure [11.082 seconds]
ClusterResourceSet Reconciler
/home/prow/go/src/sigs.k8s.io/cluster-api/exp/addons/controllers/clusterresourceset_controller_test.go:40
  Should reconcile a ClusterResourceSet when a resource is created that is part of ClusterResourceSet resources [It]
... skipping 8 lines ...
------------------------------
STEP: Creating the Cluster
STEP: Creating the remote Cluster kubeconfig
STEP: Creating a Secret and a ConfigMap with ConfigMap in their data field
STEP: Verifying ClusterResourceSetBinding is created with cluster owner reference
STEP: Deleting the Kubeconfigsecret
E0712 17:02:18.456411   11808 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"
•E0712 17:02:19.492584   11808 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"
E0712 17:02:20.514973   11808 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"
•I0712 17:02:20.524206   11808 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0712 17:02:20.524258   11808 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0712 17:02:20.524317   11808 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  



Summarizing 1 Failure:

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

Ran 5 of 5 Specs in 29.440 seconds
FAIL! -- 4 Passed | 1 Failed | 0 Pending | 0 Skipped
--- FAIL: TestAPIs (29.44s)
FAIL
FAIL	sigs.k8s.io/cluster-api/exp/addons/controllers	29.597s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-create
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-update
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-delete
... skipping 58 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.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
E0712 17:01:58.024288   12062 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 ...
•I0712 17:02:11.872899   12062 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0712 17:02:11.892930   12062 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0712 17:02:11.917566   12062 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0712 17:02:11.920730   12062 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0712 17:02:11.950269   12062 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0712 17:02:11.982453   12062 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••E0712 17:02:11.986536   12062 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 17:02:11.986666   12062 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-612040930/tls.crt: no such file or directory"  
E0712 17:02:11.986712   12062 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0712 17:02:11.986737   12062 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-612040930/tls.crt: no such file or directory"  
I0712 17:02:11.987803   12062 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0712 17:02:12.037267   12062 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinepool" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}


Ran 9 of 9 Specs in 13.940 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.94s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	14.202s
?   	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 201 lines ...
I0712 17:02:35.665251   15013 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0712 17:02:35.665402   15013 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0712 17:02:35.666121   15013 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0712 17:02:35.666288   15013 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=35169
I0712 17:02:35.666380   15013 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••I0712 17:02:36.733318   15013 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0712 17:02:36.733394   15013 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0712 17:02:36.733455   15013 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-433405905/tls.crt: no such file or directory"  
E0712 17:02:36.733492   15013 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0712 17:02:36.733534   15013 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-433405905/tls.crt: no such file or directory"  


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