Hang waiting for create_server

[jimfulton]

• uvloop 0.4.33:
• python 3.5.1, 3.5.2:
• platform Mac OS X, Ubuntu 16.04/4.4.12-boot2docker:

I need some suggestions for debugging server startup hangs.

Startup code looks like:

 cr = loop.create_server(self.factory, addr[0], addr[1],
                                reuse_address=True, ssl=ssl)
f = asyncio.async(cr, loop=loop)
server = loop.run_until_complete(f)

What's sometimes happening, in the context of the ZEO tests, is that the run_loop_until_complete call above never returns.

This is in a port of ZEO, github.com/zopefoundation/ZEO, to asyncio. The ZEO tests are exhaustive, and I suspect in uvloop's case, exhausting. :) The tests start and stop servers 10s, maybe 100s of times in a test runs that typically lasts a few minutes. If I run a smaller subset of the tests I don't get a hang.

Most tests run the server as a subprocess using multiprocessing. Some tests run the server using threading. It appears that the server isn't exiting, but merely hanging.

Do you have any suggestions for how to debug this? I've tried setting PYTHONASYNCIODEBUG=1 and enabling debug logging, but that isn't yielding any additional information..

[1st1]

The general advice is to create a minimal testcase and then debug the code with gdb (or lldb) and print statements ;)

In this particular case, could you please tell me the values of addr and ssl? Does the loop have any other scheduled tasks? Does it run in the main thread?

[1st1]

I'd also suggest to add prints before each await in Loop.create_server. That should give us better understanding where exactly the loop hangs.

[1st1]

Hm, actually, there is only one await in Loop.create_server, and it waits on getaddrinfo. So it might be a bug in the DNS resolver. What's the value of addr?

[1st1]

And there's also an option to make a debug build with make debug. When built in debug mode, loop has a print_debug_info() method which outputs a bunch of useful debug info.

[jimfulton]

On Thu, Jul 7, 2016 at 5:39 PM, Yury Selivanov notifications@github.com
wrote:

The general advice is to create a minimal testcase and then debug the code
with gdb (or lldb) and print statements ;)

Yeah. I took an initial stab at that, but it was too minimal. I'll take
another stab.

In this particular case, could you please tell me the values of addr and
ssl?

ssl is usually, but not always None. I just hacked out SSL-related tests
and ssl support, and still hanging. So for the sake of this discussion,
SSL is always None.

The address is almost always ('127.0.0.1', 0). I just did some test
cleanup to make this so. :) Previously, it often had a host of
'localhost' or '' and a randomly selected port. There may also be a
test or 2 that uses unix-domain sockets. (If not, I should add one. :) ).

Does the loop have any other scheduled tasks?

No.

Does it run in the main thread?

No. (I don't currently call set_event_loop, because I pass the loop around
and nothing was relying on the default event loop. Previously, I was
calling set_event_loop, and the server was hanging then as well.

I'm 70% sure this is a resource exhaustion problem of some sort.

Also worth noting:

• I tried just using uvloop for clients and still got a test failure, one
  of which had to do with running the client within a multiprocessing Process.
• The test servers almost always are run in a multi-Processing process.

Jim

Jim Fulton
http://jimfulton.info

[jimfulton]

On Thu, Jul 7, 2016 at 6:05 PM, Yury Selivanov notifications@github.com
wrote:

Hm, actually, there is only one await in Loop.create_server, and it waits
on getaddrinfo. So it might be a bug in the DNS resolver. What's the
value of addr?

Almost always ('127.0.0.1', 0)

[jimfulton]

On Thu, Jul 7, 2016 at 6:45 PM, Yury Selivanov notifications@github.com
wrote:

And there's also an option to make a debug build with make debug. When
built in debug mode, loop has a print_debug_info() method which outputs a
bunch of useful debug info.

OK, I'll try that. Would you suggest print_debug_info() here:

https://github.com/zopefoundation/ZEO/blob/debug-uvloop/src/ZEO/asyncio/server.py#L226

[1st1]

OK, I'll try that. Would you suggest print_debug_info() here:

The idea is to create a debug task that will periodically print debug info on the screen. This is how I use it in uvloop benchmarks:
https://github.com/MagicStack/uvloop/blob/master/examples/bench/echoserver.py#L78

I'm thinking about adding a manhole or something, that would let you attach to a running event loop from the outside.

[jimfulton]

The program was running out of file descriptors. Not an issue with uvloop at all. Sorry for the noise.

[1st1]

Thanks a lot for confirming this!

[jimfulton]

I was wrong. It has nothing to do with running out of file descriptors. (I was able to make uvloop fail when having too many open files, but that's not what made the tests fail.)

Many of the ZEO tests are integration tests. Typically, these tests run a server in a subprocess using multiprocessing. A few tests run the server in a thread, which makes it possible to introspect server state. Mixing thread-based and multiprocessing-based tests leads to hanging in the test runner when using uvloop.

Here's a minimal script that demonstrates the problem:

https://gist.github.com/jimfulton/59c02a96ebe4720d512b2b0ee426c7ed

I'm not sure if this issue is specific to multiprocessing (I suspect so because magic :) ) or would also be an issue with other ways of running a server in a subprocess.