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

一、背景

　　为了实现全链路拓扑监控，期望一层Nginx（Openresty）具备和Ingress-Nginx-Controller一样的的Metrics监控指标。通过分析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进程后，开始一切正常，也能获取到想要的数据。测试正常获取监控数据如下：

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

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

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

 

三、分析

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

【服务端代码：】

【客户端代码：】

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

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

 

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

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

# ls -lrth /tmp/prometheus-nginx.socket
srwxrwxrwx 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   socket
Device: 9fh/159d	Inode: 12853752    Links: 1
Access: (0777/srwxrwxrwx)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2021-06-28 16:34:59.447322491 +0800
Modify: 2021-06-28 16:34:59.214314837 +0800
Change: 2021-06-28 16:34:59.214314837 +0800
 Birth: -

　　发现Modify的时间和出现问题的时间点很接近，重新来一遍，观察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
", 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
", gettimeofday_us()-@entry(gettimeofday_us()), thread_indent(-1), probefunc())
          #print_backtrace(); // 打印打印调用栈
	}
}

// 执行跟踪
# ./unix-socket-trace.stp

　　执行后，可以看到：

 　　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
", 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
", 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进程导致的。最终解决了问题！）

　　

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

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等命令无法捕捉到的瞬时进程全部找出来）。到容器所在的宿主机上执行以下命令：

# execsnoop | grep nginx-custom-metrics

　　重新复现问题后，果然。。。

 　　有个进程PID为的20379的进程启动了nginx-custom-metrics，还带-V参数启动，导致/tmp/prometheus-nginx.socket文件重建了，这也是为什么inode会变的原因了。查看父进程，最终找到是它启动了。

 

 

 　　它是谁呢？看名字应该是阿里云云盾进程。找阿里云工程师确认后发现是他们安全产品巡检时核查web server版本信息时候的操作，把带有nginx字样的进程加-V参数执行了。因为nginx-custom-metrics进程没有-V参数，也没有做处理，会导致进程启动。

　　然后，修改nginx-custom-metrics程序名称为ngxcustom-metrics后重新运行。问题消失了。。。。。。

　　但是为什么宿主机上的云盾进程重启nginx-custom-metrics会影响到容器里面的nginx-custom-metrics呢？分别在宿主机和容器内查看进程：

 

　　可以看到，容器中看不到宿主机启动的nginx-custom-metrics -V进程，但是容器内的/tmp/prometheus-nginx.socket文件却被重建了。仔细看一下阿里云云盾的aegisSvrFinder进程：

　　发现它能获取到容器里面的环境变量等信息，应该是这个进程的问题。具体逻辑就不太清楚了，阿里云工程师建议将该进程删除掉。---------> 结案吧！