Debug Hacks 番外編 - ソースコードを読む前に strace のログを読もう -
Debug Hacks Conference 2009 に参加してきた tmorimoto です。会場にて、帰ったら各々のデバッグ方法をブログに書いて、そのやり方を共有しようと呼びかけがありました。そう言われても、、、すぐに思い付かないので、先日、発見した strace の用途について書きたいと思います。
リファレンス:
Debug Hacks Conference 2009
Debug Hacks Conference 2009開催した
Asianux Server3 に ZABBIX 1.6.4 をインストールする
「Hack#43 strace を使って、不具合原因の手がかりを見つける」を kyamato さんが紹介されています。strace はデバッグだけでなく、ソースコードを読む前の、アタリを付けるときにも有効だと思います。尚、この方法は sochoi さんから教わった方法です。sochoi さんは、以前、20万行の strace ログから、バグの要因となる50行を短時間で見出した strace のスペシャリストです。strace のログは、一見すると同じようなログばかりです。大量のログの中から問題の部分のみを抽出するノウハウがあるようです。何故、Debug Hacks に hack を書かなかったのかが私は不思議なぐらいです(^ ^;;
さて、先日、zabbix-agent が設定されたユーザパラメータを実行する際にどのような動作をするか調査していました。その調査について sochoi さんと一緒に strace を用いて行った方法を紹介します。
調査を容易にするために strace でアタッチしたいプロセスの候補を減らします。zabbix_agentd.conf の設定で pre-forked インスタンスの数を減らし、Active チェックを無効にします。また、ユーザパラメータの動作を検証するために my.detarame をセットします。
# vi /etc/zabbix/zabbix_agentd.conf
StartAgents=1
DisableActive=1
UserParameter=my.detarame,detarame
# service zabbix-agent restart
# pstree -ap | grep zabbix_agentd
|-zabbix_agentd,3761 -c /etc/zabbix/zabbix_agentd.conf
| |-zabbix_agentd,3762 -c /etc/zabbix/zabbix_agentd.conf
| `-zabbix_agentd,3763 -c /etc/zabbix/zabbix_agentd.conf
プロセスの候補が2つに絞れました。デフォルトでは6〜8つ程度、起動します。
zabbix_get コマンドを使用することで zabbix-agent へのクエリを送信することができます。
# zabbix_get -s localhost -k system.hostname
dhcp-1149.miraclelinux.com
zabbix-agent の PATH を調べます。
# cat /proc/3761/environ
TERM=xtermPATH=/sbin:/usr/sbin:/bin:/usr/binPWD=/LANG=ja_JP.UTF-8SHLVL=2_=/usr/sbin/zabbix_agentd
/usr/bin に PATH が通っているので、そこに detarame スクリプトを作成します。zabbix_get コマンドでユーザパラメータを実行してみます。detarame スクリプトの出力により、結果が異なります。
# cat /usr/bin/detarame
#!/bin/sh
echo "abc"
# zabbix_get -s localhost -k my.detarame
abc
# vi /usr/bin/detarame
#!/bin/sh
echo ""
# zabbix_get -s localhost -k my.detarame
ZBX_NOTSUPPORTED
ユーザパラメータにおいて、空文字列を返すと ZBX_NOTSUPPORTED と表示されました。この動作が zabbix-agent による正常なエラー処理の結果かどうかを調査するために strace を利用します。
# strace -f -p 3762
Process 3762 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 0
gettimeofday({1240532698, 749407}, NULL) = 0
~~snip~~
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({1, 0},
この状態で、別のターミナルから zabbix_get コマンドを何度か実行します。
# zabbix_get -s localhost -k my.detarame
ZBX_NOTSUPPORTED
# zabbix_get -s localhost -k my.detarame
ZBX_NOTSUPPORTED
# zabbix_get -s localhost -k my.detarame
ZBX_NOTSUPPORTED
3762 のプロセスでは特に変化は見られません。外れだったようです。そこでもう一方のプロセスをアタッチします。
# strace -f -p 3763
Process 3763 attached - interrupt to quit
select(5, [4], NULL, NULL, NULL
同様に zabbix_get コマンドを実行します。
# zabbix_get -s localhost -k my.detarame
ZBX_NOTSUPPORTED
今度は strace のログを確認することができました。
Process 3763 attached - interrupt to quit
select(5, [4], NULL, NULL, NULL) = 1 (in [4])
accept(4, {sa_family=AF_INET, sin_port=htons(40606), sin_addr=inet_addr("127.0.0.1")}, [16]) = 5
getpeername(5, {sa_family=AF_INET, sin_port=htons(40606), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
read(5, "ZBXD\1", 5) = 5
read(5, "\f\0\0\0\0\0\0\0", 8) = 8
read(5, "my.detarame\n", 2047) = 12
pipe([6, 7]) = 0
~~snip~~
strace を終了させるには Ctrl-Z で中断して、strace のプロセスを強制終了させてください。この辺は力技ですみません(- -#
[2]+ Stopped strace -f -p 3763
# ps ax | grep strace
3918 pts/2 T 0:00 strace -f -p 3763
# kill -9 3918
後で解析できるようにログへ出力するには -o オプションでファイル名を指定します。
# strace -f -p 3763 -o zabbix_agent.log
Process 3763 attached - interrupt to quit
Process 5513 attached
Process 5513 detached
[2]+ Stopped strace -f -p 3763
# vi zabbix_agent.log
3763 select(5, [4], NULL, NULL, NULL) = 1 (in [4])
3763 accept(4, {sa_family=AF_INET, sin_port=htons(40606), sin_addr=inet_addr("127.0.0.1")}, [16]) = 5
3763 getpeername(5, {sa_family=AF_INET, sin_port=htons(40606), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
3763 read(5, "ZBXD\1", 5) = 5
3763 read(5, "\f\0\0\0\0\0\0\0", 8) = 8
3763 read(5, "my.detarame\n", 2047) = 12
3763 pipe([6, 7]) = 0
3763 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7fc6718) = 5513
3763 close(7) = 0
3763 fstat64(6, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
3763 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fdd000
3763 read(6,5513 close(6) = 0
5513 dup2(7, 1) = 1
5513 close(7) = 0
5513 execve("/bin/sh", ["sh", "-c", "detarame"], [/* 6 vars */]) = 0
~~snip~~
zabbix-agent が 5513 の子プロセスを生成していることが分かります。ここで、以下のログに着目します。
3763 read(5, "ZBXD\1", 5) = 5
3763 read(5, "\f\0\0\0\0\0\0\0", 8) = 8
3763 read(5, "my.detarame\n", 2047) = 12
my.detarame のアイテムキーを読み込む際 'ZBXD' の文字列も読み込みしています。実際には、これはヘッダの文字列になります。これを検索キーワードに利用します。
# cd /usr/src/asianux/BUILD/zabbix-1.6.4
# find ./ -type f -name "*.c" -o -name "*.h" | xargs grep ZBXD
./src/libs/zbxcomms/comms.c:#define ZBX_TCP_HEADER_DATA "ZBXD"
./include/zbxdb.h:#ifndef ZABBIX_ZBXDB_H
./include/zbxdb.h:#define ZABBIX_ZBXDB_H
src/libs/zbxcomms/comms.c で定義されている事が分かります。後はこの define マクロ名を検索していけば良いですね。私は vi ユーザなので cscope や ctags を使用して辿っていきます。
# vi src/libs/zbxcomms/comms.c
Cscope タグ: ZBX_TCP_HEADER_DATA
# 行番号 ファイル名 / 文脈 / 行
1 487 src/libs/zbxcomms/comms.c <<GLOBAL>>
#define ZBX_TCP_HEADER_DATA "ZBXD"
2 489 src/libs/zbxcomms/comms.c <<ZBX_TCP_HEADER>>
#define ZBX_TCP_HEADER ZBX_TCP_HEADER_DATA ZBX_TCP_HEADER_VERSION
2を選択
Cscope タグ: ZBX_TCP_HEADER
# 行番号 ファイル名 / 文脈 / 行
1 489 src/libs/zbxcomms/comms.c <<GLOBAL>>
#define ZBX_TCP_HEADER ZBX_TCP_HEADER_DATA ZBX_TCP_HEADER_VERSION
2 504 src/libs/zbxcomms/comms.c <<zbx_tcp_send_ext>>
if( ZBX_TCP_ERROR == ZBX_TCP_WRITE(s->socket, ZBX_TCP_HEADER, ZBX_TCP_HEADER_LEN))
3 899 src/libs/zbxcomms/comms.c <<zbx_tcp_recv_ext>>
if( ZBX_TCP_HEADER_LEN == nbytes && 0 == strncmp(s->buf_stat, ZBX_TCP_HEADER, ZBX_TCP_HEADER_LEN) )
3を選択
Cscope タグ: zbx_tcp_recv_ext
# 行番号 ファイル名 / 文脈 / 行
1 98 include/comms.h <<GLOBAL>>
int zbx_tcp_recv_ext(zbx_sock_t *s, char **data, unsigned char flags);
2 96 include/comms.h <<zbx_tcp_recv>>
#define zbx_tcp_recv(s, data) zbx_tcp_recv_ext(s, data, 0)
3 874 src/libs/zbxcomms/comms.c <<zbx_tcp_recv_ext>>
int zbx_tcp_recv_ext(zbx_sock_t *s, char **data, unsigned char flags)
4 50 src/libs/zbxsysinfo/common/http.c <<get_http_page>>
if( SUCCEED == (ret = zbx_tcp_recv_ext(&s, &buf, ZBX_TCP_READ_UNTIL_CLOSE)) )
5 327 src/zabbix_agent/active.c <<refresh_active_checks>>
if( SUCCEED == (ret = zbx_tcp_recv_ext(&s, &buf, ZBX_TCP_READ_UNTIL_CLOSE)) )
6 159 src/zabbix_get/zabbix_get.c <<get_value>>
if( SUCCEED == (ret = zbx_tcp_recv_ext(&s, &buf, ZBX_TCP_READ_UNTIL_CLOSE)) )
7 67 src/zabbix_proxy/servercomms.c <<recv_data_from_server>>
if (FAIL == (res = zbx_tcp_recv_ext(sock, data, 0)))
8 83 src/zabbix_server/nodewatcher/nodecomms.c <<recv_data_from_node>>
if (FAIL == (res = zbx_tcp_recv_ext(sock, data, 0))) {
9 66 src/zabbix_server/poller/checks_agent.c <<get_value_agent>>
ret = zbx_tcp_recv_ext(&s, &buf, ZBX_TCP_READ_UNTIL_CLOSE);
2を選択
Cscope タグ: zbx_tcp_recv
# 行番号 ファイル名 / 文脈 / 行
1 96 include/comms.h <<GLOBAL>>
#define zbx_tcp_recv(s, data) zbx_tcp_recv_ext(s, data, 0)
2 61 src/libs/zbxsysinfo/common/net.c <<tcp_expect>>
else if( SUCCEED == (ret = zbx_tcp_recv(&s, &buf)) )
3 201 src/libs/zbxsysinfo/simple/ntp.c <<check_ntp>>
if( SUCCEED == (ret = zbx_tcp_recv(&s, &buf)) )
4 122 src/libs/zbxsysinfo/simple/simple.c <<check_ssh>>
if( SUCCEED == (ret = zbx_tcp_recv(&s, &recv_buf)) )
5 488 src/zabbix_agent/active.c <<send_buffer>>
if( SUCCEED == (ret = zbx_tcp_recv(&s, &buf)) )
6 44 src/zabbix_agent/listener.c <<process_listener>>
if( SUCCEED == (ret = zbx_tcp_recv(s, &command)) )
7 192 src/zabbix_agent/zabbix_agent.c <<main>>
if( SUCCEED == (ret = zbx_tcp_recv(&s_in, &command)) )
8 226 src/zabbix_sender/zabbix_sender.c <<ZBX_THREAD_ENTRY>>
if( SUCCEED == (tcp_ret = zbx_tcp_recv(&sock, &answer)) )
9 213 src/zabbix_server/trapper/nodecommand.c <<send_script>>
if (SUCCEED == zbx_tcp_recv(&sock, &answer )) {
10 738 src/zabbix_server/trapper/trapper.c <<process_trapper_child>>
if(zbx_tcp_recv(sock, &data) != SUCCEED)
7を選択
:file "src/zabbix_agent/zabbix_agent.c"
157 load_user_parameters();
load_user_parameters() へ tag ジャンプ
Cscope タグ: add_parameter
# 行番号 ファイル名 / 文脈 / 行
1 137 src/zabbix_agent/zbxconf.c <<add_parameter>>
static int add_parameter(char *key)
2 158 src/zabbix_agent/zbxconf.c <<load_user_parameters>>
{"UserParameter", 0, &add_parameter, 0, 0, 0, 0},
1を選択
:file "src/zabbix_agent/zbxconf.c"
146 return add_user_parameter(key, command);
add_user_parameter() へ tag ジャンプ
Cscope タグ: EXECUTE_STR
# 行番号 ファイル名 / 文脈 / 行
1 27 src/libs/zbxsysinfo/common/common.h <<GLOBAL>>
int EXECUTE_STR(const char *cmd, const char *param, unsigned flags, AGENT_RESULT *result);
2 197 src/libs/zbxsysinfo/aix/proc.c <<PROC_MEMORY>>
if (SYSINFO_RET_OK != EXECUTE_STR(cmd, tmp, flags, &proc_args))
3 360 src/libs/zbxsysinfo/aix/proc.c <<PROC_NUM>>
if (SYSINFO_RET_OK != EXECUTE_STR(cmd, tmp, flags, &proc_args))
4 154 src/libs/zbxsysinfo/common/common.c <<EXECUTE_STR>>
int EXECUTE_STR(const char *cmd, const char *param, unsigned flags, AGENT_RESULT *result)
5 319 src/libs/zbxsysinfo/common/common.c <<EXECUTE_INT>>
ret = EXECUTE_STR(cmd,command,flags,result);
6 378 src/libs/zbxsysinfo/common/common.c <<RUN_COMMAND>>
return EXECUTE_STR(cmd,command,flags,result);
7 170 src/libs/zbxsysinfo/common/system.c <<SYSTEM_UNAME>>
return EXECUTE_STR(cmd, "uname -a", flags, result);
8 195 src/libs/zbxsysinfo/common/system.c <<SYSTEM_HOSTNAME>>
return EXECUTE_STR(cmd, "hostname", flags, result);
9 107 src/libs/zbxsysinfo/sysinfo.c <<add_user_parameter>>
commands[i].function = &EXECUTE_STR;
10 124 src/libs/zbxsysinfo/sysinfo.c <<add_user_parameter>>
commands[i].function = &EXECUTE_STR;
4を選択
tag ジャンプや cscope を利用して前後のコードを読みつつ、目当ての関数に辿り着きました。
:file "src/libs/zbxsysinfo/common/common.c"
154 int EXECUTE_STR(const char *cmd, const char *param,
unsigned flags, AGENT_RESULT *result)
~~snip~~
239 command = zbx_dsprintf(command, "%s", param);
240
241 if(0 == (hRead = popen(command,"r")))
242 {
243 switch (errno)
244 {
245 case EINTR: ret = SYSINFO_RET_TIMEOUT;
246 default: ret = SYSINFO_RET_FAIL;
247 }
248 goto lbl_exit;
249 }
250
251 ;
252 /* Read process output */
253 while( (len = fread(stat_buf, 1, sizeof(stat_buf)-1, hRead)) > 0 )
254 {
255 cmd_result = zbx_strdcat(cmd_result, stat_buf);
256 memset(stat_buf, 0, sizeof(stat_buf));
257 }
258
259 if(0 != ferror(hRead))
260 {
261 switch (errno)
262 {
263 case EINTR: ret = SYSINFO_RET_TIMEOUT;
264 default: ret = SYSINFO_RET_FAIL;
265 }
266 goto lbl_exit;
267 }
EXECUTE_STR() の中で popen() でコマンドを実行し、返ってきた出力を cmd_result として一時保存し、最終的には result で返します。また、コマンドが空文字を返した場合はエラーとしていることも分かります。
従って、ZABBIX のユーザパラメータで detarame コマンドが空文字列を出力しても正常にエラー処理されている事が分かりました。
正直に申し上げると、strace のログから cscope と ctags だけでソースコードを調査したわけではありません(^ ^;;、しかしながら、ソースを main() から読み進めなくても、要点のアタリを付けるのに strace が有効なケースもありそうです。
> strace -f -p 3762
と
> strace -f -p 3763
は
> strace -f -p 3762 -p 3763
とすると同時に複数のプロセスを見れますよ。
出力も複数アタッチした時には先頭に
[pid 3762] 〜〜〜〜〜〜〜
[pid 3762] 〜〜〜〜〜〜〜
[pid 3763] 〜〜〜〜〜〜〜
[pid 3763] 〜〜〜〜〜〜〜
[pid 3763] 〜〜〜〜〜〜〜
とか出てくるので後でプロセス別に処理を追うことも可能です。
投稿： tsuzuki | 2009年4月24日 (金) 15:12
switch() の default: の前に break; が無いのは何故？(^^;
投稿： PANDA | 2009年4月25日 (土) 12:56
私は全く気付いていませんでした(- -#
ご指摘ありがとうございます。本家のフォーラムへパッチを投稿しておきました。
http://www.zabbix.com/forum/showthread.php?t=12354
投稿： tmorimoto | 2009年4月26日 (日) 01:09
気になったのでソースをダウンロードして見てみました。（＾＾；
EXECUTE_STR() の中で、 pclose() が失敗した場合、再度 pclose() が呼ばれてしまっていますね。１回の popen() に対して pclose() を２回呼んでも大丈夫なのかなぁ？
RUN_COMMAND() の中の "fork2 failed for '%s'" の後に _exit() ではなく return SYSINFO_RET_FAIL; しているのも意図した動作なのか気になりますね。 WINDOWS ではプログラムを実行できなかった場合にプロセス数は増えないのに、非 WINDOWS では（２回目の zbx_fork() が失敗した場合）１回目の zbx_fork() されたプロセスがずっと waitpid() で待ち続けてしまいます。
投稿： PANDA | 2009年4月26日 (日) 22:31
PANDA さん、レビューありがとうございます。
pclose() は、失敗したときに呼んでいるため、意図は分かるので置いておきましょう(^ ^;;
zbx_fork() ですが、仰る通り、おそらく親プロセスは waitpid で待ち続けると思います。しかし、子プロセスが return されるため、親プロセスの代わりに子プロセスが動作して、見た目上、正常に動作しているのではないかと思います。
ただ、元の親プロセスはずっと waitpid のままなので、コード的には良くないです。本家のフォーラムへも問題提起しておきました。
http://www.zabbix.com/forum/showthread.php?t=12358
投稿： tmorimoto | 2009年4月27日 (月) 12:51