Repository: kubernetes
Issue: [Bug] Scheduler fails to schedule a pod due to a race condition
Labels: kind/bug,sig/scheduling,needs-triage

### What happened?

A bug in the scheduler increases the time spent on scheduling a pod **from <1 second to 5 minutes**.

We discovered the bug when repeating the steps described in a fixed bug report [#106780](https://github.com/kubernetes/kubernetes/issues/106780). The setting and steps are as follows:

We have 1 node with 32Gi memory, and 3 pods to schedule: 
p1 / request 10Gi memory / low-priority,
p2 / request 25Gi memory / medium-priority,
p3 / request 20Gi memory / high-priority.

We perform the following steps:
1. add `p1` and wait until `p1` is running
2. add `p2` and wait until `p1` is terminating; this is because there are not enough resources to host both pods and `p2` has a higher priority.
**Note that at this point, `p2` is not running yet.**
3. add `p3` and wait until `p3` is running; `p2` is pending because `p2` and `p3` cannot coexist on `node0`.
4. re-add `p1` and wait until `p1` is running; `p1` should be able to run since there are enough resources to host both pods: 10 + 20 < 32

Interestingly, we find that if step 4 happened immediately after step 3, then `p1` fails to get scheduled with the reason `Insufficient Memory` and eventually gets scheduled after 5 minutes. If there is some short period between step 3 and step 4 (say 2 seconds), then `p1` is scheduled properly immediately.

#### What is the root cause?

After code and log inspections (see below), we have found the root cause of this bug: it's caused by the race condition between (A) `p1` is re-added and handled by the scheduler and (B) `p2`'s `nominated_node_name` is cleared. If A happens before B, then the bug occurs.

#### Why does 2 second make the difference?

The reason is that `p2`'s `nominated_node_name` is cleared *when it (a nominated pod) is scheduled again and failed*. But as the `p2`'s first schedule failed (need to wait for preemption to finish), it's put to BackoffQueue and need to wait for a few seconds before it's put back to ActionQueue and scheduled again.

So 
1. If `p1` is added before `p2` is scheduled again (without 2s sleep), it will **fail** as `p2`'s `nomianted_node_name` is not cleared.
2. But if we add the 2s sleep, `p2` is scheduled again and its `nominated_node_name` is cleared before `p1` is added. In this case, `p1` will be **schedulable** to node0.

<details><summary>Some scheduler logs of the bug-free and buggy trace</summary>
The lines starting with # are logged just before scheduling p1 and p2. You can notice that their order is reversed in the two traces.

Bug-free trace (B happens before A):
```markdown
# with sleep(2s)
I0814 14:19:47.939731   32287 eventhandlers.go:149] "Add event for unscheduled pod" pod="default/p3"
I0814 14:19:47.939756   32287 schedule_one.go:83] "About to try and schedule pod" pod="default/p3"
I0814 14:19:47.939768   32287 schedule_one.go:96] "Attempting to schedule pod" pod="default/p3"
I0814 14:19:47.939878   32287 default_binder.go:53] "Attempting to bind pod to node" logger="Bind.DefaultBinder" pod="default/p3" node="node0"
I0814 14:19:47.944902   32287 eventhandlers.go:313] "Delete event for scheduled pod" pod="default/p1"
I0814 14:19:47.948208   32287 scheduling_queue.go:1312] "Pod moved to an internal scheduling queue" pod="default/p2" event="AssignedPodDelete" queue="Backoff" hint=1
I0814 14:19:47.948799   32287 schedule_one.go:314] "Successfully bound pod to node" pod="default/p3" node="node0" evaluatedNodes=1 feasibleNodes=1
I0814 14:19:47.948891   32287 eventhandlers.go:201] "Delete event for unscheduled pod" pod="default/p3"
I0814 14:19:47.948901   32287 eventhandlers.go:231] "Add event for scheduled pod" pod="default/p3"
I0814 14:19:47.956662   32287 eventhandlers.go:268] "Update event for scheduled pod" pod="default/p3"
I0814 14:19:49.047040   32287 schedule_one.go:83] "About to try and schedule pod" pod="default/p2"
# I0814 14:19:49.047238   32287 schedule_one.go:96] "Attempting to schedule pod" pod="default/p2"
I0814 14:19:49.047886   32287 schedule_one.go:1055] "Unable to schedule pod; no fit; waiting" pod="default/p2" err="0/1 nodes are available: 1 Insufficient memory. preemption: 0/1 nodes are available: 1 No preemption victims found for incoming pod."
I0814 14:19:49.048895   32287 schedule_one.go:1122] "Updating pod condition" pod="default/p2" conditionType="PodScheduled" conditionStatus="False" conditionReason="Unschedulable"
I0814 14:19:49.064048   32287 eventhandlers.go:174] "Update event for unscheduled pod" pod="default/p2"
I0814 14:19:49.978428   32287 eventhandlers.go:149] "Add event for unscheduled pod" pod="default/p1"
I0814 14:19:49.978562   32287 schedule_one.go:83] "About to try and schedule pod" pod="default/p1"
# I0814 14:19:49.978580   32287 schedule_one.go:96] "Attempting to schedule pod" pod="default/p1"
I0814 14:19:49.978879   32287 default_binder.go:53] "Attempting to bind pod to node" logger="Bind.DefaultBinder" pod="default/p1" node="node0"
I0814 14:19:49.985438   32287 eventhandlers.go:201] "Delete event for unscheduled pod" pod="default/p1"
I0814 14:19:49.985476   32287 eventhandlers.go:231] "Add event for scheduled pod" pod="default/p1"
I0814 14:19:49.985747   32287 schedule_one.go:314] "Successfully bound pod to node" pod="default/p1" node="node0" evaluatedNodes=1 feasibleNodes=1
```

Buggy trace (A happens before B):
```markdown
# without sleep(2s)
I0814 14:17:47.151445   31615 eventhandlers.go:149] "Add event for unscheduled pod" pod="default/p3"
I0814 14:17:47.151515   31615 eventhandlers.go:174] "Update event for unscheduled pod" pod="default/p2"
I0814 14:17:47.151802   31615 schedule_one.go:83] "About to try and schedule pod" pod="default/p3"
I0814 14:17:47.151812   31615 schedule_one.go:96] "Attempting to schedule pod" pod="default/p3"
I0814 14:17:47.151926   31615 default_binder.go:53] "Attempting to bind pod to node" logger="Bind.DefaultBinder" pod="default/p3" node="node0"
I0814 14:17:47.156395   31615 eventhandlers.go:313] "Delete event for scheduled pod" pod="default/p1"
I0814 14:17:47.156444   31615 scheduling_queue.go:1312] "Pod moved to an internal scheduling queue" pod="default/p2" event="AssignedPodDelete" queue="Backoff" hint=1
I0814 14:17:47.160464   31615 eventhandlers.go:201] "Delete event for unscheduled pod" pod="default/p3"
I0814 14:17:47.160479   31615 eventhandlers.go:231] "Add event for scheduled pod" pod="default/p3"
I0814 14:17:47.160514   31615 schedule_one.go:314] "Successfully bound pod to node" pod="default/p3" node="node0" evaluatedNodes=1 feasibleNodes=1
I0814 14:17:47.168539   31615 eventhandlers.go:268] "Update event for scheduled pod" pod="default/p3"
I0814 14:17:47.177608   31615 eventhandlers.go:149] "Add event for unscheduled pod" pod="default/p1"
I0814 14:17:47.177642   31615 schedule_one.go:83] "About to try and schedule pod" pod="default/p1"
# I0814 14:17:47.177650   31615 schedule_one.go:96] "Attempting to schedule pod" pod="default/p1"
I0814 14:17:47.177775   31615 schedule_one.go:1055] "Unable to schedule pod; no fit; waiting" pod="default/p1" err="0/1 nodes are available: 1 Insufficient memory. preemption: 0/1 nodes are available: 1 No preemption victims found for incoming pod."
I0814 14:17:47.177802   31615 schedule_one.go:1122] "Updating pod condition" pod="default/p1" conditionType="PodScheduled" conditionStatus="False" conditionReason="Unschedulable"
I0814 14:17:47.187472   31615 eventhandlers.go:174] "Update event for unscheduled pod" pod="default/p1"
I0814 14:17:48.138665   31615 schedule_one.go:83] "About to try and schedule pod" pod="default/p2"
# I0814 14:17:48.139950   31615 schedule_one.go:96] "Attempting to schedule pod" pod="default/p2"
I0814 14:17:48.140305   31615 schedule_one.go:1055] "Unable to schedule pod; no fit; waiting" pod="default/p2" err="0/1 nodes are available: 1 Insufficient memory. preemption: 0/1 nodes are available: 1 No preemption victims found for incoming pod."
I0814 14:17:48.140582   31615 schedule_one.go:1122] "Updating pod condition" pod="default/p2" conditionType="PodScheduled" conditionStatus="False" conditionReason="Unschedulable"
I0814 14:17:48.156537   31615 eventhandlers.go:174] "Update event for unscheduled pod" pod="default/p2"
```
</details>

#### How to fix it?

1. A potential fix is:
Register all plugins that need to be aware of pods to events triggered by updates to a pod's `nominated_node_name`. This way, a failed pod will be retried as soon as any pod's `nominated_node_name` is cleared.

2. If this is too radical and can cause performance issues, another solution is: 
When a pod is bound to a node with nominated pods, either 
a) re-check the previously nominated pods (that nominated to this node), 
b) or clear the `nominated_node_name` of these nominated pods.
In this way, upcoming pods won't fail unreasonably and won't have to wait 5 minutes for the next retry.


### What did you expect to happen?

`p1` should be immediately scheduled.


### How can we reproduce it (as minimally and precisely as possible)?

We're using [kwok](https://kwok.sigs.k8s.io/) to reproduce this issue.

```yaml
# node0.yaml
apiVersion: v1
kind: Node
metadata:
  name: node0
  labels:
    kubernetes.io/hostname: node0
status:
  allocatable:
    cpu: "32"
    memory: "32Gi"
    pods: "110"
  capacity:
    cpu: "32"
    memory: "32Gi"
    pods: "110"
```

```yaml
# p1.yaml
apiVersion: v1
kind: Pod
metadata:
  name: p1
spec:
  containers:
  - name: p1-container
    image: nginx
    resources:
      requests:
        memory: "10Gi"

  priorityClassName: low-priority
```

```yaml
# p2.yaml
apiVersion: v1
kind: Pod
metadata:
  name: p2
spec:
  containers:
  - name: p2-container
    image: nginx
    resources:
      requests:
        memory: "25Gi"
  priorityClassName: medium-priority
```

```yaml
# p3.yaml
apiVersion: v1
kind: Pod
metadata:
  name: p3
spec:
  containers:
  - name: p3-container
    image: nginx
    resources:
      requests:
        memory: "20Gi"
  priorityClassName: high-priority
```

```yaml
# priority_class.yaml
apiVersion: scheduling.k8s.io/v1
kind: PriorityClass
metadata:
  name: high-priority
value: 1000000
globalDefault: false
description: "This priority class should be used for XYZ service pods only."
---
apiVersion: scheduling.k8s.io/v1
kind: PriorityClass
metadata:
  name: medium-priority
value: 500000
globalDefault: false
description: "This priority class should be used for XYZ service pods only."
---
apiVersion: scheduling.k8s.io/v1
kind: PriorityClass
metadata:
  name: low-priority
value: 0
globalDefault: false
description: "This priority class should be used for XYZ service pods only."
```


```python
# To run this reproduction script, please create a new KWOK cluster first.
# kwokctl create cluster --v DEBUG
# Also need to install the kubernetes python client library,
# and place all yaml files in the same folder with the script.
# ---
# To check the scheduler logs:
# kwokctl logs kube-scheduler
# ---
# To reproduce the bug case, please comment out `sleep(2)` between step 5 and step 6.
# To reproduce the normal case, please add `sleep(2)` between step 5 and step 6.
import unittest
import time
import shutil
import logging
from time import sleep
from os import path, makedirs
from logging import getLogger
from kubernetes import config, watch
from kubernetes.client import *
from kubernetes.utils import *
from time import strftime

logger = getLogger(__name__)
config.load_kube_config()
v1 = CoreV1Api()
k8s_cli = ApiClient()


log_dir = path.dirname(__file__)

if __name__ == "__main__":
    log_path = path.join(log_dir, f"issue-106780-reproduction-{strftime('%Y-%m-%d-%H-%M-%S')}")
    shutil.rmtree(log_path, ignore_errors=True)
    makedirs(log_path, exist_ok=True)
    log_file = path.join(log_path, 'reproduce.log')
    logging.basicConfig(level=logging.INFO,
                        filemode='w',
                        filename=log_file,
                        format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
                        datefmt='%H:%M:%S')
    node0_yaml = path.join(path.dirname(__file__), 'node0.yaml')
    p1_yaml = path.join(path.dirname(__file__), 'p1.yaml')
    p2_yaml = path.join(path.dirname(__file__), 'p2.yaml')
    p3_yaml = path.join(path.dirname(__file__), 'p3.yaml')
    priority_class_yaml = path.join(path.dirname(__file__), 'priority_class.yaml')
    w = watch.Watch()

    # 1. create priority class
    create_from_yaml(k8s_client=k8s_cli, yaml_file=priority_class_yaml)
    logger.info(f"PriorityClass created")

    # 2. add node0
    create_from_yaml(k8s_client=k8s_cli, yaml_file=node0_yaml)
    logger.info(f"Node: node0 created")

    # 3. add p1
    create_from_yaml(k8s_client=k8s_cli, yaml_file=p1_yaml)
    logger.info(f"Pod: p1 added")

    # 3. check p1 is running
    p1_running = False
    for event in w.stream(v1.list_namespaced_pod,
                          field_selector=f'metadata.name=p1',
                          namespace="default",
                          timeout_seconds=int(5)):
        p1 = event['object']
        if event['object'].status.phase == "Running":
            p1_running = True
            logger.info(f"Pod: {p1.metadata.name} scheduled on node {p1.spec.node_name}")
            break
    assert p1_running

    # 4. add p2
    create_from_yaml(k8s_client=k8s_cli, yaml_file=p2_yaml)
    logger.info(f"Pod: p2 added")

    # 4. check p1 is terminating (by p2)
    for event in w.stream(v1.list_namespaced_pod,
                          field_selector=f'metadata.name=p1',
                          namespace="default",
                          timeout_seconds=int(3)):
        logger.info(f"Pod: {event['object'].metadata.name}, event: {event['type']}")
        logger.info(
            f"deletion_timestamp: {event['object'].metadata.deletion_timestamp}, status: {event['object'].status.phase}")
        if event['object'].metadata.deletion_timestamp is not None and event['object'].status.phase in (
        'Pending', 'Running'):
            logger.info(f"Pod: {p1.metadata.name} is terminating")
            break

    # 5. add p3 and wait for p3 running (p3 will terminate p2 / let p2 pending)
    create_from_yaml(k8s_client=k8s_cli, yaml_file=p3_yaml)
    p3_running = False
    for event in w.stream(v1.list_namespaced_pod,
                          field_selector=f'metadata.name=p3',
                          namespace="default",
                          timeout_seconds=int(5)):
        p3 = event['object']
        if p3.status.phase == "Running":
            logger.info(f"Pod: {p3.metadata.name} scheduled on node p3")
            p3_running = True
            break
    assert p3_running

    # sleep(2)  # -> without this on 1.30.2 will cause pod scheduled failed at the first try

    # 6. reapply and check p1 schedulable
    create_from_yaml(k8s_client=k8s_cli, yaml_file=p1_yaml)
    tic = time.time()
    logger.info(f"Pod: p1 re-applied")

    # 7. watch pod1 events and wait it to be scheduled
    p1_running = False
    for event in w.stream(v1.list_namespaced_pod,
                          field_selector=f'metadata.name=p1',
                          namespace="default",
                          timeout_seconds=int(600)):
        p1 = event['object']
        if p1.status.phase == "Running":
            p1_running = True
            logger.info(f"Pod: {p1.metadata.name} scheduled on node {p1.spec.node_name}")
            break

    if not p1_running:
        logger.error(f"Pod: {p1.metadata.name} is not scheduled in 600s")
        assert False
    else:
        logger.info(f"Pod: {p1.metadata.name}, " + f"time between add and scheduled: {time.time() - tic}")


```


### Anything else we need to know?

Tested on 1.30.2

/sig bugs scheduling

### Kubernetes version

<details>

Tested on 1.30.2

</details>


### Cloud provider

<details>

</details>


### OS version

<details>

```console
# On Linux:
$ cat /etc/os-release
# paste output here
$ uname -a
# paste output here

# On Windows:
C:\> wmic os get Caption, Version, BuildNumber, OSArchitecture
# paste output here
```

</details>


### Install tools

<details>

</details>


### Container runtime (CRI) and version (if applicable)

<details>

</details>


### Related plugins (CNI, CSI, ...) and versions (if applicable)

<details>

</details>