一个crontab脚本，下载一个文件并把内容入mysql数据库。具体流程如下：
1， wget一个文件。
2，处理文件生成一个中间文件。
3，将中间文件load入库。
05 10 * * * /home/work/local/php5.4/bin/php /home/work/www/new_products1/web/index_cli.php actionads/index
bug现象：
在线上，5次运行中，有2次会出错，就是入库的数据会缺失30%以上。
在线上手动运行脚本，没有一次出错。但配置成crontab，5次运行中，就会出错2次。
难点：
这种不可复现的bug，实在是难找原因。我们只能保存当时的现场，但脚本每天只运行一次，一次解决不了bug，可能需要等好几天才能复现这个bug。
解决流程：
1，怀疑是load文件时，丢失了部分数据。
于是解析mysql的binlog日志，找到了load的那一部分，将日志中获取到的文件字节数相加 （mysql load过程中，每下载一部分文件，会记录一下获取到了多少字节），发现文件没有丢失。同时，找到了mysql load时保存的临时文件，也是没有丢失数据的。
2，生成中间文件时，出错。
虽然开始确认了中间文件出错，但找不到为什么出错。。。
文件的开始有约30%的内容是ascii=0代表的字节。于是怀疑是不是磁盘坏道了。。。
一个程序读一个文件，处理后，写另外一个文件，在线下运行一直没有问题，程序里面也没有使用随机数之类的。。。所以我确认这段程序肯定是没有问题的。
3，假设磁盘坏道了，找证据。
我想坏道的话，把系统调用记录下来，应该可以看到原因。于是我把crontab改成：
05 10 * * * strace -f /home/work/local/php5.4/bin/php /home/work/www/new_products1/web/index_cli.php actionads/index 2>>temp.log
发现read write系统调用没有出错的情况。
但同时也发现了一个现象，read源文件时，读到了大量的ascii=0代表的字节。如图：
同时，写中间文件时，也写入了大量的ascii=0所代表的字节：
这就解释了为什么中间文件会有这么多0，原因就是读到的源文件就有这么多0.
4，为什么源文件出错？
还是百思不得其解，下载的文件字节数也没有问题，说明数据没有丢失。为什么到线上就有问题呢？
眼睛盯着屏幕，好像突然发现了问题
*/5 * * * * /home/work/local/php5.4/bin/php /home/work/www/new_products1/web/index_cli.php appcall/index */5 * * * * /home/work/local/php5.4/bin/php /home/work/www/new_products1/web/index_cli.php actionads/index
原来有两个crontab，另外一个crontab也是下载一个文件，并且这两个crontab下载到的文件的名字是一样的。
会不会是它们两个冲突了呢？写一个脚本来验证。
wget ftp://xxxx:[email protected]/wenyisheng_tab23/20150904 -O 888 2>/dev/null & sleep 1 wget ftp://xxxx1:[email protected]/app_diaoqi/20150904 -O 888 2>/dev/null &
第一个wget下载到的文件有20M，第二个只有1M。为了故意生成冲突，我就让中间sleep 1秒种。
发现最后文件888，字节数跟第一个wget获取到的文件一样，但内容不一样，内容中间夹杂了第二个wget的文件。
后记
其实这个bug应该是可以很早就发现的，检查一下下载到的文件内容就可以发现。
我把它想复杂了，一看文件字节数没有问题，就确认这个文件也是没有问题的，所以就把这个线索中断了，被引入了歧途。
其实遇到疑难bug，不要急于下手，可以回顾一下流程，列一下可能出错的地方，一个一个排除，我想应该很快搞定它。
PS:
在追踪bug的时候，发现php yii框架在记录日志的时候，会把日志锁上，如下：
open("/home/work/www/logs/app.log", O_WRONLY|O_APPEND|O_CREAT, 0666) = 4
fstat(4, {st_mode=S_IFREG|0664, st_size=969524, ...}) = 0
lseek(4, 0, SEEK_CUR) = 0
lseek(4, 0, SEEK_CUR) = 0
flock(4, LOCK_EX)
stat("/home/work/www/logs/app.log", {st_mode=S_IFREG|0664, st_size=969524, ...}) = 0
write(4, "2015-09-04 09:25:01 [-][-][-][in"..., 8192) = 8192
为什么要加锁呢？这就验证了我以前一篇博客中的结论《日志会被写乱吗？》
因为Yii写日志的时候，会把日志记录在内存中，在一次请求处理完以后，统一写到磁盘，这时候日志会比较大，
一次write调用写不完，为了防止其它请求把日志写乱，就把日志文件加锁了。
我想这样会影响并发性能。