Description of problem: When added payload, autoscaler logs "pod.Status.StartTime is nil for pod scale-up-788b7f7c75-tpjrh. Should not reach here" every 10s. Version-Release number of selected component (if applicable): 4.4.0-0.nightly-2020-02-17-211020 How reproducible: Always Steps to Reproduce: 1.Create clusterautoscaler and machineautoscalers 2.And payload to scale up the cluster 3.Check autoscaler log Actual results: Autoscaler logs "pod.Status.StartTime is nil for pod scale-up-788b7f7c75-tpjrh. Should not reach here" every 10s E0219 08:18:00.778564 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-hv7kg. Should not reach here. E0219 08:18:00.778583 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-nm7wm. Should not reach here. E0219 08:18:00.778587 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-tpjrh. Should not reach here. E0219 08:18:00.778591 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-6znrh. Should not reach here. .. E0219 08:18:00.778861 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-nm7wm. Should not reach here. E0219 08:18:00.778864 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-t89pm. Should not reach here. E0219 08:18:00.778866 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-6znrh. Should not reach here. I0219 08:18:00.779889 1 static_autoscaler.go:343] No unschedulable pods I0219 08:18:00.780078 1 pre_filtering_processor.go:66] Skipping zhsun9-wxcfz-worker-b-ql5vx - node group min size reached W0219 08:18:10.804681 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-s4hsz" has no providerID W0219 08:18:10.804760 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-h4ghm" has no providerID W0219 08:18:10.804769 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-b45z4" has no providerID W0219 08:18:10.804774 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-frjdj" has no providerID W0219 08:18:10.804781 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-7nqf7" has no providerID E0219 08:18:10.805516 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-hv7kg. Should not reach here. E0219 08:18:10.805532 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-t89pm. Should not reach here. E0219 08:18:10.805536 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-tpjrh. Should not reach here. E0219 08:18:10.805539 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-nm7wm. Should not reach here. .. E0219 08:18:10.805782 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-t89pm. Should not reach here. E0219 08:18:10.805785 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-6znrh. Should not reach here. E0219 08:18:10.805788 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-nm7wm. Should not reach here. I0219 08:18:10.806795 1 static_autoscaler.go:343] No unschedulable pods I0219 08:18:10.806964 1 pre_filtering_processor.go:66] Skipping zhsun9-wxcfz-worker-b-ql5vx - node group min size reached W0219 08:18:20.823860 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-s4hsz" has no providerID W0219 08:18:20.823891 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-h4ghm" has no providerID W0219 08:18:20.823896 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-b45z4" has no providerID W0219 08:18:20.823901 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-frjdj" has no providerID W0219 08:18:20.823910 1 machineapi_controller.go:305] Machine "zhsun9-wxcfz-worker-7nqf7" has no providerID E0219 08:18:20.824607 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-tpjrh. Should not reach here. E0219 08:18:20.824622 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-nm7wm. Should not reach here. E0219 08:18:20.824626 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-5wnvw. Should not reach here. E0219 08:18:20.824630 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-6znrh. Should not reach here. .. E0219 08:18:20.824850 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-t89pm. Should not reach here. E0219 08:18:20.824853 1 utils.go:60] pod.Status.StartTime is nil for pod scale-up-788b7f7c75-6znrh. Should not reach here Expected results: No such logs. Additional info:
Could you specify in which provider did this happen and share must gather logs?
I've seen this myself as well. These are regular error logs from the scheduler component vendored in the autoscaler. There's no much we can do as is all behaving as intended, I agree though these logs are noisy. I'll try to put a PR to modify the move that logging on the scheduling from error to v(3)
This will go away in the next autoscaler rebase which will fetch https://github.com/kubernetes/kubernetes/commit/3c5c7191a9f39b91270565cc55f2b105e6840f74
Should be fixed by https://github.com/openshift/kubernetes-autoscaler/pull/139
Validated on : [miyadav@miyadav ManualRun]$ oc get clusterversion NAME VERSION AVAILABLE PROGRESSING SINCE STATUS version 4.5.0-0.nightly-2020-04-05-214011 True False 16m Cluster version is 4.5.0-0.nightly-2020-04-05-214011 Steps to Reproduce: 1.Create clusterautoscaler and machineautoscalers 2.And payload to scale up the cluster 3.Check autoscaler log Actual & Expected results: I0406 05:31:56.730784 1 node_instances_cache.go:156] Start refreshing cloud provider node instances cache I0406 05:31:56.731487 1 node_instances_cache.go:168] Refresh cloud provider node instances cache finished, refresh took 672.301µs I0406 05:31:57.708370 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:31:57.709450 1 static_autoscaler.go:389] No unschedulable pods I0406 05:32:07.724529 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:32:07.725624 1 static_autoscaler.go:389] No unschedulable pods I0406 05:32:17.741691 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:32:17.742652 1 static_autoscaler.go:389] No unschedulable pods I0406 05:32:27.760402 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:32:27.761698 1 static_autoscaler.go:389] No unschedulable pods I0406 05:32:37.780758 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:32:37.781781 1 static_autoscaler.go:389] No unschedulable pods I0406 05:32:47.799243 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:32:47.800221 1 static_autoscaler.go:389] No unschedulable pods I0406 05:32:57.819699 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:32:57.820723 1 static_autoscaler.go:389] No unschedulable pods I0406 05:33:07.844115 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:33:07.845477 1 static_autoscaler.go:389] No unschedulable pods I0406 05:33:17.863672 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:33:17.864476 1 static_autoscaler.go:389] No unschedulable pods I0406 05:33:27.880324 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:33:27.881845 1 static_autoscaler.go:389] No unschedulable pods I0406 05:33:37.903270 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:33:37.904390 1 static_autoscaler.go:389] No unschedulable pods I0406 05:33:47.922041 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:33:47.923189 1 static_autoscaler.go:389] No unschedulable pods I0406 05:33:56.731710 1 node_instances_cache.go:156] Start refreshing cloud provider node instances cache I0406 05:33:56.732308 1 node_instances_cache.go:168] Refresh cloud provider node instances cache finished, refresh took 559.886µs I0406 05:33:57.941487 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:33:57.942768 1 static_autoscaler.go:389] No unschedulable pods I0406 05:33:57.943965 1 scale_down.go:867] No candidates for scale down I0406 05:34:07.960724 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:34:07.961175 1 static_autoscaler.go:389] No unschedulable pods I0406 05:34:07.962110 1 scale_down.go:867] No candidates for scale down I0406 05:34:17.977036 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:34:17.977428 1 static_autoscaler.go:389] No unschedulable pods I0406 05:34:17.978057 1 scale_down.go:867] No candidates for scale down I0406 05:34:27.995542 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:34:27.996025 1 static_autoscaler.go:389] No unschedulable pods I0406 05:34:27.996994 1 scale_down.go:867] No candidates for scale down I0406 05:34:38.012805 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:34:38.013402 1 static_autoscaler.go:389] No unschedulable pods I0406 05:34:38.014323 1 scale_down.go:867] No candidates for scale down I0406 05:34:48.029274 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:34:48.029992 1 static_autoscaler.go:389] No unschedulable pods I0406 05:34:48.030972 1 scale_down.go:867] No candidates for scale down I0406 05:34:58.045924 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:34:58.046525 1 static_autoscaler.go:389] No unschedulable pods I0406 05:34:58.047517 1 scale_down.go:867] No candidates for scale down I0406 05:35:08.061848 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:35:08.062344 1 static_autoscaler.go:389] No unschedulable pods I0406 05:35:08.063211 1 scale_down.go:867] No candidates for scale down I0406 05:35:18.078037 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:35:18.078470 1 static_autoscaler.go:389] No unschedulable pods I0406 05:35:18.079426 1 scale_down.go:867] No candidates for scale down I0406 05:35:28.099881 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:35:28.100310 1 static_autoscaler.go:389] No unschedulable pods I0406 05:35:28.101306 1 scale_down.go:867] No candidates for scale down I0406 05:35:38.116252 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:35:38.116793 1 static_autoscaler.go:389] No unschedulable pods I0406 05:35:38.117663 1 scale_down.go:867] No candidates for scale down I0406 05:35:48.132621 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:35:48.133116 1 static_autoscaler.go:389] No unschedulable pods I0406 05:35:48.134082 1 scale_down.go:867] No candidates for scale down I0406 05:35:56.732543 1 node_instances_cache.go:156] Start refreshing cloud provider node instances cache I0406 05:35:56.733233 1 node_instances_cache.go:168] Refresh cloud provider node instances cache finished, refresh took 657.119µs I0406 05:35:58.152584 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:35:58.154497 1 static_autoscaler.go:389] No unschedulable pods I0406 05:35:58.160918 1 scale_down.go:867] No candidates for scale down I0406 05:36:08.175882 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:36:08.176365 1 static_autoscaler.go:389] No unschedulable pods I0406 05:36:08.177215 1 scale_down.go:867] No candidates for scale down I0406 05:36:18.192198 1 static_autoscaler.go:311] 2 unregistered nodes present I0406 05:36:18.192980 1 static_autoscaler.go:389] No unschedulable pods I0406 05:36:18.194136 1 scale_down.go:867] No candidates for scale down . . .
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2020:2409'