稼働中のapacheプロセスやphpエラーgdbで追う

稼働中のサービスにおいてapacheのプロセスが閾値を超える事象が頻発したり、
phpのバグを踏んだりした際に。なにが原因なのか究明のために行ったときの備忘録。

必ずSegmentation Faultが起きるようにphpを拡張して、デバッグしていく。

php extentionsを作成

まずSegmentation Faultとなるようにphpを拡張する。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
# php取得
curl -s -O http://jp2.php.net/distributions/php-5.6.31.tar.gz
tar -zxvf php-5.6.31.tar.gz
cd php-5.6.31/ext

# 拡張を作成するためのスケルトンを作成
./ext_skel --extname=example
Creating directory example
Creating basic files: config.m4 config.w32 .gitignore example.c php_example.h CREDITS EXPERIMENTAL tests/001.phpt example.php [done].

To use your new extension, you will have to execute the following steps:

1. $ cd ..
2. $ vi ext/example/config.m4
3. $ ./buildconf
4. $ ./configure --[with|enable]-example
5. $ make
6. $ ./sapi/cli/php -f ext/example/example.php
7. $ vi ext/example/example.c
8. $ make

Repeat steps 3-6 until you are satisfied with ext/example/config.m4 and
step 6 confirms that your module is compiled into PHP. Then, start writing
code and repeat the last two steps as often as necessary.

# 表示された手順に従い拡張を作成していく
cd example

vi config.m4

生成されたconfig.m4を編集する。
以下の箇所をコメントインする

1
2
3
4
5
6
7
/* config.m4 */
- dnl PHP_ARG_WITH(example, for example support,
- dnl Make sure that the comment is aligned:
- dnl [ --with-example Include example support])
+ PHP_ARG_WITH(example, for example support,
+ Make sure that the comment is aligned:
+ [ --with-example Include example support])

拡張モジュールをビルドのためにphpizeする

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
phpize

Configuring for:
PHP Api Version: 20121113
Zend Module Api No: 20121212
Zend Extension Api No: 220121212

./configure
...
creating libtool
appending configuration tag "CXX" to libtool
configure: creating ./config.status
config.status: creating config.h

make

...
----------------------------------------------------------------------
Libraries have been installed in:
/Users/kazu/Dropbox/workspace/debug-gdb/php-5.6.31/ext/example/modules

If you ever happen to want to link against installed libraries
in a given directory, LIBDIR, you must either use libtool, and
specify the full pathname of the library, or use the `-LLIBDIR'
flag during linking and do at least one of the following:
- add LIBDIR to the `DYLD_LIBRARY_PATH' environment variable
during execution

See any operating system documentation about shared libraries for
more information, such as the ld(1) and ld.so(8) manual pages.
----------------------------------------------------------------------

Build complete.
Don't forget to run 'make test'.

php -d extension=modules/example.so example.php
Functions available in the test extension:
confirm_example_compiled

Congratulations! You have successfully modified ext/example/config.m4. Module example is now compiled into PHP.

vi example.c

example.cに拡張を追加していく。
拡張を実装する。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
/* example.c */

const zend_function_entry example_functions[] = {
PHP_FE(confirm_example_compiled, NULL) /* For testing, remove later. */
/* 新しいphpメソッドを追加する */
+ PHP_FE(down_method, NULL)
PHP_FE_END /* Must be the last line in example_functions[] */
};

PHP_FUNCTION(confirm_example_compiled)
{
char *arg = NULL;
int arg_len, len;
char *strg;

if (zend_parse_parameters(ZEND_NUM_ARGS() TSRMLS_CC, "s", &arg, &arg_len) == FAILURE) {
return;
}

len = spprintf(&strg, 0, "Congratulations! You have successfully modified ext/%.78s/config.m4. Module %.78s is now compiled into PHP.", "example", arg);
RETURN_STRINGL(strg, len, 0);
}

+ /* NULLアドレスの参照で必ず落ちる */
+ PHP_FUNCTION(down_method)
+ {
+ char *ptr = NULL ;
+ strcpy(ptr, "down") ;
+ }

zend_module_entry example_module_entry = {
STANDARD_MODULE_HEADER,
"example",
example_functions,
- PHP_MINIT(example),
- PHP_MSHUTDOWN(example),
- PHP_RINIT(example), /* Replace with NULL if there's nothing to do at request start */
- PHP_RSHUTDOWN(example), /* Replace with NULL if there's nothing to do at request end */
- PHP_MINFO(example),
- PHP_EXAMPLE_VERSION,
STANDARD_MODULE_PROPERTIES
};
zend_module_entry example_module_entry = {
STANDARD_MODULE_HEADER,
"example",
example_functions,
+ NULL,
+ NULL,
+ NULL, /* Replace with NULL if there's nothing to do at request start */
+ NULL, /* Replace with NULL if there's nothing to do at request end */
+ NULL,
+ NO_VERSION_YET,
STANDARD_MODULE_PROPERTIES
};

makeする

1
2
make
...

一応これで必ずSegmentation Faultふがおきるphpのメソッドができた。

コンテナの起動

いろいろとコアな変更もしたいので privileged でコンテナを起動。

コアファイルへのアクセスやプロセスのtraceなどを行うため、コンテナ起動時にはcapabilityの追加の追加をしておく。

またcoreファイルのシステムリソールを変更する(unlimitedではエラーになるので十分に大きな数字を渡す)。

コンテナ内のシステムコールへのアクセスがセキュリティ的にだめなので、security-opt オプションを追加。

1
2
3
4
5
6
7
8
9
10
11
# build and run container
docker build -t kazu69/debug_apache_php_with_gdb .

# run container
docker run -d \
-p 8080:80 \
--privileged \
--ulimit core=9999999999 \
--cap-add=SYS_PTRACE \
--security-opt seccomp:unconfined \
kazu69/debug_apache_php_with_gdb

straceでシステムコールを眺める

デバッグの際によく使われるのがstrace。
プロセスがどの動きをしているのか(カーネルのシステムコール)をtraceする。

今回はphpで gethostbyaddr を実行してそれをtraceしてみる。
わかりやすいようにapacheのコプロセスを1つにしている。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
# -T 各システムコールにかかった時間
# t timestampを出力
# ff forkしたプロセスのシステムコールもトレース
# p プロセスID
# o 指定したファイルに出力

# strace -T -t -ff -o <path-to-log-file> -p <pid>

pstree -p
apache2(1)---apache2(44)

strace -p 44
Process 44 attached
accept4(3, {sa_family=AF_INET, sin_port=htons(55964), sin_addr=inet_addr("172.17.0.1")}, [16], SOCK_CLOEXEC) = 11
gettimeofday({1505745624, 9024}, NULL) = 0
getsockname(11, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("172.17.0.2")}, [16]) = 0
fcntl(11, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0
gettimeofday({1505745624, 9284}, NULL) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11695fc000
gettimeofday({1505745624, 9440}, NULL) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11695fa000
read(11, "GET / HTTP/1.1\r\nHost: localhost:"..., 8000) = 503
gettimeofday({1505745624, 9617}, NULL) = 0
gettimeofday({1505745624, 9679}, NULL) = 0
gettimeofday({1505745624, 9739}, NULL) = 0
gettimeofday({1505745624, 9771}, NULL) = 0
gettimeofday({1505745624, 9803}, NULL) = 0
gettimeofday({1505745624, 9836}, NULL) = 0
gettimeofday({1505745624, 9870}, NULL) = 0
gettimeofday({1505745624, 9920}, NULL) = 0
gettimeofday({1505745624, 9947}, NULL) = 0
gettimeofday({1505745624, 9986}, NULL) = 0
gettimeofday({1505745624, 10038}, NULL) = 0
gettimeofday({1505745624, 10198}, NULL) = 0
gettimeofday({1505745624, 10257}, NULL) = 0
stat("/var/www/html/", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/var/www/.htaccess", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/var/www/html/.htaccess", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11695f8000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11695f6000
stat("/var/www/html/index.php", {st_mode=S_IFREG|0644, st_size=44, ...}) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={30, 0}}, NULL) = 0
rt_sigaction(SIGPROF, {0x7f11652f0190, [PROF], SA_RESTORER|SA_RESTART, 0x7f11688f20e0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 0
getcwd("/var/www/html", 4095) = 14
chdir("/var/www/html") = 0
lstat("/var/www/html/index.php", {st_mode=S_IFREG|0644, st_size=44, ...}) = 0
lstat("/var/www/html", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
lstat("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("/var/www/html/index.php", O_RDONLY) = 12
fstat(12, {st_mode=S_IFREG|0644, st_size=44, ...}) = 0
fstat(12, {st_mode=S_IFREG|0644, st_size=44, ...}) = 0
fstat(12, {st_mode=S_IFREG|0644, st_size=44, ...}) = 0
mmap(NULL, 44, PROT_READ, MAP_SHARED, 12, 0) = 0x7f11695f5000
munmap(0x7f11695f5000, 44) = 0
close(12) = 0
open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 12
fstat(12, {st_mode=S_IFREG|0644, st_size=174, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11695f5000
read(12, "127.0.0.1\tlocalhost\n::1\tlocalhos"..., 4096) = 174
read(12, "", 4096) = 0
close(12) = 0
munmap(0x7f11695f5000, 4096) = 0
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 12
fstat(12, {st_mode=S_IFREG|0644, st_size=15545, ...}) = 0
mmap(NULL, 15545, PROT_READ, MAP_PRIVATE, 12, 0) = 0x7f11695f2000
close(12) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 12
read(12, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\0\21\0\0\0\0\0\0"..., 832) = 832
fstat(12, {st_mode=S_IFREG|0644, st_size=22952, ...}) = 0
mmap(NULL, 2117896, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 12, 0) = 0x7f115f1fe000
mprotect(0x7f115f203000, 2093056, PROT_NONE) = 0
mmap(0x7f115f402000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 12, 0x4000) = 0x7f115f402000
close(12) = 0
mprotect(0x7f115f402000, 4096, PROT_READ) = 0
munmap(0x7f11695f2000, 15545) = 0
stat("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=153, ...}) = 0
socket(PF_INET, SOCK_DGRAM|SOCK_NONBLOCK, IPPROTO_IP) = 12
connect(12, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.65.1")}, 16) = 0
gettimeofday({1505745624, 15912}, NULL) = 0
poll([{fd=12, events=POLLOUT}], 1, 0) = 1 ([{fd=12, revents=POLLOUT}])
sendto(12, "\307\302\1\0\0\1\0\0\0\0\0\0\0018\0018\0018\0018\7in-addr\4arp"..., 38, MSG_NOSIGNAL, NULL, 0) = 38
poll([{fd=12, events=POLLIN}], 1, 5000) = 1 ([{fd=12, revents=POLLIN}])
ioctl(12, FIONREAD, [82]) = 0
recvfrom(12, "\307\302\201\200\0\1\0\1\0\0\0\0\0018\0018\0018\0018\7in-addr\4arp"..., 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.65.1")}, [16]) = 82
close(12) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11695f4000
chdir("/var/www/html") = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11695f2000
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f11695f0000
gettimeofday({1505745624, 54797}, NULL) = 0
read(11, 0x7f11695fa048, 8000) = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1505745624, 56175}, NULL) = 0
writev(11, [{"HTTP/1.1 200 OK\r\nDate: Mon, 18 S"..., 230}, {"google-public-dns-a.google.com", 30}], 2) = 260
gettimeofday({1505745624, 57097}, NULL) = 0
write(8, "172.17.0.1 - - [18/Sep/2017:14:4"..., 197) = 197
times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 4298231454
gettimeofday({1505745624, 58609}, NULL) = 0
gettimeofday({1505745624, 58935}, NULL) = 0
poll([{fd=11, events=POLLIN}], 1, 5000) = 0 (Timeout)
gettimeofday({1505745629, 68368}, NULL) = 0
gettimeofday({1505745629, 68817}, NULL) = 0
gettimeofday({1505745629, 69508}, NULL) = 0
gettimeofday({1505745629, 70214}, NULL) = 0
shutdown(11, SHUT_WR) = 0
poll([{fd=11, events=POLLIN}], 1, 2000) = 0 (Timeout)
close(11) = 0
read(4, 0x7ffd1b7c265f, 1) = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1505745631, 75664}, NULL) = 0

なんとなく TCPで53ポートで通信して、
HTTP/1.1でレスポンスが来ていることなどもわかる。
プロセスの動きをトレースすることでプログラムとカーネル側かの問題を切り分けることができる。

gdbを使って原因を追う

最初に使った必ずエラーとなるphpを実行してSegmentation Faultを起こし、
coreファイルを出力してgdbでデバッグしてみる。

coreファイルはダンプした時点でのメモリ内容をそのまま記録しているので、そこから原因を特定できる。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
# php moduleが読込まれていること確認
php -m | grep example
example

# Segmentation faultになる
/usr/local/bin/php /var/www/html/error.php
Segmentation fault (core dumped)

# プロセス確認
# child processは1つにしておく
pstree -p
apache2(1)---apache2(16)

ps -e -o ppid,pid,stat,command | grep apache2
0 1 Ss apache2 -DFOREGROUND
1 16 S apache2 -DFOREGROUND

apacheなどのプロセスが長時間実行されている場合などは、
gcore(generate-core-file)でcoreダンプファイルを作成してみる。

gdbでプロセスにアタッチすることでデバッグはできるが、gdbがプロセス制御を奪うため、next, step, run, continueなどでプログラムを実行しないと停止している状態となるため稼働中のapcheのプロセスなどには使えない。

gcoreを使った場合はcoreダンプファイルを作成している間だけattachされるため、プログラムの停止を最小に止めることができる。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
gcore 16

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
0x00007f8754335190 in __write_nocancel () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.
warning: target file /proc/15/cmdline contained unexpected null characters
Saved corefile core.16

# core ファイルができている
ls
core.16

# coreファイルにアタッチする
gdb /usr/sbin/apache2 -c core.16
GNU gdb (Debian 7.12-6) 7.12.0.20161007-git
Copyright (C) 2016 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/apache2...(no debugging symbols found)...done.
[New LWP 16]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `apache2'.
#0 0x00007f9a03637690 in __poll_nocancel () at ../sysdeps/unix/syscall-template.S:84
84 ../sysdeps/unix/syscall-template.S: No such file or directory.

またSegmentation Faultが起きる場合はプロセスいなくなるので、あらかじめcoreファイルを出力するように設定しておくこともある。
この場合、エラーが発生すると所定のcoreファイルが出力される。

今回はphpで実際にSegmentation Faultを起こしてcoreファイルを吐き出す。

1
2
3
4
curl http://localhost:8080/error.php

ls /tmp
core.cc0a7a572fde.apache2.1505406197

gdbでcoreファイルをデバッグ

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
gdb /usr/sbin/apache2 -c core.cc0a7a572fde.apache2.1505406197

GNU gdb (Debian 7.7.1+dfsg-5) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/apache2...(no debugging symbols found)...done.
[New LWP 31]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `apache2 -DFOREGROUND'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 zif_down_method (ht=0, return_value=0x7f70ac52b210, return_value_ptr=0x7f70ac4f9088, this_ptr=0x0, return_value_used=0) at /tmp/extensions/example/example.c:72
72 strcpy(ptr, "down") ;

# バックトレース
(gdb) bt
#0 zif_down_method (ht=0, return_value=0x7f70ac52b210, return_value_ptr=0x7f70ac4f9088, this_ptr=0x0, return_value_used=0) at /tmp/extensions/example/example.c:72
#1 0x00007f70a8241173 in zend_do_fcall_common_helper_SPEC () from /usr/lib/apache2/modules/libphp5.so
#2 0x00007f70a81ca360 in execute_ex () from /usr/lib/apache2/modules/libphp5.so
#3 0x00007f70a81929d0 in zend_execute_scripts () from /usr/lib/apache2/modules/libphp5.so
#4 0x00007f70a812dfc0 in php_execute_script () from /usr/lib/apache2/modules/libphp5.so
#5 0x00007f70a82428ca in php_handler () from /usr/lib/apache2/modules/libphp5.so
#6 0x000055798cdc3880 in ap_run_handler ()
#7 0x000055798cdc3dc9 in ap_invoke_handler ()
#8 0x000055798cdd9ca2 in ap_process_async_request ()
#9 0x000055798cdd9e40 in ap_process_request ()
#10 0x000055798cdd6742 in ?? ()
#11 0x000055798cdcd130 in ap_run_process_connection ()
#12 0x00007f70a8c757ba in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#13 0x00007f70a8c75a01 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#14 0x00007f70a8c76667 in ?? () from /usr/lib/apache2/modules/mod_mpm_prefork.so
#15 0x000055798cda784e in ap_run_mpm ()
#16 0x000055798cda0673 in main ()

# エラーが発生したファイル
print (char *)executor_globals.active_op_array->filename
$1 = 0x7f70ac529bc8 "/var/www/html/error.php"

# エラーの発生した行数
print executor_globals.current_execute_data.opline->lineno
$2=2

上記の内容から想定通りexample.c 72行目で落ちていることがわかる。

まとめ

普段アプリケーションレイヤーを開発している人からすると、だいたいこの辺かなという感じで問題点を追うことができるが、はっきりとして原因を掴むために、
straceやgdbなどで追求できるようにしておくことは良いことだと思われた。

低レイヤーでの開発している人にとっては目新しいことではないでしょうが…

今回使ったサンプル

example-debug-apache-service-operating

参考にしたページ

PHPでのデバッグ方法
PHP Extension 開発入門
Apache HTTPD Debugging Guide - The Apache HTTP Server Project

Comments