tokio::run keeps on running even though all futures are done

[GeorgeKT]

The problem occurred in a unit test, which uses a hyper client to send a http request, to a hyper server, running on the same tokio::run as the client. After the request is done, I use a oneshot to tell the server to stop. And the server future stops, so at this point all futures in the tokio::run are done, and it ough to return, but it doesn't.

Note that I'm using the unreleased hyper 0.12 branch, which has support for the new tokio crate. This might be a hyper problem, but it seems more like a tokio problem, seeing that both the hyper server and client future have finished.

I have created a minimal example demonstrating the problem:

https://github.com/GeorgeKT/tokio_run_hang

This is the output of a run with RUST_LOG=debug:
RUST_LOG=debug target/debug/tokio_run_hang
DEBUG 2018-04-01T08:01:19Z: tokio_reactor::background: starting background reactor
DEBUG 2018-04-01T08:01:19Z: hyper::client::dns: resolving host="localhost", port=1234
DEBUG 2018-04-01T08:01:19Z: hyper::client::connect: connecting to 127.0.0.1:1234
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: loop process - 1 events, 0.000s
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: loop process - 1 events, 0.000s
DEBUG 2018-04-01T08:01:19Z: hyper::server: accepted new connection (127.0.0.1:45240)
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: loop process - 1 events, 0.000s
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::io: flushed 40 bytes
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: loop process - 1 events, 0.000s
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::io: read 40 bytes
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::io: parsed 1 headers (40 bytes)
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::conn: incoming body is content-length (0 bytes)
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::io: flushed 87 bytes
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: loop process - 1 events, 0.000s
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::io: read 87 bytes
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::io: parsed 2 headers (76 bytes)
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::conn: incoming body is content-length (11 bytes)
DEBUG 2018-04-01T08:01:19Z: hyper::client::pool: pooling idle connection for "http://localhost:1234"
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::conn: incoming body completed
Received: [72, 101, 108, 108, 111, 32, 87, 111, 114, 108, 100]
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: dropping I/O source: 1
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: dropping I/O source: 0
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: loop process - 1 events, 0.000s
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::io: read 0 bytes
DEBUG 2018-04-01T08:01:19Z: hyper::proto::h1::conn: read eof
DEBUG 2018-04-01T08:01:19Z: tokio_reactor: dropping I/O source: 2
Server finished

At this point the program is doing nothing and if you do an lsof, you get this:
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
tokio_run 7174 joris cwd DIR 8,19 4096 26239562 /home/joris/tmp/tokio_run_hang
tokio_run 7174 joris rtd DIR 8,17 4096 2 /
tokio_run 7174 joris txt REG 8,19 33072000 6034792 /home/joris/tmp/tokio_run_hang/target/debug/tokio_run_hang
tokio_run 7174 joris mem REG 8,17 47608 1577679 /lib/x86_64-linux-gnu/libnss_files-2.26.so
tokio_run 7174 joris mem REG 8,17 1960656 1577669 /lib/x86_64-linux-gnu/libc-2.26.so
tokio_run 7174 joris mem REG 8,17 92520 1574042 /lib/x86_64-linux-gnu/libgcc_s.so.1
tokio_run 7174 joris mem REG 8,17 144776 1577770 /lib/x86_64-linux-gnu/libpthread-2.26.so
tokio_run 7174 joris mem REG 8,17 31744 1580354 /lib/x86_64-linux-gnu/librt-2.26.so
tokio_run 7174 joris mem REG 8,17 14632 1577672 /lib/x86_64-linux-gnu/libdl-2.26.so
tokio_run 7174 joris mem REG 8,17 170960 1574048 /lib/x86_64-linux-gnu/ld-2.26.so
tokio_run 7174 joris 0u CHR 136,1 0t0 4 /dev/pts/1
tokio_run 7174 joris 1u CHR 136,1 0t0 4 /dev/pts/1
tokio_run 7174 joris 2u CHR 136,1 0t0 4 /dev/pts/1
tokio_run 7174 joris 3u a_inode 0,13 0 12538 [eventpoll]
tokio_run 7174 joris 4r FIFO 0,12 0t0 101498 pipe
tokio_run 7174 joris 5w FIFO 0,12 0t0 101498 pipe

So it only has a pipe open, all of the hyper related sockets haven been closed.

[carllerche]

Odds are, something is holding on to some resource, which keeps the runtime open.

Thoughts @seanmonstar?

[seanmonstar]

I think there may have been 1 other task spawned blocking the exit. The pool has an idle interval, and while it only takes a weak reference to the pool, and will know to drop on next wakeup, it would still wait the specified timeout.

I've push a commit to master that makes the idle interval also have a parked task that is woken when the pool drops, which should let it finish up immediately.

[zsugabubus]

I'm not an expert but I think it has something to do with the internal keep-alive pool of Client.

[carllerche]

I'm going to close this issue as it seems to be caused by a library spawning a task that isn't shutdown.

If you want to shutdown the runtime early, you can use the Runtime type directly (instead of tokio::run.

[kahing]

I came to this issue because of a similar problem, it'd be nice if tokio provided ways to make debugging this easier.

[carllerche]

I agree, #561 represents adding the necessary infrastructure for building additional debugging tools.