升级kubelet到1.7后PostStartHook的错误消息丢失问题追查

发表于 | 更新于

由于centos7 默认的3.10内核在cgroup使用cpu limit并且压力比较大的时候有kernal panic的 bug , 看了下是4.2某个版本后修复了这个问题，所以干脆我们升级了系统的内核到mainline版本4.13, 带来的问题是需要升kubelet到1.7（我们用的是1.7.8这个版本），注意升级kubelet最好机器上没有容器的情况下升级如果可能直接重装就好，人工升级的话需要自行创建/sys/fs/cgroup/rdma/kubepods 目录（这个也是查代码查了半天发现的具体就不说了）

由于我们的业务逻辑上，容器内的服务启动其实是通过PostStartHook实现的，所以非常依赖相关的Event日志来排查问题，结果发现升级到1.7.8版本后，event中的message字段变空的，并且kubelet日志中也没有相关的信息,猜测是版本变动，代码上有所变化所以就去追了下

核心代码在pkg/kubelet/kuberruntime/kuberuntime_container.go

1
2
3
4
5
6
7
8
9
10
11
12
13
// Step 4: execute the post start hook.
if container.Lifecycle != nil && container.Lifecycle.PostStart != nil {
	kubeContainerID := kubecontainer.ContainerID{
		Type: m.runtimeName,
		ID:   containerID,
	}
	msg, handlerErr := m.runner.Run(kubeContainerID, pod, container, container.Lifecycle.PostStart)
	if handlerErr != nil {
		m.recordContainerEvent(pod, container, kubeContainerID.ID, v1.EventTypeWarning, events.FailedPostStartHook, msg)
		m.killContainer(pod, kubeContainerID, container.Name, "FailedPostStartHook", nil)
		return "PostStart Hook Failed", err
	}
}

可以看到Event里面记录的是msg字段，那么很自然的想到应该是msg里面的东西变了，所以一路追下去。PS: 注意这段最后的函数return的地方，return的是个err 但是怎么看也应该是handlerErr，这个直觉给后面查问题带来了帮助

k8s的代码里面interface用的太多，IDE都不能很好的支持，不能直接跳到实际的代码的地方，费劲人肉看找了一圈，Run的函数实际代码就在这个文件下面

1
2
3
4
5
6
7
8
// RunInContainer synchronously executes the command in the container, and returns the output.
func (m *kubeGenericRuntimeManager) RunInContainer(id kubecontainer.ContainerID, cmd []string, timeout time.Duration) ([]byte, error) {
	stdout, stderr, err := m.runtimeService.ExecSync(id.ID, cmd, 0)
	// NOTE(timstclair): This does not correctly interleave stdout & stderr, but should be sufficient
	// for logging purposes. A combined output option will need to be added to the ExecSyncRequest
	// if more precise output ordering is ever required.
	return append(stdout, stderr...), err
}

注意这个里面的注释：This does not correctly interleave stdout & stderr

然后ExecSync的代码实际在[pkg/kubelet/dockershim/docker_streaming.go]

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
func (r *streamingRuntime) Exec(containerID string, cmd []string, in io.Reader, out, err io.WriteCloser, tty bool, resize <-chan remotecommand.TerminalSize) error {
	return r.exec(containerID, cmd, in, out, err, tty, resize, 0)
}

// Internal version of Exec adds a timeout.
func (r *streamingRuntime) exec(containerID string, cmd []string, in io.Reader, out, errw io.WriteCloser, tty bool, resize <-chan remotecommand.TerminalSize, timeout time.Duration) error {
	container, err := checkContainerStatus(r.client, containerID)
	if err != nil {
		return err
	}
	return r.execHandler.ExecInContainer(r.client, container, cmd, in, out, errw, tty, resize, timeout)
}

func (r *streamingRuntime) Attach(containerID string, in io.Reader, out, errw io.WriteCloser, tty bool, resize <-chan remotecommand.TerminalSize) error {
	_, err := checkContainerStatus(r.client, containerID)
	if err != nil {
		return err
	}

	return attachContainer(r.client, containerID, in, out, errw, tty, resize)
}

可以看到这段代码是进到docker容器中类似于exec的方式执行了hook脚本，并且把标准输入和标准输出获取了出来。所以Msg应该是脚本的标准输出和标准错误，这里看了半天，感觉没有半毛钱毛病，并且试了下让脚本输出点东西到1和2里面，但是也没Get到任何信息

然后想起了2件事情：

  1. 那个注释：貌似这段代码根本就没成功实现把1和2拿出来的功能
  2. 感觉写错的那个err字段，应该是handlerErr的，并且平常获取到的错误信息command ‘/xxxxxx’ exited with 1: Hook do errexit, this is stderr

觉得应该return的和丢到event里面的应该是handlerErr ，找了下1.6的代码，发现

有一段

1
err := fmt.Errorf("PostStart handler: %v", handlerErr)

然后去了找了下发现有个大哥在这个代码里面删了，2333
https://github.com/kubernetes/kubernetes/commit/a02f10fa3a956a2fc1fe0328f58b7b1cea548264

我自行改了下代码编译了个kubelet跑了试了下，发现确实是这么个问题。
去提了个Issue https://github.com/kubernetes/kubernetes/issues/54671 想说之后的版本能修下来着，
但是可惜的是k8s master的代码和分支已经很不一样了，并且社区也不修1.7这个系列的问题，再发小版本了。

后续：

  1. 本来我打算是自己编译kubelet自己维护的，但是组内的同学不太同意，毕竟我们人少，未来维护是问题
  2. 发现业务逻辑依赖这个有点风险，所以我们最终改成了hook脚本自己把错误汇报上来的机制