test_asynchat hangs

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

BPO	17992
Nosy	@josiahcarlson, @giampaolo
Files	test_asynchat.txt test_asynchat_strace.txt asyncore-timeout.patch test_asynchat.py test_asyncore.py

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields: ```python assignee = None closed_at = created_at = labels = ['invalid', 'type-bug', 'tests'] title = 'test_asynchat hangs' updated_at = user = 'https://bugs.python.org/CarlosNepomuceno' ``` bugs.python.org fields: ```python activity = actor = 'python-dev' assignee = 'none' closed = True closed_date = closer = 'neologix' components = ['Tests'] creation = creator = 'Carlos.Nepomuceno' dependencies = [] files = ['30279', '30281', '30283', '30285', '30286'] hgrepos = [] issue_num = 17992 keywords = ['patch'] message_count = 19.0 messages = ['189340', '189345', '189347', '189349', '189350', '189351', '189356', '189358', '189359', '189363', '189364', '189365', '189367', '189370', '189371', '189374', '189375', '189377', '189378'] nosy_count = 8.0 nosy_names = ['collinwinter', 'josiahcarlson', 'giampaolo.rodola', 'stutzbach', 'neologix', 'tshepang', 'python-dev', 'Carlos.Nepomuceno'] pr_nums = [] priority = 'normal' resolution = 'not a bug' stage = 'resolved' status = 'closed' superseder = None type = 'behavior' url = 'https://bugs.python.org/issue17992' versions = ['Python 2.7'] ```

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

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_ testfuture testlocale 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

[giampaolo]

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.

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

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.

[giampaolo]

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.

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

./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_resendevent.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.notifyall() --- 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: _isowned 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() testasynchat.py(226): s.join() --- modulename: threading, funcname: join threading.py(933): if not self.__initialized: threading.py(935): if not self.\_started.isset(): --- 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[_getident()] 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: _isowned threading.py(302): if self.\_lock.acquire(0): threading.py(306): return True threading.py(333): waiter = _allocatelock() threading.py(334): waiter.acquire() threading.py(335): self.\_waiters.append(waiter) threading.py(336): saved_state = self._release_save() --- modulename: threading, funcname: _releasesave 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()

[giampaolo]

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.

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

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]#

[79528080-9d85-4d18-8a2a-8b1f07640dd7]

Could you provide the output of:

strace -ttT -f ./python Lib/test/test_asynchat.py

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

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>

[79528080-9d85-4d18-8a2a-8b1f07640dd7]

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 ?

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

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]#

[79528080-9d85-4d18-8a2a-8b1f07640dd7]

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.

[giampaolo]

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?

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

Yes, but I don't have the git clone. Can you send the complete file instead of the patch?

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

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

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

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

[giampaolo]

Nevermind. It's an easy patch so I'm going to commit it anyway.

[5f1f2f5c-9512-4a7c-bae9-425451fb9925]

Ok! Thanks a lot!

[1762cc99-3127-4a62-9baf-30c3d0f51ef7]

New changeset 3ee61b048173 by Giampaolo Rodola' in branch 'default': Issue bpo-17992: Add timeouts to asyncore and asynchat tests so that they won't accidentally hang. http://hg.python.org/cpython/rev/3ee61b048173