classification
Title: test_asynchat hangs
Type: behavior Stage: resolved
Components: Tests Versions: Python 2.7
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: Carlos.Nepomuceno, collinwinter, giampaolo.rodola, josiahcarlson, neologix, python-dev, stutzbach, tshepang
Priority: normal Keywords: patch

Created on 2013-05-16 04:54 by Carlos.Nepomuceno, last changed 2013-05-16 13:22 by python-dev. 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
<PNR>
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
<PNR>

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) 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
2013-05-16 13:22:06python-devsetnosy: + python-dev
messages: + msg189378
2013-05-16 13:21:14Carlos.Nepomucenosetmessages: + msg189377
2013-05-16 13:19:22giampaolo.rodolasetmessages: + msg189375
2013-05-16 13:16:06Carlos.Nepomucenosetmessages: + msg189374
2013-05-16 13:01:37giampaolo.rodolasetfiles: + test_asyncore.py
2013-05-16 13:01:29giampaolo.rodolasetfiles: + test_asynchat.py
2013-05-16 12:54:54Carlos.Nepomucenosetmessages: + msg189371
2013-05-16 12:54:21Carlos.Nepomucenosetmessages: + msg189370
2013-05-16 12:40:24giampaolo.rodolasetfiles: + asyncore-timeout.patch
keywords: + patch
messages: + msg189367
2013-05-16 12:28:11neologixsetstatus: open -> closed
resolution: not a bug
messages: + msg189365

stage: resolved
2013-05-16 12:23:33Carlos.Nepomucenosetmessages: + msg189364
2013-05-16 12:15:06neologixsetmessages: + msg189363
2013-05-16 12:05:54Carlos.Nepomucenosetfiles: + test_asynchat_strace.txt

messages: + msg189359
2013-05-16 11:57:44neologixsetnosy: + neologix
messages: + msg189358
2013-05-16 10:59:50Carlos.Nepomucenosetmessages: + msg189356
2013-05-16 10:47:19giampaolo.rodolasetnosy: + collinwinter
messages: + msg189351
2013-05-16 10:31:52Carlos.Nepomucenosetmessages: + msg189350
2013-05-16 10:27:07giampaolo.rodolasetmessages: + msg189349
2013-05-16 10:09:46Carlos.Nepomucenosetmessages: + msg189347
2013-05-16 09:52:27giampaolo.rodolasetmessages: + msg189345
2013-05-16 06:33:03tshepangsetnosy: + tshepang
2013-05-16 06:32:14tshepangsetnosy: + josiahcarlson, giampaolo.rodola, stutzbach
2013-05-16 05:00:26Carlos.Nepomucenosetfiles: + test_asynchat.txt
2013-05-16 05:00:13Carlos.Nepomucenosetfiles: - test_asynchat.txt
2013-05-16 04:58:24Carlos.Nepomucenosetfiles: + test_asynchat.txt
2013-05-16 04:58:01Carlos.Nepomucenosetfiles: - test_asynchat.txt
2013-05-16 04:57:27brian.curtinsettype: compile error -> behavior
2013-05-16 04:54:43Carlos.Nepomucenocreate