这次的问题相比西安研发中心曾经碰上的Python信号处理问题，有不少基础知识、先验知识是共用的，此处不做再普及，感兴趣的同学可以翻看我以前发过的文章。
下文是一次具体的调试、分析记录。为了简化现场、方便调试，已将原始问题、衍生问题浓缩成DebugPythonWithGDB_6.py、DebugPythonWithGDB_7.py。
$ vi DebugPythonWithGDB_6.py
|
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
|
#!/usr/bin/env python
# -*- encoding: utf-8 -*-
traceback
:
)
)
)
try :
print os.waitpid( -1, os.WNOHANG )
except OSError :
sys.stdout.write( 'Line[%u]: OSError\n' % sys.exc_info()[2].tb_lineno )
:
count
)
#
# 这里存在竞争条件，可以增加触发OSError异常的概率
#
count
:
:
prog
:
)
#
# 本例中，即使有下列代码，Ctrl-C仍然无效。
#
)
#
# signal.signal( signal.SIGCHLD, signal.SIG_IGN )
#
)
#
0
:
#
# 本例中父进程只是一个调度框架，不需要与子进程进行通信，因此不
#
\
(
#
# 不要直接用args[0].split()，它在处理单、双引号时不是我们
#
,
#
# all file descriptors except 0, 1 and 2 will be closed
# before the child process is executed
#
,
)
)
#
# child.send_signal( signal.SIGTERM )
# child.terminate()
#
)
#
# child.wait()
#
)
1
:
:
)
:
pass
|
|
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
|
10244
10245
]
on_SIGCHLD
17
in
)
main
)
do_more
count
)
]
10246
on_SIGCHLD
17
in
)
main
)
do_more
)
:
in
)
main
)
do_more
)
on_SIGCHLD
)
processes
|
流程进入on_SIGCHLD()，但os.waitpid()抛出OSError异常。帮助里写的是，如果系统调用waitpid()返回-1，就抛出异常: An OSError is raised with the value of errno when the syscall returns -1. 10245号子进程在on_SIGCHLD()里waitpid()成功，(10245, 9)中的9表示该进程是被SIGKILL干掉的，符合预期。 10246号子进程是do_more()里的os.system()产生的shell进程，它结束时向10244号父进程投递了SIGCHLD信号。on_SIGCHLD()里waitpid()时，已经在别处wait*()过，10246号子进程已经彻底消失，系统调用waitpid()返回-1，Python函数os.waitpid()抛出异常。 整个过程非常复杂，用伪代码描述如下:
|
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
|
)
)
// posixmodule.c
// weak_alias (__libc_system, system)
// sysdeps/posix/system.c
/*
* SIG_IGN
*
* Ctrl-C暂时失效
*/
)
/*
* 屏蔽(阻塞)SIGCHLD信号
*/
)
)
)
)
/*
* 恢复原有SIGINT信号处理方式
*/
)
/*
*/
)
]
]
)
/*
* 同步调用，会阻塞。不是在信号句柄中异步调用。
*
* 10246号子进程在此被wait*()回收后彻底消失
*/
)
/*
* 恢复原有SIGINT信号处理方式
*/
)
/*
* 取消对SIGCHLD的屏蔽(阻塞)
*/
)
]
]
]
/*
* Python级信号句柄。这个SIGCHLD信号是10246号子进程投递过来的。
*
* DebugPythonWithGDB_6.py的on_SIGCHLD()得到执行
*/
)
/*
* 调用waitpid( -1, &status, WNOHANG )，试图处理10246号子进程。
*
* 10246号子进程已为前述waitpid( pid, &status, 0 )所处理，此处系统调用
* 返回-1，导致os.waitpid()抛出OSError异常。
*/
)
|
整个过程之所以如此复杂，主要是因为Python的信号处理机制比较复杂，让已经非常复杂的Linux信号机制再添变数。参看:
|
1
2
|
Python解释器进行调试》
Linux信号机制》
|
就本例而言，为了确保DebugPythonWithGDB_6.py不因OSError异常而终止，只需在on_SIGCHLD()中调用os.waitpid()时捕捉OSError异常:
|
1
2
3
4
5
|
:
:
)
:
)
|
前述观点有些是动态调试得到，有些是静态分析得到。有人可能问了，为什么不拦截Python进程的C级信号句柄，查看SIGCHLD信号源，以此确认10246号子进程可能被回收两次？其实我最初也想这么干来着，但这是行不通的，因为Python的C级信号句柄signal_handler()是那种最原始的单形参信号句柄，不是高大上的三形参信号句柄。 用GDB调试Python解释器:
|
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
|
.
185.
]
.
10284
10288
]
10289
185
{
bt
#10 Frame 0xb7c20034, for file DebugPythonWithGDB_6.py, line 21, in do_more (count=0)
)
)
#16 Frame 0xb7cbe49c, for file DebugPythonWithGDB_6.py, line 81, in ()
)
7
#0 signal_handler (sig_num=17) at ../Modules/signalmodule.c:185
#1
#2 0xb7fdcd3c in __kernel_vsyscall ()
#3 0xb7db25eb in __sigprocmask (how=how@entry=2, set=0x0, set@entry=0xbffff0d4, oset=oset@entry=0x0) at ../sysdeps/unix/sysv/linux/sigprocmask.c:57
)
|
查看#4的system.c:161，这个位置已经在waitpid( pid, &status, 0 )之后: sigprocmask( SIG_SETMASK, &omask, (sigset_t *)NULL ) 其作用是取消对SIGCHLD的屏蔽(阻塞)。 此时内存布局如下:
|
1
2
3
4
5
6
7
8
9
10
11
12
|
内存高址方向
// ESP+0x2DC output/x *(struct _fpstate *)($esp+0x2dc)
// ESP+0x2D4 x/3i $esp+0x2d4
// ESP+0x2D0 x/1wx $esp+0x2d0
// ESP+0x60 output/x *(struct _fpstate *)($esp+0x60)
// ESP+8 output/x *(struct sigcontext *)($esp+8)
// ESP+4 信号值，信号句柄第一形参
// ESP RetAddr=__kernel_sigreturn
// hexdump $esp 0x2dc
内存低址方向
|
|
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
|
esp
0x11
0x2d4
eax
0x77
0x80
)
{
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
,
0x0
}
|
因为是单形参信号句柄，没有siginfo，无法在用户态获知信号源。但我分析此时的信号源不是10289号子进程，而是10288号子进程。10288产生SIGCHLD时，SIGCHLD信号已被屏蔽(阻塞)，只能保持在内核态的未决信号链上。之后待10289产生SIGCHLD时，sigpending.signal中相应位已经置位，10289产生的SIGCHLD被丢弃，不会进入内核态的未决信号链。SIGCHLD信号的屏蔽(阻塞)被取消后，从内核态的未决信号链上取出10288产生的SIGCHLD进行处理。于是断点命中。 如果完全理解了前述实验结果及分析，就会发现DebugPythonWithGDB_6.py存在竞争条件。subprocess.Popen()对应的子进程投递SIGCHLD信号时，父进程有两种可能:
|
1
2
|
)之前
)之后
|
情况1)会触发OSError异常，情况2)不会触发OSError异常。执行: $ python DebugPythonWithGDB_6.py ‘python -c “import time;time.sleep(3600)”‘ 有时会因OSError异常而终止，有时就一直循环执行下去。出现这种差异，正是竞争环境的表征。 小结一下: 假设针对SIGCHLD安装了Python级信号句柄，其调用os.waitpid( -1, os.WNOHANG )回收子进程。如果别处会调用os.system()，则必须在os.waitpid()外侧捕捉OSError异常。不建议这种方式的混用。 对waitpid()的分析到此就结束了，说点调试过程中出现的其他问题。 意外地发现Ctrl-C无法终止情况2)，而我已经调用: signal.signal( signal.SIGINT, signal.SIG_DFL ) 这是因为do_system()中一上来就调用了:
|
1
2
|
;
;
|
导致Ctrl-C暂时失效，直至do_system()结束。假设DebugPythonWithGDB_6.py已经出 现情况2)，查看它的信号处理方式:
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
|
# ps auwx | grep python
]
python
# stap -DMAXACTION=10000 -g /usr/share/doc/systemtap-doc/examples/process/psig.stp -x 10355
python
default
// 不是预期的default
ignored
default
default
default
default
default
default
default
default
default
ignored
default
default
default
0
.
|
上面显示SIGINT的处理方式是ignored，其实是ignored、default交叉出现，但我们 基本上不可能看到default。 $ vi DebugPythonWithGDB_7.py
|
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
|
#!/usr/bin/env python
# -*- encoding: utf-8 -*-
traceback
:
count
)
count
:
:
prog
:
)
0
:
\
(
,
,
)
)
)
)
1
:
:
)
:
pass
|
$ python DebugPythonWithGDB_7.py ‘python -c “import time;time.sleep(3600)”‘ DebugPythonWithGDB_7.py没有显式调用wait()，它一直循环执行下去。我以为subprocess.Popen()会生成一堆僵尸进程。从另一个终端查看相关进程，发现始终只有一个僵尸进程，很快就被回收了。这个现象挺奇特，只能假设有隐式wait()存在。
|
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
|
.
14508
14512
]
14513
]
81
)
bt
#4 Frame 0xb7c21034, for file /usr/lib/python2.7/subprocess.py, line 1363, in _internal_poll (self=, _deadstate=2147483647, _waitpid=, _WNOHANG=1, _os_error=, _ECHILD=10)
)
#8 Frame 0xb7c6549c, for file /usr/lib/python2.7/subprocess.py, line 762, in __del__ (self=, _maxint=2147483647)
)
#21 Frame 0xb7cbe49c, for file DebugPythonWithGDB_7.py, line 31, in ()
)
9
#0 waitpid () at ../sysdeps/unix/syscall-template.S:81
#1 0x081f80a3 in posix_waitpid (self=0x0, args=(14512, 1)) at ../Modules/posixmodule.c:6207
#2 0x080bc300 in PyCFunction_Call (func=, arg=(14512, 1), kw=0x0) at ../Objects/methodobject.c:81
#3 0x08149d0b in call_function (pp_stack=0xbfffebd4, oparg=2) at ../Python/ceval.c:4033
#4 0x081454ec in PyEval_EvalFrameEx (f=Frame 0xb7c21034, for file /usr/lib/python2.7/subprocess.py, line 1363, in _internal_poll (self=, _deadstate=2147483647, _waitpid=, _WNOHANG=1, _os_error=, _ECHILD=10), throwflag=0) at ../Python/ceval.c:2679
#5 0x08147a77 in PyEval_EvalCodeEx (co=0xb7c60448, globals={'STDOUT': -2, '_has_poll': True, 'gc': , 'check_call': , 'mswindows': False, 'select': , 'list2cmdline': , '__all__': ['Popen', 'PIPE', 'STDOUT', 'call', 'check_call', 'check_output', 'CalledProcessError'], 'errno': , '_demo_posix': , '__package__': None, 'PIPE': -1, '_cleanup': , '_eintr_retry_call': , 'call': , '__doc__': 'subprocess - Subprocesses with accessible I/O streams\n\nThis module allows you to spawn processes, connect to their\ninput/output/error pipes, and obtain their return codes. This module\nintends to replace several older modules and functions:\n\nos.system\nos.spawn*\nos.popen*\npopen2.*\ncommands.*\n\nInformation about how the subprocess module can be used to replace these\nmodules and functions can be found below.\n\...(truncated), locals=0x0, args=0xb7c655e4, argcount=1, kws=0xb7c655e8, kwcount=1, defs=0xb7c73a20, defcount=5, closure=0x0) at ../Python/ceval.c:3265
#6 0x0814a1e5 in fast_function (func=, pp_stack=0xbfffeef4, n=3, na=1, nk=1) at ../Python/ceval.c:4129
#7 0x08149e93 in call_function (pp_stack=0xbfffeef4, oparg=256) at ../Python/ceval.c:4054
#8 0x081454ec in PyEval_EvalFrameEx (f=Frame 0xb7c6549c, for file /usr/lib/python2.7/subprocess.py, line 762, in __del__ (self=, _maxint=2147483647), throwflag=0) at ../Python/ceval.c:2679
)
|
调用栈回溯表明:
查看: /usr/lib/python2.7/subprocess.py:1363
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
|
:
)
.
:
.
:
#
# This happens if SIGCLD is set to be ignored or waiting for child
# processes has otherwise been disabled for our process. This
# child is dead, we can't get the status.
#
# http://bugs.python.org/issue15756
#
.
|
考虑这种情形，调用subprocess.Popen()之前做过如下动作之一:
|
1
2
|
)
)
|
_internal_poll()调用_waitpid()时，在外侧捕捉了_os_error异常，就是对付上述可能。subprocess.Popen()不是built-in函数，对应很多条PVM指令，不像os.system()是built-in函数，对应单条PVM指令。前者执行过程中，Python级信号句柄on_SIGCHLD()有很大机会得到执行，_internal_poll()调用_waitpid()，遭遇_os_error异常的可能性不低。 Popen()对象的析构函数自动调用wait*()，于是Popen()对象离开作用域时自动回收子进程。 Python能够改变变量作用域的是def、class、lamda、global。下面这些并不涉及作用域变更:
|
1
2
3
|
else
finally
while
|
DebugPythonWithGDB_7.py中Popen()对象的作用域是main()。尽管没有离开作用域，但对child变量的重新赋值会触发对前一个Popen()对象的析构。这就解释了为什么始终只有一个僵尸进程。 回顾原始问题与衍生问题，再次表明，掌握对Python解释器的调试技术可以快速排查众多看似神秘实则基础的程序故障。