Skip to content

Improve access logging #572

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 8 commits into from
Oct 22, 2015
Merged

Improve access logging #572

Show file tree
Hide file tree
Changes from 6 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
f157e32
Improve access logging
Oct 16, 2015
7114db4
Fix issue in unittest related to timezones
Oct 17, 2015
96aa607
Change time format in access log
Oct 17, 2015
87f8e17
Change value of %b in access log
Oct 18, 2015
ac9b967
Optimize logging
Oct 18, 2015
d09955e
Fix access logging when no message (status 400)
Oct 18, 2015
4107678
Restore original signature of ServerHttpProtocol
Oct 21, 2015
9b0de23
Merge branch 'master' into improve-logging
Oct 21, 2015
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
163 changes: 103 additions & 60 deletions aiohttp/helpers.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,10 +1,12 @@
"""Various helper functions"""
import base64
import datetime
import io
import os
import re
import traceback
from urllib.parse import quote, urlencode
from collections import namedtuple
from wsgiref.handlers import format_date_time

from . import hdrs, multidict
from .errors import InvalidURL
Expand Down Expand Up @@ -226,69 +228,110 @@ def parse_remote_addr(forward):
return remote[0], str(remote[1])


def atoms(message, environ, response, transport, request_time):
"""Gets atoms for log formatting."""
if message:
r = '{} {} HTTP/{}.{}'.format(
message.method, message.path,
message.version[0], message.version[1])
headers = message.headers
else:
r = ''
headers = {}
class SafeDict(dict):
"""Return a dash instead of raising KeyError"""

def __getitem__(self, key):
val = dict.get(self, key.upper())
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Use upstr(key) instead of key.upper() call.

return val or "-"

if transport is not None:
remote_addr = parse_remote_addr(
transport.get_extra_info('peername', ('127.0.0.1', )))
else:
remote_addr = ('',)

atoms = {
'h': remote_addr[0],
'l': '-',
'u': '-',
't': format_date_time(None),
'r': r,
's': str(getattr(response, 'status', '')),
'b': str(getattr(response, 'output_length', '')),
'f': headers.get(hdrs.REFERER, '-'),
'a': headers.get(hdrs.USER_AGENT, '-'),
'T': str(int(request_time)),
'D': str(request_time).split('.', 1)[-1][:6],
'p': "<%s>" % os.getpid()
}

return atoms


class SafeAtoms(dict):
"""Copy from gunicorn"""

def __init__(self, atoms, i_headers, o_headers):
dict.__init__(self)

self._i_headers = i_headers
self._o_headers = o_headers

for key, value in atoms.items():
self[key] = value.replace('"', '\\"')

def __getitem__(self, k):
if k.startswith('{'):
if k.endswith('}i'):
headers = self._i_headers
elif k.endswith('}o'):
headers = self._o_headers
else:
headers = None

if headers is not None:
return headers.get(k[1:-2], '-')
class AccessLogger:
"""Helper object to log access.

if k in self:
return super(SafeAtoms, self).__getitem__(k)
Usage:
log = logging.getLogger("spam")
log_format = "%a %{User-Agent}i"
access_logger = AccessLogger(log, log_format)
access_logger.log(message, environ, response, transport, time)

Format:
%% The percent sign
%a Remote IP-address (IP-address of proxy if using reverse proxy)
%t Time the request was received
%P The process ID of the child that serviced the request
%r First line of request
%s Status
%b Size of response in bytes, excluding HTTP headers
%O Bytes sent, including headers
%T The time taken to serve the request, in seconds
%D The time taken to serve the request, in microseconds
%{Foobar}i The contents of Foobar: header line(s) in
the request sent to the server
%{Foobar}o The contents of Foobar: header line(s) in the reply
%{FOOBAR}e The contents of the environment variable FOOBAR

"""

HEADERS_RE = re.compile(r"%\{\{([a-z\-]+)\}\}(i|o|e)", re.IGNORECASE)
ATOMS_RE = re.compile(r"%[atPlursbOTD%]")
BRACE_RE = re.compile(r"(\{|\})")
TIME_FORMAT = "[%d/%b/%Y:%H:%M:%S +0000]"

def __init__(self, logger, log_format):
"""Initialize the logger.

:param logger: logger object to be used for logging
:param log_format: apache (almost) compatible log format

Given log_format translated to form usable by `string.format`.

%{FOOBAR}i -- Input headers. Translated to {i_dict[FOOBAR]}
%{FOOBAR}o -- Iutput headers. Translated to {o_dict[FOOBAR]}
%{FOOBAR}e -- Environment variables. Translated to {e_dict[FOOBAR]}
%? -- One of atoms. Translated according to `atoms` dict (see below)
"""
atoms = {
'a': '{remote_addr}',
't': '{datetime}',
'P': "<%s>" % os.getpid(),
'l': '-',
'u': '-',
'r': '{r}',
's': '{response.status}',
'b': '{response.body_length}',
'O': '{response.output_length}',
'T': '{time:.0f}',
'D': '{microseconds:.0f}',
'%': '%', # `%%` should be converted to `%`
}
# replace single braces with double to avoid direct usage
log_format = self.BRACE_RE.sub(r"\1\1", log_format)
for atom in self.ATOMS_RE.findall(log_format):
log_format = log_format.replace(atom, atoms[atom[1]])
self._log_format = self.HEADERS_RE.sub(r"{\2_dict[\1]}", log_format)
self.logger = logger

def log(self, message, environ, response, transport, time):
"""Log access.

:param message: Request object. May be None.
:param environ: Environment dict. May be None.
:param response: Response object.
:param transport: Tansport object.
:param float time: Time taken to serve the request.
"""
environ = environ or {}
if message:
r = "%s %s HTTP/%s.%s" % tuple((message.method,
message.path) + message.version)
else:
return '-'
r = "-"
try:
self.logger.info(self._log_format.format(
message=message,
response=response,
i_dict=SafeDict(getattr(message, "headers", {})),
o_dict=SafeDict(getattr(response, "headers", {})),
e_dict=SafeDict(environ),
remote_addr=transport.get_extra_info("peername")[0],
time=time,
r=r,
datetime=datetime.datetime.utcnow().strftime(self.TIME_FORMAT),
microseconds=time*1000000,
))
except:
self.logger.error(traceback.format_exc())


_marker = object()
Expand Down
6 changes: 6 additions & 0 deletions aiohttp/protocol.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -546,8 +546,13 @@ def __init__(self, transport, version, close):
self.headers = CIMultiDict()
self.headers_sent = False
self.output_length = 0
self.headers_length = 0
self._output_size = 0

@property
def body_length(self):
return self.output_length - self.headers_length

def force_close(self):
self.closing = True
self.keepalive = False
Expand Down Expand Up @@ -651,6 +656,7 @@ def send_headers(self, _sep=': ', _end='\r\n'):
headers = headers.encode('utf-8') + b'\r\n'

self.output_length += len(headers)
self.headers_length = len(headers)
self.transport.write(headers)

def _add_default_headers(self):
Expand Down
29 changes: 9 additions & 20 deletions aiohttp/server.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@
from html import escape as html_escape

import aiohttp
from aiohttp import errors, streams, hdrs, helpers
from aiohttp import errors, streams, hdrs
from aiohttp.log import server_logger

__all__ = ('ServerHttpProtocol',)
Expand All @@ -26,8 +26,7 @@
</body>
</html>"""

ACCESS_LOG_FORMAT = (
'%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s"')
ACCESS_LOG_FORMAT = '%a %l %u %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i"'


if hasattr(socket, 'SO_KEEPALIVE'):
Expand Down Expand Up @@ -68,8 +67,8 @@ class ServerHttpProtocol(aiohttp.StreamProtocol):
:param logger: custom logger object
:type logger: aiohttp.log.server_logger

:param access_log: custom logging object
:type access_log: aiohttp.log.server_logger
:param access_logger: access logging object
:type access_log: helpers.AccessLogger

:param str access_log_format: access log format string

Expand All @@ -90,8 +89,7 @@ def __init__(self, *, loop=None,
keep_alive_on=True,
timeout=0,
logger=server_logger,
access_log=None,
access_log_format=ACCESS_LOG_FORMAT,
access_logger=None,
host="",
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Backward incompatible change: you've dropped two params and added another one.
Please keep constructor signature untouched but create access_logger inside ctor from given params.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It works even slower then current implementation if AccessLogger created in the constructor.

Converting from %h -> %(h)s takes too much time.

I have one idea have to leave current signatures and make it work faster, but then access_log_format will be not apache compatible. It would be something like:

...
'%(a)s' -- remote IP-address
'%(i_Foobar)s' -- 'Foobar' header line of input headers
'%(e_FOOBAR)s' -- The contents of the environment variable FOOBAR
...
Is it ok?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

'%(i_FOOBAR)s' looks ugly, I really like %{FOOBAR}i.
I've got your point.

What's about adding access_logger parameter but keeping access_log and access_log_format for a while?

If access_logger is None construct logger from access_log and access_log_format, use access_logger otherwise. We are keeping backward compatibility for old users but adding new functionality.

Make sure access_logger and (access_log, access_log_format) pair are mutually exclusive. Raise ValueError if both are specified.

Feel free to making access_log and access_log_format parameters deprecated, we can get rid of these after deprecation period.

port=0,
debug=False,
Expand All @@ -110,8 +108,7 @@ def __init__(self, *, loop=None,
self.port = port
self.logger = log or logger
self.debug = debug
self.access_log = access_log
self.access_log_format = access_log_format
self.access_logger = access_logger

@property
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please keep .access_log and .access_log_format -- they are part of public API

def keep_alive_timeout(self):
Expand Down Expand Up @@ -187,17 +184,9 @@ def keep_alive(self, val):
self._keep_alive = val

def log_access(self, message, environ, response, time):
if self.access_log and self.access_log_format:
try:
environ = environ if environ is not None else {}
atoms = helpers.SafeAtoms(
helpers.atoms(
message, environ, response, self.transport, time),
getattr(message, 'headers', None),
getattr(response, 'headers', None))
self.access_log.info(self.access_log_format % atoms)
except:
self.logger.error(traceback.format_exc())
if self.access_logger:
self.access_logger.log(message, environ, response,
self.transport, time)

def log_debug(self, *args, **kw):
if self.debug:
Expand Down
18 changes: 14 additions & 4 deletions aiohttp/web.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@

import asyncio

from . import helpers
from . import hdrs
from .abc import AbstractRouter, AbstractMatchInfo
from .log import web_logger
Expand All @@ -25,6 +26,8 @@
('Application', 'RequestHandler',
'RequestHandlerFactory', 'HttpVersion'))

ACCESS_LOG_FORMAT = '%a %l %u %t "%r" %s %b "%{Referrer}i" "%{User-Agent}i"'


class RequestHandler(ServerHttpProtocol):

Expand Down Expand Up @@ -58,7 +61,7 @@ def connection_lost(self, exc):

@asyncio.coroutine
def handle_request(self, message, payload):
if self.access_log:
if self.access_logger:
now = self._loop.time()

app = self._app
Expand Down Expand Up @@ -100,7 +103,7 @@ def handle_request(self, message, payload):
self.keep_alive(resp_msg.keep_alive())

# log access
if self.access_log:
if self.access_logger:
self.log_access(message, None, resp_msg, self._loop.time() - now)

# for repr
Expand All @@ -112,7 +115,8 @@ class RequestHandlerFactory:

def __init__(self, app, router, *,
handler=RequestHandler, loop=None,
secure_proxy_ssl_header=None, **kwargs):
secure_proxy_ssl_header=None, access_log=None,
access_log_format=ACCESS_LOG_FORMAT, **kwargs):
self._app = app
self._router = router
self._handler = handler
Expand All @@ -121,6 +125,12 @@ def __init__(self, app, router, *,
self._secure_proxy_ssl_header = secure_proxy_ssl_header
self._kwargs = kwargs
self._kwargs.setdefault('logger', app.logger)
if access_log:
self._access_logger = helpers.AccessLogger(access_log,
access_log_format)
else:
self._access_logger = None
self.__handler = None

@property
def secure_proxy_ssl_header(self):
Expand Down Expand Up @@ -173,7 +183,7 @@ def __call__(self):
return self._handler(
self, self._app, self._router, loop=self._loop,
secure_proxy_ssl_header=self._secure_proxy_ssl_header,
**self._kwargs)
access_logger=self._access_logger, **self._kwargs)


class Application(dict):
Expand Down
Loading