【原创】一次“诡异”的容器Unix Socket通信问题分析
![](https://img2020.cnblogs.com/blog/631958/202107/631958-20210703095045722-127528377.png)
运行一段时间后(不确定,一般在3-8分钟)出现socket部分的数据无法获取。但是其余两部分的数据仍然能够正常获取。此时,Nginx日志报如下错误:
![](https://img2020.cnblogs.com/blog/631958/202107/631958-20210703095130119-1611154843.png)
由此可见,是Lua代码无法与/tmp/prometheus-nginx.socket文件建立连接。重启nginx-custom-metrics进程后恢复。但是过一段时间后继续出现问题。只有在重启后的几分钟内是正常的。
![](https://img2020.cnblogs.com/blog/631958/202107/631958-20210703095200018-417528383.png)
![](https://img2020.cnblogs.com/blog/631958/202107/631958-20210703095216061-62900982.png)
![](https://img2020.cnblogs.com/blog/631958/202107/631958-20210703095232370-329040331.png)
监听也是正常的,使用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会变的原因了。查看父进程,最终找到是它启动了。
![](https://img2020.cnblogs.com/blog/631958/202107/631958-20210703095716907-225874511.png)
它是谁呢?看名字应该是阿里云云盾进程。找阿里云工程师确认后发现是他们安全产品巡检时核查web server版本信息时候的操作,把带有nginx字样的进程加-V参数执行了。因为nginx-custom-metrics进程没有-V参数,也没有做处理,会导致进程启动。
然后,修改nginx-custom-metrics程序名称为ngxcustom-metrics后重新运行。问题消失了。。。。。。
但是为什么宿主机上的云盾进程重启nginx-custom-metrics会影响到容器里面的nginx-custom-metrics呢?分别在宿主机和容器内查看进程:
![](https://img2020.cnblogs.com/blog/631958/202107/631958-20210703095750338-1192890670.png)
可以看到,容器中看不到宿主机启动的nginx-custom-metrics -V进程,但是容器内的/tmp/prometheus-nginx.socket文件却被重建了。仔细看一下阿里云云盾的aegisSvrFinder进程:
发现它能获取到容器里面的环境变量等信息,应该是这个进程的问题。具体逻辑就不太清楚了,阿里云工程师建议将该进程删除掉。---------> 结案吧!