记录一次排查UnexpectedAdmissionError问题的过程

1. 问题

环境

3master节点+N个GPU节点

kubelet版本:v1.19.4

kubernetes版本:v1.19.4

生产环境K8S集群,莫名其妙的出现大量UnexpectedAdmissionError状态的Pod,导致部分任务执行异常,出现这种情况时,节点的资源是足以支持运行一个GPU Pod的。

报的错误:

Allocate failed due to requested number of devices unavailable for nvidia.com/gpu. Requested: 1, Available: 0, which is unexpected

因为Pod的调度都是指定了spec.nodeName属性的,所以跳过了Pending状态强制进行调度,在资源不足的情况下,就出现了UnexpectedAdmissionError异常。

image-20231207095349410

2.排查过程

确定节点资源是否正常

 kubectl describe node <node-name>

image-20231207095740526

通过describe命令可以看到节点的GPU卡是正常的,然后可以去节点上通过nvidia-dcgm,确定GPU设备是否健康

nvidia-dcgm:nvidia官网

在确定节点和GPU设备都是没问题的情况下,那么开始排查出现问题的原因

通过查看日志和源码,可以定位到日志是在manager.go#devicesToAllocate方法的698行出现

	// resource=nvidia.com/gpu
	// Gets Devices in use.
	devicesInUse := m.allocatedDevices[resource]
	// Gets Available devices.
	available := m.healthyDevices[resource].Difference(devicesInUse)
	if available.Len() < needed {
		return nil, fmt.Errorf("requested number of devices unavailable for %s. Requested: %d, Available: %d", resource, needed, available.Len())
	}

也就是,从健康的GPU集合中去除了已使用的GPU后,可用GPU数量少于所需要的数量,但是通过上面的排查,在创建的Pod.cm.resource.limit:nvidia.com/gpu=1的情况下,理论上应该是成功的,这里出现了报错,那么肯定是GPU卡被占用了。

查看kubelet日志,定位具体问题,日志位于/var/log/messages文件,由于kubelet默认日志级别为--v=2,这里需要将其更改为--v=4

查看是否有/etc/kubernetes/kubelet.env文件,如果有,直接更改KUBE_LOG_LEVEL配置

KUBE_LOGTOSTDERR="--logtostderr=true"
KUBE_LOG_LEVEL="--v=4"

如果没有,则修改/usr/lib/systemd/system/kubelet.service.d/10-kubeadm.conf文件

添加Environment

Environment="KUBE_LOGTOSTDERR=--logtostderr=true"
Environment="KUBE_LOG_LEVEL=--v=4"

修改ExecStart命令,在参数位追加$KUBE_LOGTOSTDERR $KUBE_LOG_LEVEL

ExecStart=/usr/bin/kubelet $KUBE_LOGTOSTDERR $KUBE_LOG_LEVEL $KUBELET_KUBECONFIG_ARGS $KUBELET_CONFIG_ARGS $KUBELET_KUBEADM_ARGS $KUBELET_EXTRA_ARGS

修改后需要重启kubelet

systemctl daemon-reload && systemctl restart kubelet

通过grep命令查看关键日志

grep "package-instance-42895-test-4461" messages

从日志中发现,kubelet监听到了两次创建同一个Pod的事件,也就是为一个Job创建了两个Pod

但是Job的配置都是为1

spec:
  completions: 1
  backoffLimit: 0
  parallelism: 1

image-20231207102252049

在这样的配置下,应该只有一次创建Pod的事件才对。

再分别查看两次Pod的资源分配日志

通过less messages命令查看详细的日志过程

image-20231207102820350

从日志中可以看出,第一个Pod分配GPU资源是成功的

而在第二个Pod分配GPU资源时,就提示分配失败

image-20231207102934592

至此问题就定位到了,是因为kubelet本应只创建一个Pod,但是确监听到了多次创建Pod的事件。

从这个情况来看,应当所有的任务都失败才对,但只有小部分任务失败了,继续查看日志

image-20231207103436250

在下面的日志可以看到,kubelet随后就监听到了DELETE事件,删除了一个Pod,虽然在这个日志中删除的是创建失败的Pod

但是多观察几个Pod就会发现,删除完全的随机的,并不是根据状态来的,所以就会出现部分任务失败,但是大部分任务都成功的情况。

从上面的排查过程来看,kubeletenodegpu device都是没有问题的,那么,继续往上排查scheduler

同样的,scheduler的日志级别默认也是--v=2,这里也需要改成--v=4,修改kube-scheduler.yaml文件

vim /etc/kubernetes/manifests/kube-scheduler.yaml

command中追加一行--v=4

spec:
  containers:
  - command:
    - kube-scheduler
    - --authentication-kubeconfig=/etc/kubernetes/scheduler.conf
    - --authorization-kubeconfig=/etc/kubernetes/scheduler.conf
    - --bind-address=0.0.0.0
    - --kubeconfig=/etc/kubernetes/scheduler.conf
    - --leader-elect=false
    - --leader-elect-lease-duration=15s
    - --leader-elect-renew-deadline=10s
    - --port=0
    - --v=4

更改文件后保存,等待scheduler自动重建。注意重建后日志会清空,所以需要等待下次调度再次重新进行问题排查

然后通过kubectl logs命令,查看三个scheduler的调度日志

kubectl logs -n kube-system kube-scheduler-master-1| grep package-instance-42895-test-4461

kubectl logs -n kube-system kube-scheduler-master-2| grep package-instance-42895-test-4461

kubectl logs -n kube-system kube-scheduler-master-3| grep package-instance-42895-test-4461

[root@master-1 ~]# kubectl logs -n kube-system kube-scheduler-master-1| grep package-instance-42895-test-4461
I1206 03:23:08.641125       1 eventhandlers.go:225] add event for scheduled pod default/package-instance-42895-test-4461-xxp5t
I1206 03:23:08.641463       1 eventhandlers.go:225] add event for scheduled pod default/package-instance-42895-test-4461-72hdl
I1206 03:23:08.866294       1 eventhandlers.go:283] delete event for scheduled pod default/package-instance-42895-test-4461-72hdl

[root@master-1 ~]# kubectl logs -n kube-system kube-scheduler-master-2| grep package-instance-42895-test-4461
I1206 03:23:08.641125       1 eventhandlers.go:225] add event for scheduled pod default/package-instance-42895-test-4461-xxp5t
I1206 03:23:08.641463       1 eventhandlers.go:225] add event for scheduled pod default/package-instance-42895-test-4461-72hdl
I1206 03:23:08.866294       1 eventhandlers.go:283] delete event for scheduled pod default/package-instance-42895-test-4461-72hdl

[root@master-1 ~]# kubectl logs -n kube-system kube-scheduler-master-3| grep package-instance-42895-test-4461

从上面的日志可以看到,Pod确实被调度了两次,但是,schduler只是负责调度Pod,并不会控制Pod创建的数量。

而且,理论上,应该只有一个leader级别的schduler处于工作状态,其他两个schduler,应当是处于睡眠状态,不进行工作才对,也就说,其他的schduler不应该监听到调度事件。

虽然问题不在此,但是从这里可以发现schduler的部署是有问题的,查看schduler配置

spec:
  containers:
  - command:
    - kube-scheduler
    - --authentication-kubeconfig=/etc/kubernetes/scheduler.conf
    - --authorization-kubeconfig=/etc/kubernetes/scheduler.conf
    - --bind-address=0.0.0.0
    - --kubeconfig=/etc/kubernetes/scheduler.conf
    - --leader-elect=false
    - --leader-elect-lease-duration=15s
    - --leader-elect-renew-deadline=10s
    - --port=0
    - --v=4

在检查了三个节点的schduler配置后,发现有一个节点的schduler配置中,--leader-elect被设置成了fasle

Kubernetes的调度器可以使用leader选举来确保只有一个实例处于活跃状态,负责决策和分配Pod。一旦调度器的活跃实例失效,其他备用实例可以进行leader选举,确保集群的Pod能够被适当地调度到可用的节点上。

同样,如果多个调度器实例都设置为--leader-elect=false,它们将尝试同时管理Pod的调度决策,可能会导致混乱、资源冲突以及不一致的状态。

在这可以确定是--leader-elect=false导致的出现了多个leader级schduler,将此配置更改为--leader-elect=true

等待schudler重建,修复了schudler多leader的问题,但是,Pod重复调度的问题依旧没有解决,查看Pod调度调度流程

image-20231207110614916

从流程图上可以看出,创建Pod的请求,是由Job Controller发出的,在kubernetes中有很多的控制器,例如

Job ControllerDeployment Controller,这些控制器由控制平面进行管理kube-controller-manger

结合上面schduler的可以得出结论。是在Job Controller中,发出了两次创建Pod的请求,而kube-controller-manger集群跟schduler集群一样,理论上应该只有一个leader级别的处于工作中的状态,其他两个都应该处于休眠状态。但是这里发起了两次创建请求,显然是有一个以上的leader级kube-controller-manger,通过查看配置文件,问题跟schduler是一样的

YAML文件路径/etc/kubernetes/manifests/kube-controller-manager.yaml

有一个节点的YAML文件中--leader-elect=false,这个配置也被设置为了false,导致的出现了多个ledaer级的控制平面,从而导致Pod被多次创建

验证方式也是同样的,通过kubectl logs命令,查看三个kube-controller-manager的监听日志,发现有两个控制平面监听到了Create Job事件,从而导致的这次问题。

kubectl logs -n kube-system  kube-controller-manager-master-1 |grep package-instance-42895-test-4461

3. 解决方案

通过修改/etc/kubernetes/manifests/kube-scheduler.yaml/etc/kubernetes/manifests/kube-controller-manager.yaml两个YAML文件中的--leader-elect配置,将其修改为true,即可解决问题。

--leader-elect=false
Logo

一起探索未来云端世界的核心,云原生技术专区带您领略创新、高效和可扩展的云计算解决方案,引领您在数字化时代的成功之路。

更多推荐