【原创】⼀次“诡异”的容器UnixSocket通信问题分析
⼀、背景
为了实现全链路拓扑监控，期望⼀层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
socket通信在哪一层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），但是我并没有⼈为的做这个操作，⽽且原来的进程也好好的在运⾏。
（⾄此，黔驴技穷了！寻求同事【⼤佬】帮忙，⼤佬发现将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进程：
发现它能获取到容器⾥⾯的环境变量等信息，应该是这个进程的问题。具体逻辑就不太清楚了，阿⾥云⼯程师建议将该进程删除掉。---------> 结案吧！
版权声明：本站内容均来自互联网，仅供演示用，请勿用于商业和其他非法用途。如果侵犯了您的权益请与我们联系QQ:729038198，我们将在24小时内删除。
发表评论