This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2022-07-29 14:59
Elapsed5m27s
Revisionrelease-0.3

No Test Failures!


Error lines from build-log.txt

... skipping 773 lines ...
I0729 15:02:33.792076    8507 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I0729 15:02:33.792255    8507 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I0729 15:02:33.793206    8507 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I0729 15:02:33.793413    8507 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=33935
I0729 15:02:33.793640    8507 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0729 15:02:34.294187    8507 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" 
•E0729 15:02:34.322597    8507 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
I0729 15:02:34.322654    8507 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0729 15:02:34.322666    8507 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-149560585/tls.crt: no such file or directory"  


Ran 1 of 1 Specs in 13.633 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.65s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	51.169s
=== RUN   TestNewInitControlPlaneAdditionalFileEncodings
--- PASS: TestNewInitControlPlaneAdditionalFileEncodings (0.00s)
=== RUN   TestNewInitControlPlaneCommands
... skipping 316 lines ...
=== RUN   Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined
--- PASS: Test_clusterctlClient_GetProvidersConfig (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers (0.00s)
    --- PASS: Test_clusterctlClient_GetProvidersConfig/Returns_default_providers_and_custom_providers_if_defined (0.00s)
=== RUN   Test_clusterctlClient_GetProviderComponents
=== RUN   Test_clusterctlClient_GetProviderComponents/Pass
=== RUN   Test_clusterctlClient_GetProviderComponents/Fail
--- PASS: Test_clusterctlClient_GetProviderComponents (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Pass (0.00s)
    --- PASS: Test_clusterctlClient_GetProviderComponents/Fail (0.00s)
=== RUN   Test_getComponentsByName_withEmptyVariables
--- PASS: Test_getComponentsByName_withEmptyVariables (0.00s)
=== RUN   Test_clusterctlClient_templateOptionsToVariables
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_template_options)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_KubernetesVersion_from_env_variables)
=== RUN   Test_clusterctlClient_templateOptionsToVariables/pass_(using_defaults_for_machine_counts)
... skipping 1398 lines ...
I0729 15:02:14.744418   10530 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machineset" "worker count"=1
I0729 15:02:14.744687   10530 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0729 15:02:14.747167   10530 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"clusterName":"","bootstrap":{},"infrastructureRef":{}},"status":{"bootstrapReady":false,"infrastructureReady":false}}}
I0729 15:02:14.747243   10530 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I0729 15:02:14.747277   10530 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinehealthcheck" 
I0729 15:02:14.747310   10530 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinehealthcheck" "worker count"=1
2022/07/29 15:02:14 http: TLS handshake error from 127.0.0.1:58670: EOF
=== RUN   TestClusterReconcilePhases
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I0729 15:02:14.940740   10530 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "cluster"="test-cluster" "namespace"="test-namespace" "err"="cannot create a metadata client without a rest config"
I0729 15:02:14.944169   10530 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
... skipping 105 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I0729 15:02:14.985717   10530 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
I0729 15:02:14.988255   10530 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"
E0729 15:02:14.988696   10530 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
I0729 15:02:14.989406   10530 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine-test" "namespace"="default" "err"="cannot create a metadata client without a rest config"
--- PASS: TestReconcileInfrastructure (0.00s)
    --- PASS: TestReconcileInfrastructure/new_machine,_infrastructure_config_ready (0.00s)
    --- PASS: TestReconcileInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machine_is_running,_infra_object_is_deleted,_expect_failed (0.00s)
    --- PASS: TestReconcileInfrastructure/infrastructure_ref_is_paused (0.00s)
=== RUN   TestWatches
I0729 15:02:15.240219   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E0729 15:02:15.258526   10530 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I0729 15:02:15.265017   10530 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-b7pgr" "namespace"="test-machine-watches-4wwn4" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I0729 15:02:15.265163   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I0729 15:02:15.378080   10530 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-b7pgr" "namespace"="test-machine-watches-4wwn4" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I0729 15:02:15.378178   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I0729 15:02:15.478726   10530 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-b7pgr" "namespace"="test-machine-watches-4wwn4" "noderef"="node-1"
E0729 15:02:15.486256   10530 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0729 15:02:15.486307   10530 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E0729 15:02:15.523967   10530 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-b7pgr\" in namespace \"test-machine-watches-4wwn4\", requeuing: requeue in 1s"  
E0729 15:02:15.533921   10530 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-b7pgr\" in namespace \"test-machine-watches-4wwn4\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-b7pgr\" in namespace \"test-machine-watches-4wwn4\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-b7pgr" "namespace"="test-machine-watches-4wwn4"
--- PASS: TestWatches (0.61s)
=== 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
I0729 15:02:15.784313   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-49vl6" "namespace"="test-machine-watches-4wwn4" "count"=1
I0729 15:02:15.784381   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-49vl6" "namespace"="test-machine-watches-4wwn4" "descendants"="Worker machines: machine-created-b7pgr" "indirect descendants count"=0
I0729 15:02:15.798478   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-49vl6" "namespace"="test-machine-watches-4wwn4" "count"=1
I0729 15:02:15.798548   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-49vl6" "namespace"="test-machine-watches-4wwn4" "descendants"="Worker machines: machine-created-b7pgr" "indirect descendants count"=0
I0729 15:02:16.534433   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-49vl6" "machine"="machine-created-b7pgr" "namespace"="test-machine-watches-4wwn4" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"fc0e9f11-eed7-4cf9-b38d-e844792d770e","apiVersion":"v1"}
E0729 15:02:16.588918   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-b7pgr\" not found" "controller"="machine" "name"="machine-created-b7pgr" "namespace"="test-machine-watches-4wwn4"
E0729 15:02:17.628547   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-d9cbl\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-fthn8\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-fthn8: secrets \"machine-reconcile-fthn8-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-d9cbl" "namespace"="default"
I0729 15:02:18.629092   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fthn8" "machine"="machine-created-d9cbl" "namespace"="default" "cause"="noderef is nil" "node"=null
I0729 15:02:18.658529   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fthn8" "machine"="machine-created-d9cbl" "namespace"="default" "cause"="noderef is nil" "node"=null
I0729 15:02:18.690947   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-fthn8" "machine"="machine-created-d9cbl" "namespace"="default" "cause"="noderef is nil" "node"=null
E0729 15:02:18.728574   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-d9cbl\" not found" "controller"="machine" "name"="machine-created-d9cbl" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.13s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.13s)
=== 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 37 lines ...
I0729 15:02:18.801223   10530 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="blah" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0729 15:02:18.802250   10530 machine_controller_phases.go:278]  "msg"="Infrastructure provider is not ready, requeuing" "machine"="blah" "namespace"="default" 
=== RUN   TestMachineConditions/bootstrap_condition_consumes_reason_from_the_bootstrap_config
I0729 15:02:18.827466   10530 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="blah" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0729 15:02:18.833488   10530 machine_controller_phases.go:219]  "msg"="Bootstrap provider is not ready, requeuing" "machine"="blah" "namespace"="default" 
I0729 15:02:18.833557   10530 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="blah" "namespace"="default" "err"="cannot create a metadata client without a rest config"
E0729 15:02:18.837020   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-fthn8\" not found" "controller"="cluster" "name"="machine-reconcile-fthn8" "namespace"="default"
=== RUN   TestMachineConditions/bootstrap_condition_consumes_the_fallback_reason
I0729 15:02:18.843705   10530 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="blah" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I0729 15:02:18.844692   10530 machine_controller_phases.go:219]  "msg"="Bootstrap provider is not ready, requeuing" "machine"="blah" "namespace"="default" 
I0729 15:02:18.844759   10530 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="blah" "namespace"="default" "err"="cannot create a metadata client without a rest config"
=== RUN   TestMachineConditions/ready_condition_summary_consumes_reason_from_the_infra_condition
I0729 15:02:18.849627   10530 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="blah" "namespace"="default" "err"="cannot create a metadata client without a rest config"
... skipping 88 lines ...
    --- PASS: TestMachineDeploymentSyncStatus/machine_set_failed (0.00s)
=== RUN   TestMachineHealthCheck_Reconcile
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist
I0729 15:02:18.995350   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9tdjc" "namespace"="test-mhc-gl8nm" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
I0729 15:02:19.052797   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E0729 15:02:19.057597   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-458hf\" not found"  "cluster"="test-mhc-gl8nm/test-cluster-458hf"
E0729 15:02:19.066448   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-9tdjc\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-9tdjc\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-9tdjc" "namespace"="test-mhc-gl8nm"
=== 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
I0729 15:02:20.066784   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9tdjc" "namespace"="test-mhc-gl8nm" 
I0729 15:02:20.066901   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rvdqt" "namespace"="test-mhc-nkcgs" 
I0729 15:02:20.066931   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-d24gk" "namespace"="test-mhc-hkbw7" 
I0729 15:02:20.066958   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9bhf8" "namespace"="test-mhc-l6pc5" 
I0729 15:02:20.080971   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0729 15:02:20.117614   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9bhf8" "namespace"="test-mhc-l6pc5" 
I0729 15:02:20.119058   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9bhf8" "namespace"="test-mhc-l6pc5" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
I0729 15:02:20.208876   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-9bhf8" "namespace"="test-mhc-l6pc5" 
E0729 15:02:20.249998   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-l6pc5/test-cluster-pfvxp"
E0729 15:02:20.254220   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-pfvxp\" not found" "controller"="cluster" "name"="test-cluster-pfvxp" "namespace"="test-mhc-l6pc5"
I0729 15:02:20.258373   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p8gh7" "namespace"="test-mhc-pbwng" 
I0729 15:02:20.283372   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0729 15:02:20.305772   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p8gh7" "namespace"="test-mhc-pbwng" 
I0729 15:02:20.306490   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p8gh7" "namespace"="test-mhc-pbwng" 
E0729 15:02:20.363503   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-pbwng/test-cluster-cmc5q"
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I0729 15:02:20.368684   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-p8gh7" "namespace"="test-mhc-pbwng" 
I0729 15:02:20.491380   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
inframachine created: test-mhc-machine-infra-rg7pf
machine created: test-mhc-machine-5psgb
I0729 15:02:20.520472   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0729 15:02:20.542902   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.543249   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-5psgb/"
I0729 15:02:20.603807   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.604151   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-5psgb/"
I0729 15:02:20.626269   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.626641   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-5psgb/"
node created: test-mhc-node-r876k
E0729 15:02:20.628428   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-r876k, got []"  "node"="test-mhc-node-r876k"
E0729 15:02:20.628618   10530 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-r876k"
I0729 15:02:20.654480   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
inframachine created: test-mhc-machine-infra-tczgf
machine created: test-mhc-machine-wm5v4
I0729 15:02:20.714956   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.727101   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.728346   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.729490   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.730674   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.731693   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.734111   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.734461   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
I0729 15:02:20.746635   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.747068   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
I0729 15:02:20.754933   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.755377   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
I0729 15:02:20.762525   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.763120   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
I0729 15:02:20.768195   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.768604   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
I0729 15:02:20.791794   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.792524   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
node created: test-mhc-node-q4l97
E0729 15:02:20.802912   10530 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-q4l97"
E0729 15:02:20.803475   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-q4l97, got []"  "node"="test-mhc-node-q4l97"
I0729 15:02:20.804737   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.805172   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
I0729 15:02:20.810627   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.812044   10530 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-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
I0729 15:02:20.816209   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.826778   10530 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz" "noderef"="test-mhc-node-q4l97"
I0729 15:02:20.843446   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.847947   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
Cleaning up nodes, machines and infra machines.
I0729 15:02:20.854120   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.854568   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-b7mfz/test-mhc-w59ks/test-mhc-machine-5psgb/"
I0729 15:02:20.892199   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:20.892749   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-b7mfz/test-mhc-w59ks/test-mhc-machine-5psgb/"
I0729 15:02:20.893209   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-b7mfz/test-mhc-w59ks/test-mhc-machine-wm5v4/"
E0729 15:02:20.910551   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
E0729 15:02:20.919561   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-b7mfz/test-cluster-rcp45"
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E0729 15:02:21.049979   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-w59ks\" not found" "controller"="machinehealthcheck" "name"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz"
inframachine created: test-mhc-machine-infra-wdhgx
machine created: test-mhc-machine-2rbz8
E0729 15:02:21.266956   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-4wwn4/machine-reconcile-49vl6"
E0729 15:02:21.910904   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:22.050253   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.068516   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0729 15:02:22.112231   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-w59ks" "namespace"="test-mhc-b7mfz" 
I0729 15:02:22.112478   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.114530   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.122327   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
... skipping 342 lines ...
I0729 15:02:22.900796   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.902480   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.904568   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.906230   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.907893   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.909575   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
E0729 15:02:22.911218   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:22.911282   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.912964   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.914765   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.916489   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.918167   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:22.919822   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
... skipping 485 lines ...
I0729 15:02:23.914395   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:23.916376   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:23.919753   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:23.920629   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:23.921672   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:23.924228   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
E0729 15:02:23.924487   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:23.924900   10530 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-nslqz/test-mhc-rbr4t/test-mhc-machine-2rbz8/"
I0729 15:02:23.936823   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:23.937148   10530 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-nslqz/test-mhc-rbr4t/test-mhc-machine-2rbz8/"
E0729 15:02:24.011451   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-tc9cc, got []"  "node"="test-mhc-node-tc9cc"
node created: test-mhc-node-tc9cc
I0729 15:02:24.018516   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
inframachine created: test-mhc-machine-infra-lpk42
machine created: test-mhc-machine-s5pwb
I0729 15:02:24.042266   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.048569   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
... skipping 286 lines ...
I0729 15:02:24.903525   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.905668   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.909021   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.918082   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.920404   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.924288   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
E0729 15:02:24.924817   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:24.927137   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.929197   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.931269   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.933274   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.935301   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:24.937329   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
... skipping 414 lines ...
I0729 15:02:25.953775   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.955871   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.964598   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.967173   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.968375   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.969758   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
E0729 15:02:25.973641   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:25.973718   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.974775   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.976921   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.978995   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.981157   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:25.983287   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
... skipping 319 lines ...
I0729 15:02:26.975423   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:26.977479   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:26.979689   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:26.981814   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:26.982785   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:26.984839   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
E0729 15:02:26.984994   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:26.985884   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:26.986223   10530 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-nslqz/test-mhc-rbr4t/test-mhc-machine-s5pwb/"
I0729 15:02:26.996276   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:26.996703   10530 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-nslqz/test-mhc-rbr4t/test-mhc-machine-s5pwb/"
E0729 15:02:27.067465   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-cvkxt, got []"  "node"="test-mhc-node-cvkxt"
node created: test-mhc-node-cvkxt
I0729 15:02:27.083726   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
inframachine created: test-mhc-machine-infra-b2ndz
machine created: test-mhc-machine-9vhzq
I0729 15:02:27.106159   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:27.136524   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
... skipping 239 lines ...
I0729 15:02:27.980159   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:27.982954   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:27.985725   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:27.989138   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:27.992104   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:27.995757   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
E0729 15:02:27.998060   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:27.999109   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:28.000763   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:28.002889   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:28.025153   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:28.027429   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:28.029390   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
... skipping 279 lines ...
I0729 15:02:29.009717   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.012129   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.014235   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.021715   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.023677   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.025822   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
E0729 15:02:29.047007   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:29.047568   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.049019   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.050857   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.052661   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.054273   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:29.055835   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
... skipping 317 lines ...
I0729 15:02:30.044173   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.046727   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.052164   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.054971   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.063422   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.067208   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.067867   10530 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-nslqz/test-mhc-rbr4t/test-mhc-machine-9vhzq/"
E0729 15:02:30.071550   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:30.084047   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.084668   10530 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-nslqz/test-mhc-rbr4t/test-mhc-machine-9vhzq/"
E0729 15:02:30.129151   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-q8wmx, got []"  "node"="test-mhc-node-q8wmx"
node created: test-mhc-node-q8wmx
Cleaning up nodes, machines and infra machines.
I0729 15:02:30.137404   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.137945   10530 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-nslqz/test-mhc-rbr4t/test-mhc-machine-9vhzq/test-mhc-node-q8wmx"
Cleaning up nodes, machines and infra machines.
I0729 15:02:30.159022   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:30.159563   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-nslqz/test-mhc-rbr4t/test-mhc-machine-2rbz8/"
I0729 15:02:30.209030   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-dzcb2" "namespace"="test-mhc-nslqz" "count"=2
I0729 15:02:30.209130   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dzcb2" "namespace"="test-mhc-nslqz" "descendants"="Worker machines: test-mhc-machine-s5pwb,test-mhc-machine-9vhzq,test-mhc-machine-2rbz8" "indirect descendants count"=1
I0729 15:02:30.213392   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-dzcb2" "namespace"="test-mhc-nslqz" "count"=2
I0729 15:02:30.213454   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dzcb2" "namespace"="test-mhc-nslqz" "descendants"="Worker machines: test-mhc-machine-9vhzq,test-mhc-machine-2rbz8,test-mhc-machine-s5pwb" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
inframachine created: test-mhc-machine-infra-82mdb
machine created: test-mhc-machine-hcvln
I0729 15:02:30.383826   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-nslqz/test-mhc-rbr4t/test-mhc-machine-9vhzq/"
E0729 15:02:30.409516   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-rbr4t\" not found" "controller"="machinehealthcheck" "name"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz"
I0729 15:02:31.072248   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-dzcb2" "machine"="test-mhc-machine-s5pwb" "namespace"="test-mhc-nslqz" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-cvkxt"}
E0729 15:02:31.132996   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-s5pwb\" not found" "controller"="machine" "name"="test-mhc-machine-s5pwb" "namespace"="test-mhc-nslqz"
I0729 15:02:31.409820   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:31.432184   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0729 15:02:31.484856   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-rbr4t" "namespace"="test-mhc-nslqz" 
I0729 15:02:31.484948   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:31.491355   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:31.502025   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:31.548035   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:31.629233   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:31.791931   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:32.113006   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:32.134240   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:32.754080   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:33.134749   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-dzcb2" "machine"="test-mhc-machine-9vhzq" "namespace"="test-mhc-nslqz" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-q8wmx"}
E0729 15:02:33.184651   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9vhzq\" not found" "controller"="machine" "name"="test-mhc-machine-9vhzq" "namespace"="test-mhc-nslqz"
I0729 15:02:34.035162   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:34.189548   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:35.190112   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-dzcb2" "machine"="test-mhc-machine-2rbz8" "namespace"="test-mhc-nslqz" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-tc9cc"}
I0729 15:02:35.213276   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-dzcb2" "namespace"="test-mhc-nslqz" "count"=1
I0729 15:02:35.213375   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-dzcb2" "namespace"="test-mhc-nslqz" "descendants"="Worker machines: test-mhc-machine-2rbz8" "indirect descendants count"=0
E0729 15:02:35.303388   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2rbz8\" not found" "controller"="machine" "name"="test-mhc-machine-2rbz8" "namespace"="test-mhc-nslqz"
I0729 15:02:36.317757   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:36.323793   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:36.324317   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:36.348087   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
node created: test-mhc-node-862r9
E0729 15:02:36.386319   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-862r9, got []"  "node"="test-mhc-node-862r9"
E0729 15:02:36.388190   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-862r9, got []"  "node"="test-mhc-node-862r9"
I0729 15:02:36.398704   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
inframachine created: test-mhc-machine-infra-n6746
machine created: test-mhc-machine-skrwv
I0729 15:02:36.424063   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:36.443145   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:36.448292   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:36.469509   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:36.511923   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:36.599781   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:36.762919   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:37.085516   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:37.324267   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:37.726798   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.336989   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.339488   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.346300   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.369772   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.375358   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.383302   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.386401   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:38.388233   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:38.407374   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:38.433747   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-5fb46, got []"  "node"="test-mhc-node-5fb46"
E0729 15:02:38.433970   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-5fb46, got []"  "node"="test-mhc-node-5fb46"
node created: test-mhc-node-5fb46
I0729 15:02:38.440834   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
inframachine created: test-mhc-machine-infra-sgrqv
I0729 15:02:38.453902   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
machine created: test-mhc-machine-hvnzz
I0729 15:02:38.461543   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.471756   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:38.473141   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:39.008697   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:39.388697   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
E0729 15:02:40.227019   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-nslqz/test-cluster-dzcb2"
I0729 15:02:40.401860   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:40.425354   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:40.434743   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:40.444754   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:40.452322   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
I0729 15:02:40.458869   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:40.462048   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:40.462514   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
E0729 15:02:40.472390   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hq25n, got []"  "node"="test-mhc-node-hq25n"
node created: test-mhc-node-hq25n
I0729 15:02:40.491662   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
Cleaning up nodes, machines and infra machines.
I0729 15:02:40.503649   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-wb8c2" "namespace"="test-mhc-txkf2" 
Cleaning up nodes, machines and infra machines.
I0729 15:02:40.545119   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-hldrb" "namespace"="test-mhc-txkf2" "count"=2
... skipping 5 lines ...
I0729 15:02:40.681301   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
inframachine created: test-mhc-machine-infra-7hskn
I0729 15:02:40.700885   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-gftm2
I0729 15:02:40.723163   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:40.730100   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
E0729 15:02:41.466091   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:42.466645   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hldrb" "machine"="test-mhc-machine-hcvln" "namespace"="test-mhc-txkf2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-862r9"}
E0729 15:02:42.534729   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-hcvln\" not found" "controller"="machine" "name"="test-mhc-machine-hcvln" "namespace"="test-mhc-txkf2"
I0729 15:02:43.535296   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hldrb" "machine"="test-mhc-machine-skrwv" "namespace"="test-mhc-txkf2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-5fb46"}
E0729 15:02:43.595991   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-skrwv\" not found" "controller"="machine" "name"="test-mhc-machine-skrwv" "namespace"="test-mhc-txkf2"
I0729 15:02:44.596476   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-hldrb" "machine"="test-mhc-machine-hvnzz" "namespace"="test-mhc-txkf2" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-hq25n"}
E0729 15:02:44.652747   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-hvnzz\" not found" "controller"="machine" "name"="test-mhc-machine-hvnzz" "namespace"="test-mhc-txkf2"
E0729 15:02:45.572199   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-txkf2/test-cluster-hldrb"
I0729 15:02:45.660811   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
E0729 15:02:45.665076   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:45.665105   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
E0729 15:02:45.720599   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-lhhl5, got []"  "node"="test-mhc-node-lhhl5"
node created: test-mhc-node-lhhl5
I0729 15:02:45.727136   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
inframachine created: test-mhc-machine-infra-td6ts
machine created: test-mhc-machine-d7wbf
I0729 15:02:45.743903   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:45.750849   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
E0729 15:02:46.666016   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:47.685221   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.691525   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.705977   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.710906   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.719661   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.724619   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.736469   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.750437   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
E0729 15:02:47.762664   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pwdzx, got []"  "node"="test-mhc-node-pwdzx"
node created: test-mhc-node-pwdzx
I0729 15:02:47.768537   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.773953   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.780429   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
inframachine created: test-mhc-machine-infra-5hc7p
machine created: test-mhc-machine-mqtt5
... skipping 8 lines ...
Cleaning up nodes, machines and infra machines.
I0729 15:02:47.903129   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.904220   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-fdh6w" "machine"="test-mhc-machine-mqtt5" "namespace"="test-mhc-fg7c6" "cause"="noderef is nil" "node"=null
Cleaning up nodes, machines and infra machines.
I0729 15:02:47.917908   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.930711   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.931454   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-fg7c6/test-mhc-tdnvs/test-mhc-machine-gftm2/"
I0729 15:02:47.951993   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:47.952656   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-fg7c6/test-mhc-tdnvs/test-mhc-machine-gftm2/"
I0729 15:02:47.953121   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-fg7c6/test-mhc-tdnvs/test-mhc-machine-d7wbf/"
E0729 15:02:47.971972   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-mqtt5\" not found" "controller"="machine" "name"="test-mhc-machine-mqtt5" "namespace"="test-mhc-fg7c6"
I0729 15:02:47.977705   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-fdh6w" "namespace"="test-mhc-fg7c6" "count"=2
I0729 15:02:47.977781   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-fdh6w" "namespace"="test-mhc-fg7c6" "descendants"="Worker machines: test-mhc-machine-gftm2,test-mhc-machine-d7wbf" "indirect descendants count"=0
I0729 15:02:47.981643   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-fdh6w" "namespace"="test-mhc-fg7c6" "count"=2
I0729 15:02:47.981703   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-fdh6w" "namespace"="test-mhc-fg7c6" "descendants"="Worker machines: test-mhc-machine-gftm2,test-mhc-machine-d7wbf" "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
inframachine created: test-mhc-machine-infra-5wxd2
machine created: test-mhc-machine-tj2f8
E0729 15:02:48.147868   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-tdnvs\" not found" "controller"="machinehealthcheck" "name"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6"
I0729 15:02:48.972507   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-fdh6w" "machine"="test-mhc-machine-gftm2" "namespace"="test-mhc-fg7c6" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-lhhl5"}
E0729 15:02:49.029333   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-gftm2\" not found" "controller"="machine" "name"="test-mhc-machine-gftm2" "namespace"="test-mhc-fg7c6"
I0729 15:02:49.148171   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:49.166705   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0729 15:02:49.195856   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tdnvs" "namespace"="test-mhc-fg7c6" 
I0729 15:02:49.195939   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:49.197052   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:49.197689   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
... skipping 452 lines ...
I0729 15:02:50.071944   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.073628   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.075346   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.077406   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.079220   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.081134   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
E0729 15:02:50.082963   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-d7wbf\" not found" "controller"="machine" "name"="test-mhc-machine-d7wbf" "namespace"="test-mhc-fg7c6"
I0729 15:02:50.083036   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.085351   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.087037   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.088686   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.090344   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:50.092298   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
... skipping 431 lines ...
I0729 15:02:51.093352   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.094028   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.095756   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.097494   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.103600   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.105976   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
E0729 15:02:51.107252   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:51.107271   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.107507   10530 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-5cr7l/test-mhc-t7bng/test-mhc-machine-tj2f8/"
I0729 15:02:51.119473   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.119808   10530 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-5cr7l/test-mhc-t7bng/test-mhc-machine-tj2f8/"
node created: test-mhc-node-qxpzx
E0729 15:02:51.148627   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-qxpzx, got []"  "node"="test-mhc-node-qxpzx"
E0729 15:02:51.148633   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-qxpzx, got []"  "node"="test-mhc-node-qxpzx"
I0729 15:02:51.155022   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.179443   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.189609   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.190126   10530 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-5cr7l/test-mhc-t7bng/test-mhc-machine-tj2f8/test-mhc-node-qxpzx"
I0729 15:02:51.206012   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.206422   10530 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-5cr7l/test-mhc-t7bng/test-mhc-machine-tj2f8/test-mhc-node-qxpzx"
Cleaning up nodes, machines and infra machines.
I0729 15:02:51.213926   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.214293   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-5cr7l/test-mhc-t7bng/test-mhc-machine-tj2f8/"
I0729 15:02:51.230255   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2jn8r" "namespace"="test-mhc-5cr7l" "descendants"="Worker machines: test-mhc-machine-tj2f8" "indirect descendants count"=1
I0729 15:02:51.234324   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-2jn8r" "namespace"="test-mhc-5cr7l" "descendants"="Worker machines: test-mhc-machine-tj2f8" "indirect descendants count"=1
I0729 15:02:51.236347   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I0729 15:02:51.236847   10530 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-5cr7l/test-mhc-t7bng/test-mhc-machine-tj2f8/"
I0729 15:02:51.238013   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-t7bng" "namespace"="test-mhc-5cr7l" 
I0729 15:02:51.432271   10530 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-fpk2h" "namespace"="test-mhc-5b66c" "creating"=1 "need"=1
I0729 15:02:51.432318   10530 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-fpk2h" "namespace"="test-mhc-5b66c" 
I0729 15:02:51.444806   10530 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-fpk2h-vb6bs\"" "machineset"="mhc-ms-fpk2h" "namespace"="test-mhc-5b66c" 
I0729 15:02:51.521198   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:51.552356   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I0729 15:02:51.569934   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
E0729 15:02:52.107669   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:52.570125   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
E0729 15:02:52.998902   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-fg7c6/test-cluster-fdh6w"
I0729 15:02:53.108221   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-2jn8r" "machine"="test-mhc-machine-tj2f8" "namespace"="test-mhc-5cr7l" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-qxpzx"}
E0729 15:02:53.189348   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-tj2f8\" not found" "controller"="machine" "name"="test-mhc-machine-tj2f8" "namespace"="test-mhc-5cr7l"
I0729 15:02:53.572127   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:54.199710   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:54.199774   10530 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-fpk2h" "namespace"="test-mhc-5b66c" 
I0729 15:02:54.204038   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:54.204114   10530 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-fpk2h" "namespace"="test-mhc-5b66c" 
I0729 15:02:54.219050   10530 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
... skipping 7 lines ...
I0729 15:02:54.251654   10530 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
I0729 15:02:54.251699   10530 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
I0729 15:02:54.573155   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:55.239914   10530 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
I0729 15:02:55.239963   10530 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.000667   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.001157   10530 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-5b66c/test-mhc-n88sd/mhc-ms-fpk2h-vb6bs/"
I0729 15:02:56.008838   10530 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-fpk2h" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.014639   10530 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.014690   10530 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.016561   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.016886   10530 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-5b66c/test-mhc-n88sd/mhc-ms-fpk2h-vb6bs/"
I0729 15:02:56.030421   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.030734   10530 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-fpk2h" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.030798   10530 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-5b66c/test-mhc-n88sd/mhc-ms-fpk2h-vb6bs/"
I0729 15:02:56.042876   10530 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.042923   10530 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.098955   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-w8fp2" "namespace"="test-mhc-5b66c" "count"=1
I0729 15:02:56.099019   10530 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-w8fp2" "namespace"="test-mhc-5b66c" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-fpk2h"
I0729 15:02:56.100331   10530 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-fpk2h" "namespace"="test-mhc-5b66c" "machine"="mhc-ms-fpk2h-vb6bs"
I0729 15:02:56.105027   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-n88sd" "namespace"="test-mhc-5b66c" 
I0729 15:02:56.107056   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-w8fp2" "namespace"="test-mhc-5b66c" "descendants"="Machine sets: mhc-ms-fpk2h;Worker machines: mhc-ms-fpk2h-vb6bs" "indirect descendants count"=1
I0729 15:02:56.108554   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-w8fp2" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" "cause"="cluster is being deleted" "node"=null
I0729 15:02:56.112679   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-w8fp2" "namespace"="test-mhc-5b66c" "descendants"="Worker machines: mhc-ms-fpk2h-vb6bs" "indirect descendants count"=1
=== RUN   TestMachineHealthCheck_Reconcile/when_a_machine_is_paused
=== RUN   TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created
E0729 15:02:56.247072   10530 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-5cr7l/test-cluster-2jn8r"
I0729 15:02:56.259993   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
inframachine created: test-mhc-machine-infra-l2zl9
I0729 15:02:56.275146   10530 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
machine created: test-mhc-machine-7cgnd
E0729 15:02:56.325171   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-5psgb\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-5psgb" "namespace"="test-mhc-b7mfz"
I0729 15:02:56.395911   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:56.409127   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:56.410767   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:56.412987   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:56.415614   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:56.417402   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
... skipping 429 lines ...
I0729 15:02:57.332788   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.333515   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.334527   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.336803   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.337415   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.337524   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-w8fp2" "machine"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c" "cause"="cluster is being deleted" "node"=null
E0729 15:02:57.362680   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-fpk2h-vb6bs\" not found" "controller"="machine" "name"="mhc-ms-fpk2h-vb6bs" "namespace"="test-mhc-5b66c"
I0729 15:02:57.381177   10530 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-7cgnd" "target"="test-mhc-7q5vs/test-mhc-j2dfj/test-mhc-machine-7cgnd/"
E0729 15:02:57.387263   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c7cth, got []"  "node"="test-mhc-node-c7cth"
node created: test-mhc-node-c7cth
E0729 15:02:57.387503   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-c7cth, got []"  "node"="test-mhc-node-c7cth"
I0729 15:02:57.398314   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.439794   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.445461   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.448915   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.451834   10530 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-7cgnd" "target"="test-mhc-7q5vs/test-mhc-j2dfj/test-mhc-machine-7cgnd/test-mhc-node-c7cth"
I0729 15:02:57.466782   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
Cleaning up nodes, machines and infra machines.
I0729 15:02:57.474232   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.476556   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.480584   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-j2dfj" "namespace"="test-mhc-7q5vs" 
I0729 15:02:57.484400   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-k2v7s" "namespace"="test-mhc-7q5vs" "descendants"="Worker machines: test-mhc-machine-7cgnd" "indirect descendants count"=1
... skipping 392 lines ...
I0729 15:02:58.353672   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.355335   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.357133   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.358819   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.360541   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.362120   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
E0729 15:02:58.362953   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get cluster \"test-cluster-rcp45\" for machine \"test-mhc-machine-wm5v4\" in namespace \"test-mhc-b7mfz\": Cluster.cluster.x-k8s.io \"test-cluster-rcp45\" not found" "controller"="machine" "name"="test-mhc-machine-wm5v4" "namespace"="test-mhc-b7mfz"
I0729 15:02:58.363682   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.365288   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.366874   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.368421   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.369989   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:58.371640   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
... skipping 560 lines ...
I0729 15:02:59.400674   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.402475   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.404471   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.406194   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.407932   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.409855   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
E0729 15:02:59.410359   10530 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-7cgnd\" not found" "controller"="machine" "name"="test-mhc-machine-7cgnd" "namespace"="test-mhc-7q5vs"
I0729 15:02:59.412210   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.413964   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.415534   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.417467   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.419337   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:02:59.421281   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
... skipping 554 lines ...
I0729 15:03:00.414886   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.416580   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.418103   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.418748   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.419880   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.421644   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.424863   10530 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-g5qdn" "target"="test-mhc-dvbsg/test-mhc-kzhrz/test-mhc-machine-g5qdn/"
I0729 15:03:00.436418   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
node created: test-mhc-node-d9c7z
E0729 15:03:00.498102   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-d9c7z, got []"  "node"="test-mhc-node-d9c7z"
E0729 15:03:00.498132   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-d9c7z, got []"  "node"="test-mhc-node-d9c7z"
E0729 15:03:00.498181   10530 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-d9c7z, got []"  "node"="test-mhc-node-d9c7z"
I0729 15:03:00.503405   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.533554   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.541511   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.544670   10530 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-g5qdn" "target"="test-mhc-dvbsg/test-mhc-kzhrz/test-mhc-machine-g5qdn/test-mhc-node-d9c7z"
I0729 15:03:00.558649   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.566064   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.588177   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.591373   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.593921   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
Cleaning up nodes, machines and infra machines.
I0729 15:03:00.598828   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.601994   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.604945   10530 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-kzhrz" "namespace"="test-mhc-dvbsg" 
I0729 15:03:00.611575   10530 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-g5qdn" "target"="test-mhc-dvbsg/test-mhc-kzhrz/test-mhc-machine-g5qdn/"
I0729 15:03:00.614551   10530 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-zdqsg" "machine"="test-mhc-machine-g5qdn" "namespace"="test-mhc-dvbsg" "cause"="no control plane members" "node"={"name":"test-mhc-node-d9c7z"}
I0729 15:03:00.618832   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-zdqsg" "namespace"="test-mhc-dvbsg" "count"=1
I0729 15:03:00.618926   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-zdqsg" "namespace"="test-mhc-dvbsg" "descendants"="Worker machines: test-mhc-machine-g5qdn" "indirect descendants count"=0
I0729 15:03:00.628503   10530 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-zdqsg" "namespace"="test-mhc-dvbsg" "count"=1
I0729 15:03:00.628555   10530 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-zdqsg" "namespace"="test-mhc-dvbsg" "descendants"="Worker machines: test-mhc-machine-g5qdn" "indirect descendants count"=0
--- PASS: TestMachineHealthCheck_Reconcile (41.66s)
... skipping 15 lines ...
    --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s)
        machinehealthcheck_controller_test.go:933: skipping until made stable
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (1.36s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (3.14s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E0729 15:03:00.634980   10530 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
E0729 15:03:00.637249   10530 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
E0729 15:03:00.639546   10530 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E0729 15:03:00.640002   10530 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
E0729 15:03:00.640621   10530 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
I0729 15:03:00.645019   10530 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I0729 15:03:00.645766   10530 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E0729 15:03:00.648352   10530 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 9 lines ...
=== RUN   TestHealthCheckTargets
=== RUN   TestHealthCheckTargets/when_the_node_has_not_yet_started
=== RUN   TestHealthCheckTargets/when_the_node_has_gone_away
=== RUN   TestHealthCheckTargets/when_the_node_has_been_in_an_unknown_state_for_shorter_than_the_timeout
=== RUN   TestHealthCheckTargets/when_the_node_has_been_in_an_unknown_state_for_longer_than_the_timeout
=== RUN   TestHealthCheckTargets/when_the_node_is_healthy
fatal error: concurrent map read and map write

goroutine 1275 [running]:
runtime.throw(0x19d1121, 0x21)
	/usr/local/go/src/runtime/panic.go:774 +0x72 fp=0xc0008e5768 sp=0xc0008e5738 pc=0x4314c2
runtime.mapaccess2(0x177f3a0, 0xc000285650, 0xc0008e5828, 0x203000, 0x203000)
	/usr/local/go/src/runtime/map.go:470 +0x278 fp=0xc0008e57b0 sp=0xc0008e5768 pc=0x40fda8
... skipping 2948 lines ...

goroutine 9304 [select]:
k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch.func2(0xc0012960b0, 0xc00127c120, 0xc0006400c0, 0xc00034c3c0)
	/home/prow/go/pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:260 +0x178
created by k8s.io/client-go/tools/cache.(*Reflector).ListAndWatch
	/home/prow/go/pkg/mod/k8s.io/client-go@v0.17.9/tools/cache/reflector.go:254 +0x262
FAIL	sigs.k8s.io/cluster-api/controllers	58.018s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
--- PASS: TestCloneTemplateResourceNotFound (0.00s)
... skipping 259 lines ...
I0729 15:02:15.289825   10969 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=39199
I0729 15:02:15.289920   10969 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I0729 15:02:15.300634   10969 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}}}
I0729 15:02:15.501992   10969 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I0729 15:02:15.502054   10969 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I0729 15:02:15.720988   10969 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
E0729 15:02:17.757973   10969 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-sgjnt/test-cluster"
•E0729 15:02:18.206910   10969 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-pg2sr/test-cluster"
•E0729 15:02:18.758438   10969 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:33515/?timeout=50ms: dial tcp 127.0.0.1:33515: connect: connection refused"  "cluster"="cluster-cache-test-5wnkd/test-cluster"
•I0729 15:02:18.991977   10969 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":{}}}
I0729 15:02:19.192403   10969 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I0729 15:02:19.192470   10969 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I0729 15:02:19.192562   10969 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•E0729 15:02:19.721068   10969 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0729 15:02:19.721120   10969 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-865765238/tls.crt: no such file or directory"  
I0729 15:02:19.721171   10969 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0729 15:02:19.721406   10969 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
E0729 15:02:19.758552   10969 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:36203/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:36203: connect: connection refused


Ran 5 of 5 Specs in 15.016 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (15.02s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	15.188s
?   	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
I0729 15:02:28.214166   11605 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
E0729 15:02:28.215447   11605 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
I0729 15:02:28.216917   11605 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I0729 15:02:28.217132   11605 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
--- PASS: TestReconcilePaused (0.00s)
=== RUN   TestReconcileClusterNoEndpoints
... skipping 192 lines ...
    --- PASS: TestSelectMachineForScaleDown/when_there_is_an_up_to_date_machine_with_delete_annotation,_while_there_are_any_outdated_machines_without_annotatio_that_still_exist,_it_returns_oldest_marked_machine_first (0.00s)
=== RUN   TestPreflightChecks
=== RUN   TestPreflightChecks/control_plane_without_machines_(not_initialized)_should_pass
=== RUN   TestPreflightChecks/control_plane_with_a_deleting_machine_should_requeue
I0729 15:02:44.130392   11605 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
I0729 15:02:44.130640   11605 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: 1659106934
Will run 1 of 1 specs

E0729 15:02:44.160885   11605 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-nqio29\" not found" "kubeadmControlPlane"="kcp-foo-nqio29" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.026 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I0729 15:02:44.162843   11605 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-kneeuy" "kubeadmControlPlane"="kcp-foo-kneeuy" "namespace"="test" 
I0729 15:02:45.933196   11605 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-kneeuy" "kubeadmControlPlane"="kcp-foo-kneeuy" "namespace"="test" "needRollout"=["kcp-foo-kneeuy-4xrwq"]
I0729 15:02:45.933448   11605 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-kneeuy" "kubeadmControlPlane"="kcp-foo-kneeuy" "namespace"="test" "failures"="[machine kcp-foo-kneeuy-d52h7 does not have APIServerPodHealthy condition, machine kcp-foo-kneeuy-d52h7 does not have ControllerManagerPodHealthy condition, machine kcp-foo-kneeuy-d52h7 does not have SchedulerPodHealthy condition, machine kcp-foo-kneeuy-d52h7 does not have EtcdPodHealthy condition, machine kcp-foo-kneeuy-d52h7 does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (1.77s)
PASS
E0729 15:02:45.934413   11605 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0729 15:02:45.934453   11605 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-703918830/tls.crt: no such file or directory"  
I0729 15:02:45.934483   11605 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/controllers	31.206s
I0729 15:02:26.354887   11546 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"
I0729 15:02:26.355121   11546 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I0729 15:02:26.355172   11546 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"
I0729 15:02:26.355194   11546 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
... skipping 53 lines ...
==================================
Random Seed: 1659106933
Will run 7 of 7 specs

•••••••
Ran 7 of 7 Specs in 0.000 seconds
SUCCESS! -- 7 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestControlPlane (0.00s)
=== RUN   TestHasUnhealthyMachine
--- PASS: TestHasUnhealthyMachine (0.00s)
=== RUN   TestNewFailureDomainPicker
=== RUN   TestNewFailureDomainPicker/simple
=== RUN   TestNewFailureDomainPicker/no_machines
... skipping 111 lines ...
=======================================
Random Seed: 1659106933
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
E0729 15:02:28.469587   11546 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"  
E0729 15:02:36.792672   11546 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"  
E0729 15:02:45.778657   11546 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"  
E0729 15:02:56.908945   11546 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"  
E0729 15:03:13.382162   11546 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"  
E0729 15:03:26.390853   11546 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"  
E0729 15:03:44.038330   11546 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"  
E0729 15:04:04.961764   11546 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"  
E0729 15:04:35.978337   11546 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"  
E0729 15:05:21.135673   11546 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 83 lines ...
    --- PASS: TestIsKubernetesVersionSupported/workload_cluster_and_version_<_v1.22.0 (0.00s)
    --- 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
E0729 15:05:21.145429   11546 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0729 15:05:21.145511   11546 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-357255094/tls.crt: no such file or directory"  
E0729 15:05:21.145531   11546 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0729 15:05:21.145550   11546 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-357255094/tls.crt: no such file or directory"  
I0729 15:05:21.145706   11546 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	188.002s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
... skipping 288 lines ...
I0729 15:02:37.592116   11885 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourcesetbinding" "worker count"=1
I0729 15:02:37.592292   11885 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0729 15:02:37.692717   11885 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I0729 15:02:37.793114   11885 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I0729 15:02:37.793179   11885 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I0729 15:02:37.872213   11885 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-en5qlx"} 
E0729 15:02:37.896517   11885 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"
•I0729 15:02:38.940374   11885 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-hzqfcp"} 
E0729 15:02:38.982216   11885 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"
•E0729 15:02:50.105851   11885 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusterresourcesets.addons.cluster.x-k8s.io \"test-clusterresourceset\" not found" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"

------------------------------
• Failure [11.130 seconds]
ClusterResourceSet Reconciler
/home/prow/go/src/sigs.k8s.io/cluster-api/exp/addons/controllers/clusterresourceset_controller_test.go:40
  Should reconcile a ClusterResourceSet when a resource is created that is part of ClusterResourceSet resources [It]
... skipping 8 lines ...
------------------------------
STEP: Creating the Cluster
STEP: Creating the remote Cluster kubeconfig
STEP: Creating a Secret and a ConfigMap with ConfigMap in their data field
STEP: Verifying ClusterResourceSetBinding is created with cluster owner reference
STEP: Deleting the Kubeconfigsecret
E0729 15:02:51.260928   11885 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"
E0729 15:02:52.297969   11885 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"
•E0729 15:02:53.311369   11885 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"
•I0729 15:02:53.317413   11885 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I0729 15:02:53.317486   11885 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I0729 15:02:53.317571   11885 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E0729 15:02:53.317611   11885 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0729 15:02:53.317646   11885 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-075203628/tls.crt: no such file or directory"  
E0729 15:02:53.317664   11885 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0729 15:02:53.317682   11885 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-075203628/tls.crt: no such file or directory"  



Summarizing 1 Failure:

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

Ran 5 of 5 Specs in 30.203 seconds
FAIL! -- 4 Passed | 1 Failed | 0 Pending | 0 Skipped
--- FAIL: TestAPIs (30.20s)
FAIL
FAIL	sigs.k8s.io/cluster-api/exp/addons/controllers	30.276s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-create
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-update
=== RUN   TestMachinePoolDefault/for_MachinePool/validate-on-delete
... skipping 58 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E0729 15:02:27.948136   12052 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.01s)
    --- 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 92 lines ...
•I0729 15:02:39.608981   12052 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0729 15:02:39.644335   12052 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0729 15:02:39.646279   12052 machinepool_controller_phases.go:268]  "msg"="Infrastructure provider is not ready, requeuing" "cluster"="test-cluster" "machinepool"="machinepool-test" "namespace"="default" 
•I0729 15:02:39.647140   12052 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}}}
I0729 15:02:39.672932   12052 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I0729 15:02:39.714357   12052 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••E0729 15:02:39.717014   12052 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0729 15:02:39.717050   12052 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-797056447/tls.crt: no such file or directory"  
E0729 15:02:39.717080   12052 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E0729 15:02:39.717105   12052 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-797056447/tls.crt: no such file or directory"  
I0729 15:02:39.717777   12052 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
I0729 15:02:39.748116   12052 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinepool" 
E0729 15:02:39.748191   12052 controller.go:173] controller-runtime/controller "msg"="Could not wait for Cache to sync" "error"="failed to wait for machinepool caches to sync: cache did not sync" "controller"="machinepool" 


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


Ran 14 of 14 Specs in 7.673 seconds
SUCCESS! -- 14 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestPatch (7.67s)
=== 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.036s
FAIL
make: *** [Makefile:116: test] Error 1