【原创】一次“诡异”的容器Unix Socket通信问题分析
运行一段时间后（不确定，一般在3-8分钟）出现socket部分的数据无法获取。但是其余两部分的数据仍然能够正常获取。此时，Nginx日志报如下错误：
由此可见，是Lua代码无法与/tmp/prometheus-nginx.socket文件建立连接。重启nginx-custom-metrics进程后恢复。但是过一段时间后继续出现问题。只有在重启后的几分钟内是正常的。
监听也是正常的，使用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\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
执行后，可以看到：
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），但是我并没有人为的做这个操作，而且原来的进程也好好的在运行。
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进程：
发现它能获取到容器里面的环境变量等信息，应该是这个进程的问题。具体逻辑就不太清楚了，阿里云工程师建议将该进程删除掉。---------> 结案吧！
