openstack/keystoneauth
Code Issues Proposed changes

Split request logging into four different loggers

Browse Source 
Python logging is pretty amazingly flexible, and allows us to emit
to arbitrary logging domains so that a consumer can direct log output
with specificity.

Turning on HTTP debug logging currently produces an avalanche of output,
when sometimes just seeing that the requests were made and responded to
is perfectly fine.

Split the loggers used into four - one for request ids, one for request
commands, one for response headers and one for response body content.
Make them subloggers of keystoneauth.session so that if a user does nothing,
their existing logging config will be unchanged.

If someone passes in a logger, behave as before logging all things to
the provided logger.

While we're at it, document this in the using-sessions document, so that
people know that the loggers exist and what they do.

NOTE:
The tox (>=1.7.0) by default sets a random python hash seed which
causes ordering of dicts and sets to be different between tests runs.
Disabled the random python hash seed by setting PYTHONHASHSEED=0 to
fix the random failure of below test:

keystoneauth1.tests.unit.test_session.SessionAuthTests.
test_split_loggers

The PYTHONHASHSEED=0 is removed in the followup patch so that we can
separate the tracking down of ordering issues in tests from this patch.

Change-Id: Ide7dac8adf5c76c9019c35867cda632aff39770f
This commit is contained in:
Monty Taylor 2017-09-20 12:11:40 -05:00
parent dc667f7354
commit 56b2c89c39
No known key found for this signature in database
GPG Key ID: 7BAE94BC7141A594
4 changed files with 307 additions and 32 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

161
doc/source/using-sessions.rst
View File

@ -39,6 +39,10 @@ Features
plugins. Discovery information is automatically cached in memory, so the user
need not worry about excessive use of discovery metadata.
- Safe logging of HTTP interactions
Clients need to be able to enable logging of the HTTP interactions, but some
things, such as the token or secrets, need to be ommitted.
Sessions for Users
==================
@ -433,8 +437,163 @@ expects ``volume``.
'min_version': '3',
'max_version': 'latest'})
Logging
=======
The logging system uses standard `python logging`_ rooted on the
``keystoneauth`` namespace as would be expected. There are two possibilities
of where log messages about HTTP interactions will go.
By default, all messages will go to the ``keystoneauth.session`` logger.
If the ``split_loggers`` option on the :class:`keystoneauth1.session.Session`
constructor is set to ``True``, the HTTP content will be split across four
subloggers to allow for fine-grained control of what is logged and how:
keystoneauth.session.request-id
Emits a log entry at the ``DEBUG`` level for every http request
including information about the URL, ``service-type`` and ``request-id``.
keystoneauth.session.request
Emits a log entry at the ``DEBUG`` level for every http request including a
curl formatted string of the request.
keystoneauth.session.response
Emits a log entry at the ``DEBUG`` level for every http response received,
including the status code, and the headers received.
keystoneauth.session.body
Emits a log entry at the ``DEBUG`` level containing the contents of the
response body if the ``content-type`` is either ``text`` or ``json``.
Using loggers
-------------
A full description of how to consume `python logging`_ is out of scope of this
document, but a few simple examples are provided.
If you would like to configure logging to log keystoneuath at the ``INFO``
level with no ``DEBUG`` messages:
.. code-block:: python
import keystoneauth1
import logging
logger = logging.getLogger('keystoneauth')
logger.addHandler(logging.StreamHandler())
logger.setLevel(logging.INFO)
If you would like to get a full HTTP debug trace including bodies:
.. code-block:: python
import keystoneauth1
import logging
logger = logging.getLogger('keystoneauth')
logger.addHandler(logging.StreamHandler())
logger.setLevel(logging.DEBUG)
If you would like to get a full HTTP debug trace bug with no bodies:
.. code-block:: python
import keystoneauth1
import keystoneauth1.session
import logging
logger = logging.getLogger('keystoneauth')
logger.addHandler(logging.StreamHandler())
logger.setLevel(logging.DEBUG)
body_logger = logging.getLogger('keystoneauth.session.body')
body_logger.setLevel(logging.WARN)
session = keystoneauth1.session.Session(split_loggers=True)
Finally, if you would like to log request-ids and response headers to one file,
request commands, response headers and response bodies to a different file,
and everything else to the console:
.. code-block:: python
import keystoneauth1
import keystoneauth1.session
import logging
# Create a handler that outputs only outputs INFO level messages to stdout
stream_handler = logging.StreamHandler()
stream_handler.setLevel(logging.INFO)
# Configure the default behavior of all keystoneauth logging to log at the
# INFO level.
logger = logging.getLogger('keystoneauth')
logger.setLevel(logging.INFO)
# Emit INFO messages from all keystoneauth loggers to stdout
logger.addHandler(stream_handler)
# Create an output formatter that includes logger name and timestamp.
formatter = logging.Formatter('%(asctime)s %(name)s %(message)s')
# Create a file output for request ids and response headers
request_handler = logging.FileHandler('request.log')
request_handler.setFormatter(formatter)
# Create a file output for request commands, response headers and bodies
body_handler = logging.FileHandler('response-body.log')
body_handler.setFormatter(formatter)
# Log all HTTP interactions at the DEBUG level
session_logger = logging.getLogger('keystoneauth.session')
session_logger.setLevel(logging.DEBUG)
# Emit request ids to the request log
request_id_logger = logging.getLogger('keystoneauth.session.request-id')
request_id_logger.addHandler(request_handler)
# Emit response headers to both the request log and the body log
header_logger = logging.getLogger('keystoneauth.session.response')
header_logger.addHandler(request_handler)
header_logger.addHandler(body_handler)
# Emit request commands to the body log
request_logger = logging.getLogger('keystoneauth.session.request')
request_logger.addHandler(body_handler)
# Emit bodies only to the body log
body_logger = logging.getLogger('keystoneauth.session.body')
body_logger.addHandler(body_handler)
session = keystoneauth1.session.Session(split_loggers=True)
The above will produce messages like the following in request.log:
::
2017-09-19 22:10:09,466 keystoneauth.session.request-id GET call to volumev2 for http://cloud.example.com/volume/v2/137155c35fb34172a284a3c2540c92ab/volumes/detail used request id req-f4f2058a-9308-4c4a-94e6-5ee1cd6c78bd
2017-09-19 22:10:09,751 keystoneauth.session.response [200] Date: Tue, 19 Sep 2017 22:10:09 GMT Server: Apache/2.4.18 (Ubuntu) x-compute-request-id: req-2e9181d2-9f3e-404e-a12f-1f1566736ab3 Content-Type: application/json Content-Length: 15 x-openstack-request-id: req-2e9181d2-9f3e-404e-a12f-1f1566736ab3 Connection: close
And content like the following into response-body.log:
::
2017-09-19 22:10:09,490 keystoneauth.session.request curl -g -i -X GET http://cloud.example.com/volume/v2/137155c35fb34172a284a3c2540c92ab/volumes/detail?marker=34cd00cf-bf67-4667-a900-5ce233e383d5 -H "User-Agent: os-client-config/1.28.0 shade/1.23.1 keystoneauth1/3.2.0 python-requests/2.18.4 CPython/2.7.12" -H "X-Auth-Token: {SHA1}a1d03d2a4cbee590a55f1786d452e1027d5fd781"
2017-09-19 22:10:09,751 keystoneauth.session.response [200] Date: Tue, 19 Sep 2017 22:10:09 GMT Server: Apache/2.4.18 (Ubuntu) x-compute-request-id: req-2e9181d2-9f3e-404e-a12f-1f1566736ab3 Content-Type: application/json Content-Length: 15 x-openstack-request-id: req-2e9181d2-9f3e-404e-a12f-1f1566736ab3 Connection: close
2017-09-19 22:10:09,751 keystoneauth.session.body {"volumes": []}
User Provided Loggers
---------------------
The HTTP methods (request, get, post, put, etc) on
`keystoneauth1.session.Session` and `keystoneauth1.adapter.Adapter` all support
a ``logger`` parameter. A user can provide their own `logger`_ which will
override the session loggers mentioned above. If a single logger is provided
in this manner, request, response and body content will all be logged to that
logger at the ``DEBUG`` level, and the strings ``REQ:``, ``RESP:`` and
``RESP BODY:`` will be pre-pended as appropriate.
.. _API-WG Specs: http://specs.openstack.org/openstack/api-wg/
.. _Consuming the Catalog: http://specs.openstack.org/openstack/api-wg/guidelines/consuming-catalog.html
.. _Microversions: http://specs.openstack.org/openstack/api-wg/guidelines/microversion_specification.html#version-discovery
.. _python logging: https://docs.python.org/3/library/logging.html
.. _logger: https://docs.python.org/3/library/logging.html#logging.Logger

123
keystoneauth1/session.py
View File

@ -50,8 +50,6 @@ DEFAULT_USER_AGENT = 'keystoneauth1/%s %s %s/%s' % (
# here and we'll add it to the list as required.
_LOG_CONTENT_TYPES = set(['application/json'])
_logger = utils.get_logger(__name__)
def _construct_session(session_obj=None):
# NOTE(morganfainberg): if the logic in this function changes be sure to
@ -244,6 +242,8 @@ class Session(object):
that do not share an auth plugin, it can
be provided here. (optional, defaults to
None which means automatically manage)
:param bool split_loggers: Split the logging of requests across multiple
loggers instead of just one. Defaults to False.
"""
user_agent = None
@ -256,7 +256,7 @@ class Session(object):
cert=None, timeout=None, user_agent=None,
redirect=_DEFAULT_REDIRECT_LIMIT, additional_headers=None,
app_name=None, app_version=None, additional_user_agent=None,
discovery_cache=None):
discovery_cache=None, split_loggers=None):
self.auth = auth
self.session = _construct_session(session)
@ -273,6 +273,7 @@ class Session(object):
if discovery_cache is None:
discovery_cache = {}
self._discovery_cache = discovery_cache
self._split_loggers = split_loggers
if timeout is not None:
self.timeout = float(timeout)
@ -324,16 +325,33 @@ class Session(object):
return (header[0], '{SHA1}%s' % token_hash)
return header
def _get_split_loggers(self, split_loggers):
if split_loggers is None:
split_loggers = self._split_loggers
if split_loggers is None:
split_loggers = False
return split_loggers
def _http_log_request(self, url, method=None, data=None,
json=None, headers=None, query_params=None,
logger=_logger):
logger=None, split_loggers=None):
string_parts = []
if self._get_split_loggers(split_loggers):
logger = utils.get_logger(__name__ + '.request')
else:
# Only a single logger was passed in, use string prefixing.
string_parts.append('REQ:')
if not logger:
logger = utils.get_logger(__name__)
if not logger.isEnabledFor(logging.DEBUG):
# NOTE(morganfainberg): This whole debug section is expensive,
# there is no need to do the work if we're not going to emit a
# debug log.
return
string_parts = ['REQ: curl -g -i']
string_parts.append('curl -g -i')
# NOTE(jamielennox): None means let requests do its default validation
# so we need to actually check that this is False.
@ -356,7 +374,8 @@ class Session(object):
string_parts.append(url)
if headers:
for header in headers.items():
# Sort headers so that testing can work consistently.
for header in sorted(headers.items()):
string_parts.append('-H "%s: %s"'
% self._process_header(header))
if json:
@ -373,7 +392,18 @@ class Session(object):
def _http_log_response(self, response=None, json=None,
status_code=None, headers=None, text=None,
logger=_logger):
logger=None, split_loggers=True):
string_parts = []
body_parts = []
if self._get_split_loggers(split_loggers):
logger = utils.get_logger(__name__ + '.response')
body_logger = utils.get_logger(__name__ + '.body')
else:
# Only a single logger was passed in, use string prefixing.
string_parts.append('RESP:')
body_parts.append('RESP BODY:')
body_logger = logger
if not logger.isEnabledFor(logging.DEBUG):
return
@ -382,6 +412,19 @@ class Session(object):
status_code = response.status_code
if not headers:
headers = response.headers
if status_code:
string_parts.append('[%s]' % status_code)
if headers:
# Sort headers so that testing can work consistently.
for header in sorted(headers.items()):
string_parts.append('%s: %s' % self._process_header(header))
logger.debug(' '.join(string_parts))
if not body_logger.isEnabledFor(logging.DEBUG):
return
if response is not None:
if not text:
# NOTE(samueldmq): If the response does not provide enough info
# about the content type to decide whether it is useful and
@ -406,17 +449,9 @@ class Session(object):
if json:
text = self._json.encode(json)
string_parts = ['RESP:']
if status_code:
string_parts.append('[%s]' % status_code)
if headers:
for header in headers.items():
string_parts.append('%s: %s' % self._process_header(header))
if text:
string_parts.append('\nRESP BODY: %s\n' % text)
logger.debug(' '.join(string_parts))
body_parts.append(text)
body_logger.debug(' '.join(body_parts))
@staticmethod
def _set_microversion_headers(
@ -465,7 +500,7 @@ class Session(object):
user_agent=None, redirect=None, authenticated=None,
endpoint_filter=None, auth=None, requests_auth=None,
raise_exc=True, allow_reauth=True, log=True,
endpoint_override=None, connect_retries=0, logger=_logger,
endpoint_override=None, connect_retries=0, logger=None,
allow=None, client_name=None, client_version=None,
microversion=None, microversion_service_type=None,
**kwargs):
@ -560,6 +595,14 @@ class Session(object):
:returns: The response to the request.
"""
# If a logger is passed in, use it and do not log requests, responses
# and bodies separately.
if logger:
split_loggers = False
else:
split_loggers = None
logger = logger or utils.get_logger(__name__)
headers = kwargs.setdefault('headers', dict())
if microversion:
self._set_microversion_headers(
@ -671,7 +714,7 @@ class Session(object):
data=kwargs.get('data'),
headers=headers,
query_params=query_params,
logger=logger)
logger=logger, split_loggers=split_loggers)
# Force disable requests redirect handling. We will manage this below.
kwargs['allow_redirects'] = False
@ -681,7 +724,7 @@ class Session(object):
send = functools.partial(self._send_request,
url, method, redirect, log, logger,
connect_retries)
split_loggers, connect_retries)
try:
connection_params = self.get_auth_connection_params(auth=auth)
@ -713,13 +756,29 @@ class Session(object):
request_id = (resp.headers.get('x-openstack-request-id') or
resp.headers.get('x-compute-request-id'))
if request_id:
logger.debug('%(method)s call to %(service_name)s for '
'%(url)s used request id '
'%(response_request_id)s',
{'method': resp.request.method,
'service_name': service_name,
'url': resp.url,
'response_request_id': request_id})
if self._get_split_loggers(split_loggers):
id_logger = utils.get_logger(__name__ + '.request-id')
else:
id_logger = logger
if service_name:
id_logger.debug(
'%(method)s call to %(service_name)s for '
'%(url)s used request id '
'%(response_request_id)s', {
'method': resp.request.method,
'service_name': service_name,
'url': resp.url,
'response_request_id': request_id
})
else:
id_logger.debug(
'%(method)s call to '
'%(url)s used request id '
'%(response_request_id)s', {
'method': resp.request.method,
'url': resp.url,
'response_request_id': request_id
})
# handle getting a 401 Unauthorized response by invalidating the plugin
# and then retrying the request. This is only tried once.
@ -738,7 +797,7 @@ class Session(object):
return resp
def _send_request(self, url, method, redirect, log, logger,
def _send_request(self, url, method, redirect, log, logger, split_loggers,
connect_retries, connect_retry_delay=0.5, **kwargs):
# NOTE(jamielennox): We handle redirection manually because the
# requests lib follows some browser patterns where it will redirect
@ -784,13 +843,15 @@ class Session(object):
time.sleep(connect_retry_delay)
return self._send_request(
url, method, redirect, log, logger,
url, method, redirect, log, logger, split_loggers,
connect_retries=connect_retries - 1,
connect_retry_delay=connect_retry_delay * 2,
**kwargs)
if log:
self._http_log_response(response=resp, logger=logger)
self._http_log_response(
response=resp, logger=logger,
split_loggers=split_loggers)
if resp.status_code in self._REDIRECT_STATUSES:
# be careful here in python True == 1 and False == 0
@ -812,7 +873,7 @@ class Session(object):
# NOTE(jamielennox): We don't pass through connect_retry_delay.
# This request actually worked so we can reset the delay count.
new_resp = self._send_request(
location, method, redirect, log, logger,
location, method, redirect, log, logger, split_loggers,
connect_retries=connect_retries,
**kwargs)

54
keystoneauth1/tests/unit/test_session.py
View File

@ -956,6 +956,60 @@ class SessionAuthTests(utils.TestCase):
self.assertNotIn(list(response.keys())[0], self.logger.output)
self.assertNotIn(list(response.values())[0], self.logger.output)
def test_split_loggers(self):
def get_logger_io(name):
logger_name = 'keystoneauth.session.{name}'.format(name=name)
logger = logging.getLogger(logger_name)
logger.setLevel(logging.DEBUG)
io = six.StringIO()
handler = logging.StreamHandler(io)
logger.addHandler(handler)
return io
io = {}
for name in ('request', 'body', 'response', 'request-id'):
io[name] = get_logger_io(name)
auth = AuthPlugin()
sess = client_session.Session(auth=auth, split_loggers=True)
response_key = uuid.uuid4().hex
response_val = uuid.uuid4().hex
response = {response_key: response_val}
request_id = uuid.uuid4().hex
self.stub_url(
'GET',
json=response,
headers={
'Content-Type': 'application/json',
'X-OpenStack-Request-ID': request_id,
})
resp = sess.get(self.TEST_URL)
self.assertEqual(response, resp.json())
request_output = io['request'].getvalue().strip()
response_output = io['response'].getvalue().strip()
body_output = io['body'].getvalue().strip()
id_output = io['request-id'].getvalue().strip()
self.assertIn('curl -g -i -X GET {url}'.format(url=self.TEST_URL),
request_output)
self.assertEqual('[200] Content-Type: application/json '
'X-OpenStack-Request-ID: '
'{id}'.format(id=request_id), response_output)
self.assertEqual(
'GET call to {url} used request id {id}'.format(
url=self.TEST_URL, id=request_id),
id_output)
self.assertEqual(
'{{"{key}": "{val}"}}'.format(
key=response_key, val=response_val),
body_output)
class AdapterTest(utils.TestCase):

1
tox.ini
View File

@ -7,6 +7,7 @@ envlist = py35,py27,pep8,releasenotes
usedevelop = True
install_command = {toxinidir}/tools/tox_install.sh {env:UPPER_CONSTRAINTS_FILE:https://git.openstack.org/cgit/openstack/requirements/plain/upper-constraints.txt} {opts} {packages}
setenv = VIRTUAL_ENV={envdir}
PYTHONHASHSEED=0
BRANCH_NAME=master
CLIENT_NAME=keystoneauth1
OS_STDOUT_NOCAPTURE=False