Path: csiph.com!feeder.erje.net!2.eu.feeder.erje.net!news2.arglkargh.de!news.mixmin.net!aioe.org!bofh.it!news.nic.it!robomod
From: Alexandros Afentoulis <alexaf@bloom.re>
Newsgroups: linux.debian.maint.python
Subject: ITP #816713 , pytest stuck while dpkg building
Date: Sun, 21 Jan 2018 20:50:02 +0100
Message-ID: <vatMR-2JJ-3@gated-at.bofh.it>
Old-Return-Path: <alexaf@bloom.re>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Language: en-US
Content-Transfer-Encoding: 8bit
Approved: robomod@news.nic.it
Lines: 128
Organization: linux.* mail to news gateway
Sender: robomod@news.nic.it
Xref: csiph.com linux.debian.maint.python:10077

Hello people,

I've ITPed #816713, pytest-flask, and been working to provide a package
for it [1].

There is a specific pytest test [2] that gets stuck (neither passing nor
failing) when building the package, either with pbuilder or
dpkg-buildpackage. On the other hand when running the test within a
simple virtualenv it passes alright.

This is the test, essentially two HTTP endpoints where a GET to the
first results in a GET to the second, as far as I can tell:

> def test_concurrent_requests_to_live_server(self, appdir):
>         appdir.create_test_module('''
>             import pytest
>             try:
>                 from urllib2 import urlopen
>             except ImportError:
>                 from urllib.request import urlopen
>             from flask import url_for
>             def test_concurrent_requests(live_server):
>                 @live_server.app.route('/one')
>                 def one():
>                     res = urlopen(url_for('two', _external=True))
>                     return res.read()
>                 @live_server.app.route('/two')
>                 def two():
>                     return '42'
>                 live_server.start()
>                 res = urlopen(url_for('one', _external=True))
>                 assert res.code == 200
>                 assert b'42' in res.read()
>         ''')
>         result = appdir.runpytest('-v', '--no-start-live-server')
>         result.stdout.fnmatch_lines(['*PASSED*'])
>         assert result.ret == 0
> 

This is the cowbuilder point that gets stuck:

> make[1]: Entering directory '/build/pytest-flask-0.10.0'
> PYBUILD_SYSTEM=custom PYBUILD_TEST_ARGS="{interpreter} -m pytest -v -x" dh_auto_test
> I: pybuild base:184: python2.7 -m pytest -v -x
> ===================================================================================== test session starts =====================================================================================
> platform linux2 -- Python 2.7.13, pytest-3.0.6, py-1.4.32, pluggy-0.4.0 -- /usr/bin/python2.7
> cachedir: .cache
> rootdir: /build/pytest-flask-0.10.0, inifile: 
> plugins: flask-0.10.0
> collected 22 items 
> 
> tests/test_fixtures.py::TestFixtures::test_config_access PASSED
> tests/test_fixtures.py::TestFixtures::test_client PASSED
> tests/test_fixtures.py::TestFixtures::test_accept_json PASSED
> tests/test_fixtures.py::TestFixtures::test_accept_jsonp PASSED
> tests/test_fixtures.py::TestFixtures::test_request_ctx PASSED
> tests/test_fixtures.py::TestFixtures::test_request_ctx_is_kept_around PASSED
> tests/test_fixtures.py::TestJSONResponse::test_json_response PASSED
> tests/test_fixtures.py::TestJSONResponse::test_dont_rewrite_existing_implementation PASSED
> tests/test_fixtures.py::TestClientClass::test_client_attribute PASSED
> tests/test_live_server.py::TestLiveServer::test_server_is_alive PASSED
> tests/test_live_server.py::TestLiveServer::test_server_url PASSED
> tests/test_live_server.py::TestLiveServer::test_server_listening PASSED
> tests/test_live_server.py::TestLiveServer::test_url_for PASSED
> tests/test_live_server.py::TestLiveServer::test_set_application_server_name PASSED
> tests/test_live_server.py::TestLiveServer::test_rewrite_application_server_name PASSED
> tests/test_live_server.py::TestLiveServer::test_prevent_starting_live_server PASSED
> tests/test_live_server.py::TestLiveServer::test_start_live_server PASSED
> tests/test_live_server.py::TestLiveServer::test_add_endpoint_to_live_server PASSED
> tests/test_live_server.py::TestLiveServer::test_concurrent_requests_to_live_server 

This ^^ never returns.

I tried to understand why this test never ends and reran with
dpkg-buildpackage instead of pbuilder, which resulted in getting stuck
at the same point.

> ➜  localhost ~  ps auxw | grep pytest
> ale 15047  0.0  0.0   4292   728 pts/3    S+   16:42   0:00 /bin/sh -c PYBUILD_SYSTEM=custom PYBUILD_TEST_ARGS="{interpreter} -m pytest -v -x" dh_auto_test
> ale 15058  0.1  0.1  39148 13156 pts/3    S+   16:42   0:00 /usr/bin/python3 /usr/bin/pybuild --test --test-pytest -i python{version} -p 2.7
> ale 15060  0.0  0.0   4292   728 pts/3    S+   16:42   0:00 /bin/sh -c python2.7 -m pytest -v -x
> ale 15061  2.0  0.7 103820 60772 pts/3    S+   16:42   0:01 python2.7 -m pytest -v -x
> ale 15081  0.0  0.7 104084 57636 pts/3    S+   16:42   0:00 python2.7 -m pytest -v -x

> ➜  localhost ~  ps -o ppid -p 15081      
>  PPID
> 15061

And these are the open sockets:
> ➜  localhost ~  lsof -p 15061 | grep TCP 
> python2.7 15061 ale   15u  IPv4 988438      0t0     TCP localhost:38524->localhost:50549 (ESTABLISHED)
> ➜  localhost ~  lsof -p 15081 | grep TCP
> python2.7 15081 ale   17u  IPv4 990400      0t0     TCP localhost:50549 (LISTEN)
> python2.7 15081 ale   18u  IPv4 987027      0t0     TCP localhost:50549->localhost:38524 (ESTABLISHED)
> python2.7 15081 ale   19u  IPv4 987032      0t0     TCP localhost:38528->localhost:50549 (ESTABLISHED)

Stack trace points that both processes are waiting with 'sk_wait_data'.

The Recv-Q counter troubles me a bit:
> root@localhost:~# netstat -p | grep "Proto Rec\|50549"
> Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name    
> tcp      121      0 localhost:50549         localhost:38528         ESTABLISHED -                   
> tcp        0      0 localhost:38528         localhost:50549         ESTABLISHED 15081/python2.7     
> tcp        0      0 localhost:38524         localhost:50549         ESTABLISHED 15061/python2.7     
> tcp        0      0 localhost:50549         localhost:38524         ESTABLISHED 15081/python2.7 

Does this mean that the listener has some bytes in the recv-q
that have not been processed for some reason? Perhaps that's why the
test never ends?

I'm trying to understand which parameter of the dpkg environment results
in this behavior. Is there some kind of restriction for the
interprocess communication through TCP sockets? As far as I can tell
'USENETWORK' has nothing to do with this, since all connections are to
localhost.

Any insight would be appreciated.

Of course bypassing the test with
'-k-test_concurrent_requests_to_live_server' successfully builds the
package.

Thanks in advance,
Alexandros

[1] https://gitlab.com/alexaf/pytest-flask
[2]
https://github.com/pytest-dev/pytest-flask/blob/master/tests/test_live_server.py#L86