烂笔头

记一次lnmp环境问题

起因

本打算把公司内部的php升级为5.6.x,op給了一个测试环境。于是便开始了环境搭建并测试的工作,configure,make,make install。正当我使用phpinfo()测试通过天真地以为环境搭建完成的时候,突然发现了一个奇怪的问题:通过fpm访问php的错误日志并未纪录在php.ini指定的日志文件中而却出现在了php-fpm.conf指定的配置文件。

问题复现

php.ini中跟错误记录相关的配置如下:

1
2
3
error_reporting = E_ALL
log_errors = On
error_log = /home/ziroom/runtime/php/var/log/php-errors.log

php-fpm.conf的配置:

1
2
3
4
error_log = /home/ziroom/runtime/php/var/log/php-fpm.log
log_level = notice
; Redirect worker stdout and stderr into main error log. If not set, stdout and stderr will be redirected to /dev/null according to FastCGI specs. Note: on highloaded environement, this can cause some delay in the page process time (several ms).
catch_workers_output = yes

注意fpm中的catch_workers_output设置,它的作用是把fpm worker进程的stdout和stderr转发到主进程的error log。一定设置它为yes!!!

访问测试脚本test.php,它的内容为echo 2/0;,php-fpm.log中的日志内容如下:

1
[08-Sep-2016 14:29:41] WARNING: [pool www] child 126 said into stderr: "NOTICE: PHP message: PHP Warning:  Division by zero in /usr/local/nginx/html/index.php on line 2"

问题排查

从上面的日志可以看出pid为126的进程(fpm子进程)向stderr发送了一条级别为NOTICE的错误信息,这条错误信息恰好是php抛出的一个Warning;但是对于真正记录错误日志的fpm主进程来说却又是一个WARNING。

接下来试着调高fpm的log_level为warning,重新访问test.php。结果并没有记录任何错误日志。这个现象很容易解释,fpm子进程向stderr传递的是一个NOTICE级别的信息,而配置文件中log_level的设置高于NOTICE,因而不会记录日志。

但是!!!为何php的错误会记录到fpm的日志文件中?请叫老b得知他没有这个问题,那么一定我自己的问题了。几经辗转后超哥提醒我:看看是不是权限的问题! 刚开始其实我是拒绝的,因为按常理来说如果是因为权限问题的话在日志文件里应该会有报错的。苦于没有别的办法就看了下目录权限,卧槽!!!真是有问题,fpm的用户和组都是ziroom,而配置的/home/ziroom/runtime/php/var/log/php-errors.log对ziroom用户来说却没有写入权限。修改权限后重启fpm,访问test.php,一切正常,错误日志写到了php-errors.log中。

追根溯源

问题虽然解决了,但是并未解决掉心里的疑问,打算再追查下去。疑问有2 :

  1. 没有权限为什么没有报错
  2. 写入php-errors.log没有权限,为何写入php-fpm.log却有权限

对于问题1,root用户启动php-fpm主进程,主进程fork子进程,它的用户被设置成了fpm。于是把fpm的子进程数量改为1,strace该进程看到以下信息:

docker环境直接使用strace会报错(strace: attach: ptrace(PTRACE_ATTACH, …): Operation not permitted)必须打开选项–privileged

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
...
open("/usr/local/nginx/html/index.php", O_RDONLY) = 5
fstat(5, {st_mode=S_IFREG|0644, st_size=16, ...}) = 0
fstat(5, {st_mode=S_IFREG|0644, st_size=16, ...}) = 0
fstat(5, {st_mode=S_IFREG|0644, st_size=16, ...}) = 0
mmap(NULL, 16, PROT_READ, MAP_SHARED, 5, 0) = 0x7f8aa96dd000
getcwd("/", 4095) = 2
chdir("/usr/local/nginx/html") = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0
munmap(0x7f8aa96dd000, 16) = 0
close(5) = 0
open("/usr/local/php/var/log/php_errors.log", O_WRONLY|O_CREAT|O_APPEND, 0644) = -1 EACCES (Permission denied)
write(2, "NOTICE: PHP message: PHP Warning"..., 97) = 97
chdir("/") = 0
times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 4296910449
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=118, ...}) = 0
write(4, "127.0.0.1 - 09/Sep/2016:01:59:5"..., 110) = 110
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
write(3, "\1\7\0\1\0Y\7\0PHP message: PHP Warning"..., 200) = 200
shutdown(3, SHUT_WR) = 0
recvfrom(3, "\1\5\0\1\0\0\0\0", 8, 0, NULL, NULL) = 8
recvfrom(3, "", 8, 0, NULL, NULL) = 0
close(3)

可以看到通过strace拿到的信息中出现了Permission denied关键字,紧接着把”NOTICE: PHP message: PHP Warning”字符串写到了标准错误输出。这就和第一次在php-fpm日志中看到的信息相符了。

问题2,fpm主进程是以root用户启动的,那么大胆猜测一下php-fpm.log只有fpm主进程才往日志里添加内容。lsof看一下:

1
2
3
$ lsof /usr/local/php/var/log/php-fpm.log
$ php-fpm 125 root 2w REG 0,46 1967 607 /usr/local/php/var/log/php-fpm.log
$ php-fpm 125 root 3w REG 0,46 1967 607 /usr/local/php/var/log/php-fpm.log

果不其然,只有fpm的主进程(pid为125)才向php-fpm.log文件中写入日志。

总结

至此,忽略内部更详尽细节,已经完全解决了文章开头的疑问。至于fpm为何这么设计,我等菜鸟无法评论。

最后感谢老b同志亲临现场指导,虽是由一个低级错误引起,但只需要稍微往深一点研究还是挺有意思的。