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

No Test Failures!


Error lines from build-log.txt

... skipping 773 lines ...
I0815 15:08:40.185522    8467 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0815 15:08:40.186256    8467 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0815 15:08:40.187213    8467 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0815 15:08:40.187555    8467 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=46279
I0815 15:08:40.187757    8467 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0815 15:08:40.893247    8467 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" 
•E0815 15:08:40.904790    8467 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0815 15:08:40.904851    8467 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-642405683/tls.crt: no such file or directory"  
E0815 15:08:40.904876    8467 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0815 15:08:40.904896    8467 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-642405683/tls.crt: no such file or directory"  
I0815 15:08:40.904992    8467 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 18.233 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (18.23s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	61.900s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 316 lines ...
=== RUN   Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined
--- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s)
=== RUN   Test_clusterctlClient_GetProviderComponents
=== RUN   Test_clusterctlClient_GetProviderComponents/Pass
=== RUN   Test_clusterctlClient_GetProviderComponents/Fail
--- PASS: Test_clusterctlClient_GetProviderComponents (0.01s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.01s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s)
=== RUN   Test_getComponentsByName_withEmptyVariables
--- PASS: Test_getComponentsByName_withEmptyVariables (0.01s)
=== 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 1390 lines ...
I0815 15:08:35.288519   10872 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machineset" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"clusterName":"","bootstrap":{},"infrastructureRef":{}},"status":{"bootstrapReady":false,"infrastructureReady":false}}}
I0815 15:08:35.288832   10872 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machineset" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"clusterName":"","bootstrap":{},"infrastructureRef":{}},"status":{"bootstrapReady":false,"infrastructureReady":false}}}
I0815 15:08:35.289051   10872 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machineset" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0815 15:08:35.289265   10872 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machineset" 
=== RUN   TestClusterReconcilePhases
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
2022/08/15 15:08:35 http: TLS handshake error from 127.0.0.1:52208: EOF
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
I0815 15:08:35.387465   10872 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":{}}}
I0815 15:08:35.387644   10872 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
I0815 15:08:35.387665   10872 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":{}}}
I0815 15:08:35.387794   10872 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0815 15:08:35.387884   10872 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
... skipping 113 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0815 15:08:35.471015   10872 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
I0815 15:08:35.473957   10872 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"
E0815 15:08:35.474487   10872 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
I0815 15:08:35.475220   10872 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
--- PASS: TestReconcileInfrastructure (0.01s)
    --- PASS: TestReconcileInfrastructure/new_machine,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestWatches
I0815 15:08:35.984203   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0815 15:08:35.989138   10872 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0815 15:08:35.996399   10872 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-n85zm" "namespace"="test-machine-watches-2hh8z" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0815 15:08:35.996497   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0815 15:08:36.110067   10872 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-n85zm" "namespace"="test-machine-watches-2hh8z" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0815 15:08:36.110206   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0815 15:08:36.211254   10872 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-n85zm" "namespace"="test-machine-watches-2hh8z" "noderef"="node-1"
E0815 15:08:36.226287   10872 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0815 15:08:36.226352   10872 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0815 15:08:36.316044   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"machine-created-n85zm\" in namespace \"test-machine-watches-2hh8z\": cannot find node with matching ProviderID" "controller"="machine" "name"="machine-created-n85zm" "namespace"="test-machine-watches-2hh8z"
E0815 15:08:37.321620   10872 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-n85zm\" in namespace \"test-machine-watches-2hh8z\", requeuing: requeue in 1s"  
E0815 15:08:37.332291   10872 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-n85zm\" in namespace \"test-machine-watches-2hh8z\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-n85zm\" in namespace \"test-machine-watches-2hh8z\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-n85zm" "namespace"="test-machine-watches-2hh8z"
--- PASS: TestWatches (1.87s)
=== 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
I0815 15:08:37.557359   10872 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-78q9n" "namespace"="test-machine-watches-2hh8z" "count"=1
I0815 15:08:37.557428   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-78q9n" "namespace"="test-machine-watches-2hh8z" "descendants"="Worker machines: machine-created-n85zm" "indirect descendants count"=0
I0815 15:08:37.573824   10872 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-78q9n" "namespace"="test-machine-watches-2hh8z" "count"=1
I0815 15:08:37.573883   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-78q9n" "namespace"="test-machine-watches-2hh8z" "descendants"="Worker machines: machine-created-n85zm" "indirect descendants count"=0
I0815 15:08:38.332898   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-78q9n" "machine"="machine-created-n85zm" "namespace"="test-machine-watches-2hh8z" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"e03b933c-73a6-4be6-b8c3-20a094f24b5b","apiVersion":"v1"}
E0815 15:08:38.381213   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-n85zm\" not found" "controller"="machine" "name"="machine-created-n85zm" "namespace"="test-machine-watches-2hh8z"
E0815 15:08:39.457459   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-7b6kl\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-rxhff\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-rxhff: secrets \"machine-reconcile-rxhff-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-7b6kl" "namespace"="default"
I0815 15:08:40.458119   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rxhff" "machine"="machine-created-7b6kl" "namespace"="default" "cause"="noderef is nil" "node"=null
I0815 15:08:40.501273   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rxhff" "machine"="machine-created-7b6kl" "namespace"="default" "cause"="noderef is nil" "node"=null
I0815 15:08:40.534834   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-rxhff" "machine"="machine-created-7b6kl" "namespace"="default" "cause"="noderef is nil" "node"=null
E0815 15:08:40.597970   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-7b6kl\" not found" "controller"="machine" "name"="machine-created-7b6kl" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.26s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.26s)
=== RUN   TestMachineFinalizer
=== RUN   TestMachineFinalizer/should_add_a_machine_finalizer_to_the_machine_if_it_doesn't_have_one
=== RUN   TestMachineFinalizer/should_append_the_machine_finalizer_to_the_machine_if_it_already_has_a_finalizer
--- PASS: TestMachineFinalizer (0.00s)
... skipping 14 lines ...
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set (0.00s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.01s)
=== RUN   TestReconcileRequest
=== RUN   TestReconcileRequest/machine_should_be_created
I0815 15:08:40.644349   10872 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="created" "namespace"="default" "err"="cannot create a metadata client without a rest config"
=== RUN   TestReconcileRequest/machine_should_be_updated
E0815 15:08:40.649437   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-rxhff\" not found" "controller"="cluster" "name"="machine-reconcile-rxhff" "namespace"="default"
I0815 15:08:40.656596   10872 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
I0815 15:08:40.667354   10872 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)
    --- PASS: TestReconcileRequest/machine_should_be_updated (0.01s)
... skipping 110 lines ...
    --- PASS: TestMachineDeploymentSyncStatus/machine_set_failed (0.00s)
    --- PASS: TestMachineDeploymentSyncStatus/all_machines_are_running (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0815 15:08:40.898202   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lzq6b" "namespace"="test-mhc-fwr29" 
I0815 15:08:40.920158   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0815 15:08:40.921520   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-khjk7\" not found"  "cluster"="test-mhc-fwr29/test-cluster-khjk7"
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
E0815 15:08:40.935818   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-lzq6b\" not found" "controller"="machinehealthcheck" "name"="test-mhc-lzq6b" "namespace"="test-mhc-fwr29"
=== 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
I0815 15:08:41.936115   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-lzq6b" "namespace"="test-mhc-fwr29" 
I0815 15:08:41.936228   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4tsz6" "namespace"="test-mhc-rvc4m" 
I0815 15:08:41.936267   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g7wn2" "namespace"="test-mhc-dqgl5" 
I0815 15:08:41.936312   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bvcz8" "namespace"="test-mhc-cqj75" 
I0815 15:08:41.969911   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 15:08:42.006396   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bvcz8" "namespace"="test-mhc-cqj75" 
I0815 15:08:42.042037   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bvcz8" "namespace"="test-mhc-cqj75" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
I0815 15:08:42.060027   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-bvcz8" "namespace"="test-mhc-cqj75" 
E0815 15:08:42.079106   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-cqj75/test-cluster-nch4z"
E0815 15:08:42.081516   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-nch4z\" not found" "controller"="cluster" "name"="test-cluster-nch4z" "namespace"="test-mhc-cqj75"
I0815 15:08:42.086917   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hqvlp" "namespace"="test-mhc-xrclb" 
I0815 15:08:42.111293   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 15:08:42.131951   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hqvlp" "namespace"="test-mhc-xrclb" 
I0815 15:08:42.138943   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hqvlp" "namespace"="test-mhc-xrclb" 
E0815 15:08:42.192132   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-xrclb/test-cluster-ft2jh"
I0815 15:08:42.196360   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-hqvlp" "namespace"="test-mhc-xrclb" 
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0815 15:08:42.244799   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-88zh6" "namespace"="test-mhc-vrcgk" 
inframachine created: test-mhc-machine-infra-x9gxm
machine created: test-mhc-machine-b5lnd
I0815 15:08:42.275727   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
node created: test-mhc-node-tsltr
E0815 15:08:42.373262   10872 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-tsltr"
E0815 15:08:42.377233   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tsltr, got []"  "node"="test-mhc-node-tsltr"
I0815 15:08:42.377334   10872 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-vrcgk/test-mhc-88zh6/test-mhc-machine-b5lnd/"
I0815 15:08:42.377411   10872 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk" "noderef"="test-mhc-node-tsltr"
inframachine created: test-mhc-machine-infra-8kl28
machine created: test-mhc-machine-772n7
node created: test-mhc-node-bm97x
E0815 15:08:42.505835   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bm97x, got []"  "node"="test-mhc-node-bm97x"
E0815 15:08:42.506037   10872 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-bm97x"
I0815 15:08:42.507982   10872 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk" "noderef"="test-mhc-node-bm97x"
E0815 15:08:42.513684   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bm97x, got []"  "node"="test-mhc-node-bm97x"
E0815 15:08:42.513734   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bm97x, got []"  "node"="test-mhc-node-bm97x"
E0815 15:08:42.513772   10872 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-bm97x"
E0815 15:08:42.513833   10872 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-bm97x"
I0815 15:08:42.549625   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-88zh6" "namespace"="test-mhc-vrcgk" 
I0815 15:08:42.584916   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-88zh6" "namespace"="test-mhc-vrcgk" 
Cleaning up nodes, machines and infra machines.
I0815 15:08:42.604721   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-88zh6" "namespace"="test-mhc-vrcgk" 
I0815 15:08:42.605362   10872 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vrcgk/test-mhc-88zh6/test-mhc-machine-b5lnd/"
I0815 15:08:42.638119   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-88zh6" "namespace"="test-mhc-vrcgk" 
I0815 15:08:42.638635   10872 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vrcgk/test-mhc-88zh6/test-mhc-machine-772n7/"
E0815 15:08:42.697858   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-vrcgk/test-cluster-lgbfp"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E0815 15:08:42.711950   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:08:42.848482   10872 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-vrcgk/test-mhc-88zh6/test-mhc-machine-b5lnd/"
inframachine created: test-mhc-machine-infra-jj2tr
E0815 15:08:42.871275   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-88zh6\" not found" "controller"="machinehealthcheck" "name"="test-mhc-88zh6" "namespace"="test-mhc-vrcgk"
machine created: test-mhc-machine-75c2d
E0815 15:08:43.104474   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-2hh8z/machine-reconcile-78q9n"
E0815 15:08:43.712412   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:08:43.871567   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:43.906552   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 15:08:43.934336   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-88zh6" "namespace"="test-mhc-vrcgk" 
I0815 15:08:43.934423   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:43.940992   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:43.942095   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
... skipping 329 lines ...
I0815 15:08:44.682265   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.683980   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.685699   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.687447   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.689097   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.690866   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
E0815 15:08:44.712847   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:08:44.713526   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.715679   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.717525   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.719408   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.721385   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:44.723321   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
... skipping 454 lines ...
I0815 15:08:45.716089   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.717821   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.719560   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.721427   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.722009   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.727673   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
E0815 15:08:45.730803   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:08:45.734055   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.738967   10872 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-nqlmn/test-mhc-q565n/test-mhc-machine-75c2d/"
I0815 15:08:45.778269   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.778612   10872 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-nqlmn/test-mhc-q565n/test-mhc-machine-75c2d/"
node created: test-mhc-node-qj6n7
E0815 15:08:45.826766   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-qj6n7, got []"  "node"="test-mhc-node-qj6n7"
I0815 15:08:45.834661   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
inframachine created: test-mhc-machine-infra-r6glq
machine created: test-mhc-machine-98dzb
I0815 15:08:45.866217   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.872831   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:45.873994   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
... skipping 268 lines ...
I0815 15:08:46.719607   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.721783   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.724033   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.726175   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.728284   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.730380   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
E0815 15:08:46.731150   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:08:46.732624   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.734993   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.737554   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.740502   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.743380   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:46.745694   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
... skipping 367 lines ...
I0815 15:08:47.758468   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.759874   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.763559   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.766110   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.768797   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.770211   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
E0815 15:08:47.782938   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:08:47.785420   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.788249   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.790673   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.793161   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.795522   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:47.797981   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
... skipping 291 lines ...
I0815 15:08:48.779184   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:48.781429   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:48.789513   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:48.792272   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:48.796344   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:48.804873   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
E0815 15:08:48.808649   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:08:48.809522   10872 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-nqlmn/test-mhc-q565n/test-mhc-machine-98dzb/"
I0815 15:08:48.826537   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:48.826974   10872 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-nqlmn/test-mhc-q565n/test-mhc-machine-98dzb/"
node created: test-mhc-node-4764q
E0815 15:08:48.892804   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4764q, got []"  "node"="test-mhc-node-4764q"
I0815 15:08:48.906580   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
inframachine created: test-mhc-machine-infra-lbkxh
machine created: test-mhc-machine-xwhm5
I0815 15:08:48.933281   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:48.968284   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:48.974430   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
... skipping 215 lines ...
I0815 15:08:49.803999   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.806444   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.808862   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.811786   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.815773   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.818391   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
E0815 15:08:49.821937   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:08:49.822259   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.823451   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.829504   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.832302   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.835042   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:49.841484   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
... skipping 272 lines ...
I0815 15:08:50.880827   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.885725   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.888498   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.891439   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.894812   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.900023   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
E0815 15:08:50.901817   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:08:50.902088   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.903813   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.905303   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.907931   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.909525   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:50.911505   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
... skipping 259 lines ...
I0815 15:08:51.911933   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.913681   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.915971   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.917814   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.919664   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.922356   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.922992   10872 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-nqlmn/test-mhc-q565n/test-mhc-machine-xwhm5/"
E0815 15:08:51.931860   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:08:51.939376   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.940193   10872 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-nqlmn/test-mhc-q565n/test-mhc-machine-xwhm5/"
E0815 15:08:51.962659   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-qglpr, got []"  "node"="test-mhc-node-qglpr"
node created: test-mhc-node-qglpr
I0815 15:08:51.970842   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.971437   10872 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-nqlmn/test-mhc-q565n/test-mhc-machine-xwhm5/test-mhc-node-qglpr"
Cleaning up nodes, machines and infra machines.
I0815 15:08:51.983994   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-q565n" "namespace"="test-mhc-nqlmn" 
I0815 15:08:51.984597   10872 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-nqlmn/test-mhc-q565n/test-mhc-machine-xwhm5/"
Cleaning up nodes, machines and infra machines.
I0815 15:08:52.021192   10872 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-l97vb" "namespace"="test-mhc-nqlmn" "count"=2
I0815 15:08:52.021299   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-l97vb" "namespace"="test-mhc-nqlmn" "descendants"="Worker machines: test-mhc-machine-75c2d,test-mhc-machine-98dzb,test-mhc-machine-xwhm5" "indirect descendants count"=1
I0815 15:08:52.031526   10872 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-l97vb" "namespace"="test-mhc-nqlmn" "count"=2
I0815 15:08:52.031599   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-l97vb" "namespace"="test-mhc-nqlmn" "descendants"="Worker machines: test-mhc-machine-75c2d,test-mhc-machine-98dzb,test-mhc-machine-xwhm5" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
... skipping 7 lines ...
I0815 15:08:52.263577   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:52.304595   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:52.385709   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:52.546737   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:52.867808   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:52.932667   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-l97vb" "machine"="test-mhc-machine-98dzb" "namespace"="test-mhc-nqlmn" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-4764q"}
E0815 15:08:53.072355   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-98dzb\" not found" "controller"="machine" "name"="test-mhc-machine-98dzb" "namespace"="test-mhc-nqlmn"
I0815 15:08:53.508855   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
E0815 15:08:54.072813   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:08:54.797399   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:55.073378   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-l97vb" "machine"="test-mhc-machine-xwhm5" "namespace"="test-mhc-nqlmn" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-qglpr"}
E0815 15:08:55.121106   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-xwhm5\" not found" "controller"="machine" "name"="test-mhc-machine-xwhm5" "namespace"="test-mhc-nqlmn"
I0815 15:08:56.121762   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-l97vb" "machine"="test-mhc-machine-75c2d" "namespace"="test-mhc-nqlmn" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-qj6n7"}
E0815 15:08:56.191825   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-75c2d\" not found" "controller"="machine" "name"="test-mhc-machine-75c2d" "namespace"="test-mhc-nqlmn"
E0815 15:08:57.046063   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-nqlmn/test-cluster-l97vb"
E0815 15:08:57.192204   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:08:57.358605   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.200279   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
E0815 15:08:58.204589   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:08:58.204940   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
node created: test-mhc-node-8mvtc
E0815 15:08:58.222494   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-8mvtc, got []"  "node"="test-mhc-node-8mvtc"
I0815 15:08:58.230584   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.234082   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
inframachine created: test-mhc-machine-infra-72gsr
machine created: test-mhc-machine-6p4kb
I0815 15:08:58.256276   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.284391   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.289549   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.310866   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.354658   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.436037   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.602610   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:08:58.923989   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
E0815 15:08:59.210815   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:08:59.565460   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:00.223215   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:00.233270   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:00.251634   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:00.261390   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:00.268894   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
E0815 15:09:00.274729   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:09:00.274729   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
node created: test-mhc-node-cjnms
E0815 15:09:00.279546   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cjnms, got []"  "node"="test-mhc-node-cjnms"
inframachine created: test-mhc-machine-infra-tkzxf
I0815 15:09:00.302252   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
machine created: test-mhc-machine-twxk2
I0815 15:09:00.312912   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:00.325822   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:00.847060   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
E0815 15:09:01.275187   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:09:02.285659   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:02.311733   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:02.323100   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:02.333164   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:02.347855   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:02.363179   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:02.367738   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
E0815 15:09:02.370026   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:09:02.414285   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
node created: test-mhc-node-bt9xt
E0815 15:09:02.428055   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bt9xt, got []"  "node"="test-mhc-node-bt9xt"
I0815 15:09:02.436182   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
Cleaning up nodes, machines and infra machines.
I0815 15:09:02.450724   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
Cleaning up nodes, machines and infra machines.
I0815 15:09:02.499907   10872 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-qrhzt" "namespace"="test-mhc-km2nl" "count"=2
I0815 15:09:02.499992   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-qrhzt" "namespace"="test-mhc-km2nl" "descendants"="Worker machines: test-mhc-machine-xz4d2,test-mhc-machine-6p4kb,test-mhc-machine-twxk2" "indirect descendants count"=1
... skipping 3 lines ...
I0815 15:09:02.590361   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzzcv" "namespace"="test-mhc-km2nl" 
I0815 15:09:02.633123   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
inframachine created: test-mhc-machine-infra-lcl6j
I0815 15:09:02.658579   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-sv427
I0815 15:09:02.778067   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
E0815 15:09:03.370432   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:09:04.370994   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-qrhzt" "machine"="test-mhc-machine-xz4d2" "namespace"="test-mhc-km2nl" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-8mvtc"}
E0815 15:09:04.432794   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-xz4d2\" not found" "controller"="machine" "name"="test-mhc-machine-xz4d2" "namespace"="test-mhc-km2nl"
I0815 15:09:05.433297   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-qrhzt" "machine"="test-mhc-machine-6p4kb" "namespace"="test-mhc-km2nl" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-cjnms"}
E0815 15:09:05.478204   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-6p4kb\" not found" "controller"="machine" "name"="test-mhc-machine-6p4kb" "namespace"="test-mhc-km2nl"
I0815 15:09:06.478727   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-qrhzt" "machine"="test-mhc-machine-twxk2" "namespace"="test-mhc-km2nl" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-bt9xt"}
E0815 15:09:06.525077   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-twxk2\" not found" "controller"="machine" "name"="test-mhc-machine-twxk2" "namespace"="test-mhc-km2nl"
E0815 15:09:07.519684   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-km2nl/test-cluster-qrhzt"
I0815 15:09:07.533322   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
E0815 15:09:07.539453   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:09:07.540011   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
E0815 15:09:07.602635   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-l9h5r, got []"  "node"="test-mhc-node-l9h5r"
node created: test-mhc-node-l9h5r
I0815 15:09:07.611069   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
inframachine created: test-mhc-machine-infra-lws52
I0815 15:09:07.628292   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:07.630889   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:07.639408   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
machine created: test-mhc-machine-hv852
E0815 15:09:08.539907   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:09:09.562202   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.577947   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.605426   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.611866   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.627365   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.634929   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.645651   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
E0815 15:09:09.661231   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t64nq, got []"  "node"="test-mhc-node-t64nq"
node created: test-mhc-node-t64nq
I0815 15:09:09.677651   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
inframachine created: test-mhc-machine-infra-2j66m
I0815 15:09:09.692909   10872 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-hv852" "namespace"="test-mhc-47j4l" "noderef"="test-mhc-node-t64nq"
I0815 15:09:09.704120   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
machine created: test-mhc-machine-986v4
... skipping 7 lines ...
Cleaning up nodes, machines and infra machines.
I0815 15:09:09.824725   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.844090   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
Cleaning up nodes, machines and infra machines.
I0815 15:09:09.859568   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.861929   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:09.863580   10872 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-47j4l/test-mhc-xfldf/test-mhc-machine-sv427/"
I0815 15:09:09.865285   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-wkkq6" "machine"="test-mhc-machine-986v4" "namespace"="test-mhc-47j4l" "cause"="noderef is nil" "node"=null
I0815 15:09:09.918824   10872 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-wkkq6" "namespace"="test-mhc-47j4l" "count"=3
I0815 15:09:09.918919   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-wkkq6" "namespace"="test-mhc-47j4l" "descendants"="Worker machines: test-mhc-machine-sv427,test-mhc-machine-hv852,test-mhc-machine-986v4" "indirect descendants count"=0
I0815 15:09:09.930362   10872 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-wkkq6" "namespace"="test-mhc-47j4l" "count"=3
I0815 15:09:09.930503   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-wkkq6" "namespace"="test-mhc-47j4l" "descendants"="Worker machines: test-mhc-machine-sv427,test-mhc-machine-hv852,test-mhc-machine-986v4" "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
E0815 15:09:09.950772   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-986v4\" not found" "controller"="machine" "name"="test-mhc-machine-986v4" "namespace"="test-mhc-47j4l"
inframachine created: test-mhc-machine-infra-ql5q5
machine created: test-mhc-machine-szbg6
E0815 15:09:10.075916   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-xfldf\" not found" "controller"="machinehealthcheck" "name"="test-mhc-xfldf" "namespace"="test-mhc-47j4l"
I0815 15:09:10.951486   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-wkkq6" "machine"="test-mhc-machine-sv427" "namespace"="test-mhc-47j4l" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-l9h5r"}
E0815 15:09:11.001945   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-sv427\" not found" "controller"="machine" "name"="test-mhc-machine-sv427" "namespace"="test-mhc-47j4l"
I0815 15:09:11.076182   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:11.088399   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 15:09:11.208806   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-xfldf" "namespace"="test-mhc-47j4l" 
I0815 15:09:11.208893   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:11.211668   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:11.218343   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
... skipping 374 lines ...
I0815 15:09:12.040185   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.041875   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.043599   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.045396   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.047142   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.049352   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
E0815 15:09:12.060976   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-hv852\" not found" "controller"="machine" "name"="test-mhc-machine-hv852" "namespace"="test-mhc-47j4l"
I0815 15:09:12.061584   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.071787   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.074048   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.075853   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.077572   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:12.079402   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
... skipping 460 lines ...
I0815 15:09:13.070593   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.071879   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.073552   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.075286   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.077068   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.079081   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.079377   10872 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-8wmvv/test-mhc-r62n5/test-mhc-machine-szbg6/"
E0815 15:09:13.079604   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:09:13.090224   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.090600   10872 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-8wmvv/test-mhc-r62n5/test-mhc-machine-szbg6/"
node created: test-mhc-node-bqhfx
E0815 15:09:13.119639   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bqhfx, got []"  "node"="test-mhc-node-bqhfx"
E0815 15:09:13.119892   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-bqhfx, got []"  "node"="test-mhc-node-bqhfx"
I0815 15:09:13.128012   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.145580   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.153861   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.154200   10872 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-8wmvv/test-mhc-r62n5/test-mhc-machine-szbg6/test-mhc-node-bqhfx"
I0815 15:09:13.171756   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.172211   10872 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-8wmvv/test-mhc-r62n5/test-mhc-machine-szbg6/test-mhc-node-bqhfx"
Cleaning up nodes, machines and infra machines.
I0815 15:09:13.184758   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.185152   10872 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-8wmvv/test-mhc-r62n5/test-mhc-machine-szbg6/test-mhc-node-bqhfx"
I0815 15:09:13.186458   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.186763   10872 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-8wmvv/test-mhc-r62n5/test-mhc-machine-szbg6/"
I0815 15:09:13.204574   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-6rstw" "namespace"="test-mhc-8wmvv" "descendants"="Worker machines: test-mhc-machine-szbg6" "indirect descendants count"=1
I0815 15:09:13.210165   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-6rstw" "namespace"="test-mhc-8wmvv" "descendants"="Worker machines: test-mhc-machine-szbg6" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0815 15:09:13.314417   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" "creating"=1 "need"=1
I0815 15:09:13.314474   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" 
I0815 15:09:13.327074   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-zqscx-l49bb\"" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" 
I0815 15:09:13.389738   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-r62n5" "namespace"="test-mhc-8wmvv" 
I0815 15:09:13.403922   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:13.420488   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0815 15:09:13.438325   10872 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" 
I0815 15:09:13.550340   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
E0815 15:09:14.080053   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:09:14.550575   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
E0815 15:09:14.943340   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-47j4l/test-cluster-wkkq6"
I0815 15:09:15.080669   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-6rstw" "machine"="test-mhc-machine-szbg6" "namespace"="test-mhc-8wmvv" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-bqhfx"}
E0815 15:09:15.147261   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-szbg6\" not found" "controller"="machine" "name"="test-mhc-machine-szbg6" "namespace"="test-mhc-8wmvv"
I0815 15:09:15.551702   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:16.157508   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:16.158363   10872 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" 
I0815 15:09:16.167908   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:16.168790   10872 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" 
I0815 15:09:16.185890   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
... skipping 7 lines ...
I0815 15:09:16.232909   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
I0815 15:09:16.232961   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
I0815 15:09:16.552875   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:17.222745   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
I0815 15:09:17.222790   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.000689   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.001149   10872 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-9qxhj/test-mhc-g5xq7/mhc-ms-zqscx-l49bb/"
I0815 15:09:18.009287   10872 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.017218   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.017613   10872 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-9qxhj/test-mhc-g5xq7/mhc-ms-zqscx-l49bb/"
I0815 15:09:18.019154   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.019190   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.027331   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.027755   10872 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-9qxhj/test-mhc-g5xq7/mhc-ms-zqscx-l49bb/"
I0815 15:09:18.028661   10872 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.049965   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.050032   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.082362   10872 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-zsz2l" "namespace"="test-mhc-9qxhj" "count"=1
I0815 15:09:18.082433   10872 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-zsz2l" "namespace"="test-mhc-9qxhj" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-zqscx"
I0815 15:09:18.083547   10872 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" "machine"="mhc-ms-zqscx-l49bb"
I0815 15:09:18.090193   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-zsz2l" "machine"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj" "cause"="cluster is being deleted" "node"=null
I0815 15:09:18.091813   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.092210   10872 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-9qxhj/test-mhc-g5xq7/mhc-ms-zqscx-l49bb/"
I0815 15:09:18.093865   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-zsz2l" "namespace"="test-mhc-9qxhj" "descendants"="Machine sets: mhc-ms-zqscx;Worker machines: mhc-ms-zqscx-l49bb" "indirect descendants count"=1
I0815 15:09:18.094880   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-g5xq7" "namespace"="test-mhc-9qxhj" 
I0815 15:09:18.113777   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-zsz2l" "namespace"="test-mhc-9qxhj" "descendants"="Worker machines: mhc-ms-zqscx-l49bb" "indirect descendants count"=1
E0815 15:09:18.117685   10872 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-zqscx\" not found" "machineset"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj" 
E0815 15:09:18.117778   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-zqscx\" not found" "controller"="machineset" "name"="mhc-ms-zqscx" "namespace"="test-mhc-9qxhj"
=== 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
E0815 15:09:18.223067   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-8wmvv/test-cluster-6rstw"
I0815 15:09:18.315482   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
inframachine created: test-mhc-machine-infra-k256p
E0815 15:09:18.341992   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
I0815 15:09:18.345200   10872 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-m5dqt
I0815 15:09:18.468173   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:18.469330   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:18.471703   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:18.473591   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
... skipping 374 lines ...
I0815 15:09:19.398741   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.400784   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.409485   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.412076   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.413927   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.415711   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
E0815 15:09:19.417888   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-zqscx-l49bb\" not found" "controller"="machine" "name"="mhc-ms-zqscx-l49bb" "namespace"="test-mhc-9qxhj"
I0815 15:09:19.418076   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.419898   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.421749   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.423604   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.426050   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:19.427887   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
... skipping 440 lines ...
I0815 15:09:20.417628   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.419545   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.423775   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.426135   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.426979   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.429514   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
E0815 15:09:20.431463   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
I0815 15:09:20.431480   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
E0815 15:09:20.462524   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tlgwr, got []"  "node"="test-mhc-node-tlgwr"
E0815 15:09:20.462803   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tlgwr, got []"  "node"="test-mhc-node-tlgwr"
node created: test-mhc-node-tlgwr
I0815 15:09:20.527658   10872 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-m5dqt" "target"="test-mhc-w627n/test-mhc-v5m99/test-mhc-machine-m5dqt/"
I0815 15:09:20.555803   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.582899   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.597078   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.601000   10872 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-m5dqt" "target"="test-mhc-w627n/test-mhc-v5m99/test-mhc-machine-m5dqt/test-mhc-node-tlgwr"
I0815 15:09:20.623482   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
Cleaning up nodes, machines and infra machines.
I0815 15:09:20.642813   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.646426   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.654903   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v5m99" "namespace"="test-mhc-w627n" 
I0815 15:09:20.662524   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-bjmlc" "namespace"="test-mhc-w627n" "descendants"="Worker machines: test-mhc-machine-m5dqt" "indirect descendants count"=1
... skipping 265 lines ...
I0815 15:09:21.479787   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.481587   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.483522   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.485327   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.487096   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.488769   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
E0815 15:09:21.489201   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-m5dqt\" not found" "controller"="machine" "name"="test-mhc-machine-m5dqt" "namespace"="test-mhc-w627n"
I0815 15:09:21.490593   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.492346   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.494011   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.495837   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.497781   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:21.499549   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
... skipping 459 lines ...
I0815 15:09:22.493693   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.495584   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.497042   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.497742   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.498866   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.501224   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.506027   10872 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-mvjgx" "target"="test-mhc-t4x9w/test-mhc-vgz8w/test-mhc-machine-mvjgx/"
I0815 15:09:22.522494   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
node created: test-mhc-node-r2ftv
E0815 15:09:22.532747   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-r2ftv, got []"  "node"="test-mhc-node-r2ftv"
E0815 15:09:22.532823   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-r2ftv, got []"  "node"="test-mhc-node-r2ftv"
E0815 15:09:22.533293   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-r2ftv, got []"  "node"="test-mhc-node-r2ftv"
I0815 15:09:22.556766   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.597001   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.603811   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.606003   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.609628   10872 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-mvjgx" "target"="test-mhc-t4x9w/test-mhc-vgz8w/test-mhc-machine-mvjgx/test-mhc-node-r2ftv"
I0815 15:09:22.632367   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.638713   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.659656   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
Cleaning up nodes, machines and infra machines.
I0815 15:09:22.665738   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.668161   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:22.676102   10872 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-mvjgx" "target"="test-mhc-t4x9w/test-mhc-vgz8w/test-mhc-machine-mvjgx/"
I0815 15:09:22.678316   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-btxzz" "namespace"="test-mhc-t4x9w" "descendants"="Worker machines: test-mhc-machine-mvjgx" "indirect descendants count"=1
I0815 15:09:22.685436   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-btxzz" "namespace"="test-mhc-t4x9w" "descendants"="Worker machines: test-mhc-machine-mvjgx" "indirect descendants count"=1
E0815 15:09:22.707438   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-vgz8w\" not found" "controller"="machinehealthcheck" "name"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w"
--- PASS: TestMachineHealthCheck_Reconcile (41.84s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.06s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.19s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.07s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist (0.88s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones (0.14s)
... skipping 10 lines ...
    --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s)
        machinehealthcheck_controller_test.go:933: skipping until made stable
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (2.56s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (2.03s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0815 15:09:22.708256   10872 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
E0815 15:09:22.712203   10872 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
E0815 15:09:22.715473   10872 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0815 15:09:22.715857   10872 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
E0815 15:09:22.716668   10872 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
I0815 15:09:22.719973   10872 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0815 15:09:22.721858   10872 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0815 15:09:22.723920   10872 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.01s)
=== 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 27 lines ...
    --- 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
I0815 15:09:22.737050   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-btxzz" "machine"="test-mhc-machine-mvjgx" "namespace"="test-mhc-t4x9w" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-r2ftv"}
E0815 15:09:22.737662   10872 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
E0815 15:09:22.740663   10872 machineset_controller.go:569]  "msg"="Unable to convert selector" "error"="\"bad-operator\" is not a valid pod selector operator" "machine"="match" "machineset"="" "namespace"="" 
--- PASS: TestHasMatchingLabels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_and_machine_do_not_have_matching_labels (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_empty_selector (0.00s)
    --- PASS: TestHasMatchingLabels/machine_set_has_bad_selector (0.00s)
=== RUN   TestMachineToDelete
... skipping 57 lines ...
=== RUN   TestGinkgoSuite
Running Suite: Controllers Suite
================================
Random Seed: 1660576097
Will run 16 of 16 specs

E0815 15:09:22.789049   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-mvjgx\" not found" "controller"="machine" "name"="test-mhc-machine-mvjgx" "namespace"="test-mhc-t4x9w"
I0815 15:09:22.807784   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "creating"=2 "need"=2
I0815 15:09:22.807845   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" 
I0815 15:09:22.821148   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"md-zflgk-6657c7fddb-m72ll\"" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" 
I0815 15:09:22.821221   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" 
I0815 15:09:22.843692   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"md-zflgk-6657c7fddb-958p6\"" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" 
E0815 15:09:22.910627   10872 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"md-zflgk-6657c7fddb\" not found" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" 
E0815 15:09:22.910776   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"md-zflgk-6657c7fddb\" not found" "controller"="machineset" "name"="md-zflgk-6657c7fddb" "namespace"="md-test"
E0815 15:09:23.129726   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-9qxhj/test-cluster-zsz2l"
I0815 15:09:23.707752   10872 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-vgz8w" "namespace"="test-mhc-t4x9w" 
I0815 15:09:23.843819   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:23.843878   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:23.869748   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:23.869794   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:23.894806   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
... skipping 23 lines ...
I0815 15:09:24.084835   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-zl462" "namespace"="md-test" 
I0815 15:09:24.094907   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zflgk-cdfc6fd6c-2zs7c\"" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" 
I0815 15:09:24.129261   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test" 
I0815 15:09:24.129302   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test" 
I0815 15:09:24.155235   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test" 
I0815 15:09:24.155279   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test" 
E0815 15:09:24.159355   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-2zs7c-px858, got []"  "node"="md-zflgk-cdfc6fd6c-2zs7c-px858"
E0815 15:09:24.159555   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-2zs7c-px858, got []"  "node"="md-zflgk-cdfc6fd6c-2zs7c-px858"
E0815 15:09:24.183634   10872 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"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test" 
E0815 15:09:24.207728   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="the cache is not started, can not read objects" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test"
E0815 15:09:24.263597   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-2zs7c-px858, got []"  "node"="md-zflgk-cdfc6fd6c-2zs7c-px858"
E0815 15:09:24.263662   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-2zs7c-px858, got []"  "node"="md-zflgk-cdfc6fd6c-2zs7c-px858"
E0815 15:09:24.263845   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-2zs7c-px858, got []"  "node"="md-zflgk-cdfc6fd6c-2zs7c-px858"
E0815 15:09:24.263892   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-2zs7c-px858, got []"  "node"="md-zflgk-cdfc6fd6c-2zs7c-px858"
I0815 15:09:24.311553   10872 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=2
I0815 15:09:24.311642   10872 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0815 15:09:24.316794   10872 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "machine"="md-zflgk-6657c7fddb-jwlxc"
I0815 15:09:24.344955   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=2
I0815 15:09:24.345004   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" 
I0815 15:09:24.358822   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zflgk-cdfc6fd6c-j47rt\"" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" 
E0815 15:09:24.401268   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-j47rt-mx9jb, got []"  "node"="md-zflgk-cdfc6fd6c-j47rt-mx9jb"
E0815 15:09:24.401341   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-j47rt-mx9jb, got []"  "node"="md-zflgk-cdfc6fd6c-j47rt-mx9jb"
E0815 15:09:24.405468   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-j47rt-mx9jb, got []"  "node"="md-zflgk-cdfc6fd6c-j47rt-mx9jb"
E0815 15:09:24.405539   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-j47rt-mx9jb, got []"  "node"="md-zflgk-cdfc6fd6c-j47rt-mx9jb"
E0815 15:09:24.405692   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-j47rt-mx9jb, got []"  "node"="md-zflgk-cdfc6fd6c-j47rt-mx9jb"
E0815 15:09:24.405749   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-j47rt-mx9jb, got []"  "node"="md-zflgk-cdfc6fd6c-j47rt-mx9jb"
I0815 15:09:24.442095   10872 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=1
I0815 15:09:24.442144   10872 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0815 15:09:24.446089   10872 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "machine"="md-zflgk-6657c7fddb-xxj7v"
I0815 15:09:24.555757   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" "creating"=1 "need"=3
I0815 15:09:24.555810   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" 
I0815 15:09:24.568851   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zflgk-cdfc6fd6c-wmczm\"" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" 
E0815 15:09:24.660426   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-wmczm-6pq8j, got []"  "node"="md-zflgk-cdfc6fd6c-wmczm-6pq8j"
E0815 15:09:24.660506   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-wmczm-6pq8j, got []"  "node"="md-zflgk-cdfc6fd6c-wmczm-6pq8j"
E0815 15:09:24.663993   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-wmczm-6pq8j, got []"  "node"="md-zflgk-cdfc6fd6c-wmczm-6pq8j"
E0815 15:09:24.664048   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-wmczm-6pq8j, got []"  "node"="md-zflgk-cdfc6fd6c-wmczm-6pq8j"
E0815 15:09:24.664176   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-wmczm-6pq8j, got []"  "node"="md-zflgk-cdfc6fd6c-wmczm-6pq8j"
E0815 15:09:24.664230   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-cdfc6fd6c-wmczm-6pq8j, got []"  "node"="md-zflgk-cdfc6fd6c-wmczm-6pq8j"
I0815 15:09:24.707347   10872 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "deleting"=1 "need"=0
I0815 15:09:24.707397   10872 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "delete-policy"="Random"
I0815 15:09:24.714195   10872 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zflgk-6657c7fddb" "namespace"="md-test" "machine"="md-zflgk-6657c7fddb-zl462"
E0815 15:09:24.869230   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="Operation cannot be fulfilled on machinedeployments.cluster.x-k8s.io \"md-zflgk\": the object has been modified; please apply your changes to the latest version and try again" "controller"="machinedeployment" "name"="md-zflgk" "namespace"="md-test"
E0815 15:09:25.245189   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-cdfc6fd6c-2zs7c\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test"
E0815 15:09:25.682035   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-w627n/test-cluster-bjmlc"
I0815 15:09:25.891675   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=1
I0815 15:09:25.891725   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" 
I0815 15:09:25.906659   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zflgk-74d45c49c5-zht78\"" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" 
E0815 15:09:26.005656   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-zht78-gjt8w, got []"  "node"="md-zflgk-74d45c49c5-zht78-gjt8w"
E0815 15:09:26.009194   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-zht78-gjt8w, got []"  "node"="md-zflgk-74d45c49c5-zht78-gjt8w"
E0815 15:09:26.009237   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-zht78-gjt8w, got []"  "node"="md-zflgk-74d45c49c5-zht78-gjt8w"
I0815 15:09:26.049811   10872 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=2
I0815 15:09:26.049859   10872 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0815 15:09:26.057577   10872 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" "machine"="md-zflgk-cdfc6fd6c-2zs7c"
I0815 15:09:26.082892   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=2
I0815 15:09:26.082938   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" 
I0815 15:09:26.094942   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zflgk-74d45c49c5-bj45m\"" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" 
E0815 15:09:26.171960   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-bj45m-fkbdg, got []"  "node"="md-zflgk-74d45c49c5-bj45m-fkbdg"
E0815 15:09:26.176078   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-bj45m-fkbdg, got []"  "node"="md-zflgk-74d45c49c5-bj45m-fkbdg"
E0815 15:09:26.176141   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-bj45m-fkbdg, got []"  "node"="md-zflgk-74d45c49c5-bj45m-fkbdg"
I0815 15:09:26.212969   10872 machineset_controller.go:388] controllers/MachineSet "msg"="Too many replicas" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" "deleting"=1 "need"=1
I0815 15:09:26.213008   10872 machineset_controller.go:394] controllers/MachineSet "msg"="Found delete policy" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" "delete-policy"="Random"
I0815 15:09:26.217943   10872 machineset_controller.go:405] controllers/MachineSet "msg"="Deleted machine" "machineset"="md-zflgk-cdfc6fd6c" "namespace"="md-test" "machine"="md-zflgk-cdfc6fd6c-j47rt"
I0815 15:09:26.228539   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" "creating"=1 "need"=3
I0815 15:09:26.228589   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(3) \u003e currentMachineCount(2) )" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" 
I0815 15:09:26.239321   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"md-zflgk-74d45c49c5-7znk2\"" "machineset"="md-zflgk-74d45c49c5" "namespace"="md-test" 
I0815 15:09:26.245787   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-zflgk-6657c7fddb-jwlxc" "namespace"="md-test" "cause"="noderef is nil" "node"=null
I0815 15:09:26.280578   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-zflgk-6657c7fddb-xxj7v" "namespace"="md-test" "cause"="noderef is nil" "node"=null
E0815 15:09:26.329209   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-7znk2-mfkqd, got []"  "node"="md-zflgk-74d45c49c5-7znk2-mfkqd"
I0815 15:09:26.331120   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-zflgk-6657c7fddb-zl462" "namespace"="md-test" "cause"="noderef is nil" "node"=null
E0815 15:09:26.332673   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-7znk2-mfkqd, got []"  "node"="md-zflgk-74d45c49c5-7znk2-mfkqd"
E0815 15:09:26.332751   10872 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node md-zflgk-74d45c49c5-7znk2-mfkqd, got []"  "node"="md-zflgk-74d45c49c5-7znk2-mfkqd"
I0815 15:09:26.355430   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-zflgk-74d45c49c5,md-zflgk-cdfc6fd6c;Worker machines: md-zflgk-6657c7fddb-m72ll,md-zflgk-6657c7fddb-958p6,md-zflgk-6657c7fddb-jwlxc,md-zflgk-74d45c49c5-bj45m,md-zflgk-74d45c49c5-7znk2,md-zflgk-6657c7fddb-xxj7v,md-zflgk-6657c7fddb-zl462,md-zflgk-cdfc6fd6c-2zs7c,md-zflgk-cdfc6fd6c-wmczm,md-zflgk-74d45c49c5-zht78" "indirect descendants count"=12
•I0815 15:09:26.361073   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-zflgk-74d45c49c5,md-zflgk-cdfc6fd6c;Worker machines: md-zflgk-6657c7fddb-m72ll,md-zflgk-6657c7fddb-958p6,md-zflgk-6657c7fddb-jwlxc,md-zflgk-74d45c49c5-bj45m,md-zflgk-74d45c49c5-7znk2,md-zflgk-6657c7fddb-xxj7v,md-zflgk-6657c7fddb-zl462,md-zflgk-cdfc6fd6c-2zs7c,md-zflgk-cdfc6fd6c-wmczm,md-zflgk-74d45c49c5-zht78" "indirect descendants count"=12
I0815 15:09:26.373876   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:26.373921   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:26.378373   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:26.378415   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:26.378927   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-zflgk-cdfc6fd6c-2zs7c-px858"}
I0815 15:09:26.455746   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-zflgk-6657c7fddb-jwlxc" "namespace"="md-test" "cause"="cluster is being deleted" "node"=null
•E0815 15:09:26.482800   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test1-nkd2n\" not found" "controller"="cluster" "name"="test1-nkd2n" "namespace"="default"
E0815 15:09:26.487021   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"md-zflgk-6657c7fddb-jwlxc\" not found" "controller"="machine" "name"="md-zflgk-6657c7fddb-jwlxc" "namespace"="md-test"
I0815 15:09:27.487600   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-zflgk-6657c7fddb-xxj7v" "namespace"="md-test" "cause"="cluster is being deleted" "node"=null
E0815 15:09:27.518041   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"md-zflgk-6657c7fddb-xxj7v\" not found" "controller"="machine" "name"="md-zflgk-6657c7fddb-xxj7v" "namespace"="md-test"
•I0815 15:09:27.602741   10872 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-kqcx5" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0815 15:09:27.726623   10872 conversion.go:64] controllers/Cluster "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test2-kqcx5" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0815 15:09:27.730911   10872 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-kqcx5" "namespace"="default"
E0815 15:09:28.548641   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-cdfc6fd6c-wmczm\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-wmczm" "namespace"="md-test"
E0815 15:09:28.751889   10872 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-t4x9w/test-cluster-btxzz"
E0815 15:09:28.755697   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
•I0815 15:09:29.549260   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-zflgk-6657c7fddb-zl462" "namespace"="md-test" "cause"="cluster is being deleted" "node"=null
E0815 15:09:29.585466   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"md-zflgk-6657c7fddb-zl462\" not found" "controller"="machine" "name"="md-zflgk-6657c7fddb-zl462" "namespace"="md-test"
E0815 15:09:29.772266   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test3-vchhs\" not found" "controller"="cluster" "name"="test3-vchhs" "namespace"="default"
I0815 15:09:30.586617   10872 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster" "machine"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test" "cause"="cluster is being deleted" "node"={"name":"md-zflgk-cdfc6fd6c-2zs7c-px858"}
E0815 15:09:30.624331   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"md-zflgk-cdfc6fd6c-2zs7c\" not found" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-2zs7c" "namespace"="md-test"
E0815 15:09:30.773205   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
E0815 15:09:31.650692   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-zht78\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-zht78" "namespace"="md-test"
E0815 15:09:31.783664   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
•E0815 15:09:32.680773   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-bj45m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-bj45m" "namespace"="md-test"
I0815 15:09:32.784707   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-zflgk-cdfc6fd6c,md-zflgk-74d45c49c5;Worker machines: md-zflgk-6657c7fddb-m72ll,md-zflgk-6657c7fddb-958p6,md-zflgk-cdfc6fd6c-wmczm,md-zflgk-74d45c49c5-zht78,md-zflgk-74d45c49c5-bj45m,md-zflgk-74d45c49c5-7znk2" "indirect descendants count"=8
E0815 15:09:32.789989   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
I0815 15:09:33.709001   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:33.709056   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:33.714442   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:33.714493   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
E0815 15:09:33.719302   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-cdfc6fd6c-wmczm\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-wmczm" "namespace"="md-test"
E0815 15:09:33.790623   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
E0815 15:09:34.719843   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-b5lnd\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-b5lnd" "namespace"="test-mhc-vrcgk"
E0815 15:09:34.800287   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
•E0815 15:09:35.720482   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-lgbfp\" for machine \"test-mhc-machine-772n7\" in namespace \"test-mhc-vrcgk\": Cluster.cluster.x-k8s.io \"test-cluster-lgbfp\" not found" "controller"="machine" "name"="test-mhc-machine-772n7" "namespace"="test-mhc-vrcgk"
E0815 15:09:35.801084   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
E0815 15:09:36.729742   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-zht78\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-zht78" "namespace"="md-test"
E0815 15:09:36.802016   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
E0815 15:09:37.737811   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-bj45m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-bj45m" "namespace"="md-test"
E0815 15:09:37.814428   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
E0815 15:09:38.748048   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-cdfc6fd6c-wmczm\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-wmczm" "namespace"="md-test"
E0815 15:09:38.815126   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
I0815 15:09:39.752954   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:39.753001   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:39.757562   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:39.757604   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
E0815 15:09:39.763188   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-zht78\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-zht78" "namespace"="md-test"
I0815 15:09:39.815791   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-zflgk-74d45c49c5,md-zflgk-cdfc6fd6c;Worker machines: md-zflgk-cdfc6fd6c-wmczm,md-zflgk-74d45c49c5-zht78,md-zflgk-74d45c49c5-bj45m,md-zflgk-74d45c49c5-7znk2,md-zflgk-6657c7fddb-m72ll,md-zflgk-6657c7fddb-958p6" "indirect descendants count"=8
E0815 15:09:39.816722   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
E0815 15:09:40.768230   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-bj45m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-bj45m" "namespace"="md-test"
E0815 15:09:40.817439   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
E0815 15:09:41.784771   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-cdfc6fd6c-wmczm\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-wmczm" "namespace"="md-test"
E0815 15:09:41.818257   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
E0815 15:09:42.789814   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-zht78\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-zht78" "namespace"="md-test"
E0815 15:09:42.818971   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
I0815 15:09:43.795048   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:43.795088   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:43.799794   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:43.799831   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
E0815 15:09:43.805193   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-bj45m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-bj45m" "namespace"="md-test"
E0815 15:09:43.819723   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
E0815 15:09:44.820378   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
I0815 15:09:44.820534   10872 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-486f2" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
E0815 15:09:44.830101   10872 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-486f2" "namespace"="default" 
E0815 15:09:44.844378   10872 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-486f2" "namespace"="default"
E0815 15:09:45.821089   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
E0815 15:09:45.849689   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-cdfc6fd6c-wmczm\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-wmczm" "namespace"="md-test"
I0815 15:09:46.821692   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="md-test" "descendants"="Machine sets: md-zflgk-74d45c49c5,md-zflgk-cdfc6fd6c;Worker machines: md-zflgk-6657c7fddb-m72ll,md-zflgk-6657c7fddb-958p6,md-zflgk-cdfc6fd6c-wmczm,md-zflgk-74d45c49c5-zht78,md-zflgk-74d45c49c5-bj45m,md-zflgk-74d45c49c5-7znk2" "indirect descendants count"=8
E0815 15:09:46.822153   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
E0815 15:09:46.855318   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-zht78\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-zht78" "namespace"="md-test"
E0815 15:09:47.822880   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test-too\" for Cluster default/test2-kqcx5: failed to retrieve  external object \"default\"/\"test-too\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test2-kqcx5" "namespace"="default"
E0815 15:09:47.860676   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-74d45c49c5-bj45m\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-74d45c49c5-bj45m" "namespace"="md-test"
E0815 15:09:48.823777   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get  \"test\" for Cluster default/test4-jcllt: failed to retrieve  external object \"default\"/\"test\": Object 'Kind' is missing in 'unstructured object has no kind'" "controller"="cluster" "name"="test4-jcllt" "namespace"="default"
I0815 15:09:48.865233   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:48.865272   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-m72ll" "namespace"="md-test" 
I0815 15:09:48.869285   10872 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:48.869411   10872 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="md-zflgk-6657c7fddb-958p6" "namespace"="md-test" 
I0815 15:09:48.883003   10872 conversion.go:64] controllers/Machine "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="test6-486f2" "namespace"="default" "err"="you requested PartialObjectMetadata, but the requested object is a list (*apiextensions.CustomResourceDefinitionList)"
I0815 15:09:48.883270   10872 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test6-486f2" "namespace"="default" "noderef"="id-node-1"
E0815 15:09:48.899327   10872 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-486f2" "namespace"="default"
E0815 15:09:49.905428   10872 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"md-zflgk-cdfc6fd6c-wmczm\" in namespace \"md-test\": cannot find node with matching ProviderID" "controller"="machine" "name"="md-zflgk-cdfc6fd6c-wmczm" "namespace"="md-test"

------------------------------
• [SLOW TEST:15.066 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 ...
I0815 15:09:49.935633   10872 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"
•I0815 15:09:49.937023   10872 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"
I0815 15:09:49.937668   10872 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"
I0815 15:09:49.938218   10872 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="machine-test" "namespace"="default" 
I0815 15:09:49.938251   10872 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine-test" "namespace"="default" 
•I0815 15:09:49.938708   10872 machine_controller.go:327]  "msg"="Draining node" "cluster"="test-cluster" "machine"="machine-test" "namespace"="default" "node"="machine-test-node"
E0815 15:09:49.939873   10872 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" 
•I0815 15:09:50.013010   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-zcxnp" "namespace"="ms-test" "creating"=2 "need"=2
I0815 15:09:50.013052   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-zcxnp" "namespace"="ms-test" 
I0815 15:09:50.027070   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 2 with name \"ms-zcxnp-blrcf\"" "machineset"="ms-zcxnp" "namespace"="ms-test" 
I0815 15:09:50.027120   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 2 of 2, ( spec.replicas(2) \u003e currentMachineCount(0) )" "machineset"="ms-zcxnp" "namespace"="ms-test" 
I0815 15:09:50.041407   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 2 of 2 with name \"ms-zcxnp-b22vw\"" "machineset"="ms-zcxnp" "namespace"="ms-test" 
I0815 15:09:50.150745   10872 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="ms-zcxnp" "namespace"="ms-test" "creating"=1 "need"=2
I0815 15:09:50.150795   10872 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(2) \u003e currentMachineCount(1) )" "machineset"="ms-zcxnp" "namespace"="ms-test" 
I0815 15:09:50.164937   10872 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"ms-zcxnp-cdqw5\"" "machineset"="ms-zcxnp" "namespace"="ms-test" 
E0815 15:09:50.293567   10872 machineset_controller.go:625] controllers/MachineSet "msg"="Unable to retrieve Node status" "error"="error retrieving node ms-zcxnp-cdqw5-2ljg5 for machine ms-test/ms-zcxnp-cdqw5: the cache is not started, can not read objects" "machineset"="ms-zcxnp" "namespace"="ms-test" 
I0815 15:09:50.410458   10872 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster" "namespace"="ms-test" "descendants"="Worker machines: ms-zcxnp-cdqw5,ms-zcxnp-b22vw" "indirect descendants count"=2
•

Ran 16 of 16 Specs in 27.671 seconds
SUCCESS! -- 16 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (27.67s)
PASS
Tearing down test suite
I0815 15:09:50.413426   10872 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machineset" 
E0815 15:09:50.413450   10872 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0815 15:09:50.413494   10872 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-286750748/tls.crt: no such file or directory"  
I0815 15:09:50.413518   10872 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0815 15:09:50.413522   10872 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0815 15:09:50.413543   10872 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-286750748/tls.crt: no such file or directory"  
I0815 15:09:50.413708   10872 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I0815 15:09:50.413728   10872 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I0815 15:09:50.413841   10872 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machine" 
I0815 15:09:50.413898   10872 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinehealthcheck" 
I0815 15:09:50.414053   10872 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0815 15:09:50.445250   10872 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:39331/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1282&timeout=10s&timeoutSeconds=519&watch=true: dial tcp 127.0.0.1:39331: connect: connection refused
W0815 15:09:50.445290   10872 reflector.go:328] pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:105: watch of *v1.Node ended with: very short watch: pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:105: Unexpected watch close - watch lasted less than a second and no items received
E0815 15:09:50.446595   10872 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:39331/api/v1/nodes?allowWatchBookmarks=true&resourceVersion=1282&timeout=10s&timeoutSeconds=354&watch=true: dial tcp 127.0.0.1:39331: connect: connection refused
ok  	sigs.k8s.io/cluster-api/controllers	93.386s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.02s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
... skipping 260 lines ...
I0815 15:08:38.734434   11361 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=41229
I0815 15:08:38.737641   11361 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0815 15:08:38.756322   11361 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}}}
I0815 15:08:38.957082   11361 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0815 15:08:38.957149   11361 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I0815 15:08:39.336655   11361 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0815 15:08:41.433931   11361 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-cwlth/test-cluster"
•E0815 15:08:41.876426   11361 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-qq7qd/test-cluster"
•E0815 15:08:42.429874   11361 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:42035/?timeout=50ms: dial tcp 127.0.0.1:42035: connect: connection refused"  "cluster"="cluster-cache-test-wdvpf/test-cluster"
•I0815 15:08:42.687007   11361 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":{}}}
I0815 15:08:42.990712   11361 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0815 15:08:42.990801   11361 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0815 15:08:42.990882   11361 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•I0815 15:08:43.546171   11361 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0815 15:08:43.546393   11361 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0815 15:08:43.593750   11361 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:39499/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:39499: connect: connection refused


Ran 5 of 5 Specs in 23.106 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (23.11s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	23.398s
?   	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
I0815 15:08:56.606736   11985 controller.go:130]  "msg"="Cluster Controller has not yet set OwnerRef" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoClusterOwnerRef (0.00s)
=== RUN   TestReconcileNoKCP
--- PASS: TestReconcileNoKCP (0.00s)
=== RUN   TestReconcileNoCluster
E0815 15:08:56.608226   11985 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="clusters.cluster.x-k8s.io \"foo\" not found" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcileNoCluster (0.00s)
=== RUN   TestReconcilePaused
I0815 15:08:56.608965   11985 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0815 15:08:56.609159   11985 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 94 lines ...
I0815 15:09:09.672766   11985 remediation.go:248]  "msg"="etcd cluster projected after remediation of m1-unhealthy-m7wws" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "canSafelyRemediate"=true "healthyMembers"=["node-m2-healthy-nzn4x (m2-healthy-nzn4x)","node-m3-healthy-tzjc9 (m3-healthy-tzjc9)"] "targetQuorum"=2 "targetTotalMembers"=2 "targetUnhealthyMembers"=0 "unhealthyMembers"=[]
I0815 15:09:09.677553   11985 remediation.go:154]  "msg"="Remediating unhealthy machine" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "UnhealthyMachine"="m1-unhealthy-m7wws"
=== RUN   TestReconcileUnhealthyMachines/Remediation_deletes_unhealthy_machine_-_4_CP_(during_3_CP_rolling_upgrade)
I0815 15:09:09.805403   11985 remediation.go:195]  "msg"="etcd cluster before remediation" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "currentMembers"=["node-m3-healthy-tlc7w","node-m4-healthy-kczkx","node-m1-unhealthy-vwmg5","node-m2-healthy-hhttm"] "currentTotalMembers"=4
I0815 15:09:09.805495   11985 remediation.go:248]  "msg"="etcd cluster projected after remediation of m1-unhealthy-vwmg5" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "canSafelyRemediate"=true "healthyMembers"=["node-m3-healthy-tlc7w (m3-healthy-tlc7w)","node-m4-healthy-kczkx (m4-healthy-kczkx)","node-m2-healthy-hhttm (m2-healthy-hhttm)"] "targetQuorum"=2 "targetTotalMembers"=3 "targetUnhealthyMembers"=0 "unhealthyMembers"=[]
I0815 15:09:09.810906   11985 remediation.go:154]  "msg"="Remediating unhealthy machine" "cluster"="" "kubeadmControlPlane"="" "namespace"="" "UnhealthyMachine"="m1-unhealthy-vwmg5"
--- FAIL: TestReconcileUnhealthyMachines (0.91s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_are_no_unhealthy_machines (0.00s)
    --- PASS: TestReconcileUnhealthyMachines/reconcileUnhealthyMachines_return_early_if_the_machine_to_be_remediated_is_marked_for_deletion (0.00s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_desired_replicas_<=_1 (0.04s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_number_of_machines_lower_than_desired (0.06s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_is_a_deleting_machine (0.06s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_is_at_least_one_additional_unhealthy_etcd_member_on_a_3_machine_CP (0.09s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_does_not_happen_if_there_is_at_least_two_additional_unhealthy_etcd_member_on_a_5_machine_CP (0.14s)
    --- PASS: TestReconcileUnhealthyMachines/Remediation_deletes_unhealthy_machine_-_2_CP_(during_1_CP_rolling_upgrade) (0.23s)
    --- FAIL: TestReconcileUnhealthyMachines/Remediation_deletes_unhealthy_machine_-_3_CP (0.09s)
        remediation_test.go:839: 
            Expected
                <string>: WaitingForRemediation
            to equal
                <string>: RemediationInProgress
    --- PASS: TestReconcileUnhealthyMachines/Remediation_deletes_unhealthy_machine_-_4_CP_(during_3_CP_rolling_upgrade) (0.19s)
... skipping 81 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
I0815 15:09:13.323022   11985 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
I0815 15:09:13.323180   11985 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: 1660576121
Will run 1 of 1 specs

E0815 15:09:13.356084   11985 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-81dwm3\" not found" "kubeadmControlPlane"="kcp-foo-81dwm3" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.029 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0815 15:09:13.358179   11985 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-waky0r" "kubeadmControlPlane"="kcp-foo-waky0r" "namespace"="test" 
I0815 15:09:15.433935   11985 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-waky0r" "kubeadmControlPlane"="kcp-foo-waky0r" "namespace"="test" "needRollout"=["kcp-foo-waky0r-jd8bv"]
I0815 15:09:15.434108   11985 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-waky0r" "kubeadmControlPlane"="kcp-foo-waky0r" "namespace"="test" "failures"="[machine kcp-foo-waky0r-shnhr does not have APIServerPodHealthy condition, machine kcp-foo-waky0r-shnhr does not have ControllerManagerPodHealthy condition, machine kcp-foo-waky0r-shnhr does not have SchedulerPodHealthy condition, machine kcp-foo-waky0r-shnhr does not have EtcdPodHealthy condition, machine kcp-foo-waky0r-shnhr does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (2.08s)
FAIL
I0815 15:09:15.435145   11985 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
FAIL	sigs.k8s.io/cluster-api/controlplane/kubeadm/controllers	34.575s
I0815 15:08:52.624325   11955 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0815 15:08:52.626491   11955 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0815 15:08:52.626587   11955 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Cluster"} "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0815 15:08:52.626629   11955 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I0815 15:08:52.626811   11955 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Machine"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
I0815 15:08:52.626849   11955 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
... skipping 51 lines ...
==================================
Random Seed: 1660576119
Will run 7 of 7 specs

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

•••••••
Ran 7 of 7 Specs in 0.001 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestMachineCollection (0.00s)
=== RUN   TestUpdateEtcdConditions
=== RUN   TestUpdateEtcdConditions/if_list_nodes_return_an_error_should_report_all_the_conditions_Unknown
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_be_ignored_if_there_are_provisioning_machines
=== RUN   TestUpdateEtcdConditions/node_without_machine_should_report_a_problem_at_KCP_level_if_there_are_no_provisioning_machines
=== RUN   TestUpdateEtcdConditions/failure_creating_the_etcd_client_should_report_unknown_condition
... skipping 297 lines ...
    --- PASS: TestUpdateKubeProxyImageInfo/returns_error_if_image_repository_is_invalid (0.00s)
    --- PASS: TestUpdateKubeProxyImageInfo/does_not_update_image_repository_when_no_kube-proxy_update_is_requested (0.00s)
=== RUN   TestRemoveMachineFromKubeadmConfigMap
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_find_kubeadm-config_for_Kubernetes_version_<_1.22.0
E0815 15:08:54.155970   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:09:02.479522   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:09:11.465533   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:09:22.595860   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:09:39.069196   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:09:52.077837   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:10:09.725287   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:10:30.648741   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:11:01.665508   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
E0815 15:11:46.822735   11955 workload_cluster.go:354]  "msg"="unable to get kubeadmConfigMap" "error"="error getting kube-system/kubeadm-config configmap from target cluster: configmaps \"kubeadm-config\" not found"  
=== RUN   TestRemoveMachineFromKubeadmConfigMap/returns_error_if_unable_to_remove_api_endpoint_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/removes_the_machine_node_ref_from_kubeadm_config_for_Kubernetes_version_<_1.22.0
=== RUN   TestRemoveMachineFromKubeadmConfigMap/no_op_for_Kubernetes_version_>=_1.22.0
--- PASS: TestRemoveMachineFromKubeadmConfigMap (172.67s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_is_nil (0.00s)
    --- PASS: TestRemoveMachineFromKubeadmConfigMap/does_not_panic_if_machine_noderef_is_nil (0.00s)
... skipping 84 lines ...
    --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_<_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.22.0 (0.00s)
    --- PASS: TestIsKubernetesVersionSupported/management_cluster_and_version_>=_v1.23.0 (0.00s)
PASS
I0815 15:11:46.831854   11955 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0815 15:11:46.832496   11955 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0815 15:11:46.832541   11955 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-263963049/tls.crt: no such file or directory"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	187.166s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
PASS
... skipping 287 lines ...
I0815 15:09:02.655929   12305 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0815 15:09:02.656964   12305 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0815 15:09:02.757476   12305 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0815 15:09:02.857948   12305 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0815 15:09:02.858044   12305 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0815 15:09:02.951004   12305 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-fo3qit"} 
E0815 15:09:02.980453   12305 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"
•I0815 15:09:04.031515   12305 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-fnkrt9"} 
•E0815 15:09:04.084643   12305 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"
E0815 15:09:05.152658   12305 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get data field from the resource" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
•E0815 15:09:06.175894   12305 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"
E0815 15:09:07.303529   12305 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"
•E0815 15:09:08.341049   12305 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"
•I0815 15:09:09.359648   12305 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0815 15:09:09.359715   12305 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0815 15:09:09.359738   12305 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
E0815 15:09:09.360774   12305 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E0815 15:09:09.360849   12305 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-234208235/tls.crt: no such file or directory"  
E0815 15:09:09.364535   12305 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"


Ran 5 of 5 Specs in 20.606 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (20.61s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/addons/controllers	20.708s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
... skipping 61 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0815 15:08:51.660064   12468 machinepool_controller_phases.go:237]  "msg"="MachinePool infrastructure reference has been deleted after being ready, setting failure state" "error"="could not find infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureConfig \"infra-config1\" for MachinePool \"machinepool-test\" in namespace \"default\", requeuing: failed to retrieve InfrastructureConfig external object \"default\"/\"infra-config1\": infrastructureconfigs.infrastructure.cluster.x-k8s.io \"infra-config1\" not found" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
=== RUN   TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused
--- PASS: TestReconcileMachinePoolInfrastructure (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileMachinePoolInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestMachinePoolFinalizer
... skipping 96 lines ...
•I0815 15:09:04.342448   12468 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}}}
I0815 15:09:04.409555   12468 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••I0815 15:09:04.417037   12468 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 9 of 9 Specs in 12.715 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (12.72s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	13.060s
?   	sigs.k8s.io/cluster-api/exp/util	[no test files]
?   	sigs.k8s.io/cluster-api/feature	[no test files]
?   	sigs.k8s.io/cluster-api/hack/boilerplate/test	[no test files]
... skipping 266 lines ...
--- PASS: TestGetFirstReasonAndMessage (0.00s)
=== RUN   TestNewConditionsGroup
--- PASS: TestNewConditionsGroup (0.00s)
=== RUN   TestMergeRespectPriority
=== RUN   TestMergeRespectPriority/aggregate_nil_list_return_nil
=== RUN   TestMergeRespectPriority/aggregate_empty_list_return_nil
=== RUN   TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error
=== RUN   TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning
=== RUN   TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info
=== RUN   TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info
=== RUN   TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown
=== RUN   TestMergeRespectPriority/nil_conditions_are_ignored
--- PASS: TestMergeRespectPriority (0.00s)
    --- PASS: TestMergeRespectPriority/aggregate_nil_list_return_nil (0.00s)
    --- PASS: TestMergeRespectPriority/aggregate_empty_list_return_nil (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/error_it_returns_false/error (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/warning_and_no_false/error,_it_returns_false/warning (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_false/info_and_no_false/error_or_false/warning,_it_returns_false/info (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_true_and_no_false/*,_it_returns_info (0.00s)
    --- PASS: TestMergeRespectPriority/When_there_is_unknown_and_no_true_or_false/*,_it_returns_unknown (0.00s)
    --- PASS: TestMergeRespectPriority/nil_conditions_are_ignored (0.00s)
=== RUN   TestNewPatch
=== RUN   TestNewPatch/No_changes_return_empty_patch
... skipping 200 lines ...
I0815 15:09:30.026361   15352 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1alpha3","Kind":"ClusterResourceSet"} "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0815 15:09:30.026382   15352 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0815 15:09:30.026548   15352 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0815 15:09:30.027515   15352 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0815 15:09:30.027900   15352 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=40407
I0815 15:09:30.028014   15352 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
••••••••••••••E0815 15:09:30.919856   15352 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0815 15:09:30.919925   15352 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-304947028/tls.crt: no such file or directory"  
E0815 15:09:30.919948   15352 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0815 15:09:30.919982   15352 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-304947028/tls.crt: no such file or directory"  
I0815 15:09:30.920199   15352 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


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