periodic-cluster-api-test-release-0-3 #1590910385907568640
Recent runs || View in Spyglass
| Result | FAILURE |
| Tests | 0 failed / 0 succeeded |
| Started | |
| Elapsed | 4m32s |
| Revision | release-0.3 |
... 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" [32m•[0mE1111 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" [1m[32mRan 1 of 1 Specs in 13.285 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- 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" [32m•[0mE1111 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" [32m•[0mE1111 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" [32m•[0mI1111 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 [32m•[0mI1111 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"={} [32m•[0mE1111 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 [1m[32mRan 5 of 5 Specs in 16.503 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- 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: [1m1668137673[0m Will run [1m1[0m of [1m1[0m 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" [32m•[0m [1m[32mRan 1 of 1 Specs in 0.032 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m1 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- 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: [1m1668137672[0m Will run [1m7[0m of [1m7[0m specs [32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m [1m[32mRan 7 of 7 Specs in 0.000 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m7 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- PASS: TestControlPlane (0.00s) === RUN TestHasUnhealthyMachine --- PASS: TestHasUnhealthyMachine (0.00s) === RUN TestNewFailureDomainPicker === RUN TestNewFailureDomainPicker/simple === RUN TestNewFailureDomainPicker/no_machines ... skipping 111 lines ... ======================================= Random Seed: [1m1668137672[0m Will run [1m7[0m of [1m7[0m specs [32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m[32m•[0m [1m[32mRan 7 of 7 Specs in 0.001 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m7 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- 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" [32m•[0mI1111 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"} [32m•[0mE1111 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" [32m•[0mE1111 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" [32m•[0mE1111 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" [32m•[0mE1111 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" [1m[32mRan 5 of 5 Specs in 19.616 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m5 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- 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 ... [32m•[0mI1111 03:35:00.015828 12143 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0mI1111 03:35:00.064476 12143 machinepool_controller_noderef.go:90] "msg"="Cannot assign NodeRefs to MachinePool, no matching Nodes" [32m•[0m[32m•[0mI1111 03:35:00.067287 12143 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [1m[32mRan 9 of 9 Specs in 11.927 seconds[0m [1m[32mSUCCESS![0m -- [32m[1m9 Passed[0m | [91m[1m0 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- 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 ... [90m/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:39[0m Should patch a clusterv1.Cluster [90m/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:411[0m [91m[1mupdating both spec, status, and adding a condition [It][0m [90m/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:550[0m [91mExpected success, but got an error: <errors.aggregate | len:1, cap:1>: [ { ErrStatus: { TypeMeta: {Kind: "", APIVersion: ""}, ListMeta: { SelfLink: "", ... skipping 29 lines ... [32m•[0mI1111 03:35:25.374693 15072 server.go:208] controller-runtime/webhook "msg"="shutting down webhook server" [91m[1mSummarizing 1 Failure:[0m [91m[1m[Fail] [0m[90mPatch Helper [0m[0mShould patch a clusterv1.Cluster [0m[91m[1m[It] updating both spec, status, and adding a condition [0m [37m/home/prow/go/src/sigs.k8s.io/cluster-api/util/patch/patch_test.go:580[0m [1m[91mRan 14 of 14 Specs in 8.166 seconds[0m [1m[91mFAIL![0m -- [32m[1m13 Passed[0m | [91m[1m1 Failed[0m | [33m[1m0 Pending[0m | [36m[1m0 Skipped[0m --- 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