一次“诡异”的容器Unix Socket通信问题分析

vlambda
2021-07-15

一次“诡异”的容器Unix Socket通信问题分析

一、背景

为了实现全链路拓扑监控，期望一层Nginx（Openresty）具备和Ingress-Nginx-Controller一样的的Metrics监控指标。通过分析Ingress-Nginx-Controller的Metrics源码并将其抽离改造（可参考另一篇分析文档：）为nginx-custom-metrics进程集成到一层Nginx的容器中，实现对Nginx的监控。其中Metrics由process-exporter，nginx_status，和socket三部分数据组成，socket部分监控数据是通过Unix Socket的方式由Nginx中的Lua脚本采集发送到/tmp/prometheus-nginx.socket文件中，然后由监听/tmp/prometheus-nginx.socket文件的nginx-custom-metrics进程获取并以Metrics的方式暴露出来。

二、问题

在阿里云ECS主机上运行的Nginx容器中执行nginx-custom-metrics进程后，开始一切正常，也能获取到想要的数据。测试正常获取监控数据如下：

一次“诡异”的容器Unix Socket通信问题分析

运行一段时间后（不确定，一般在3-8分钟）出现socket部分的数据无法获取。但是其余两部分的数据仍然能够正常获取。此时，Nginx日志报如下错误：

一次“诡异”的容器Unix Socket通信问题分析

此时nginx-custom-metrics的日志如下，没有“Metrics message”的消息了。

一次“诡异”的容器Unix Socket通信问题分析

由此可见，是Lua代码无法与/tmp/prometheus-nginx.socket文件建立连接。重启nginx-custom-metrics进程后恢复。但是过一段时间后继续出现问题。只有在重启后的几分钟内是正常的。

三、分析

首先，先看下关键代码部分：

【服务端代码：】

一次“诡异”的容器Unix Socket通信问题分析

【客户端代码：】

一次“诡异”的容器Unix Socket通信问题分析

通信代码和逻辑都很简单！为什么会突然连接不上呢？是Lua客户端的问题？还是nginx-custom-metrics服务端的问题呢？通过重启nginx-custom-metrics服务可以短暂恢复，初步判断是nginx-custom-metrics程序的问题。但是程序日志和内核日志没有任何的报错。查看socket文件的监听情况:

一次“诡异”的容器Unix Socket通信问题分析

监听也是正常的，使用nc手工连接/tmp/prometheus-nginx.socket文件：

一次“诡异”的容器Unix Socket通信问题分析

也是一样的错误，此时断定是服务端的问题。strace一顿之后没有任何信息，顿时无法继续分析。于是，我给nginx-custom-metrics程序相关的每一个步骤都加上日志打印（如上服务端代码注释部分的println），重新来一遍。发现出问题时加的日志一个都没有打印，但是没有打印日志也是一个信息，可以判断程序执行到了哪里，由此判断是“阻塞”在了accept函数里了。再回看一下strace错误是Connection refused，connect()内核函数返回ECONNREFUSED。unix socket相关的内核代码在net/unix/af_unix.c文件中，去搜一下看看：

一次“诡异”的容器Unix Socket通信问题分析

看了下可能和socket文件的inode，权限有关系。难道是socket文件权限被改了？查看一下：

# ls -lrth /tmp/prometheus-nginx.socketsrwxrwxrwx 1 root root 0 6月 28 16:41 /tmp/prometheus-nginx.socket

权限没问题，stat再看看更加详细的信息：

# stat /tmp/prometheus-nginx.socket File: ‘/tmp/prometheus-nginx.socket’ Size: 0 Blocks: 0 IO Block: 4096 socketDevice: 9fh/159d Inode: 12853752 Links: 1Access: (0777/srwxrwxrwx) Uid: ( 0/ root) Gid: ( 0/ root)Access: 2021-06-28 16:34:59.447322491 +0800Modify: 2021-06-28 16:34:59.214314837 +0800Change: 2021-06-28 16:34:59.214314837 +0800 Birth: -

发现Modify的时间和出现问题的时间点很接近，重新来一遍，观察socket文件的情况。

一次“诡异”的容器Unix Socket通信问题分析

这一次发现socket文件的inode发生了变化，确认证实socket文件重建了（文件重建才会导致inode变）。但是被谁重建了呢？nginx-custom-metrics进程还运行的好好的。没办法了，跟踪一下内核函数吧。看看这个时候到底在干啥？使用SystemTap跟踪一下net/unix/af_unix.c文件的函数看看：

# cat unix-socket-trace.stp#!/usr/bin/env stap
probe kernel.function("unix_accept@net/unix/af_unix.c").call, kernel.function("unix_stream_connect@net/unix/af_unix.c").call { if (execname() == "nginx-custom-me" || execname() == "nginx") { printf ("###%-25s %s -> %s\n", ctime(gettimeofday_s()), thread_indent(1), probefunc()) #print_backtrace(); // 打印打印调用栈 }}
probe kernel.function("unix_accept@net/unix/af_unix.c").return, kernel.function("unix_stream_connect@net/unix/af_unix.c").return { if (execname() == "nginx-custom-me" || execname() == "nginx") { printf ("---%-25d %s <- %s\n", gettimeofday_us()-@entry(gettimeofday_us()), thread_indent(-1), probefunc()) #print_backtrace(); // 打印打印调用栈 }}
// 执行跟踪# ./unix-socket-trace.stp

执行后，可以看到：

一次“诡异”的容器Unix Socket通信问题分析

nginx-custom-metrics进程在出现问题的时候居然会有unix_stream_connect的调用，程序没有这个逻辑啊？修改下跟踪脚本打印更加详细的信息看看，因为知道了是nginx-custom-metrics程序的问题，所有我们只过滤服务端的进程，并且探测af_unix.c文件的所有函数：

# cat unix-socket-trace.stp#!/usr/bin/env stap
probe kernel.function("*@net/unix/af_unix.c").call { if (execname() == "nginx-custom-me") { printf ("###%-25s %s -> %s\n", ctime(gettimeofday_s()), thread_indent(1), probefunc()) }}
probe kernel.function("*@net/unix/af_unix.c").return { if (execname() == "nginx-custom-me") { printf ("---%-25d %s <- %s\n", gettimeofday_us()-@entry(gettimeofday_us()), thread_indent(-1), probefunc()) }}
// 执行跟踪# ./unix-socket-trace.stp

重新执行后出问题时打印信息如下：

###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_create###Wed Jun 30 03:48:23 2021 17 nginx-custom-me(225893): -> unix_create1###Wed Jun 30 03:48:23 2021 25 nginx-custom-me(225893): -> __unix_insert_socket---6 34 nginx-custom-me(225893): <- unix_create1---26 46 nginx-custom-me(225893): <- unix_create---38 49 nginx-custom-me(225893): <- __sock_create###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_stream_connect###Wed Jun 30 03:48:23 2021 15 nginx-custom-me(225893): -> unix_mkname---4 22 nginx-custom-me(225893): <- unix_stream_connect###Wed Jun 30 03:48:23 2021 26 nginx-custom-me(225893): -> unix_create1###Wed Jun 30 03:48:23 2021 35 nginx-custom-me(225893): -> __unix_insert_socket---3 43 nginx-custom-me(225893): <- unix_create1---16 45 nginx-custom-me(225893): <- unix_stream_connect###Wed Jun 30 03:48:23 2021 49 nginx-custom-me(225893): -> unix_find_other---24 77 nginx-custom-me(225893): <- unix_stream_connect###Wed Jun 30 03:48:23 2021 82 nginx-custom-me(225893): -> unix_write_space---4 88 nginx-custom-me(225893): <- sock_wfree###Wed Jun 30 03:48:23 2021 94 nginx-custom-me(225893): -> unix_release_sock###Wed Jun 30 03:48:23 2021 101 nginx-custom-me(225893): -> unix_sock_destructor---4 108 nginx-custom-me(225893): <- __sk_destruct---16 112 nginx-custom-me(225893): <- unix_stream_connect---105 115 nginx-custom-me(225893): <- SYSC_connect###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_release###Wed Jun 30 03:48:23 2021 6 nginx-custom-me(225893): -> unix_release_sock###Wed Jun 30 03:48:23 2021 10 nginx-custom-me(225893): -> unix_sock_destructor---0 13 nginx-custom-me(225893): <- __sk_destruct---6 15 nginx-custom-me(225893): <- unix_release---15 17 nginx-custom-me(225893): <- sock_release###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_create###Wed Jun 30 03:48:23 2021 8 nginx-custom-me(225893): -> unix_create1###Wed Jun 30 03:48:23 2021 12 nginx-custom-me(225893): -> __unix_insert_socket---1 15 nginx-custom-me(225893): <- unix_create1---7 17 nginx-custom-me(225893): <- unix_create---16 19 nginx-custom-me(225893): <- __sock_create###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_stream_connect###Wed Jun 30 03:48:23 2021 4 nginx-custom-me(225893): -> unix_mkname---1 7 nginx-custom-me(225893): <- unix_stream_connect###Wed Jun 30 03:48:23 2021 10 nginx-custom-me(225893): -> unix_create1###Wed Jun 30 03:48:23 2021 14 nginx-custom-me(225893): -> __unix_insert_socket---1 16 nginx-custom-me(225893): <- unix_create1---7 18 nginx-custom-me(225893): <- unix_stream_connect###Wed Jun 30 03:48:23 2021 21 nginx-custom-me(225893): -> unix_find_other---3 27 nginx-custom-me(225893): <- unix_stream_connect###Wed Jun 30 03:48:23 2021 30 nginx-custom-me(225893): -> unix_write_space---0 33 nginx-custom-me(225893): <- sock_wfree###Wed Jun 30 03:48:23 2021 36 nginx-custom-me(225893): -> unix_release_sock###Wed Jun 30 03:48:23 2021 40 nginx-custom-me(225893): -> unix_sock_destructor---1 42 nginx-custom-me(225893): <- __sk_destruct---7 45 nginx-custom-me(225893): <- unix_stream_connect---45 47 nginx-custom-me(225893): <- SYSC_connect###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_release###Wed Jun 30 03:48:23 2021 4 nginx-custom-me(225893): -> unix_release_sock###Wed Jun 30 03:48:23 2021 8 nginx-custom-me(225893): -> unix_sock_destructor---1 10 nginx-custom-me(225893): <- __sk_destruct---7 12 nginx-custom-me(225893): <- unix_release---12 14 nginx-custom-me(225893): <- sock_release###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_create###Wed Jun 30 03:48:23 2021 11 nginx-custom-me(225893): -> unix_create1###Wed Jun 30 03:48:23 2021 20 nginx-custom-me(225893): -> __unix_insert_socket---3 27 nginx-custom-me(225893): <- unix_create1---16 30 nginx-custom-me(225893): <- unix_create---26 33 nginx-custom-me(225893): <- __sock_create###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_bind###Wed Jun 30 03:48:23 2021 9 nginx-custom-me(225893): -> unix_mkname---1 15 nginx-custom-me(225893): <- unix_bind###Wed Jun 30 03:48:23 2021 63 nginx-custom-me(225893): -> __unix_insert_socket---1 68 nginx-custom-me(225893): <- unix_bind---65 70 nginx-custom-me(225893): <- SYSC_bind###Wed Jun 30 03:48:23 2021 0 nginx-custom-me(225893): -> unix_listen###Wed Jun 30 03:48:23 2021 7 nginx-custom-me(225893): -> init_peercred---4 14 nginx-custom-me(225893): <- unix_listen---14 17 nginx-custom-me(225893): <- SyS_listen

由此可见，是nginx-custom-metrics“重启”了（启动过程会调用unix_stream_connect），但是我并没有人为的做这个操作，而且原来的进程也好好的在运行。

（至此，黔驴技穷了！寻求同事【大佬】帮忙，大佬发现将nginx-custom-metrics进程改名后问题没有出现，并发现是aegisSvrFinder进程启动了nginx-custom-metrics进程导致的。最终解决了问题！）

。。。。。。

一次“诡异”的容器Unix Socket通信问题分析

。。。。。。

但是如果没有发现是名称导致的问题，还可以有哪些思路去尝试呢？什么情况会导致“重启”呢？猜想以下三种情况：

1）内核因为某种原因触发“重启”了nginx-custom-metrics进程；2）某种原因导致accept函数重走了net/unix/af_unix.c文件中的create逻辑；3）“有人”额外启动了nginx-custom-metrics进程；

如果是第一种，内核日志应该会有相关的信息；先排除（因为也没招）。至于第二种，大致看了一遍net/unix/af_unix.c代码，没有accept重回create的逻辑，也不太可能。剩下最后一种了，确认过没有其他同事操作，只有可能是其他进程在“搞鬼”。于是计划重来一遍，观察系统进程状态，看看是不是nginx-custom-metrics额外又启动了，为了防止“搞鬼”进程瞬时执行难以捕捉，这里我使用了ebpf工具execsnoop（可以将top，ps等命令无法捕捉到的瞬时进程全部找出来）。到容器所在的宿主机上执行以下命令：