Improve 401 Error Logging

[nagem]

Closes #188

Adds additional logging to 'Invalid OAuth2 Token' logging. Discussion about additional changes that could be made can be found in the issue linked above.

[kofalt]

LGTM.

@rentzso / @gsfr, if ya'll have some python vodoo to throw our way - Megan ran into a dict that resisted serialization, so she added a util func. A quick sanity check for our benefit in case there's a better way to accomplish this?

[gsfr]

@nagem What's the offending value? And how were you trying to serialize? Simply, str(d)?

[nagem]

@gsfr I'm still not sure exactly what is causing json.dumps to fail because when I use the str_from_dict method I added, none of the headers are changed to the error text. Here were the two ways I tried initially:

Code:

log.debug('Attempting to json dump dict')
log.debug(json.dumps(self.request.headers))

Log:

uwsgi_1          | 2016-03-16 19:22:53      scitran.api                  base.py    33:DEBU Attempting to json dump dict
uwsgi_1          | 2016-03-16 19:22:53             root               webapp2.py  1552:ERRO <webob.headers.EnvironHeaders object at 0x7f41303cef10> is not JSON serializable
uwsgi_1          | Traceback (most recent call last):
uwsgi_1          |   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1535, in __call__
uwsgi_1          |     rv = self.handle_exception(request, response, e)
uwsgi_1          |   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1529, in __call__
uwsgi_1          |     rv = self.router.dispatch(request, response)
uwsgi_1          |   File "./api/api.py", line 143, in dispatcher
uwsgi_1          |     rv = router.default_dispatcher(request, response)
uwsgi_1          |   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1278, in default_dispatcher
uwsgi_1          |     return route.handler_adapter(request, response)
uwsgi_1          |   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 1101, in __call__
uwsgi_1          |     handler = self.handler(request, response)
uwsgi_1          |   File "./api/base.py", line 34, in __init__
uwsgi_1          |     log.debug(json.dumps(self.request.headers))
uwsgi_1          |   File "/usr/lib/python2.7/json/__init__.py", line 243, in dumps
uwsgi_1          |     return _default_encoder.encode(obj)
uwsgi_1          |   File "/usr/lib/python2.7/json/encoder.py", line 207, in encode
uwsgi_1          |     chunks = self.iterencode(o, _one_shot=True)
uwsgi_1          |   File "/usr/lib/python2.7/json/encoder.py", line 270, in iterencode
uwsgi_1          |     return _iterencode(o, 0)
uwsgi_1          |   File "/usr/lib/python2.7/json/encoder.py", line 184, in default
uwsgi_1          |     raise TypeError(repr(o) + " is not JSON serializable")

Code:

log.debug('Attempting to cast dict as string')
log.debug(str(self.request.headers))

Log:

uwsgi_1          | 2016-03-16 19:24:49      scitran.api                  base.py    33:DEBU Attempting to cast dict as string
uwsgi_1          | 2016-03-16 19:24:49      scitran.api                  base.py    34:DEBU <webob.headers.EnvironHeaders object at 0x7f30b00f4e10>

Here str(d) helpfully tells me it's an EnvironHeaders object

[gsfr]

TL;DR: log.debug(json.dumps(self.request.headers.items())) or simply log.debug(str(self.request.headers.items())).

Ok, so we know that self.request.headers is a webob.headers.EnvironHeaders object, but json only knows how to serialize simple objects like list and dict.

The key to debugging this is getting a handle on one of these objects in an IPython shell, which has tab completion that greatly eases exploration.

import json, webapp2, webob.headers
req = webapp2.Request.blank('')
h = webob.headers.EnvironHeaders(req.environ)
json.dumps(h.items())

[nagem]

Thanks @gsfr, the str(dict.items()) works just fine. I should really make the IPython shell a more integral part of my daily dev process.

PR updated - removed str_from_dict. Will merge unless anyone else has any comments.

[gsfr]

👍

Happy to help get you set up. @kofalt, you too.