Issue 17992: test_asynchat hangs - Python tracker (original) (raw)

Issue17992

Created on 2013-05-16 04:54 by Carlos.Nepomuceno, last changed 2022-04-11 14:57 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
test_asynchat.txt Carlos.Nepomuceno,2013-05-16 05:00
test_asynchat_strace.txt Carlos.Nepomuceno,2013-05-16 12:05
asyncore-timeout.patch giampaolo.rodola,2013-05-16 12:40 review
test_asynchat.py giampaolo.rodola,2013-05-16 13:01
test_asyncore.py giampaolo.rodola,2013-05-16 13:01
Messages (19)
msg189340 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 04:54
after running 'make' i entered 'make test' and it hanged on test_asynchat. stayed there for more than 1 hour. --- Python build finished, but the necessary bits to build these modules were not found: _bsddb _tkinter bsddb185 bz2 dbm dl gdbm imageop readline sunaudiodev To find the necessary bits, look in setup.py in detect_modules() for the module's name. running build_scripts ./python -E -c 'import sys ; from sysconfig import get_platform ; print get_platform()+"-"+sys.version[0:3]' >platform find ./Lib -name '*.py[co]' -print | xargs rm -f ./python -Wd -3 -E -tt ./Lib/test/regrtest.py -l == CPython 2.7.5 (default, May 16 2013, 00:43:33) [GCC 4.4.7 20120313 (Red Hat 4.4.7-3)] == Linux-2.6.32-279.19.1.el6.x86_64-x86_64-with-centos-6.4-Final little-endian == /usr/src/Python-2.7.5/build/test_python_26106 Testing with flags: sys.flags(debug=0, py3k_warning=1, division_warning=1, division_new=0, inspect=0, interactive=0, optimize=0, dont_write_bytecode=0, no_user_site=0, no_site=0, ignore_environment=1, tabcheck=2, verbose=0, unicode=0, bytes_warning=0, hash_randomization=0) test_grammar test_opcodes test_dict test_builtin test_exceptions test_types test_unittest /usr/src/Python-2.7.5/Lib/unittest/runner.py:39: DeprecationWarning: comparing unequal types not supported in 3.x self.showAll = verbosity > 1 test_doctest test_doctest2 test_MimeWriter test_SimpleHTTPServer test_StringIO test___all__ test___future__ test__locale test__osx_support test_abc test_abstract_numbers test_aepack test_aepack skipped -- No module named aetypes test_aifc test_al test_al skipped -- No module named al test_anydbm test_applesingle test_applesingle skipped -- No module named MacOS test_argparse test_array test_ascii_formatd test_ast test_asynchat
msg189345 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2013-05-16 09:52
Can you try to figure out where it hangs exactly? I can't reproduce the issue on Ubuntu and FreeBSD and don't have a Red Hat to test against.
msg189347 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 10:09
I don't know what to do. I tried CTRL+C but it didn't stop. Then I pressed CTRL+Z and kill the python process and when i got back with 'fg' the make process had been terminated. No messages were printed.
msg189349 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2013-05-16 10:27
Does it hang also if you run it directly as in "./python Lib/test/test_asynchat.py". Perhaps you ca try "./python -m trace -t Lib/test/test_asynchat.py"? Figuring this out should be relatively easy: you can also just put prints into test_asynchat.py yourself.
msg189350 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 10:31
./python -m trace -t Lib/test/test_asynchat.py [...] --- modulename: asyncore, funcname: poll asyncore.py(126): if map is None: asyncore.py(128): if map: asyncore.py(129): r = []; w = []; e = [] asyncore.py(130): for fd, obj in map.items(): asyncore.py(131): is_r = obj.readable() --- modulename: asynchat, funcname: readable asynchat.py(198): return 1 asyncore.py(132): is_w = obj.writable() --- modulename: asynchat, funcname: writable asynchat.py(202): return self.producer_fifo or (not self.connected) asyncore.py(133): if is_r: asyncore.py(134): r.append(fd) asyncore.py(136): if is_w and not obj.accepting: asyncore.py(137): w.append(fd) asyncore.py(138): if is_r or is_w: asyncore.py(139): e.append(fd) asyncore.py(130): for fd, obj in map.items(): asyncore.py(140): if [] == r == w == e: asyncore.py(144): try: asyncore.py(145): r, w, e = select.select(r, w, e, timeout) asyncore.py(152): for fd in r: asyncore.py(158): for fd in w: asyncore.py(164): for fd in e: asyncore.py(221): count = count - 1 asyncore.py(219): while map and count > 0: test_asynchat.py(225): s.start_resend_event.set() --- modulename: threading, funcname: set threading.py(580): self.__cond.acquire() threading.py(581): try: threading.py(582): self.__flag = True threading.py(583): self.__cond.notify_all() --- modulename: threading, funcname: notifyAll threading.py(406): self.notify(len(self.__waiters)) --- modulename: threading, funcname: notify threading.py(382): if not self._is_owned(): --- modulename: threading, funcname: _is_owned threading.py(302): if self.__lock.acquire(0): threading.py(306): return True threading.py(384): __waiters = self.__waiters threading.py(385): waiters = __waiters[:n] threading.py(386): if not waiters: threading.py(388): self._note("%s.notify(): no waiters", self) --- modulename: threading, funcname: _note threading.py(64): if self.__verbose: threading.py(389): return threading.py(585): self.__cond.release() test_asynchat.py(226): s.join() --- modulename: threading, funcname: join threading.py(933): if not self.__initialized: threading.py(935): if not self.__started.is_set(): --- modulename: threading, funcname: isSet threading.py(569): return self.__flag threading.py(937): if self is current_thread(): --- modulename: threading, funcname: currentThread threading.py(1157): try: threading.py(1158): return _active[_get_ident()] threading.py(941): if not self.__stopped: threading.py(942): self._note("%s.join(): waiting until thread stops", self) --- modulename: threading, funcname: _note threading.py(64): if self.__verbose: threading.py(943): self.__block.acquire() threading.py(944): try: threading.py(945): if timeout is None: threading.py(946): while not self.__stopped: threading.py(947): self.__block.wait() --- modulename: threading, funcname: wait threading.py(331): if not self._is_owned(): --- modulename: threading, funcname: _is_owned threading.py(302): if self.__lock.acquire(0): threading.py(306): return True threading.py(333): waiter = _allocate_lock() threading.py(334): waiter.acquire() threading.py(335): self.__waiters.append(waiter) threading.py(336): saved_state = self._release_save() --- modulename: threading, funcname: _release_save threading.py(294): self.__lock.release() # No state to save threading.py(337): try: # restore state no matter what (e.g., KeyboardInterrupt) threading.py(338): if timeout is None: threading.py(339): waiter.acquire()
msg189351 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2013-05-16 10:47
Nosying Collin Winter as per rev 531d3023b48b. In the meantime you can try to specify a timeout for join() as in: diff --git a/Lib/test/test_asynchat.py b/Lib/test/test_asynchat.py --- a/Lib/test/test_asynchat.py +++ b/Lib/test/test_asynchat.py @@ -223,7 +223,7 @@ # where the server echoes all of its data before we can check that it # got any down below. s.start_resend_event.set() - s.join() + s.join(timeout=2.0) That should at least fix the hanging, but I guess it will produce another error later on.
msg189356 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 10:59
Thank you! But what's going on? Do my system have any limitation that is causing such hang? Here goes it's ulimit output just in case: [root@localhost Python-2.7.5]# ulimit -a core file size (blocks, -c) 0 data seg size (kbytes, -d) unlimited scheduling priority (-e) 0 file size (blocks, -f) unlimited pending signals (-i) 31259 max locked memory (kbytes, -l) 64 max memory size (kbytes, -m) unlimited open files (-n) 1024 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 10240 cpu time (seconds, -t) unlimited max user processes (-u) 31259 virtual memory (kbytes, -v) unlimited file locks (-x) unlimited [root@localhost Python-2.7.5]#
msg189358 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2013-05-16 11:57
Could you provide the output of: strace -ttT -f ./python Lib/test/test_asynchat.py
msg189359 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 12:05
Full output in the attached file. [root@localhost Python-2.7.5]# strace -ttT -f ./python Lib/test/test_asynchat.py [...] [pid 1697] 08:01:27.815179 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010095> [pid 1697] 08:01:27.825348 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010096> [pid 1697] 08:01:27.835509 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010097> [pid 1697] 08:01:27.845669 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010096> [pid 1697] 08:01:27.855830 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010095> [pid 1697] 08:01:27.866028 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010096> [pid 1697] 08:01:27.876188 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010096> [pid 1697] 08:01:27.886388 futex(0x1bb8280, FUTEX_WAIT_PRIVATE, 0, NULL
msg189363 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2013-05-16 12:15
That's what I thought: 08:01:24.824406 bind(3, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("127.0.0.1")}, 16) = 0 <0.000024> [pid 1698] 08:01:24.825502 listen(3, 1) = 0 <0.000035> [pid 1698] 08:01:24.825786 accept(3, <unfinished ...> [pid 1697] 08:01:24.837622 connect(5, {sa_family=AF_INET, sin_port=htons(43785), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000074> [pid 1697] 08:01:24.837811 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010095> [pid 1697] 08:01:27.876188 select(6, [5], [5], [5], {0, 10000}) = 0 (Timeout) <0.010096> [pid 1697] 08:01:27.886388 futex(0x1bb8280, FUTEX_WAIT_PRIVATE, 0, NULL See the EINPROGRESS? The connect() doesn't return within 3 seconds. You probably have a firewall on your machine. What does: # iptables -L return ?
msg189364 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 12:23
What ports are needed? [root@localhost Python-2.7.5]# iptables -L Chain INPUT (policy DROP) target prot opt source destination ACCEPT udp -- anywhere anywhere udp dpt:domain ACCEPT tcp -- anywhere anywhere tcp dpt:http ACCEPT tcp -- anywhere anywhere tcp dpt:https ACCEPT icmp -- anywhere anywhere icmp echo-request ACCEPT all -- anywhere anywhere state RELATED,ESTABLISHED Chain FORWARD (policy DROP) target prot opt source destination Chain OUTPUT (policy ACCEPT) target prot opt source destination ACCEPT all -- anywhere anywhere state NEW [root@localhost Python-2.7.5]#
msg189365 - (view) Author: Charles-François Natali (neologix) * (Python committer) Date: 2013-05-16 12:28
> What ports are needed? Many tests use random ephemeral ports on the loopback interface (e.g. 43785 above). You should update your rules to apply to external NIC, not on the loopback.
msg189367 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2013-05-16 12:40
Good catch! I think we better set a general timeout so that the tests fail instead of hanging though. Carlos can you try the patch in attachment and confirm you see failures instead of hangings?
msg189370 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 12:54
Yes, but I don't have the git clone. Can you send the complete file instead of the patch?
msg189371 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 12:54
BTW, problem solved with: iptables -A INPUT -d 127.0.0.1 -j ACCEPT iptables -A INPUT -s 127.0.0.1 -j ACCEPT Thanks a lot! \o
msg189374 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 13:16
Tried to use the new files[1] but they use 'support' instead of 'test_support' from 'test' module. [1] test_asynchat.py, test_asyncore.py
msg189375 - (view) Author: Giampaolo Rodola' (giampaolo.rodola) * (Python committer) Date: 2013-05-16 13:19
Nevermind. It's an easy patch so I'm going to commit it anyway.
msg189377 - (view) Author: Carlos Nepomuceno (Carlos.Nepomuceno) Date: 2013-05-16 13:21
Ok! Thanks a lot!
msg189378 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2013-05-16 13:22
New changeset 3ee61b048173 by Giampaolo Rodola' in branch 'default': Issue #17992: Add timeouts to asyncore and asynchat tests so that they won't accidentally hang. http://hg.python.org/cpython/rev/3ee61b048173
History
Date User Action Args
2022-04-11 14:57:45 admin set github: 62192
2013-05-16 13:22:06 python-dev set nosy: + python-devmessages: +
2013-05-16 13:21:14 Carlos.Nepomuceno set messages: +
2013-05-16 13:19:22 giampaolo.rodola set messages: +
2013-05-16 13:16:06 Carlos.Nepomuceno set messages: +
2013-05-16 13:01:37 giampaolo.rodola set files: + test_asyncore.py
2013-05-16 13:01:29 giampaolo.rodola set files: + test_asynchat.py
2013-05-16 12:54:54 Carlos.Nepomuceno set messages: +
2013-05-16 12:54:21 Carlos.Nepomuceno set messages: +
2013-05-16 12:40:24 giampaolo.rodola set files: + asyncore-timeout.patchkeywords: + patchmessages: +
2013-05-16 12:28:11 neologix set status: open -> closedresolution: not a bugmessages: + stage: resolved
2013-05-16 12:23:33 Carlos.Nepomuceno set messages: +
2013-05-16 12:15:06 neologix set messages: +
2013-05-16 12:05:54 Carlos.Nepomuceno set files: + test_asynchat_strace.txtmessages: +
2013-05-16 11:57:44 neologix set nosy: + neologixmessages: +
2013-05-16 10:59:50 Carlos.Nepomuceno set messages: +
2013-05-16 10:47:19 giampaolo.rodola set nosy: + collinwintermessages: +
2013-05-16 10:31:52 Carlos.Nepomuceno set messages: +
2013-05-16 10:27:07 giampaolo.rodola set messages: +
2013-05-16 10:09:46 Carlos.Nepomuceno set messages: +
2013-05-16 09:52:27 giampaolo.rodola set messages: +
2013-05-16 06:33:03 tshepang set nosy: + tshepang
2013-05-16 06:32:14 tshepang set nosy: + josiahcarlson, giampaolo.rodola, stutzbach
2013-05-16 05:00:26 Carlos.Nepomuceno set files: + test_asynchat.txt
2013-05-16 05:00:13 Carlos.Nepomuceno set files: - test_asynchat.txt
2013-05-16 04:58:24 Carlos.Nepomuceno set files: + test_asynchat.txt
2013-05-16 04:58:01 Carlos.Nepomuceno set files: - test_asynchat.txt
2013-05-16 04:57:27 brian.curtin set type: compile error -> behavior
2013-05-16 04:54:43 Carlos.Nepomuceno create