一次切割日志引发的血案

一次切割日志引发的血案

很多应用程序会产生日志,有些程序已经实现了日志切割,一般是每天一个文件。但有时这个切割并不能满足我们的需求,例如我们需要颗粒度更细的切割。

切割日志的目的是什么?

  1. 日志尺寸过大
  2. 便于分析
  3. 切割后归档,或者导入日志平台

切割日志基本两种方法:

  1. 手工或者 shell
  2. 工具,例如logrotate,传统的cronolog

日志切割方案网上有很多,很多运维也是参考这些方案进行配置,网上的例子不完全都是对的,可能你用了很多年配置方案是错误的。 没有出现故障是侥幸,因为笔者15年前就在此处栽过,由于日志太大,我便清空了日志,以为程序仍然会继续写入,最后直到服务器崩溃。 最近发现很多新手再谈cronolog,我便想起当前发生的故障,有必要跟大家分享。

首先日志是可以切割的,网上的例子理论上也是可行,但我们不能不求甚解,稀里糊涂的用下去。

我们首先了解一下日志是怎么产生的,那种日志可以切割,那些日志不能切割,为什么不能切割,如果需要切割日志怎么处理?

首先日志是怎么产生的

日志生命周期,创建/打开日志文件,追加日志记录,关闭日志文件。请看下面伪代码。

main (){

	f = open(/tmp/prog.log)
	...
	...
	f.append('DEBUG .............')
	...
	f.append('INFO .............')
	...
	f.append('WARN .............')
	
	f.close()}

这个程序是顺序运行,每次运行都会经历,打开日志文件,追加日志记录,关闭日志文件,一个日志生命周期结束。 在完成日志生命周后,你就可以切割日志了。因为f.close()后日志文件已经被释放。

再看下面的程序

main (){
	f = open(/tmp/prog.log)
	loop{
		...
		...
		f.append('DEBUG .............')
		...
		f.append('INFO .............')
		...
		f.append('WARN .............')
		
		if(quit){
			break
		}
	}
	f.close()}

这个程序就不同了,程序运行,打开日志文件,然后进入无穷循环,期间不断写入日志,知道接到重载命令才会关闭日志。 那么这个程序你就不能随便切割日志。你一旦修改了日志文件,程序将不能在写入日志到文件中。 这个程序切割日志的过程是这样的

split loop {
	prog run
	prog quit && mv /tmp/prog.log /tmp/prog.2016-05-05.log
	}

再看下面的程序

main (){
	loop{
		f = open(/tmp/prog.log)
		loop{
			...
			...
			f.append('DEBUG .............')
			...
			f.append('INFO .............')
			...
			f.append('WARN .............')
			
			if(reload){
				break
			}
		}
		f.close()
	}}

这个程序多了一层循环,并加入了重载功能。这个程序怎样切割日志呢:

split loop {
	prog run
	mv /tmp/prog.log /tmp/prog.YYYY-MM-DD.log
	prog reload 
}

如果你是程序猿,这个程序可以优化一下,一了百了,就是在reload 的时候重新创建或打开日志。

main (){
	loop{
		f = open(/tmp/prog.YYYY-MM-DD.log)
		loop{
			...
			...
			f.append('DEBUG .............')
			...
			f.append('INFO .............')
			...
			f.append('WARN .............')
			
			if(reload){
				break
			}
		}
		f.close()
	}}

还有一种情况,你会问为什么不这么写?

prog {

	log(type, msg){
		f = open(/tmp/prog.YYYY-MM-DD.log)
		f.append(type, msg)
		f.close()
	}
	
	main(){
		...
		...
		log('INFO','..............')
		...
		...
		log('DEBUG','..............')
		...
		...	}}

这种代码的适应性非常强,但牺牲了IO性能,如果平凡打开/关闭文件同时进行写IO操作,这样的程序很难实现高并发。 所以很多高并发的程序,只会打开一次日志文件(追加模式),不会再运行期间关闭日志文件,直到进程发出退出信号。

让我们看个究竟

我们手工模拟一次日志分割的过程,首先开启三个Shell终端。

第一种情况,日志文件被重命名

终端一,模拟打开日志文件

[root@www.netkiller.cn ~]# cat > /tmp/test.log

终端二,重命名文件

[root@www.netkiller.cn ~]# mv /tmp/test.log /tmp/test.2016.05.05.log

终端一,输入一些内容然后按下Ctrl+D 保存文件

[root@www.netkiller.cn ~]# cat > /tmp/test.log
Helloworld
Ctrl + D[root@www.netkiller.cn ~]# cat /tmp/test.log
cat: /tmp/test.log: No such file or directory

第二种情况,日志文件被删除

终端一,模拟打开日志文件

[root@www.netkiller.cn ~]# cat > /tmp/test.log

终端二,使用lsof查看文件的打开情况

[root@www.netkiller.cn ~]# lsof | grep /tmp/test.log
cat       20032           root    1w      REG              253,1          0     288466 /tmp/test.log

终端三,删除日志文件

[root@www.netkiller.cn ~]# rm -rf /tmp/test.log 

终端二,查看日志的状态,你能看到 deleted

[root@www.netkiller.cn ~]# lsof | grep /tmp/test.log
cat        5269           root    1w      REG              253,1          0     277445 /tmp/test.log (deleted)

终端一,回到终端一种,继续写入一些内容并保存,然后查看日志文件是否有日志记录被写入

[root@www.netkiller.cn ~]# cat > /tmp/test.log
Helloworld
^D[root@www.netkiller.cn ~]# cat /tmp/test.log
cat: /tmp/test.log: No such file or directory

经过上面两个实验,你应该明白了在日志打开期间对日志文件做重命名或者删除都会造成日志记录的写入失败。

第三种情况,日志没有被删除,也没有被重命名,而是被其他程序做了修改

第一步,终端窗口一中创建一个文件,文件写入一些字符串,这里写入 “one”,然后查看是否成功写入。

[root@www.netkiller.cn ~]# echo one > /tmp/test.log[root@www.netkiller.cn ~]# cat /tmp/test.log
one

上面我们可以看到/tmp/test.log文件成功写入一个字符串”one”

第二步,开始追加一些字符串

[root@www.netkiller.cn ~]# cat > /tmp/test.log
two

先不要保存(不要发出^D)

第三部,在终端二窗口中清空这个文件

[root@www.netkiller.cn ~]# > /tmp/test.log 
[root@www.netkiller.cn ~]# cat /tmp/test.log

通过cat查看/tmp/test.log文件,什么也没也表示操作成功。

第四步,完成字符串追加,使用Ctrl+D保存文件,最后使用cat /tmp/test.log 查看内容。

[root@www.netkiller.cn ~]# cat > /tmp/test.log
two[root@www.netkiller.cn ~]# cat /tmp/test.log

你会发现/tmp/test.log文件中没有写入任何内容。这表示在日志的访问期间,如果其他程序修改了该日志文件,原来的程序将无法再写入日志。

让我们再来一次,看个究竟

终端一,创建并追加字符串到日志文件中

# echo one > /tmp/test.log# cat /tmp/test.logone# cat >> /tmp/test.logtwo

记得不要保存

终端二,使用lsof查看文件的打开情况

# lsof | grep /tmp/test.logcat       22631           root    1w      REG              253,1          0     277445 /tmp/test.log

终端三,开启另一个程序追加字符串到日志文件中

# cat >> /tmp/test.log three

先不要保存(不要发出^D)

终端二,查看文件的打开情况

# lsof | grep /tmp/test.logcat       22631           root    1w      REG              253,1          0     277445 /tmp/test.log
cat       23350           root    1w      REG              253,1          0     277445 /tmp/test.log

终端三,保存three字符串

# cat >> /tmp/test.log three
^D# cat /tmp/test.log three

回到终端一,继续保存内容

# cat > /tmp/test.logtwo
^D# cat /tmp/test.logtwo
e

出现新的行情况了,two报道最上面去了,这是因为打开文件默认文件指针是页首,它不知道最后一次文件写入的位置。

你可以反复实验,结果相同。

# cat /tmp/test.logtwo
e
four
five

我为什么没有使用 echo “five” » /tmp/test.log 这种方式追加呢?因为 cat 重定向后只要不发出^D就不会保存文件,而echo是打开文件,获取文件尾部位置,然后追加,最后关闭文件。

经典案例分析

Nginx

[root@www.netkiller.cn ~]# cat /etc/logrotate.d/nginx
/var/log/nginx/*.log {
        daily
        missingok
        rotate 52
        compress
        delaycompress
        notifempty
        create 640 nginx adm
        sharedscripts
        postrotate                [ -f /var/run/nginx.pid ] && kill -USR1 `cat /var/run/nginx.pid`
        endscript}

nginx 日志切割后会运行 kill -USR1 这个让nginx 重新创建日志文件或者夺回日志文件的操作权。

怎样监控日志

那么怎样监控日志被删除,写入权被其他程序夺取?对于程序猿一定很关注这个问题。下面我们讲解怎么监控日志。

Linux 系统可以使用 inotify 开发包来监控文件的状态变化,包括开打,写入,修改权限等等。

你需要启动一个进程或者线程监控日志文件的变化,以便随时reload 你的主程序。

prog {
	sign = null
	logfile = /var/log/your.log
	
	thread monitor {
		inotify logfile {
			sign = reload		}
	}
	thread worker {
		loop{		
			f = open(logfile)
			loop{
				f.append(....)
				
				if(sign == reload)
				{
					break
				}
			}
			f.close()		
		}
	}
	main(){
		monitor.start()
		worker.start()
	}}

不知你是否看懂,简单的说就是两个并行运行的程序,一个负责日志监控,一个负责干活,一旦日志发生变化就通知主程序 reload。 至于使用进程还是线程去实现,取决于你熟悉那种语言或者你擅长的技术。

总结

小小的日志文件有如此大的学问,目前很多应用程序写的比较健壮,能够判断出当前日志被删除,改写。程序运行中能够在创建丢失的日志文件,当日志被其他程序改写后,能够夺回写入权。 但这样的程序会影响程序并发性能,鱼和熊掌不能兼得。看了这篇文章我想你应该对日志有了全面了解,也会在接下来的工作中谨慎处理日志。

原文发布于微信公众号 - Netkiller(netkiller-ebook)

原文发表时间:2016-10-16

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏数据库新发现

DBA警世录:有些习惯DBA需要养成

作者:eygle  原文链接: http://www.eygle.com/archives/2007/02/dba_need_some_habit.html

673
来自专栏源哥的专栏

基于linux的嵌入IPv4协议栈的内容过滤防火墙系统(4)-包过滤模块和内容过滤模块

Netfilter是linux2.4内核实现数据包过滤/数据包处理/NAT等的功能框架。它在网络上设置了五个钩(hook),我们可以在我们所需要的一个钩对数据...

492
来自专栏PHP技术

FastCgi与PHP-fpm之间的关系

刚开始对这个问题我也挺纠结的,看了《HTTP权威指南》后,感觉清晰了不少。 首先,CGI是干嘛的?CGI是为了保证web server传递过来的数据是标准格式的...

3566
来自专栏张戈的专栏

nginx配置文件参数详解

这年头原创技术博文真心难写,不可能每天都有灵感,也不可能每天都出问题。而且技术教程也非常全面,不管是百度一下,你就知道,还是谷歌一把,你就找到,基本要啥有啥,只...

3126
来自专栏潘嘉兴的专栏

手把手教你如何优化linux服务器

服务器的优化是我们最小化安装系统后应该做的事情,下面是一些常见的基本的优化服务器的方法。关闭不需要的服务。列出需要启动的的服务crond、network、ssh...

5530
来自专栏Vamei实验室

Python应用01 原始Python服务器

之前我的Python教程中有人留言,表示只学Python没有用,必须学会一个框架(比如Django和web.py)才能找到工作。而我的想法是,掌握一个类似于框架...

19410
来自专栏哲学驱动设计

Rafy 领域实体框架演示(2) - 新功能展示

本文的演示需要先完成上一篇文章中的演示:《Rafy 领域实体框架示例(1) - 转换传统三层应用程序》。在完成改造传统的三层系统之后,本文将讲解使用 Rafy ...

1758
来自专栏腾讯Bugly的专栏

移动 H5 首屏秒开优化方案探讨

导语 随着移动设备性能不断增强,web 页面的性能体验逐渐变得可以接受,又因为 web 开发模式的诸多好处(跨平台,动态更新,减体积,无限扩展),APP 客户端...

4875
来自专栏Netkiller

一次切割日志引发的血案

一次切割日志引发的血案 很多应用程序会产生日志,有些程序已经实现了日志切割,一般是每天一个文件。但有时这个切割并不能满足我们的需求,例如我们需要颗粒度更细的切割...

3468
来自专栏张善友的专栏

系统进程管理工具Process Explorer

系统进程往往是不少读者操作的“禁区”,其实借助一些功能强大的工具即可消除对该禁区的恐惧。Process Explorer就是一款系统进程管理工具,它不仅能方便地...

1917

扫描关注云+社区