AI 助理
备案控制台
开发者社区 PHP技术进阶 文章 正文

面向祖传代码 Debug，我挽回了一位准备跑路的程序员

2021-06-17 498
版权
版权声明：
本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《 阿里云开发者社区用户服务协议》和 《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写 侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。
简介： 交流群的风格突然骤变，没有了往日的灌水扯淡，居然聊起了技术。看了大家的全部的聊天记录，发现问题并没解决。群里难得这么多人聊技术，抱着问答不断，必有回响的原则，主动勾搭一起看看是什么问题。大概了解其问题是这样，apache 子进程一直异常退出。

交流群的风格突然骤变，没有了往日的灌水扯淡，居然聊起了技术。
1623650919857100.jpg
1623650924550111.jpg

看了大家的全部的聊天记录，发现问题并没解决。群里难得这么多人聊技术，抱着问答不断，必有回响的原则，主动勾搭一起看看是什么问题。

大概了解其问题是这样，apache 子进程一直异常退出

$ sudo tail -f /var/log/httpd/error_log
[Sun Jun 13 19:32:25.660349 2021] [core:notice] [pid 23340] AH00052: child pid 20605 exit signal Bus error (7)
[Sun Jun 13 19:32:25.660413 2021] [core:notice] [pid 23340] AH00052: child pid 20606 exit signal Bus error (7)
[Sun Jun 13 19:35:39.862368 2021] [core:notice] [pid 23340] AH00052: child pid 21332 exit signal Bus error (7)
[Sun Jun 13 19:35:50.872363 2021] [core:notice] [pid 23340] AH00052: child pid 21369 exit signal Bus error (7)
[Sun Jun 13 19:39:43.079650 2021] [core:notice] [pid 23340] AH00052: child pid 18595 exit signal Bus error (7)
[Sun Jun 13 19:42:08.210353 2021] [core:notice] [pid 23340] AH00052: child pid 21348 exit signal Bus error (7)
[Sun Jun 13 19:42:16.221076 2021] [core:notice] [pid 23340] AH00052: child pid 21331 exit signal Bus error (7)
[Sun Jun 13 19:42:16.221177 2021] [core:notice] [pid 23340] AH00052: child pid 23156 exit signal Bus error (7)
[Sun Jun 13 19:44:11.329344 2021] [core:notice] [pid 23340] AH00052: child pid 27824 exit signal Bus error (7)

现场复现

了解到其架构是 apache + php ，群友也是临时接受的祖传代码，项目也不是很清楚。可以使用strace来看看，背后到底是什么问题

$ ps -ef|grep apache

首先看到主进程 id 是 23340，这里需要跟着其子进程，所以我执行了如下命令

$ sudo strace -o strace.log -s 1024 $(pidof "/usr/sbin/httpd" -o 23340|sed 's/\([0-9]*\)/-p \1/g')
strace: Process 26212 attached
strace: Process 26211 attached
strace: Process 26191 attached
strace: Process 25940 attached
...

参数大概解释下

code 释义
-o strace.log 输出 strace 日志到 strace.log
-s 1024 当系统调用的某个参数是字符串时，最多输出指定长度的内容，默认是32个字节
pidof "/usr/sbin/httpd" -o 23340 排除主进程 23340 之外的 httpd 子进程

然后新开一个窗口监控日志

$ sudo tail -f strace.log |grep SIGBUS -B 500
28741 open("/xxxx/www/data/cache/xxx.php", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 15
28741 write(15, "<?php defined('DYMall') or exit('Access Invalid!'); return array ( ) ?>", 71) = 71
28741 close(15)
...
28741 open("/xxxx/www/data/cache/xxx.php", O_RDONLY) = 15
28741 fstat(15, {st_mode=S_IFREG|0644, st_size=71, ...}) = 0
28741 fstat(15, {st_mode=S_IFREG|0644, st_size=71, ...}) = 0
28741 fstat(15, {st_mode=S_IFREG|0644, st_size=71, ...}) = 0
28741 mmap(NULL, 71, PROT_READ, MAP_SHARED, 15, 0) = 0x7f584aee8000
28741 --- SIGBUS {si_signo=SIGBUS, si_code=BUS_ADRERR, si_addr=0x7f584aee8000} ---
28741 chdir("/etc/httpd")               = 0
28741 rt_sigaction(SIGBUS, {SIG_DFL, [], SA_RESTORER|SA_INTERRUPT, 0x7f58499bc5e0}, {SIG_DFL, [], SA_RESTORER|SA_RESETHAND, 0x7f58499bc5e0}, 8) = 0
28741 kill(28741, SIGBUS)               = 0
28741 rt_sigreturn({mask=[]})           = 140017190993928
28741 --- SIGBUS {si_signo=SIGBUS, si_code=SI_USER, si_pid=28741, si_uid=48} ---
28741 +++ killed by SIGBUS +++
SIGBUS 在用户态最为常见的场景，也最容易触发，通常来说根本原因都是进程 mmap 了一个文件后，另外的进程把这个文件截断了，导致 mmap 出来的某些内存页超出文件的实际大小，访问那些超出的内存页就会触发 SIGBUS

验证文件大小变化

监控文件的大小来验证文件是否一直在变化

$ while :; do cat /xxxx/www/data/cache/xxx.php|wc -L ;done
$ while :; do cat /xxxx/www/data/cache/xxx.php|wc -L ;done|grep -v 71

发现文件确实在少数情况下会变为 0 个字节，根据文件的路径，初步估计应该是缓存文件被重写了

确认文件写操作来源

$ sudo yum -y install audit auditd-libs

监控topic_goodsclass.php文件的写入操作

$ sudo auditctl -w /xxxx/www/data/cache/xxx.php -p w

结果类似于

time->Mon Jun 14 21:21:39 2021
type=PROCTITLE msg=audit(1623676899.778:1883303): proctitle=2F7573722F7362696E2F6874747064002D44464F524547524F554E44
type=PATH msg=audit(1623676899.778:1883303): item=1 name="/xxxx/www/data/cache/xxx.php" inode=30151674 dev=fd:11 mode=0100644 ouid=48 ogid=48 rdev=00:00 objtype=NORMAL
type=PATH msg=audit(1623676899.778:1883303): item=0 name="/xxxx/www/data/cache/" inode=30151667 dev=fd:11 mode=040755 ouid=48 ogid=48 rdev=00:00 objtype=PARENT
type=CWD msg=audit(1623676899.778:1883303):  cwd="/xxxx/www"
type=SYSCALL msg=audit(1623676899.778:1883303): arch=c000003e syscall=2 success=yes exit=16 a0=55b452b93078 a1=241 a2=1b6 a3=2a items=2 ppid=31318 pid=18269 auid=4294967295 uid=48 gid=48 euid=48 suid=48 fsuid=48 egid=48 sgid=48 fsgid=48 tty=(none) ses=4294967295 comm="httpd" exe="/usr/sbin/httpd" key=(null)

收集一段时间，做下统计

$ sudo ausearch -f /xxxx/www/data/cache/xxx.php |grep "exe="|awk '{print $12,$26}'|sort|uniq -c
  44200 ppid=31318 exe="/usr/sbin/httpd"

发现都是来自于/usr/sbin/httpd，并没有CLI模式的写入（担心有定时任务来生成缓存），清理掉监控

sudo auditctl -D

多进程文件读写冲突的解决方案

需要注意，在对文件进行fopen($filename, "w+")的时候，就已经将文件清空了，所以加锁需要在fopen目标文件之前，所以我的方式是增加一个文件一一对应的锁文件。如下:
aa.php

function addFileLock($filename, $lock)
{
    $fp = fopen($filename . ".lock", "w+");
    flock($fp, $lock);
    return $fp;
}

function releaseLock($fp)
{
    flock($fp, LOCK_UN);
}

$filename = "cc.log";


// mock 数据
file_put_contents($filename, "100");

$fp = fopen($filename, "r");

if ($lockfp = addFileLock($filename, LOCK_SH)) {

    $n = 10;
    while ($n > 0) {
        sleep(1);
        printf("%d %d\n", time(), --$n);
    }

    echo fgets($fp);

    releaseLock($lockfp);
}

fclose($fp);

bb.php

function setFileLock($filename, $lock)
{
    $fp = fopen($filename . ".lock", "w+");
    flock($fp, $lock);
    return $fp;
}

function releaseFileLock($fp)
{
    flock($fp, LOCK_UN);
    fclose($fp);
}

$filename = "cc.log";

if ($lockfp = setFileLock($filename, LOCK_EX)) {
    $fp = fopen($filename, "w+");
    echo time();
    fwrite($fp, 200);
    releaseFileLock($lockfp);
}

fclose($fp);

所以先执行 php aa.php 再执行 php bb.php，就能看到效果。

实际代码定位

根据系统调用里面的字符串关键字，搜到了相关的缓存操作代码

28741 write(15, "<?php defined('DYMall') or exit('Access Invalid!'); return array ( ) ?>", 71) = 71

改完之后发现线上还是有问题，本来我已经怀疑人生了，还是通过系统调用发现读取的时候并没有走我增加的共享锁
WechatIMG536.jpg
原来缓存的读取是走的别的逻辑，从上面的截图可以看到缓存的写入已经走了修改之后的代码（加锁逻辑），然后根据个人经验加搜索该缓存写入方法，按图索骥找到了另外一个缓存文件的读取逻辑，然后再次修改，线上问题没有再复现。

问题解决，跑路哥给我发来红包，我心满意足的接受了。

IMG_9532.jpg

总结

  1. 首先通过strace复现SIGBUS的场景
  2. 预计是文件在多进程模型下，并发读写导致的问题
  3. 通过auditctl监控统计文件的写操作来源均为httpd没有其他进程来修改
  4. 通过读加共享锁、写加排它锁，线上还是有问题
  5. 再次根据strace 发现读的地方另有他处，根据经验，补上，问题修复

不足的地方：最后定位过于依靠个人经验，不够系统化。

小想法：可以弄一个扩展使用 zend_set_user_opcode_handler 来监控自定义函数和方法和系统方法和函数调用链，然后在每个请求初始化阶段写入日志，比如

write(fd, "{unique code}", xxx);
write(fd, "request uri", xxx);

然后的方法调用在 zend_set_user_opcode_handler里面打印，这样就能方便排查祖传代码的一些业务逻辑问题了。

如果有其他更快更简单的方案，大家留言告诉我。

“程序员跑路笔记” 我的公众号，期待你的关注，一起避免跑路

qrcode_for_gh_6c1e2273268c_258.jpg

文章标签：
PHP
Perl
监控
Apache
程序员
缓存
周梦康
目录
相关文章
lian8306
|
6月前
|
程序员 测试技术
程序员的“Bug之旅”：为何无法一次性写出完美代码？
程序员在软件开发过程中难以一次性写出完美代码，需要不断修改和调试，即“改Bug”，这是由多个因素共同作用的结果。技术层面的复杂性、管理和流程上的不足以及个人能力和认知的局限性都是导致这一现象的重要原因。然而，这并不意味着无法避免或改进。通过加强需求管理、建立有效的版本控制和测试机制、推动团队知识共享以及鼓励代码审查和自我反思等措施，可以降低改Bug的频率和成本，提高软件开发的效率和质量。辩证地看待这一问题，既要理解其存在的合理性，也要积极寻求改进之道，以实现更好的产品和服务。
lian8306
59 2
Man9Oo
|
安全 NoSQL 程序员
我就算跳出去死外边也不会学【实用调试技巧/程序员内功修炼】
我就算跳出去死外边也不会学【实用调试技巧/程序员内功修炼】
Man9Oo
37 1
嵌入式Linux充电站
|
存储 算法 Linux
当我用几道题考了一遍做Linux驱动的同事......
当我用几道题考了一遍做Linux驱动的同事......
嵌入式Linux充电站
90 0
Python乱炖
|
SQL 人工智能 Java
程序员：你见过哪些要命的奇葩代码？
程序员：你见过哪些要命的奇葩代码？
Python乱炖
113 0
尼德兰的喵
|
Perl
【perl】老司机的再一次翻车：没有想到加了一句打印，会影响结果输出
【perl】老司机的再一次翻车：没有想到加了一句打印，会影响结果输出
尼德兰的喵
94 0
孙叫兽
|
机器学习/深度学习 前端开发 小程序
想当程序员，如何判断自己是否适合当前端程序员？
真正学习的时候，大多数所谓的兴趣就是扯淡； 只有那种遇到难题就兴奋，敲代码时候，越挫越勇的人，才叫感兴趣； 真正的感兴趣是让你学的久，学的不累；
孙叫兽
175 0
未闻Code
|
Python
又烧脑又炫技还没什么用，在代码里面打印自身
又烧脑又炫技还没什么用，在代码里面打印自身
未闻Code
207 0
又烧脑又炫技还没什么用，在代码里面打印自身
不脱发的程序猿
|
传感器 算法 内存技术
困扰一周的奇葩bug：重复相似代码多，导致单片机程序跑飞
困扰一周的奇葩bug：重复相似代码多，导致单片机程序跑飞
不脱发的程序猿
187 0
java隋七哥
|
Java 应用服务中间件 程序员
一年了，请不要忘记这位枉死的天才程序员，以及......
不知大家是否还记得一年前的苏享茂事件。 苏享茂，一个出生在贫寒家庭的程序员，依靠自己在技术上的天赋和努力，逆袭成为WePhone 的创始人，坐拥千万身家。
java隋七哥
1066 0
前端白鸽
|
程序员 uml 中间件
应届程序员进阿里1个月还在打杂看代码，难道让你写一堆BUG上线？
有位应届生开发进阿里一个月了，每天打杂看代码，始终不让动手写。还发帖问网友，这样情况要持续多久？感觉一个月都没多大成长。一般阿里多久才会把应届生看做一个正常的开发？ 不过有网友就怼到：看代码都没成长？ 下个月你可以走了。
前端白鸽
1467 0