This job view page is being replaced by Spyglass soon. Check out the new job view.
ResultFAILURE
Tests 0 failed / 0 succeeded
Started2022-11-11 03:33
Elapsed4m32s
Revisionrelease-0.3

No Test Failures!


Error lines from build-log.txt

... skipping 773 lines ...
I1111 03:34:43.624474    8351 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I1111 03:34:43.625203    8351 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I1111 03:34:43.626411    8351 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I1111 03:34:43.626639    8351 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=38145
I1111 03:34:43.626830    8351 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
I1111 03:34:44.580488    8351 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" 
•E1111 03:34:44.590885    8351 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E1111 03:34:44.590946    8351 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-143252803/tls.crt: no such file or directory"  
E1111 03:34:44.590969    8351 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E1111 03:34:44.590996    8351 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-143252803/tls.crt: no such file or directory"  
I1111 03:34:44.591111    8351 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 1 of 1 Specs in 13.285 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (13.28s)
PASS
ok  	sigs.k8s.io/cluster-api/bootstrap/kubeadm/controllers	46.975s
=== 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 1406 lines ...
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_ref_is_nil
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_unable_to_reconcile_infrastructure_ref
I1111 03:34:33.267133   10536 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"
I1111 03:34:33.270290   10536 cluster_controller_phases.go:76]  "msg"="Could not find external object for cluster, requeuing" "cluster"="test-cluster" "namespace"="test-namespace" "refGroupVersionKind"={"Group":"infrastructure.cluster.x-k8s.io","Version":"v1alpha3","Kind":"InfrastructureMachine"} "refName"="test"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infra_config_is_marked_for_deletion
I1111 03:34:33.270815   10536 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"
2022/11/11 03:34:33 http: TLS handshake error from 127.0.0.1:54748: EOF
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_no_error_if_infrastructure_is_marked_ready_on_cluster
I1111 03:34:33.272993   10536 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"
=== RUN   TestClusterReconcilePhases/reconcile_infrastructure/returns_error_if_infrastructure_has_the_paused_annotation
I1111 03:34:33.274837   10536 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"
=== RUN   TestClusterReconcilePhases/reconcile_kubeconfig
=== RUN   TestClusterReconcilePhases/reconcile_kubeconfig/cluster_not_provisioned,_apiEndpoint_is_not_set
... skipping 97 lines ...
    --- PASS: TestReconcileBootstrap/existing_machine,_machineset_owner_and_version_v1alpha2,_and_ownerref_updated (0.00s)
=== RUN   TestReconcileInfrastructure
=== RUN   TestReconcileInfrastructure/new_machine,_infrastructure_config_ready
I1111 03:34:33.317369   10536 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
I1111 03:34:33.319102   10536 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"
E1111 03:34:33.319522   10536 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
I1111 03:34:33.319999   10536 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
I1111 03:34:33.657990   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={}
E1111 03:34:33.758766   10536 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I1111 03:34:33.767843   10536 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-bbb7h" "namespace"="test-machine-watches-d2snc" "GroupVersionKind"="bootstrap.cluster.x-k8s.io/v1alpha3, Kind=BootstrapMachine"
I1111 03:34:33.767934   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"bootstrap.cluster.x-k8s.io/v1alpha3","kind":"BootstrapMachine"}}
I1111 03:34:33.880480   10536 tracker.go:55] controllers/Machine "msg"="Adding watcher on external object" "machine"="machine-created-bbb7h" "namespace"="test-machine-watches-d2snc" "GroupVersionKind"="infrastructure.cluster.x-k8s.io/v1alpha3, Kind=InfrastructureMachine"
I1111 03:34:33.880572   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machine" "source"={"Type":{"apiVersion":"infrastructure.cluster.x-k8s.io/v1alpha3","kind":"InfrastructureMachine"}}
I1111 03:34:33.981178   10536 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-bbb7h" "namespace"="test-machine-watches-d2snc" "noderef"="node-1"
E1111 03:34:33.991262   10536 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
E1111 03:34:33.991332   10536 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="node-1"
I1111 03:34:34.037416   10536 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="machine-created-bbb7h" "namespace"="test-machine-watches-d2snc" "noderef"="node-1"
E1111 03:34:34.067570   10536 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-bbb7h\" in namespace \"test-machine-watches-d2snc\", requeuing: requeue in 1s"  
E1111 03:34:34.084036   10536 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-bbb7h\" in namespace \"test-machine-watches-d2snc\", requeuing: requeue in 1s, no matching Node for Machine \"machine-created-bbb7h\" in namespace \"test-machine-watches-d2snc\": cannot find node with matching ProviderID]" "controller"="machine" "name"="machine-created-bbb7h" "namespace"="test-machine-watches-d2snc"
--- PASS: TestWatches (0.78s)
=== 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
I1111 03:34:34.202185   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-n9d7r" "namespace"="test-machine-watches-d2snc" "count"=1
I1111 03:34:34.202252   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-n9d7r" "namespace"="test-machine-watches-d2snc" "descendants"="Worker machines: machine-created-bbb7h" "indirect descendants count"=0
I1111 03:34:34.217644   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="machine-reconcile-n9d7r" "namespace"="test-machine-watches-d2snc" "count"=1
I1111 03:34:34.217714   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="machine-reconcile-n9d7r" "namespace"="test-machine-watches-d2snc" "descendants"="Worker machines: machine-created-bbb7h" "indirect descendants count"=0
I1111 03:34:35.084650   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-n9d7r" "machine"="machine-created-bbb7h" "namespace"="test-machine-watches-d2snc" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"node-1","uid":"dcb522c5-cc36-4bc6-91aa-a3485bda888f","apiVersion":"v1"}
E1111 03:34:35.133070   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-bbb7h\" not found" "controller"="machine" "name"="machine-created-bbb7h" "namespace"="test-machine-watches-d2snc"
E1111 03:34:36.212972   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[retrieved empty dataSecretName from bootstrap provider for Machine \"machine-created-p5gh6\" in namespace \"default\", error creating client and cache for remote cluster: error fetching REST client config for remote cluster \"default/machine-reconcile-mgjwn\": failed to retrieve kubeconfig secret for Cluster default/machine-reconcile-mgjwn: secrets \"machine-reconcile-mgjwn-kubeconfig\" not found]" "controller"="machine" "name"="machine-created-p5gh6" "namespace"="default"
I1111 03:34:37.213554   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-mgjwn" "machine"="machine-created-p5gh6" "namespace"="default" "cause"="noderef is nil" "node"=null
I1111 03:34:37.248492   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-mgjwn" "machine"="machine-created-p5gh6" "namespace"="default" "cause"="noderef is nil" "node"=null
I1111 03:34:37.271391   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="machine-reconcile-mgjwn" "machine"="machine-created-p5gh6" "namespace"="default" "cause"="noderef is nil" "node"=null
E1111 03:34:37.319553   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"machine-created-p5gh6\" not found" "controller"="machine" "name"="machine-created-p5gh6" "namespace"="default"
--- PASS: TestMachine_Reconcile (3.22s)
    --- PASS: TestMachine_Reconcile/reconcile_create (3.22s)
=== 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 6 lines ...
=== RUN   TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set
I1111 03:34:37.339187   10536 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine3" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I1111 03:34:37.339315   10536 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine3" "namespace"="default" 
=== RUN   TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner
I1111 03:34:37.343165   10536 conversion.go:64]  "msg"="Cannot retrieve CRD with metadata only client, falling back to slower listing" "machine"="machine4" "namespace"="default" "err"="cannot create a metadata client without a rest config"
I1111 03:34:37.343303   10536 machine_controller_noderef.go:45]  "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="machine4" "namespace"="default" 
E1111 03:34:37.347800   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"machine-reconcile-mgjwn\" not found" "controller"="cluster" "name"="machine-reconcile-mgjwn" "namespace"="default"
--- PASS: TestMachineOwnerReference (0.02s)
    --- PASS: TestMachineOwnerReference/should_add_owner_reference_to_machine_referencing_a_cluster_with_correct_type_meta (0.01s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_is_owned_by_a_machine_set (0.00s)
    --- PASS: TestMachineOwnerReference/should_not_add_cluster_owner_reference_if_machine_has_a_controller_owner (0.01s)
=== RUN   TestReconcileRequest
=== RUN   TestReconcileRequest/machine_should_be_created
... skipping 119 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
I1111 03:34:37.533959   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dqnpc" "namespace"="test-mhc-k94lb" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value
I1111 03:34:37.595680   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E1111 03:34:37.596893   10536 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Cluster.cluster.x-k8s.io \"test-cluster-f65k6\" not found"  "cluster"="test-mhc-k94lb/test-cluster-f65k6"
E1111 03:34:37.600899   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="[MachineHealthCheck.cluster.x-k8s.io \"test-mhc-dqnpc\" not found, machinehealthchecks.cluster.x-k8s.io \"test-mhc-dqnpc\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-dqnpc" "namespace"="test-mhc-k94lb"
=== 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
I1111 03:34:38.602224   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-dqnpc" "namespace"="test-mhc-k94lb" 
I1111 03:34:38.602339   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-s6jm5" "namespace"="test-mhc-2j8pk" 
I1111 03:34:38.602377   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-4q74p" "namespace"="test-mhc-xbrdd" 
I1111 03:34:38.602410   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v7742" "namespace"="test-mhc-5zh22" 
I1111 03:34:38.624493   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I1111 03:34:38.747269   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v7742" "namespace"="test-mhc-5zh22" 
=== RUN   TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones
I1111 03:34:38.801107   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-v7742" "namespace"="test-mhc-5zh22" 
E1111 03:34:38.818873   10536 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-5zh22/test-cluster-rqzkv"
E1111 03:34:38.822671   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="clusters.cluster.x-k8s.io \"test-cluster-rqzkv\" not found" "controller"="cluster" "name"="test-cluster-rqzkv" "namespace"="test-mhc-5zh22"
I1111 03:34:38.939496   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b9wlq" "namespace"="test-mhc-4jxh6" 
I1111 03:34:38.964744   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I1111 03:34:39.101844   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b9wlq" "namespace"="test-mhc-4jxh6" 
I1111 03:34:39.108320   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b9wlq" "namespace"="test-mhc-4jxh6" 
E1111 03:34:39.153944   10536 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-4jxh6/test-cluster-8f98f"
=== RUN   TestMachineHealthCheck_Reconcile/it_doesn't_mark_anything_unhealthy_when_all_Machines_are_healthy
I1111 03:34:39.159180   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-b9wlq" "namespace"="test-mhc-4jxh6" 
I1111 03:34:39.276718   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qmnq7" "namespace"="test-mhc-n9scr" 
inframachine created: test-mhc-machine-infra-22j55
machine created: test-mhc-machine-ch8hv
I1111 03:34:39.304739   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I1111 03:34:39.406703   10536 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-n9scr/test-mhc-qmnq7/test-mhc-machine-ch8hv/"
E1111 03:34:39.412321   10536 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-gs5pj"
E1111 03:34:39.412870   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-gs5pj, got []"  "node"="test-mhc-node-gs5pj"
node created: test-mhc-node-gs5pj
inframachine created: test-mhc-machine-infra-cw7zb
machine created: test-mhc-machine-7km7n
E1111 03:34:39.561247   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-wfjxg, got []"  "node"="test-mhc-node-wfjxg"
node created: test-mhc-node-wfjxg
E1111 03:34:39.562708   10536 machine_controller.go:685] controllers/Machine "msg"="Unable to retrieve machine from node" "error"="no matching Machine"  "node"="test-mhc-node-wfjxg"
I1111 03:34:39.697489   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qmnq7" "namespace"="test-mhc-n9scr" 
E1111 03:34:39.849901   10536 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-machine-watches-d2snc/machine-reconcile-n9d7r"
I1111 03:34:39.918839   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qmnq7" "namespace"="test-mhc-n9scr" 
Cleaning up nodes, machines and infra machines.
I1111 03:34:39.925434   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qmnq7" "namespace"="test-mhc-n9scr" 
I1111 03:34:39.927409   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qmnq7" "namespace"="test-mhc-n9scr" 
I1111 03:34:39.927817   10536 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-n9scr/test-mhc-qmnq7/test-mhc-machine-ch8hv/"
I1111 03:34:39.957144   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qmnq7" "namespace"="test-mhc-n9scr" 
I1111 03:34:39.957687   10536 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-n9scr/test-mhc-qmnq7/test-mhc-machine-ch8hv/"
I1111 03:34:39.958324   10536 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-n9scr/test-mhc-qmnq7/test-mhc-machine-7km7n/"
I1111 03:34:39.978005   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-7jlfb" "namespace"="test-mhc-n9scr" "count"=2
I1111 03:34:39.978095   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-7jlfb" "namespace"="test-mhc-n9scr" "descendants"="Worker machines: test-mhc-machine-ch8hv,test-mhc-machine-7km7n" "indirect descendants count"=0
I1111 03:34:39.983602   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-7jlfb" "namespace"="test-mhc-n9scr" "count"=2
I1111 03:34:39.983676   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-7jlfb" "namespace"="test-mhc-n9scr" "descendants"="Worker machines: test-mhc-machine-ch8hv,test-mhc-machine-7km7n" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_there_is_one_unhealthy_Machine
E1111 03:34:40.097636   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-ch8hv\" in namespace \"test-mhc-n9scr\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-ch8hv" "namespace"="test-mhc-n9scr"
inframachine created: test-mhc-machine-infra-f99v6
machine created: test-mhc-machine-q2sbq
E1111 03:34:40.182686   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-qmnq7\" not found" "controller"="machinehealthcheck" "name"="test-mhc-qmnq7" "namespace"="test-mhc-n9scr"
I1111 03:34:41.098257   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-7jlfb" "machine"="test-mhc-machine-7km7n" "namespace"="test-mhc-n9scr" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-wfjxg"}
E1111 03:34:41.150329   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-7km7n\" not found" "controller"="machine" "name"="test-mhc-machine-7km7n" "namespace"="test-mhc-n9scr"
I1111 03:34:41.183020   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:41.201200   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I1111 03:34:41.320162   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-qmnq7" "namespace"="test-mhc-n9scr" 
I1111 03:34:41.320234   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:41.321246   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:41.323317   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
... skipping 370 lines ...
I1111 03:34:42.187823   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.189557   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.191232   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.192886   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.194875   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.196581   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
E1111 03:34:42.201758   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-ch8hv\" not found" "controller"="machine" "name"="test-mhc-machine-ch8hv" "namespace"="test-mhc-n9scr"
I1111 03:34:42.202052   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.203955   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.205732   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.207793   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.209553   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:42.211396   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
... skipping 352 lines ...
I1111 03:34:43.204490   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.206173   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.221307   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.224542   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.225423   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.226527   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
E1111 03:34:43.233740   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ggj4g, got []"  "node"="test-mhc-node-ggj4g"
E1111 03:34:43.234039   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-ggj4g, got []"  "node"="test-mhc-node-ggj4g"
node created: test-mhc-node-ggj4g
I1111 03:34:43.236917   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-q2sbq/"
I1111 03:34:43.251147   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.251457   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-q2sbq/"
I1111 03:34:43.252479   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
inframachine created: test-mhc-machine-infra-9gm8s
I1111 03:34:43.256572   10536 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-q2sbq" "namespace"="test-mhc-pjbvq" "noderef"="test-mhc-node-ggj4g"
machine created: test-mhc-machine-9hgz9
I1111 03:34:43.270627   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.283686   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.294554   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.303460   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.306323   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.312830   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.314337   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.329060   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.330195   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-9hgz9/"
I1111 03:34:43.353159   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.353685   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-9hgz9/"
I1111 03:34:43.364520   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.365008   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-9hgz9/"
node created: test-mhc-node-v8swf
E1111 03:34:43.376779   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-v8swf, got []"  "node"="test-mhc-node-v8swf"
E1111 03:34:43.376934   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-v8swf, got []"  "node"="test-mhc-node-v8swf"
I1111 03:34:43.386437   10536 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-9hgz9" "namespace"="test-mhc-pjbvq" "noderef"="test-mhc-node-v8swf"
I1111 03:34:43.390971   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
inframachine created: test-mhc-machine-infra-v8tz7
I1111 03:34:43.411929   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.417893   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
machine created: test-mhc-machine-2sms9
... skipping 11 lines ...
I1111 03:34:43.512403   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.519489   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.537055   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.540028   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.556425   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.585869   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.587167   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-2sms9/"
I1111 03:34:43.612081   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.612718   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-2sms9/"
node created: test-mhc-node-sbsvs
E1111 03:34:43.632158   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-sbsvs, got []"  "node"="test-mhc-node-sbsvs"
E1111 03:34:43.632388   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-sbsvs, got []"  "node"="test-mhc-node-sbsvs"
I1111 03:34:43.633725   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.634260   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-2sms9/"
I1111 03:34:43.643586   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
Cleaning up nodes, machines and infra machines.
I1111 03:34:43.644173   10536 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-pjbvq/test-mhc-tcn4b/test-mhc-machine-2sms9/test-mhc-node-sbsvs"
I1111 03:34:43.658775   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:43.659331   10536 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-pjbvq/test-mhc-tcn4b/test-mhc-machine-2sms9/"
Cleaning up nodes, machines and infra machines.
I1111 03:34:43.689506   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-4rwm9" "machine"="test-mhc-machine-2sms9" "namespace"="test-mhc-pjbvq" "cause"="no control plane members" "node"={"name":"test-mhc-node-sbsvs"}
I1111 03:34:43.745770   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-4rwm9" "namespace"="test-mhc-pjbvq" "count"=3
I1111 03:34:43.745855   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-4rwm9" "namespace"="test-mhc-pjbvq" "descendants"="Worker machines: test-mhc-machine-q2sbq,test-mhc-machine-9hgz9,test-mhc-machine-2sms9" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/it_marks_unhealthy_machines_for_remediation_when_the_unhealthy_Machines_exceed_MaxUnhealthy
I1111 03:34:43.755073   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-4rwm9" "namespace"="test-mhc-pjbvq" "count"=3
I1111 03:34:43.755139   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-4rwm9" "namespace"="test-mhc-pjbvq" "descendants"="Worker machines: test-mhc-machine-2sms9,test-mhc-machine-q2sbq,test-mhc-machine-9hgz9" "indirect descendants count"=0
E1111 03:34:43.786530   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-2sms9\" not found" "controller"="machine" "name"="test-mhc-machine-2sms9" "namespace"="test-mhc-pjbvq"
E1111 03:34:43.813803   10536 machinehealthcheck_controller.go:167] controllers/MachineHealthCheck "msg"="Failed to reconcile MachineHealthCheck" "error"="failed to patch unhealthy machine status for machine: test-mhc-pjbvq/test-mhc-machine-2sms9: [Machine.cluster.x-k8s.io \"test-mhc-machine-2sms9\" not found, machines.cluster.x-k8s.io \"test-mhc-machine-2sms9\" not found]" "cluster"="test-cluster-4rwm9" 
E1111 03:34:43.814185   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch unhealthy machine status for machine: test-mhc-pjbvq/test-mhc-machine-2sms9: [Machine.cluster.x-k8s.io \"test-mhc-machine-2sms9\" not found, machines.cluster.x-k8s.io \"test-mhc-machine-2sms9\" not found]" "controller"="machinehealthcheck" "name"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq"
inframachine created: test-mhc-machine-infra-c4vdm
machine created: test-mhc-machine-w77xl
I1111 03:34:44.787200   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-4rwm9" "machine"="test-mhc-machine-q2sbq" "namespace"="test-mhc-pjbvq" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-ggj4g","uid":"ecaa87a2-8dbf-4820-9a61-b66d0da53288","apiVersion":"v1"}
I1111 03:34:44.814451   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-tcn4b" "namespace"="test-mhc-pjbvq" 
I1111 03:34:44.814553   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:44.845325   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
E1111 03:34:44.859703   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-q2sbq\" not found" "controller"="machine" "name"="test-mhc-machine-q2sbq" "namespace"="test-mhc-pjbvq"
I1111 03:34:45.010159   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:45.019140   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
E1111 03:34:45.024405   10536 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-n9scr/test-cluster-7jlfb"
I1111 03:34:45.029336   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:45.070323   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:45.151290   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:45.312342   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:45.633393   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:45.860251   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-4rwm9" "machine"="test-mhc-machine-9hgz9" "namespace"="test-mhc-pjbvq" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-v8swf","uid":"a05f9f7f-0e68-43dd-9288-a58dfb8aec57","apiVersion":"v1"}
E1111 03:34:45.914792   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-9hgz9\" not found" "controller"="machine" "name"="test-mhc-machine-9hgz9" "namespace"="test-mhc-pjbvq"
I1111 03:34:46.274682   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:46.930266   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:46.940179   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:46.977056   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:46.984951   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:46.996657   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
E1111 03:34:47.004166   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g7pnz, got []"  "node"="test-mhc-node-g7pnz"
E1111 03:34:47.004550   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g7pnz, got []"  "node"="test-mhc-node-g7pnz"
node created: test-mhc-node-g7pnz
I1111 03:34:47.007252   10536 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-w77xl" "namespace"="test-mhc-xhblw" "noderef"="test-mhc-node-g7pnz"
E1111 03:34:47.011740   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g7pnz, got []"  "node"="test-mhc-node-g7pnz"
E1111 03:34:47.011789   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g7pnz, got []"  "node"="test-mhc-node-g7pnz"
E1111 03:34:47.011835   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g7pnz, got []"  "node"="test-mhc-node-g7pnz"
E1111 03:34:47.011864   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g7pnz, got []"  "node"="test-mhc-node-g7pnz"
I1111 03:34:47.017116   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
inframachine created: test-mhc-machine-infra-48mfm
machine created: test-mhc-machine-lslkb
I1111 03:34:47.054354   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.071911   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.077700   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
... skipping 2 lines ...
I1111 03:34:47.152234   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.158421   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.183376   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.191012   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.236688   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.246385   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
E1111 03:34:47.248125   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t94kc, got []"  "node"="test-mhc-node-t94kc"
node created: test-mhc-node-t94kc
E1111 03:34:47.249130   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-t94kc, got []"  "node"="test-mhc-node-t94kc"
I1111 03:34:47.292067   10536 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-lslkb" "namespace"="test-mhc-xhblw" "noderef"="test-mhc-node-t94kc"
I1111 03:34:47.292152   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
inframachine created: test-mhc-machine-infra-4vvjn
machine created: test-mhc-machine-5jn2v
node created: test-mhc-node-4rswm
E1111 03:34:47.426148   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4rswm, got []"  "node"="test-mhc-node-4rswm"
E1111 03:34:47.426205   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-4rswm, got []"  "node"="test-mhc-node-4rswm"
I1111 03:34:47.431167   10536 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-5jn2v" "namespace"="test-mhc-xhblw" "noderef"="test-mhc-node-4rswm"
I1111 03:34:47.509711   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.554527   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
Cleaning up nodes, machines and infra machines.
I1111 03:34:47.570205   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.572998   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.574735   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:47.589896   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
E1111 03:34:47.609683   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-lslkb\" in namespace \"test-mhc-xhblw\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-lslkb" "namespace"="test-mhc-xhblw"
Cleaning up nodes, machines and infra machines.
I1111 03:34:47.632825   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-mt28s" "namespace"="test-mhc-xhblw" "count"=3
I1111 03:34:47.632910   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-mt28s" "namespace"="test-mhc-xhblw" "descendants"="Worker machines: test-mhc-machine-w77xl,test-mhc-machine-lslkb,test-mhc-machine-5jn2v" "indirect descendants count"=0
=== RUN   TestMachineHealthCheck_Reconcile/when_a_Machine_has_no_Node_ref_for_less_than_the_NodeStartupTimeout
I1111 03:34:47.641014   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-mt28s" "namespace"="test-mhc-xhblw" "count"=3
I1111 03:34:47.641087   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-mt28s" "namespace"="test-mhc-xhblw" "descendants"="Worker machines: test-mhc-machine-5jn2v,test-mhc-machine-w77xl,test-mhc-machine-lslkb" "indirect descendants count"=0
... skipping 2 lines ...
inframachine created: test-mhc-machine-infra-wpmsp
machine created: test-mhc-machine-dvs2s
I1111 03:34:47.779740   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I1111 03:34:47.814137   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:48.516935   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-sqltb" "namespace"="test-mhc-xhblw" 
I1111 03:34:48.610244   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-mt28s" "machine"="test-mhc-machine-5jn2v" "namespace"="test-mhc-xhblw" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-4rswm","uid":"71d9a3c4-33e8-4cb5-b6dd-6a279936e2d6","apiVersion":"v1"}
E1111 03:34:48.745329   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-5jn2v\" not found" "controller"="machine" "name"="test-mhc-machine-5jn2v" "namespace"="test-mhc-xhblw"
E1111 03:34:48.786572   10536 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-pjbvq/test-cluster-4rwm9"
I1111 03:34:49.745975   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-mt28s" "machine"="test-mhc-machine-lslkb" "namespace"="test-mhc-xhblw" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-t94kc","uid":"65d2c777-bee2-4fed-90b2-21f0094b2b28","apiVersion":"v1"}
E1111 03:34:49.800556   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-lslkb\" not found" "controller"="machine" "name"="test-mhc-machine-lslkb" "namespace"="test-mhc-xhblw"
I1111 03:34:50.801140   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-mt28s" "machine"="test-mhc-machine-w77xl" "namespace"="test-mhc-xhblw" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-g7pnz","uid":"20b97536-5fcb-4f60-81e3-57c4a0f5dbd1","apiVersion":"v1"}
E1111 03:34:50.851235   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-w77xl\" not found" "controller"="machine" "name"="test-mhc-machine-w77xl" "namespace"="test-mhc-xhblw"
I1111 03:34:51.860510   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:51.868414   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:51.900583   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
E1111 03:34:51.908224   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hz2tz, got []"  "node"="test-mhc-node-hz2tz"
node created: test-mhc-node-hz2tz
E1111 03:34:51.910093   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-hz2tz, got []"  "node"="test-mhc-node-hz2tz"
I1111 03:34:51.921014   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:51.926834   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
inframachine created: test-mhc-machine-infra-4psck
machine created: test-mhc-machine-fc78k
E1111 03:34:52.058243   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g98jd, got []"  "node"="test-mhc-node-g98jd"
node created: test-mhc-node-g98jd
I1111 03:34:52.059306   10536 machine_controller_noderef.go:86] controllers/Machine "msg"="Set Machine's NodeRef" "machine"="test-mhc-machine-fc78k" "namespace"="test-mhc-hhnsv" "noderef"="test-mhc-node-g98jd"
E1111 03:34:52.060497   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g98jd, got []"  "node"="test-mhc-node-g98jd"
E1111 03:34:52.079065   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g98jd, got []"  "node"="test-mhc-node-g98jd"
E1111 03:34:52.079134   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g98jd, got []"  "node"="test-mhc-node-g98jd"
E1111 03:34:52.079961   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g98jd, got []"  "node"="test-mhc-node-g98jd"
E1111 03:34:52.079995   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-g98jd, got []"  "node"="test-mhc-node-g98jd"
inframachine created: test-mhc-machine-infra-8xqp7
I1111 03:34:52.108344   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
machine created: test-mhc-machine-7j9k4
I1111 03:34:52.132768   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:52.139647   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:52.268743   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:52.281190   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:52.305780   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:52.310886   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
Cleaning up nodes, machines and infra machines.
I1111 03:34:52.334757   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
Cleaning up nodes, machines and infra machines.
I1111 03:34:52.355569   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:52.356131   10536 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-hhnsv/test-mhc-mvhm8/test-mhc-machine-dvs2s/"
I1111 03:34:52.396616   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:52.397230   10536 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-hhnsv/test-mhc-mvhm8/test-mhc-machine-dvs2s/"
I1111 03:34:52.397655   10536 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-hhnsv/test-mhc-mvhm8/test-mhc-machine-fc78k/"
I1111 03:34:52.435729   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-lvmlm" "namespace"="test-mhc-hhnsv" "count"=2
I1111 03:34:52.435839   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-lvmlm" "namespace"="test-mhc-hhnsv" "descendants"="Worker machines: test-mhc-machine-dvs2s,test-mhc-machine-fc78k,test-mhc-machine-7j9k4" "indirect descendants count"=1
I1111 03:34:52.443951   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-lvmlm" "namespace"="test-mhc-hhnsv" "count"=2
I1111 03:34:52.444013   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-lvmlm" "namespace"="test-mhc-hhnsv" "descendants"="Worker machines: test-mhc-machine-dvs2s,test-mhc-machine-fc78k,test-mhc-machine-7j9k4" "indirect descendants count"=1
=== 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
I1111 03:34:52.536112   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-lvmlm" "machine"="test-mhc-machine-dvs2s" "namespace"="test-mhc-hhnsv" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-hz2tz"}
E1111 03:34:52.573192   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-mvhm8\" not found" "controller"="machinehealthcheck" "name"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv"
inframachine created: test-mhc-machine-infra-tcrpc
E1111 03:34:52.625561   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-dvs2s\" not found" "controller"="machine" "name"="test-mhc-machine-dvs2s" "namespace"="test-mhc-hhnsv"
machine created: test-mhc-machine-6btcv
E1111 03:34:52.656960   10536 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-xhblw/test-cluster-mt28s"
I1111 03:34:53.573449   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-mvhm8" "namespace"="test-mhc-hhnsv" 
I1111 03:34:53.573832   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:53.588129   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I1111 03:34:53.626100   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-lvmlm" "machine"="test-mhc-machine-fc78k" "namespace"="test-mhc-hhnsv" "cause"="cluster is being deleted" "node"={"kind":"Node","name":"test-mhc-node-g98jd","uid":"e6a6ddce-a943-4a0e-b629-fa9492db722f","apiVersion":"v1"}
E1111 03:34:53.673396   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-fc78k\" not found" "controller"="machine" "name"="test-mhc-machine-fc78k" "namespace"="test-mhc-hhnsv"
I1111 03:34:53.718229   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:53.719102   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:53.719769   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:53.720895   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:53.724051   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:53.726125   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
... skipping 387 lines ...
I1111 03:34:54.702535   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.704333   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.708623   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.712490   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.714527   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.718720   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
E1111 03:34:54.720633   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-7j9k4\" not found" "controller"="machine" "name"="test-mhc-machine-7j9k4" "namespace"="test-mhc-hhnsv"
I1111 03:34:54.722486   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.724317   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.726212   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.728041   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.729912   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:54.731757   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
... skipping 441 lines ...
I1111 03:34:55.727506   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.729976   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.731108   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.732329   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.735476   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.737339   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.737617   10536 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-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/"
I1111 03:34:55.750945   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.751257   10536 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-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/"
node created: test-mhc-node-pcwrw
E1111 03:34:55.758567   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pcwrw, got []"  "node"="test-mhc-node-pcwrw"
E1111 03:34:55.758567   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-pcwrw, got []"  "node"="test-mhc-node-pcwrw"
I1111 03:34:55.759010   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.759331   10536 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-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/"
I1111 03:34:55.770950   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.800899   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.802625   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.809858   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.812616   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.813053   10536 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-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/test-mhc-node-pcwrw"
I1111 03:34:55.846930   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.847438   10536 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-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/test-mhc-node-pcwrw"
I1111 03:34:55.851179   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.851483   10536 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-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/test-mhc-node-pcwrw"
I1111 03:34:55.852758   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.853096   10536 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-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/test-mhc-node-pcwrw"
Cleaning up nodes, machines and infra machines.
I1111 03:34:55.859815   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.860209   10536 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-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/test-mhc-node-pcwrw"
I1111 03:34:55.862708   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:55.863059   10536 machinehealthcheck_controller.go:387] controllers/MachineHealthCheck "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="NodeNotFound" "target"="test-mhc-cv8v7/test-mhc-zk4dh/test-mhc-machine-6btcv/"
I1111 03:34:55.894881   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-b8wgz" "namespace"="test-mhc-cv8v7" "count"=1
I1111 03:34:55.894966   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-b8wgz" "namespace"="test-mhc-cv8v7" "descendants"="Worker machines: test-mhc-machine-6btcv" "indirect descendants count"=0
I1111 03:34:55.900276   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-b8wgz" "namespace"="test-mhc-cv8v7" "count"=1
I1111 03:34:55.900339   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-b8wgz" "namespace"="test-mhc-cv8v7" "descendants"="Worker machines: test-mhc-machine-6btcv" "indirect descendants count"=0
E1111 03:34:55.902243   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="no matching Node for Machine \"test-mhc-machine-6btcv\" in namespace \"test-mhc-cv8v7\": cannot find node with matching ProviderID" "controller"="machine" "name"="test-mhc-machine-6btcv" "namespace"="test-mhc-cv8v7"
=== RUN   TestMachineHealthCheck_Reconcile/when_in_a_MachineSet,_unhealthy_machines_should_be_deleted
I1111 03:34:56.008264   10536 machineset_controller.go:316] controllers/MachineSet "msg"="Too few replicas" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" "creating"=1 "need"=1
I1111 03:34:56.008313   10536 machineset_controller.go:324] controllers/MachineSet "msg"="Creating machine 1 of 1, ( spec.replicas(1) \u003e currentMachineCount(0) )" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
I1111 03:34:56.023860   10536 machineset_controller.go:378] controllers/MachineSet "msg"="Created machine 1 of 1 with name \"mhc-ms-s68ss-w96d2\"" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
I1111 03:34:56.028251   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-zk4dh" "namespace"="test-mhc-cv8v7" 
I1111 03:34:56.100728   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:56.149564   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
I1111 03:34:56.150347   10536 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
I1111 03:34:56.277590   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:56.902807   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-b8wgz" "machine"="test-mhc-machine-6btcv" "namespace"="test-mhc-cv8v7" "cause"="cluster is being deleted" "node"={"name":"test-mhc-node-pcwrw"}
E1111 03:34:56.949984   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-6btcv\" not found" "controller"="machine" "name"="test-mhc-machine-6btcv" "namespace"="test-mhc-cv8v7"
I1111 03:34:57.278147   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
E1111 03:34:57.478850   10536 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="test-mhc-hhnsv/test-cluster-lvmlm"
I1111 03:34:57.966841   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:57.968205   10536 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
I1111 03:34:57.973692   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:57.974483   10536 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
I1111 03:34:57.994826   10536 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4" 
I1111 03:34:57.994949   10536 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.006053   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.006407   10536 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-5tbq4/test-mhc-ftlxx/mhc-ms-s68ss-w96d2/"
I1111 03:34:58.007637   10536 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.016202   10536 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.023104   10536 machineset_controller.go:139] controllers/MachineSet "msg"="Reconciliation is paused for this object" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.026239   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.026563   10536 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-5tbq4/test-mhc-ftlxx/mhc-ms-s68ss-w96d2/"
I1111 03:34:58.033086   10536 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.033149   10536 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.047129   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.047474   10536 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-5tbq4/test-mhc-ftlxx/mhc-ms-s68ss-w96d2/"
I1111 03:34:58.057354   10536 machineset_controller.go:237] controllers/MachineSet "msg"="Deleting unhealthy machine" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" "machine"="mhc-ms-s68ss-w96d2"
I1111 03:34:58.058233   10536 cluster_controller.go:223] controllers/Cluster "msg"="Cluster still has children - deleting them first" "cluster"="test-cluster-g25wq" "namespace"="test-mhc-5tbq4" "count"=1
I1111 03:34:58.058294   10536 cluster_controller.go:241] controllers/Cluster "msg"="Deleting child" "cluster"="test-cluster-g25wq" "namespace"="test-mhc-5tbq4" "gvk"="cluster.x-k8s.io/v1alpha3, Kind=MachineSet" "name"="mhc-ms-s68ss"
I1111 03:34:58.062386   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.065802   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-g25wq" "namespace"="test-mhc-5tbq4" "descendants"="Machine sets: mhc-ms-s68ss;Worker machines: mhc-ms-s68ss-w96d2" "indirect descendants count"=1
I1111 03:34:58.066827   10536 machine_controller_phases.go:278] controllers/Machine "msg"="Infrastructure provider is not ready, requeuing" "machine"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.066869   10536 machine_controller_noderef.go:45] controllers/Machine "msg"="Cannot reconcile Machine's Node, no valid ProviderID yet" "machine"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.067541   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-g25wq" "machine"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4" "cause"="cluster is being deleted" "node"=null
I1111 03:34:58.068986   10536 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-5tbq4/test-mhc-ftlxx/mhc-ms-s68ss-w96d2/"
I1111 03:34:58.069776   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-ftlxx" "namespace"="test-mhc-5tbq4" 
I1111 03:34:58.071896   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-g25wq" "namespace"="test-mhc-5tbq4" "descendants"="Worker machines: mhc-ms-s68ss-w96d2" "indirect descendants count"=1
E1111 03:34:58.081220   10536 machineset_controller.go:151] controllers/MachineSet "msg"="Failed to reconcile MachineSet" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-s68ss\" not found" "machineset"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4" 
E1111 03:34:58.081317   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to patch MachineSet's Status: machinesets.cluster.x-k8s.io \"mhc-ms-s68ss\" not found" "controller"="machineset" "name"="mhc-ms-s68ss" "namespace"="test-mhc-5tbq4"
=== 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
I1111 03:34:58.205001   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
inframachine created: test-mhc-machine-infra-45m2z
machine created: test-mhc-machine-fmnlg
I1111 03:34:58.255065   10536 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinehealthcheck" "source"={}
... skipping 8 lines ...
I1111 03:34:58.292754   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.294849   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.295555   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.297677   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.300125   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.300332   10536 machine_controller.go:305] controllers/Machine "msg"="Deleting Kubernetes Node associated with Machine is not allowed" "cluster"="test-cluster-g25wq" "machine"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4" "cause"="cluster is being deleted" "node"=null
E1111 03:34:58.350152   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"mhc-ms-s68ss-w96d2\" not found" "controller"="machine" "name"="mhc-ms-s68ss-w96d2" "namespace"="test-mhc-5tbq4"
E1111 03:34:58.354464   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-clbzj, got []"  "node"="test-mhc-node-clbzj"
E1111 03:34:58.354704   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-clbzj, got []"  "node"="test-mhc-node-clbzj"
E1111 03:34:58.354928   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-clbzj, got []"  "node"="test-mhc-node-clbzj"
node created: test-mhc-node-clbzj
I1111 03:34:58.390648   10536 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-fmnlg" "target"="test-mhc-5454g/test-mhc-6z2lt/test-mhc-machine-fmnlg/"
I1111 03:34:58.418868   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.451961   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.462684   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.465091   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.468665   10536 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-fmnlg" "target"="test-mhc-5454g/test-mhc-6z2lt/test-mhc-machine-fmnlg/test-mhc-node-clbzj"
I1111 03:34:58.511390   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
Cleaning up nodes, machines and infra machines.
I1111 03:34:58.531683   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.534872   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.542129   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-6z2lt" "namespace"="test-mhc-5454g" 
I1111 03:34:58.546471   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-m4qnn" "namespace"="test-mhc-5454g" "descendants"="Worker machines: test-mhc-machine-fmnlg" "indirect descendants count"=1
... skipping 316 lines ...
I1111 03:34:59.389170   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.390881   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.392963   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.394762   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.396521   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.398281   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
E1111 03:34:59.399680   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machines.cluster.x-k8s.io \"test-mhc-machine-fmnlg\" not found" "controller"="machine" "name"="test-mhc-machine-fmnlg" "namespace"="test-mhc-5454g"
I1111 03:34:59.400149   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.401900   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.403670   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.405469   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.407378   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:34:59.409166   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
... skipping 387 lines ...
I1111 03:35:00.404611   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.406500   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.408258   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.408953   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.410024   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.411845   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.417101   10536 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-q6d5f" "target"="test-mhc-2qwdd/test-mhc-5xz7l/test-mhc-machine-q6d5f/"
I1111 03:35:00.451528   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
E1111 03:35:00.479231   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jgmjb, got []"  "node"="test-mhc-node-jgmjb"
E1111 03:35:00.479995   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jgmjb, got []"  "node"="test-mhc-node-jgmjb"
node created: test-mhc-node-jgmjb
E1111 03:35:00.481431   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jgmjb, got []"  "node"="test-mhc-node-jgmjb"
E1111 03:35:00.481920   10536 machinehealthcheck_controller.go:480] controllers/MachineHealthCheck "msg"="Unable to retrieve machine from node" "error"="expecting one machine for node test-mhc-node-jgmjb, got []"  "node"="test-mhc-node-jgmjb"
I1111 03:35:00.491817   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.530839   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.543054   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.545453   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.549727   10536 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-q6d5f" "target"="test-mhc-2qwdd/test-mhc-5xz7l/test-mhc-machine-q6d5f/test-mhc-node-jgmjb"
I1111 03:35:00.570909   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.573917   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.578306   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.600064   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.610395   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
Cleaning up nodes, machines and infra machines.
I1111 03:35:00.614554   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.617021   10536 machinehealthcheck_controller.go:109] controllers/MachineHealthCheck "msg"="Reconciling" "machinehealthcheck"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd" 
I1111 03:35:00.622056   10536 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-q6d5f" "target"="test-mhc-2qwdd/test-mhc-5xz7l/test-mhc-machine-q6d5f/"
I1111 03:35:00.628325   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-9jvh2" "namespace"="test-mhc-2qwdd" "descendants"="Worker machines: test-mhc-machine-q6d5f" "indirect descendants count"=1
I1111 03:35:00.633379   10536 cluster_controller.go:256] controllers/Cluster "msg"="Cluster still has descendants - need to requeue" "cluster"="test-cluster-9jvh2" "namespace"="test-mhc-2qwdd" "descendants"="Worker machines: test-mhc-machine-q6d5f" "indirect descendants count"=1
E1111 03:35:00.637060   10536 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="machinehealthchecks.cluster.x-k8s.io \"test-mhc-5xz7l\" not found" "controller"="machinehealthcheck" "name"="test-mhc-5xz7l" "namespace"="test-mhc-2qwdd"
--- PASS: TestMachineHealthCheck_Reconcile (23.14s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_no_existing_labels_exist (0.05s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_the_label_has_the_wrong_value (0.07s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_the_correct_cluster-name_label_when_other_labels_are_present (0.04s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_no_existing_ones_exist (1.15s)
    --- PASS: TestMachineHealthCheck_Reconcile/it_should_ensure_an_owner_reference_is_present_when_modifying_existing_ones (0.36s)
... skipping 10 lines ...
    --- SKIP: TestMachineHealthCheck_Reconcile/when_a_machine_is_paused (0.00s)
        machinehealthcheck_controller_test.go:933: skipping until made stable
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_to_unhealthy,_new_Remediation_Request_should_be_created (0.48s)
    --- PASS: TestMachineHealthCheck_Reconcile/When_remediationTemplate_is_set_and_node_transitions_back_to_healthy,_new_Remediation_Request_should_be_deleted (2.08s)
=== RUN   TestClusterToMachineHealthCheck
=== RUN   TestClusterToMachineHealthCheck/when_the_object_passed_isn't_a_cluster
E1111 03:35:00.639863   10536 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
E1111 03:35:00.641552   10536 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
E1111 03:35:00.643329   10536 machinehealthcheck_controller.go:474]  "msg"="expected a Node" "error"="incorrect type"  "type"="handler.MapObject"
=== RUN   TestNodeToMachineHealthCheck/when_no_Machine_exists_for_the_Node
E1111 03:35:00.643583   10536 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
E1111 03:35:00.644052   10536 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
I1111 03:35:00.648744   10536 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine1/"
I1111 03:35:00.649448   10536 machinehealthcheck_controller.go:387]  "msg"="Target has failed health check, marking for remediation"  "message"="" "reason"="" "target"="default/mhc/machine2/"
E1111 03:35:00.671871   10536 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.03s)
=== 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
fatal error: concurrent map read and map write

goroutine 1224 [running]:
runtime.throw(0x19d1121, 0x21)
	/usr/local/go/src/runtime/panic.go:774 +0x72 fp=0xc000bbb798 sp=0xc000bbb768 pc=0x4314c2
runtime.mapaccess2(0x1780720, 0xc0002416b0, 0xc000bbb858, 0xc0002c3438, 0x1814f01)
	/usr/local/go/src/runtime/map.go:470 +0x278 fp=0xc000bbb7e0 sp=0xc000bbb798 pc=0x40fda8
... skipping 3046 lines ...

goroutine 5010 [chan receive]:
sigs.k8s.io/controller-runtime/pkg/cache/internal.(*specificInformersMap).Start(0xc000e8a460, 0xc000fc61e0)
	/home/prow/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.5.14/pkg/cache/internal/informers_map.go:144 +0x4c
created by sigs.k8s.io/controller-runtime/pkg/cache/internal.(*InformersMap).Start
	/home/prow/go/pkg/mod/sigs.k8s.io/controller-runtime@v0.5.14/pkg/cache/internal/deleg_map.go:67 +0xb0
FAIL	sigs.k8s.io/cluster-api/controllers	41.293s
=== RUN   TestGetResourceFound
--- PASS: TestGetResourceFound (0.00s)
=== RUN   TestGetResourceNotFound
--- PASS: TestGetResourceNotFound (0.00s)
=== RUN   TestCloneTemplateResourceNotFound
--- PASS: TestCloneTemplateResourceNotFound (0.00s)
... skipping 255 lines ...
I1111 03:34:33.766273   11022 webhook.go:123] controller-runtime/builder "msg"="Registering a validating webhook"  "GVK"={"Group":"addons.cluster.x-k8s.io","Version":"v1alpha3","Kind":"ClusterResourceSet"} "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I1111 03:34:33.766342   11022 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-addons-cluster-x-k8s-io-v1alpha3-clusterresourceset"
I1111 03:34:33.766776   11022 server.go:141] controller-runtime/webhook/webhooks "msg"="starting webhook server"  
I1111 03:34:33.767973   11022 certwatcher.go:127] controller-runtime/certwatcher "msg"="Updated current TLS certificate"  
I1111 03:34:33.768249   11022 server.go:199] controller-runtime/webhook "msg"="serving webhook server"  "host"="" "port"=35913
I1111 03:34:33.768448   11022 certwatcher.go:83] controller-runtime/certwatcher "msg"="Starting certificate watcher"  
E1111 03:34:35.923232   11022 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="timed out waiting for the condition"  "cluster"="cluster-cache-test-4np8f/test-cluster"
•E1111 03:34:36.412264   11022 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="the server could not find the requested resource"  "cluster"="cluster-cache-test-ctnpf/test-cluster"
•E1111 03:34:36.981739   11022 cluster_cache.go:366]  "msg"="Error health checking cluster" "error"="Get http://127.0.0.1:39347/?timeout=50ms: dial tcp 127.0.0.1:39347: connect: connection refused"  "cluster"="cluster-cache-test-9t6p9/test-cluster"
•I1111 03:34:37.208812   11022 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}}}
I1111 03:34:37.309214   11022 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="cluster" 
I1111 03:34:37.309290   11022 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="cluster" "worker count"=1
•I1111 03:34:37.572162   11022 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="cluster" 
I1111 03:34:37.589416   11022 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":{}}}
I1111 03:34:37.789936   11022 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="machinedeployment" 
I1111 03:34:37.790005   11022 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="machinedeployment" "worker count"=1
I1111 03:34:37.790272   11022 controller.go:132] controller-runtime/controller "msg"="Starting EventSource" "controller"="machinedeployment" "source"={}
•E1111 03:34:38.317826   11022 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E1111 03:34:38.317896   11022 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-402741799/tls.crt: no such file or directory"  
E1111 03:34:38.317924   11022 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E1111 03:34:38.317951   11022 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-402741799/tls.crt: no such file or directory"  
I1111 03:34:38.318148   11022 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="machinedeployment" 
I1111 03:34:38.318356   11022 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E1111 03:34:38.365966   11022 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:34983/apis/cluster.x-k8s.io/v1alpha3/clusters?allowWatchBookmarks=true&resourceVersion=146&timeout=10s&timeoutSeconds=478&watch=true: dial tcp 127.0.0.1:34983: connect: connection refused


Ran 5 of 5 Specs in 16.503 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestGinkgoSuite (16.50s)
PASS
ok  	sigs.k8s.io/cluster-api/controllers/remote	16.686s
?   	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
I1111 03:34:47.148633   11613 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
E1111 03:34:47.152724   11613 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
I1111 03:34:47.153461   11613 controller.go:136]  "msg"="Reconciliation is paused for this object" "cluster"="foo" "kubeadmControlPlane"="foo" "namespace"="test" 
I1111 03:34:47.153660   11613 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
I1111 03:35:06.677387   11613 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
I1111 03:35:06.677531   11613 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: 1668137673
Will run 1 of 1 specs

E1111 03:35:06.712958   11613 controller.go:126]  "msg"="Failed to retrieve owner Cluster from the API Server" "error"="Cluster.cluster.x-k8s.io \"kcp-foo-foaxum\" not found" "kubeadmControlPlane"="kcp-foo-foaxum" "namespace"="test" 
•

Ran 1 of 1 Specs in 0.032 seconds
SUCCESS! -- 1 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (0.03s)
=== RUN   TestKubeadmControlPlaneReconciler_upgradeControlPlane
I1111 03:35:06.714671   11613 controller.go:246]  "msg"="Reconcile KubeadmControlPlane" "cluster"="kcp-foo-85va56" "kubeadmControlPlane"="kcp-foo-85va56" "namespace"="test" 
I1111 03:35:09.225755   11613 controller.go:331]  "msg"="Rolling out Control Plane machines" "cluster"="kcp-foo-85va56" "kubeadmControlPlane"="kcp-foo-85va56" "namespace"="test" "needRollout"=["kcp-foo-85va56-75947"]
I1111 03:35:09.226029   11613 scale.go:212]  "msg"="Waiting for control plane to pass preflight checks" "cluster"="kcp-foo-85va56" "kubeadmControlPlane"="kcp-foo-85va56" "namespace"="test" "failures"="[machine kcp-foo-85va56-qlzj9 does not have APIServerPodHealthy condition, machine kcp-foo-85va56-qlzj9 does not have ControllerManagerPodHealthy condition, machine kcp-foo-85va56-qlzj9 does not have SchedulerPodHealthy condition, machine kcp-foo-85va56-qlzj9 does not have EtcdPodHealthy condition, machine kcp-foo-85va56-qlzj9 does not have EtcdMemberHealthy condition]"
--- PASS: TestKubeadmControlPlaneReconciler_upgradeControlPlane (2.51s)
PASS
I1111 03:35:09.227781   11613 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
E1111 03:35:09.228023   11613 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="inotify instance already closed"  
E1111 03:35:09.228087   11613 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-353588430/tls.crt: no such file or directory"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/controllers	36.346s
I1111 03:34:44.827856   11573 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"
I1111 03:34:44.827994   11573 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/mutate-cluster-x-k8s-io-v1alpha3-cluster"
I1111 03:34:44.828095   11573 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"
I1111 03:34:44.828113   11573 server.go:121] controller-runtime/webhook "msg"="registering webhook"  "path"="/validate-cluster-x-k8s-io-v1alpha3-cluster"
I1111 03:34:44.828275   11573 webhook.go:102] controller-runtime/builder "msg"="Registering a mutating webhook"  "GVK"={"Group":"cluster.x-k8s.io","Version":"v1alpha3","Kind":"Machine"} "path"="/mutate-cluster-x-k8s-io-v1alpha3-machine"
... skipping 52 lines ...
==================================
Random Seed: 1668137672
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: 1668137672
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
E1111 03:34:46.944632   11573 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"  
E1111 03:34:55.267768   11573 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"  
E1111 03:35:04.253729   11573 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"  
E1111 03:35:15.383962   11573 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"  
E1111 03:35:31.857188   11573 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"  
E1111 03:35:44.865834   11573 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"  
E1111 03:36:02.513371   11573 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"  
E1111 03:36:23.436692   11573 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"  
E1111 03:36:54.453216   11573 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"  
E1111 03:37:39.610425   11573 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
E1111 03:37:39.620878   11573 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E1111 03:37:39.620919   11573 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-399115283/tls.crt: no such file or directory"  
E1111 03:37:39.620938   11573 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E1111 03:37:39.620958   11573 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-399115283/tls.crt: no such file or directory"  
I1111 03:37:39.620980   11573 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  
ok  	sigs.k8s.io/cluster-api/controlplane/kubeadm/internal	187.557s
=== RUN   TestEtcdMembers_WithErrors
--- PASS: TestEtcdMembers_WithErrors (0.00s)
=== RUN   TestEtcdMembers_WithSuccess
--- PASS: TestEtcdMembers_WithSuccess (0.00s)
... skipping 288 lines ...
I1111 03:34:56.092389   11926 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"metadata":{"creationTimestamp":null},"spec":{"controlPlaneEndpoint":{"host":"","port":0}},"status":{"infrastructureReady":false,"controlPlaneInitialized":false}}}
I1111 03:34:56.092534   11926 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"ConfigMap","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I1111 03:34:56.192965   11926 controller.go:155] controller-runtime/controller "msg"="Starting EventSource" "controller"="clusterresourceset" "source"={"Type":{"kind":"Secret","apiVersion":"v1","metadata":{"creationTimestamp":null}}}
I1111 03:34:56.293369   11926 controller.go:162] controller-runtime/controller "msg"="Starting Controller" "controller"="clusterresourceset" 
I1111 03:34:56.293468   11926 controller.go:189] controller-runtime/controller "msg"="Starting workers" "controller"="clusterresourceset" "worker count"=1
I1111 03:34:56.436239   11926 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-afy6xg"} 
E1111 03:34:56.491678   11926 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"
•I1111 03:34:57.563484   11926 clusterresourcesetbinding_controller.go:84]  "msg"="deleting ClusterResourceSetBinding because the owner Cluster no longer exists" "clusterresourcesetbinding"={"Namespace":"default","Name":"cluster-7pxbja"} 
•E1111 03:34:57.626298   11926 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"
E1111 03:34:58.699651   11926 controller.go:257] controller-runtime/controller "msg"="Reconciler error" "error"="failed to get data field from the resource" "controller"="clusterresourceset" "name"="test-clusterresourceset" "namespace"="default"
•E1111 03:34:59.737235   11926 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"
E1111 03:35:00.918729   11926 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"
•E1111 03:35:01.956896   11926 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"
•E1111 03:35:02.985992   11926 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E1111 03:35:02.986037   11926 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-163627688/tls.crt: no such file or directory"  
E1111 03:35:02.986059   11926 certwatcher.go:143] controller-runtime/certwatcher "msg"="error re-watching file" "error"="no such file or directory"  
E1111 03:35:02.986088   11926 certwatcher.go:148] controller-runtime/certwatcher "msg"="error re-reading certificate" "error"="open /tmp/envtest-serving-certs-163627688/tls.crt: no such file or directory"  
E1111 03:35:02.986179   11926 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"
I1111 03:35:02.986271   11926 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourceset" 
I1111 03:35:02.986333   11926 controller.go:203] controller-runtime/controller "msg"="Stopping workers" "controller"="clusterresourcesetbinding" 
I1111 03:35:02.986431   11926 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 5 of 5 Specs in 19.616 seconds
SUCCESS! -- 5 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (19.62s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/addons/controllers	19.715s
?   	sigs.k8s.io/cluster-api/exp/addons/controllers/predicates	[no test files]
=== RUN   TestMachinePoolDefault
=== RUN   TestMachinePoolDefault/for_MachinePool
... skipping 61 lines ...
    --- PASS: TestReconcileMachinePoolBootstrap/new_machinepool,_no_bootstrap_config_or_data (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_data_should_not_change (0.00s)
    --- PASS: TestReconcileMachinePoolBootstrap/existing_machinepool,_bootstrap_provider_is_to_not_ready (0.00s)
=== RUN   TestReconcileMachinePoolInfrastructure
=== RUN   TestReconcileMachinePoolInfrastructure/new_machinepool,_infrastructure_config_ready
=== RUN   TestReconcileMachinePoolInfrastructure/ready_bootstrap,_infra,_and_nodeRef,_machinepool_is_running,_infra_object_is_deleted,_expect_failed
E1111 03:34:48.156380   12143 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 96 lines ...
•I1111 03:35:00.015828   12143 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
•I1111 03:35:00.064476   12143 machinepool_controller_noderef.go:90]  "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes"  
••I1111 03:35:00.067287   12143 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  


Ran 9 of 9 Specs in 11.927 seconds
SUCCESS! -- 9 Passed | 0 Failed | 0 Pending | 0 Skipped
--- PASS: TestAPIs (11.93s)
PASS
ok  	sigs.k8s.io/cluster-api/exp/controllers	12.154s
?   	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 210 lines ...
/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:39
  Should patch a clusterv1.Cluster
  /home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:411
    updating both spec, status, and adding a condition [It]
    /home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:550

    Expected success, but got an error:
        <errors.aggregate | len:1, cap:1>: [
            {
                ErrStatus: {
                    TypeMeta: {Kind: "", APIVersion: ""},
                    ListMeta: {
                        SelfLink: "",
... skipping 29 lines ...
•I1111 03:35:25.374693   15072 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server"  



Summarizing 1 Failure:

[Fail] Patch Helper Should patch a clusterv1.Cluster [It] updating both spec, status, and adding a condition 
/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:580

Ran 14 of 14 Specs in 8.166 seconds
FAIL! -- 13 Passed | 1 Failed | 0 Pending | 0 Skipped
--- FAIL: TestPatch (8.17s)
=== 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)
    --- PASS: TestToUnstructured/with_an_unstructured_object (0.00s)
... skipping 2 lines ...
=== RUN   TestUnsafeFocusedUnstructured/focus=status_w/_condition-setter_object,_should_only_return_status_(without_conditions)_and_common_fields
=== RUN   TestUnsafeFocusedUnstructured/focus=status_w/o_condition-setter_object,_should_only_return_status_and_common_fields
--- PASS: TestUnsafeFocusedUnstructured (0.00s)
    --- PASS: TestUnsafeFocusedUnstructured/focus=spec,_should_only_return_spec_and_common_fields (0.00s)
    --- PASS: TestUnsafeFocusedUnstructured/focus=status_w/_condition-setter_object,_should_only_return_status_(without_conditions)_and_common_fields (0.00s)
    --- PASS: TestUnsafeFocusedUnstructured/focus=status_w/o_condition-setter_object,_should_only_return_status_and_common_fields (0.00s)
FAIL
FAIL	sigs.k8s.io/cluster-api/util/patch	8.202s
?   	sigs.k8s.io/cluster-api/util/predicates	[no test files]
?   	sigs.k8s.io/cluster-api/util/record	[no test files]
=== RUN   TestSortForCreate
--- PASS: TestSortForCreate (0.00s)
PASS
ok  	sigs.k8s.io/cluster-api/util/resource	0.059s
... skipping 88 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