关于php:面向祖传代码-Debug我挽回了一位准备跑路的程序员

交换群的格调忽然骤变，没有了来日的灌水扯淡，竟然聊起了技术。

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

大略理解其问题是这样，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

改完之后发现线上还是有问题，原本我曾经狐疑人生了，还是通过零碎调用发现 读取的时候并没有走我减少的共享锁

原来缓存的读取是走的别的逻辑，从下面的截图能够看到缓存的写入曾经走了批改之后的代码（加锁逻辑），而后依据集体教训加搜寻该缓存写入办法，按图索骥找到了另外一个缓存文件的读取逻辑，而后再次批改，线上问题没有再复现。

问题解决，跑路哥给我发来红包，我称心如意的承受了。

首先通过 strace 复现 SIGBUS 的场景
预计是文件在多过程模型下，并发读写导致的问题
通过 auditctl 监控统计文件的写操作起源均为 httpd 没有其余过程来批改
通过读加共享锁、写加排它锁，线上还是有问题
再次依据strace 发现读的中央另有他处，依据教训，补上，问题修复

有余的中央：最初定位过于依附集体教训，不够系统化。

小想法：能够弄一个扩大应用 zend_set_user_opcode_handler 来监控自定义函数和办法和零碎办法和函数调用链，而后在每个申请初始化阶段写入日志，比方

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

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

如果有其余更快更简略的计划，大家留言通知我。

关于php:面向祖传代码-Debug我挽回了一位准备跑路的程序员

现场复现

验证文件大小变动

确认文件写操作起源

多过程文件读写抵触的解决方案

理论代码定位

总结