鄙人最近遇到了1个奇特的线上事故,记录1下,以备记忆。
鄙人所在的部门负责给公司提供各种基础库,即基础架构部门。最近某别的部门用本部门提供的支持多线程版本的日志库后,出现这样1个奇特的现象:当磁盘被日志写满以后,他们的数据文件的头部被写上了最新的日志!就是说,别的部门的程序的数据文件被日志数据给污染了。
这里先不介绍这个事故的缘由。先说下这个日志库的写日志进程,其流程大致以下:
step1 如果log的fd为⑴,就重新通过C函数open再打开1个log_fd;
step2 写log内容,即ssize_t size = write(log_fd, buf, len);
step3 如果size等于len,则转step 7,否则继续step 8;
step4 对log_fd加mutex锁;
step5 close(log_fd);
step6 log_fd赋值为⑴;
step7 解锁;
step8 return。
然后用户进程的逻辑大致为:
logic1 当有新数据的时候,通过C函数open打开1个data_fd;
logic2 write(data_fd, data, data_len);
logic3 close(data_fd)。
假定这样1个场景:有线程A先写了1条日志,线程B紧随其后也来写1条日志,线程C正常进行数据文件写操作。通过假定1下情况,在磁盘满的时候可能复现这个bug。假定程序运行进程是:
进程1 线程A履行到step6,此时log_fd为3,线程A给log_fd赋值为⑴;
进程2 线程B履行到step2,此时log_fd依然为3,但其实线程A已将fd为3的文件关闭掉了,所以线程B持有的这个log_fd此时为非法描写符;
进程3 线程C履行到logic2,由于线程A已将fd 3归还给os,所以os此时把3给了data_fd,即data_fd为3。
如果这个假定成立,那末在进程线程B的log内容1定会写到数据文件中。
为了验证这个情况,先在公司的linuxhttp://www.wfuyu.com/server/建立了1个loop文件系统,简历步骤以下:
1 dd if=/dev/zero of=/home/alex/100.img bs=1M count=100 # 在这1步建立1个容量为100M的loop装备
2 mkfs.ext2 100.img # 将loop装备格式化为ext2格式
3 mount 100.img /home/alex/vfs -o loop -n # 简历loop装备,将/home/alex/vfs目录映照到这个loop装备上
由于装备的容量非常小,上面的bug就很容易重现,重现逻辑很简单,首先设置log的文件目录是/home/alex/vfs,然后启动1000个线程,每一个线程的逻辑函数以下:
上面的线程函在循环里不断的打开关闭数据文件,即其大小为0。程序运行终了后,数据文件的大小若不为0,就可以验证上面的假定。
运行以上测试程序后,视察到大量的数据文件的大小不为0,其内容为log内容。其实这个事故还算荣幸,若用户的数据不是输出到磁盘,而是通过tcp socket发送到别的机器,那末这个bug会致使tcp的流内容稀里糊涂的乱掉,那问题就更不容易清查了。
验证了假定,问题就很容易解决了。解决方法有两种:
第1种方法,对fd加援用计数。即线程每获得1个新的log_fd时候,要增加1次援用次数;如果出现write失败的情况,要减小1次援用次数,当援用次数为0的时候,再close掉log_fd;
第2种方法,使用tls(thread local storage)情势的log file。即每一个线程都打开同1个log file,open函数的“mode参数”为“O_CREAT | O_APPEND | O_RDWR”,当写失败的时候,各自close各自的log_fd。
终究我采取了第2种解决方法,很好地解决了问题。如果你有更好的方法,欢迎评论。
此记,谢绝转载。