Aiohttp: Logging error

[AndreLouisCaron]

I'm getting an error in the aiohttp.access logger related to an invalid log format.

ERROR:aiohttp.access:Error in logging
Traceback (most recent call last):
  File "aiohttp\helpers.py", line 365, in log
    [message, environ, response, transport, time]))
  File "aiohttp\helpers.py", line 352, in _format_line
    return tuple(m(args) for m in self._methods)
  File "aiohttp\helpers.py", line 352, in <genexpr>
    return tuple(m(args) for m in self._methods)
  File "aiohttp\helpers.py", line 309, in _format_a
    return args[3].get_extra_info('peername')[0]
AttributeError: 'NoneType' object has no attribute 'get_extra_info'

I'm using version 0.21.2 on Python 3.5.1 for Windows (x86 build).

The stack trace doesn't include any spec of the message, but from what I can make of it, the transport is None. I'm not sure why that would be the case for successful connections.

I'm getting this using the WebSocket server from a browser on the same machine as the WebSocket server (haven't tried remote to see if it makes a difference).

Is there any additional info I can get you that will help fix this?

Thanks!

[asvetlov]

Showing args content would be nice.

Also might you provide access_log_format parameter from app.make_handler() if you specify it explicitly?

[AndreLouisCaron]

I use the default in app.make_handler().

I added this code:

    @staticmethod
    def _format_a(args):
        try:
            return args[3].get_extra_info('peername')[0]
        except AttributeError:
            import logging
            logging.exception('Accessing `peername` with args: %r.', args)
            raise

And I got this output when reproducing the problem (I indented for ease of reading):

ERROR:root:Accessing `peername` with args:
[
 RawRequestMessage(
  method='GET',
  path='/tunnel/cafebabe-0000-0000-0000-000000000001',
  version=HttpVersion(major=1, minor=1),
  headers=<CIMultiDict(
   'HOST': '127.0.0.1:8080',
   'CONNECTION': 'Upgrade',
   'PRAGMA': 'no-cache',
   'CACHE-CONTROL': 'no-cache',
   'UPGRADE': 'websocket',
   'ORIGIN': 'file://',
   'SEC-WEBSOCKET-VERSION': '13',
   'USER-AGENT': 'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/48.0.2564.116 Safari/537.36',
   'ACCEPT-ENCODING': 'gzip, deflate, sdch',
   'ACCEPT-LANGUAGE': 'en-US,en;q=0.8,fr;q=0.6',
   'SEC-WEBSOCKET-KEY': 'tSUNQBPedRNnyrjR1SN2fg==',
   'SEC-WEBSOCKET-EXTENSIONS': 'permessage-deflate; client_max_window_bits'
   )>,
  raw_headers=[
   (bytearray(b'HOST'), bytearray(b'127.0.0.1:8080')),
   (bytearray(b'CONNECTION'), bytearray(b'Upgrade')),
   (bytearray(b'PRAGMA'), bytearray(b'no-cache')),
   (bytearray(b'CACHE-CONTROL'), bytearray(b'no-cache')),
   (bytearray(b'UPGRADE'), bytearray(b'websocket')),
   (bytearray(b'ORIGIN'), bytearray(b'file://')),
   (bytearray(b'SEC-WEBSOCKET-VERSION'), bytearray(b'13')),
   (bytearray(b'USER-AGENT'), bytearray(b'Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/48.0.2564.116 Safari/537.36')),
   (bytearray(b'ACCEPT-ENCODING'), bytearray(b'gzip, deflate, sdch')),
   (bytearray(b'ACCEPT-LANGUAGE'), bytearray(b'en-US,en;q=0.8,fr;q=0.6')),
   (bytearray(b'SEC-WEBSOCKET-KEY'), bytearray(b'tSUNQBPedRNnyrjR1SN2fg==')),
   (bytearray(b'SEC-WEBSOCKET-EXTENSIONS'), bytearray(b'permessage-deflate; client_max_window_bits'))
  ],
  should_close=False,
  compression=None
 ),
 None,
 <aiohttp.protocol.Response object at 0x03474570>,
 None,
 2.714000000152737
 ].

[AndreLouisCaron]

Hi @asvetlov, does this help?

I've tried looking at the code, but I'm having a hard time following. For all I can tell, this is the culprit:

class ServerHttpProtocol(aiohttp.StreamProtocol):
    def log_access(self, message, environ, response, time):
        if self.access_logger:
            self.access_logger.log(message, environ, response,
                                   self.transport, time)

It seems like self.transport becomes None in the call to ServerHttpProtocol.closing() and that log_access() is somehow called after that.

However, I'm having a hard time explaining why this is the case. Any ideas?

Thanks,

André

[asvetlov]

Hmm. Yes, looks like the only line that makes self.transport = None is ServerHttpProtocol.closing().

But it's called only on server finishing. Is it your case?

I can easy add a workaround to don't log transport info if it is None but really prefer to fix initial issue.

After quick review I see just dropping self.transport = None may solve the problem but I want to make more investigation and write a test at least.

[AndreLouisCaron]

Yes, I usually get this error when I send CTRL-C/SIGINT.

[AndreLouisCaron]

I also only get the the error if there are any pending connections.

[AndreLouisCaron]

In case it helps, here is my setup/teardown sequence:

async def main(arguments):
    """Run application."""
    arguments = cli.parse_args(arguments)

    app = aiohttp.web.Application()
    app.router.add_route('GET', '/tunnel/{profileid}', connection)
    app.router.add_route('GET', '/', index)

    cancel = asyncio.Future()
    def shutdown():
        if cancel.done():
            return
        cancel.set_result(None)
        loop.remove_signal_handler(signal.SIGINT)
    loop.add_signal_handler(signal.SIGINT, shutdown)

    handler = app.make_handler()
    server = await loop.create_server(
        handler, arguments.host, arguments.port
    )
    try:
        print('Serving at: http//%s:%d (CTRL-C to stop).' % (
            arguments.host,
            arguments.port,
        ))
        await cancel
    finally:
        server.close()
        await server.wait_closed()
        await handler.finish_connections(arguments.linger)
        await app.finish()

[myfreeweb]

Just got the same error. Using aiohttp-wsgi to serve on a unix socket. Yeah, unix sockets don't have peer names, you should handle that.

[asvetlov]

Fixed by #889

[AndreLouisCaron]

Thanks!

[shvechikov]

I have found the same traceback with the last stable build (0.21.6).

Error in logging
Traceback (most recent call last):
  File "/home/datingdev/.virtualenvs/xo/lib/python3.5/site-packages/aiohttp/helpers.py", line 365, in log
    [message, environ, response, transport, time]))
  File "/home/datingdev/.virtualenvs/xo/lib/python3.5/site-packages/aiohttp/helpers.py", line 352, in _format_line
    return tuple(m(args) for m in self._methods)
  File "/home/datingdev/.virtualenvs/xo/lib/python3.5/site-packages/aiohttp/helpers.py", line 352, in <genexpr>
    return tuple(m(args) for m in self._methods)
  File "/home/datingdev/.virtualenvs/xo/lib/python3.5/site-packages/aiohttp/helpers.py", line 309, in _format_a
    return args[3].get_extra_info('peername')[0]
AttributeError: 'NoneType' object has no attribute 'get_extra_info'

I'm going to add more info as soon as I catch it again.

[asvetlov]

Should be fixed in next aiohttp release

[satarsa]

I still have a similar issue with aiohttp-0.22.4.
I also use unix sockets, if it helps.

Traceback (most recent call last):
  File "/home/feeds/.local/lib64/python3.5/site-packages/aiohttp/helpers.py", line 405, in log
    [message, environ, response, transport, time]))
  File "/home/feeds/.local/lib64/python3.5/site-packages/aiohttp/helpers.py", line 392, in _format_line
    return tuple(m(args) for m in self._methods)
  File "/home/feeds/.local/lib64/python3.5/site-packages/aiohttp/helpers.py", line 392, in <genexpr>
    return tuple(m(args) for m in self._methods)
  File "/home/feeds/.local/lib64/python3.5/site-packages/aiohttp/helpers.py", line 348, in _format_a
    return args[3].get_extra_info('peername')[0] if args[3] is not None \
IndexError: index out of range

[satarsa]

print(args[3].get_extra_info('peername'))

gives

b''

[asvetlov]

I never tested it on unix sockets.
Will add a fix for the case to don't crash.
But in general I recommend to never use %a formatting for your case: unix socket has no peer name at all.

[asvetlov]

Fixed by 8e8469b

[satarsa]

Andrew, thanks, but I do not really understand, what you are talking about, I don't use any format at all. I use aiohttp_wsgi, where a Unix socket lives. How could I trace the exact place where it happens?

[asvetlov]

Ok, you've got default format string containing '%a'.
WSGIServerHttpProtocol accepts optional access_log_format, '%a %l %u %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i"' by default.

[lock[bot]]

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