allow ressources to disable error logging in requests wrapper (#31114)
- modify ProxyLogger to get request from the "extra" parameter like Django, it
incurs that we need to clean extra from non JSON-serializable values
before using it in the ResourceLog model.
- modify to_json() so that request is passed to every log calls as
before commit 5286592cf, now we will get error mails containing Django
request details.
- resource can set "log_requests_errors = False" so that the Request
wrapper never log at the error/warning level.
- small annoyance: requests errors are logged two times, at the INFO
level and the ERROR level.
- connector MDPH13 is adapted to use all this.
This commit is contained in:
parent
a8eb92ef6f
commit
941d080094
|
|
@ -18,7 +18,7 @@ from django.db import models, transaction
|
|||
from django.db.models import Q
|
||||
from django.test import override_settings
|
||||
from django.utils.text import slugify
|
||||
from django.utils import timezone
|
||||
from django.utils import timezone, six
|
||||
from django.utils.translation import ugettext_lazy as _
|
||||
from django.core.files.base import ContentFile
|
||||
|
||||
|
|
@ -665,8 +665,13 @@ class ProxyLogger(object):
|
|||
|
||||
attr['appname'] = self.appname
|
||||
attr['slug'] = self.slug
|
||||
attr['extra'] = kwargs.get('extra', {})
|
||||
request = kwargs.pop('request', None)
|
||||
|
||||
extra = kwargs.get('extra', {})
|
||||
request = extra.get('request')
|
||||
|
||||
def is_json_serializable(value):
|
||||
return isinstance(value, (list, dict) + six.integer_types + six.string_types)
|
||||
attr['extra'] = {key: value for key, value in extra.items() if is_json_serializable(value)}
|
||||
|
||||
if getattr(request, 'META', None):
|
||||
if 'HTTP_X_FORWARDED_FOR' in request.META:
|
||||
|
|
|
|||
|
|
@ -15,6 +15,7 @@
|
|||
# You should have received a copy of the GNU Affero General Public License
|
||||
# along with this program. If not, see <http://www.gnu.org/licenses/>.
|
||||
|
||||
import sys
|
||||
import base64
|
||||
import urlparse
|
||||
import datetime
|
||||
|
|
@ -44,6 +45,12 @@ def json_walker(value, func, path=None):
|
|||
else:
|
||||
func(value, path)
|
||||
|
||||
ERROR_MAPPING = {
|
||||
'dossier-inconnu': 'dossier-inconnu',
|
||||
'secret-invalide': 'secret-invalide',
|
||||
'dateNaissance-erronee': 'date-de-naissance-erronee',
|
||||
}
|
||||
|
||||
|
||||
class MDPH13Resource(BaseResource, HTTPResource):
|
||||
category = _('Business Process Connectors')
|
||||
|
|
@ -53,6 +60,8 @@ class MDPH13Resource(BaseResource, HTTPResource):
|
|||
EMAIL_RE = re.compile(r'^[^@\s]+@[^@\s]+\.[^@\s]+$')
|
||||
DATE_RE = re.compile(r'^\d{4}-\d{2}-\d{2}$')
|
||||
|
||||
log_requests_errors = False
|
||||
|
||||
class Meta:
|
||||
verbose_name = _('MDPH CD13')
|
||||
|
||||
|
|
@ -60,60 +69,31 @@ class MDPH13Resource(BaseResource, HTTPResource):
|
|||
return urlparse.urljoin(self.webservice_base_url, 'situation/dossier/%s' % file_number)
|
||||
|
||||
def url_get(self, *args, **kwargs):
|
||||
try:
|
||||
response = None
|
||||
response = self.requests.get(*args, **kwargs)
|
||||
response.raise_for_status()
|
||||
except requests.RequestException as e:
|
||||
data = {'exception': six.text_type(e)}
|
||||
if response is not None:
|
||||
try:
|
||||
if response.json():
|
||||
data['body'] = response.json()
|
||||
except ValueError:
|
||||
body = response.content[:1000]
|
||||
if len(response.content) > 1000:
|
||||
body += b'<SNIPPED>'
|
||||
data['body'] = repr(body)
|
||||
data['status_code'] = response.status_code
|
||||
raise APIError('HTTP request failed', data=data)
|
||||
response = self.requests.get(*args, **kwargs)
|
||||
try:
|
||||
content = response.json()
|
||||
except ValueError as e:
|
||||
data = {'exception': six.text_type(e)}
|
||||
data['body'] = '%r<SNIPPED>' % response.content[:1000]
|
||||
raise APIError('HTTP request did not respond with JSON', data=data)
|
||||
except ValueError:
|
||||
response.raise_for_status()
|
||||
raise requests.RequestException('JSON expected', response=response)
|
||||
|
||||
if content.get('err') != 0:
|
||||
err_desc = ERROR_MAPPING.get(
|
||||
content.get('err_code'),
|
||||
'err != 0: missing or unknown error code')
|
||||
raise APIError(err_desc, data=content)
|
||||
response.raise_for_status()
|
||||
return content
|
||||
|
||||
def call_situation_dossier(self, file_number, secret, dob, email=None):
|
||||
url = self.situation_dossier_url(file_number)
|
||||
email = email or 'appel-sans-utilisateur@cd13.fr'
|
||||
error_mapping = {
|
||||
'dossier-inconnu': 'dossier-inconnu',
|
||||
'secret-invalide': 'secret-invalide',
|
||||
'dateNaissance-erronee': 'date-de-naissance-erronee',
|
||||
}
|
||||
try:
|
||||
content = self.url_get(
|
||||
url,
|
||||
headers={
|
||||
'X-CD13-Secret': base64.b64encode(secret.encode('utf-8')).decode('ascii'),
|
||||
'X-CD13-Email': email,
|
||||
'X-CD13-DateNaissBenef': dob.isoformat(),
|
||||
})
|
||||
except APIError as e:
|
||||
if e.data and e.data.get('status_code') == 404 and isinstance(e.data.get('body'), dict):
|
||||
content = e.data['body']
|
||||
if content.get('err') != 0:
|
||||
error_code = content.get('err_code')
|
||||
err_desc = error_mapping.get(error_code, 'err != 0')
|
||||
raise APIError(err_desc, data=e.data)
|
||||
raise
|
||||
|
||||
if content.get('err') != 0:
|
||||
error_code = content.get('err_code')
|
||||
err_desc = error_mapping.get(error_code, 'err != 0')
|
||||
raise APIError(err_desc, data=content)
|
||||
content = self.url_get(
|
||||
url,
|
||||
headers={
|
||||
'X-CD13-Secret': base64.b64encode(secret.encode('utf-8')).decode('ascii'),
|
||||
'X-CD13-Email': email,
|
||||
'X-CD13-DateNaissBenef': dob.isoformat(),
|
||||
})
|
||||
|
||||
data = content.get('data')
|
||||
if not isinstance(data, dict):
|
||||
|
|
|
|||
|
|
@ -42,9 +42,6 @@ from passerelle.base.context_processors import template_vars
|
|||
from passerelle.base.models import ApiUser, AccessRight, BaseResource
|
||||
from passerelle.base.signature import check_query, check_url
|
||||
|
||||
# legacy import, other modules keep importing to_json from passerelle.utils
|
||||
from .jsonresponse import to_json
|
||||
|
||||
|
||||
def get_template_vars():
|
||||
"""
|
||||
|
|
@ -173,6 +170,39 @@ def content_type_match(ctype):
|
|||
return False
|
||||
|
||||
|
||||
def log_http_request(logger, request, response=None, exception=None, error_log=True, extra=None):
|
||||
log_function = logger.info
|
||||
message = '%s %s' % (request.method, request.url)
|
||||
extra = extra or {}
|
||||
extra['request_url'] = request.url
|
||||
if logger.level == 10: # DEBUG
|
||||
extra['request_headers'] = dict(request.headers.items())
|
||||
if request.body:
|
||||
extra['request_payload'] = repr(request.body[:5000])
|
||||
if response is not None:
|
||||
message = message + ' (=> %s)' % response.status_code
|
||||
extra['response_status'] = response.status_code
|
||||
if logger.level == 10: # DEBUG
|
||||
extra['response_headers'] = dict(response.headers.items())
|
||||
# log body only if content type is allowed
|
||||
if content_type_match(response.headers.get('Content-Type')):
|
||||
content = response.content[:settings.LOGGED_RESPONSES_MAX_SIZE]
|
||||
extra['response_content'] = repr(content)
|
||||
if response.status_code // 100 == 3:
|
||||
log_function = logger.warning
|
||||
elif response.status_code // 100 >= 4:
|
||||
log_function = logger.error
|
||||
elif exception:
|
||||
message = message + ' (=> %s)' % repr(exception)
|
||||
extra['response_exception'] = repr(exception)
|
||||
log_function = logger.error
|
||||
|
||||
# allow resources to disable any error log at requests level
|
||||
if not error_log:
|
||||
log_function = logger.info
|
||||
log_function(message, extra=extra)
|
||||
|
||||
|
||||
# Wrapper around requests.Session
|
||||
# - log input and output data
|
||||
# - use HTTP Basic auth if resource.basic_auth_username and resource.basic_auth_password exist
|
||||
|
|
@ -182,7 +212,6 @@ def content_type_match(ctype):
|
|||
# - use a proxy for HTTP and HTTPS if resource.http_proxy exists
|
||||
|
||||
class Request(RequestSession):
|
||||
|
||||
def __init__(self, *args, **kwargs):
|
||||
self.logger = kwargs.pop('logger')
|
||||
self.resource = kwargs.pop('resource', None)
|
||||
|
|
@ -251,37 +280,12 @@ class Request(RequestSession):
|
|||
except Exception as exc:
|
||||
self.log_http_request(request, exception=exc)
|
||||
raise
|
||||
self.log_http_request(request, response)
|
||||
self.log_http_request(request, response=response)
|
||||
return response
|
||||
|
||||
def log_http_request(self, request, response=None, exception=None):
|
||||
message = '%s %s' % (request.method, request.url)
|
||||
extra = {}
|
||||
extra['request_url'] = request.url
|
||||
if self.logger.level == 10: # DEBUG
|
||||
extra['request_headers'] = dict(request.headers.items())
|
||||
if request.body:
|
||||
extra['request_payload'] = repr(request.body[:5000])
|
||||
log_function = self.logger.info
|
||||
if response is not None:
|
||||
message = message + ' (=> %s)' % response.status_code
|
||||
extra['response_status'] = response.status_code
|
||||
if self.logger.level == 10: # DEBUG
|
||||
extra['response_headers'] = dict(response.headers.items())
|
||||
# log body only if content type is allowed
|
||||
if content_type_match(response.headers.get('Content-Type')):
|
||||
content = response.content[:settings.LOGGED_RESPONSES_MAX_SIZE]
|
||||
extra['response_content'] = repr(content)
|
||||
if response.status_code // 100 == 3:
|
||||
log_function = self.logger.warning
|
||||
elif response.status_code // 100 >= 4:
|
||||
log_function = self.logger.error
|
||||
elif exception:
|
||||
message = message + ' (=> %s)' % repr(exception)
|
||||
extra['response_exception'] = repr(exception)
|
||||
log_function = self.logger.error
|
||||
|
||||
log_function(message, extra=extra)
|
||||
error_log = getattr(self.resource, 'log_requests_errors', True)
|
||||
log_http_request(self.logger, request=request, response=response, exception=exception, error_log=error_log)
|
||||
|
||||
|
||||
class SOAPClient(Client):
|
||||
|
|
@ -359,3 +363,6 @@ def batch(iterable, size):
|
|||
# call next() at least one time to advance, if the caller does not
|
||||
# consume the returned iterators, sourceiter will never be exhausted.
|
||||
yield chain([batchiter.next()], batchiter)
|
||||
|
||||
# legacy import, other modules keep importing to_json from passerelle.utils
|
||||
from .jsonresponse import to_json
|
||||
|
|
|
|||
|
|
@ -16,7 +16,9 @@ from django.core.serializers.json import DjangoJSONEncoder
|
|||
from django.utils.translation import force_text
|
||||
from django.utils import six
|
||||
|
||||
from requests.exceptions import RequestException
|
||||
from requests import RequestException, HTTPError
|
||||
|
||||
from passerelle.utils import log_http_request
|
||||
|
||||
|
||||
DEFAULT_DEBUG = getattr(settings, 'JSONRESPONSE_DEFAULT_DEBUG', False)
|
||||
|
|
@ -148,9 +150,7 @@ class to_json(object):
|
|||
data = self.obj_to_response(req, resp)
|
||||
status = 200
|
||||
except Exception as e:
|
||||
extras = {'method': req.method, 'exception': exception_to_text(e)}
|
||||
if not self.logger:
|
||||
extras['request'] = req
|
||||
extras = {'method': req.method, 'exception': exception_to_text(e), 'request': req}
|
||||
if req.method == 'POST':
|
||||
extras.update({'body': repr(req.body[:5000])})
|
||||
if (not isinstance(e, (Http404, PermissionDenied, ObjectDoesNotExist, RequestException))
|
||||
|
|
@ -160,8 +160,16 @@ class to_json(object):
|
|||
logger.warning('object not found: %r', e, extra=extras)
|
||||
elif isinstance(e, PermissionDenied):
|
||||
logger.warning('Permission denied', extra=extras)
|
||||
elif isinstance(e, HTTPError):
|
||||
log_http_request(logger,
|
||||
request=e.request,
|
||||
response=e.response,
|
||||
extra=extras)
|
||||
elif isinstance(e, RequestException):
|
||||
logger.warning("RequestException occurred while processing request", extra=extras)
|
||||
log_http_request(logger,
|
||||
request=e.request,
|
||||
exception=e,
|
||||
extra=extras)
|
||||
elif isinstance(e, Http404):
|
||||
# Http404 is for silent object not found exceptions
|
||||
pass
|
||||
|
|
|
|||
|
|
@ -376,8 +376,8 @@ class GenericEndpointView(GenericConnectorMixin, SingleObjectMixin, View):
|
|||
payload = '<BINARY PAYLOAD>'
|
||||
connector.logger.info('endpoint %s %s (%r) ' %
|
||||
(request.method, url, payload),
|
||||
request=request,
|
||||
extra={
|
||||
'request': request,
|
||||
'connector': connector_name,
|
||||
'connector_endpoint': endpoint_name,
|
||||
'connector_endpoint_method': request.method,
|
||||
|
|
|
|||
|
|
@ -18,6 +18,10 @@
|
|||
import json
|
||||
import base64
|
||||
import datetime
|
||||
import logging
|
||||
|
||||
import requests
|
||||
import requests.exceptions
|
||||
|
||||
import httmock
|
||||
import pytest
|
||||
|
|
@ -216,7 +220,12 @@ def mock_http():
|
|||
def request_handler(self, url, request):
|
||||
idx = len(self.requests)
|
||||
self.requests.append(request)
|
||||
return self.responses[idx]
|
||||
response = self.responses[idx]
|
||||
if isinstance(response, Exception):
|
||||
raise response
|
||||
elif hasattr(response, '__call__'):
|
||||
response = response(url, request)
|
||||
return response
|
||||
|
||||
mock_http = MockHttp()
|
||||
with httmock.HTTMock(httmock.urlmatch()(mock_http.request_handler)):
|
||||
|
|
@ -488,3 +497,23 @@ def test_dossier_bad_date(mdph13, mock_http):
|
|||
with pytest.raises(APIError) as exc_info:
|
||||
mdph13.dossiers(None, NAME_ID, EMAIL, link_id=str(link.pk))
|
||||
assert str(exc_info.value) == 'invalid-response-format'
|
||||
|
||||
|
||||
def test_dossier_http_error(app, mdph13, mock_http, caplog):
|
||||
url = '/mdph13/test1/link/?NameID=%s&numero_dossier=%s&date_de_naissance=%s&secret=%s&email=%s'
|
||||
url = url % (NAME_ID, FILE_NUMBER, DOB, SECRET, EMAIL)
|
||||
mock_http.add_response({'status_code': 401, 'content': 'wtf', 'reason': 'Authentication required'})
|
||||
response = app.post(url, status=500)
|
||||
assert response.json['err_class'] == 'requests.exceptions.HTTPError'
|
||||
assert caplog.records[-1].levelno == logging.ERROR
|
||||
assert caplog.records[-1].getMessage() == 'GET http://cd13.fr/situation/dossier/1234 (=> 401)'
|
||||
assert hasattr(caplog.records[-1].request, 'META')
|
||||
|
||||
def raise_ssl_error(url, request):
|
||||
raise requests.exceptions.SSLError(request=request)
|
||||
mock_http.add_response(raise_ssl_error)
|
||||
response = app.post(url, status=500)
|
||||
assert response.json['err_class'] == 'requests.exceptions.SSLError'
|
||||
assert caplog.records[-1].levelno == logging.ERROR
|
||||
assert caplog.records[-1].getMessage() == 'GET http://cd13.fr/situation/dossier/1234 (=> SSLError())'
|
||||
assert hasattr(caplog.records[-1].request, 'META')
|
||||
|
|
|
|||
Loading…
Reference in New Issue