aiohttp client timeout does not work

[lorien]

Long story short

I use ClientTimeout(total=0.1 to process request that takes 0.5 seconds and no exception is raised.

Expected behaviour

I expect to raise exception in 100% times

Actual behaviour

Sometimes it raise exception (concurrent.futures._base.TimeoutError), sometimes it works and ignores timeout option:

127.0.0.1 - - [06/Aug/2018 10:50:55] "GET / HTTP/1.1" 200 -
TRACE {'total': 511.8, 'is_redirect': False, 'dns_lookup_and_dial': 0, 'connect': 5.67, 'transfer': 506.13}

By looking at TRACE object it is clear that request takes more time than specified in ClientTimeout(total= option

Steps to reproduce

• Save content of two files on your disk
• Run python3 test.py

Script test.py to run:

import time
import asyncio
import aiohttp
from threading import Thread
from http.server import HTTPServer, BaseHTTPRequestHandler

from trace import request_tracer

PORT = 9876


class HomePageRequestHandler(BaseHTTPRequestHandler):
    def do_GET(self):
        time.sleep(0.5)
        self.send_response(200)
        self.end_headers()
        self.wfile.write(b'foo')


def server_thread():
    server = HTTPServer(('127.0.0.1', PORT), HomePageRequestHandler)
    server.serve_forever()


async def make_request():
    trace = {}
    timeout = aiohttp.ClientTimeout(total=0.1)
    url = 'http://127.0.0.1:%d/' % PORT
    async with aiohttp.ClientSession(trace_configs=[request_tracer(trace)]) as session:
        io_res = await session.request('get', url, timeout=timeout)
        body = await io_res.read()
        assert body == b'foo'
        print('TRACE', trace)


def main():
    th = Thread(target=server_thread)
    th.daemon = True
    th.start()
    time.sleep(0.2) # time to start server

    loop = asyncio.get_event_loop()
    loop.run_until_complete(make_request())


if __name__ == '__main__':
    main()

trace.py module:

import aiohttp


def request_tracer(results_collector):
    """
    Provides request tracing to aiohttp client sessions.
    :param results_collector: a dict to which the tracing results will be added.
    :return: an aiohttp.TraceConfig object.
    :example:
    >>> import asyncio
    >>> import aiohttp
    >>> from aiohttp_trace import request_tracer
    >>>
    >>>
    >>> async def func():
    >>>     trace = {}
    >>>     async with aiohttp.ClientSession(trace_configs=[request_tracer(trace)]) as client:
    >>>         async with client.get('https://github.com') as response:
    >>>             print(trace)
    >>>
    >>> asyncio.get_event_loop().run_until_complete(func())
    {'dns_lookup_and_dial': 43.3, 'connect': 334.29, 'transfer': 148.48, 'total': 526.08, 'is_redirect': False}
    """

    async def on_request_start(session, context, params):
        context.on_request_start = session.loop.time()
        context.is_redirect = False

    async def on_connection_create_start(session, context, params):
        since_start = session.loop.time() - context.on_request_start
        context.on_connection_create_start = since_start

    async def on_request_redirect(session, context, params):
        since_start = session.loop.time() - context.on_request_start
        context.on_request_redirect = since_start
        context.is_redirect = True

    async def on_dns_resolvehost_start(session, context, params):
        since_start = session.loop.time() - context.on_request_start
        context.on_dns_resolvehost_start = since_start

    async def on_dns_resolvehost_end(session, context, params):
        since_start = session.loop.time() - context.on_request_start
        context.on_dns_resolvehost_end = since_start

    async def on_connection_create_end(session, context, params):
        since_start = session.loop.time() - context.on_request_start
        context.on_connection_create_end = since_start
    
    async def on_request_chunk_sent(session, context, params):
        since_start = session.loop.time() - context.on_request_start
        context.on_request_chunk_sent = since_start

    async def on_request_end(session, context, params):
        total = session.loop.time() - context.on_request_start
        context.on_request_end = total

        try:
            dns_lookup_and_dial = context.on_dns_resolvehost_end - context.on_dns_resolvehost_start
        except AttributeError:
            dns_lookup_and_dial = 0

        connect = context.on_connection_create_end - dns_lookup_and_dial
        transfer = total - context.on_connection_create_end
        is_redirect = context.is_redirect

        results_collector['dns_lookup_and_dial'] = round(dns_lookup_and_dial * 1000, 2)
        results_collector['connect'] = round(connect * 1000, 2)
        results_collector['transfer'] = round(transfer * 1000, 2)
        results_collector['total'] = round(total * 1000, 2)
        results_collector['is_redirect'] = is_redirect

    trace_config = aiohttp.TraceConfig()

    trace_config.on_request_start.append(on_request_start)
    trace_config.on_request_redirect.append(on_request_redirect)
    trace_config.on_dns_resolvehost_start.append(on_dns_resolvehost_start)
    trace_config.on_dns_resolvehost_end.append(on_dns_resolvehost_end)
    trace_config.on_connection_create_start.append(on_connection_create_start)
    trace_config.on_connection_create_end.append(on_connection_create_end)
    trace_config.on_request_end.append(on_request_end)
    trace_config.on_request_chunk_sent.append(on_request_chunk_sent)

    return trace_config

Your environment

OS: Linux air 4.9.0-1-amd64 #1 SMP Debian 4.9.6-3 (2017-01-28) x86_64 GNU/Linux
python: 3.5.3
aiohttp: 3.3.2

[amirouche]

isn't it supposed to be:

async with AsyncTimeout():
    ...

[nikan1996]

Ok, I find in aiohttphelpers.py, there is one class to handle the timeout.

class TimeoutHandle:
    """ Timeout handle """

    def __init__(self, loop, timeout):
        self._timeout = timeout
        self._loop = loop
        self._callbacks = []

    def register(self, callback, *args, **kwargs):
        self._callbacks.append((callback, args, kwargs))

    def close(self):
        self._callbacks.clear()

    def start(self):
        if self._timeout is not None and self._timeout > 0:
            at = ceil(self._loop.time() + self._timeout)
            return self._loop.call_at(at, self.__call__)

    def timer(self):
        if self._timeout is not None and self._timeout > 0:
            timer = TimerContext(self._loop)
            self.register(timer.timeout)
        else:
            timer = TimerNoop()
        return timer

    def __call__(self):
        for cb, args, kwargs in self._callbacks:
            with suppress(Exception):
                cb(*args, **kwargs)

        self._callbacks.clear()

Instart method, the loop will call the timeout handler at at time by using theceil function which will return the ceiling of x as an Integral.
So, does aiohttp only support an integer as timeout?

[asvetlov]

Yes, the limitation is driven by performance reasons.
Better to execute 100 callbacks at the same time than smash them into a short time period randomly.

Short timeouts make no sense for network operations in practice, think about network latency, bridge hardware slowdowns, and other things.

Given that asyncio itself is not real-time system at most 1 second delay for timeout reporting is perfectly fine I think.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a [new issue] for related bugs.
If you feel like there's important points made in this discussion, please include those exceprts into that [new issue].
[new issue]: https://github.com/aio-libs/aiohttp/issues/new