0002-logging-append-connector-response-to-ressource-log-3.patch
passerelle/base/models.py | ||
---|---|---|
11 | 11 |
import itertools |
12 | 12 | |
13 | 13 |
from django.apps import apps |
14 | 14 |
from django.conf import settings |
15 | 15 |
from django.core.exceptions import ValidationError, ObjectDoesNotExist, PermissionDenied |
16 | 16 |
from django.core.urlresolvers import reverse |
17 | 17 |
from django.db import connection, models, transaction |
18 | 18 |
from django.db.models import Q |
19 |
from django.db.utils import DataError |
|
20 |
from django.http.response import HttpResponse |
|
19 | 21 |
from django.test import override_settings |
20 | 22 |
from django.utils.text import slugify |
21 | 23 |
from django.utils import timezone, six |
22 | 24 |
from django.utils import six |
23 | 25 |
from django.utils.encoding import force_text |
24 | 26 |
from django.utils.six.moves.urllib.parse import urlparse |
25 | 27 |
from django.utils.translation import ugettext_lazy as _ |
26 | 28 |
from django.utils.timezone import now |
... | ... | |
731 | 733 | |
732 | 734 |
@property |
733 | 735 |
def level(self): |
734 | 736 |
return slugify(logging.getLevelName(self.levelno)) |
735 | 737 | |
736 | 738 |
def __str__(self): |
737 | 739 |
return '%s %s %s %s' % (self.timestamp, self.levelno, self.appname, self.slug) |
738 | 740 | |
741 |
def log_response(self, response, from_cache=False, |
|
742 |
responses_max_size=settings.LOGGED_RESPONSES_MAX_SIZE): |
|
743 |
if from_cache: |
|
744 |
self.extra['from_cache'] = True |
|
745 |
if isinstance(response, HttpResponse): |
|
746 |
self.extra['response_status'] = response.status_code |
|
747 |
self.extra['response_headers'] = force_text( |
|
748 |
response.serialize_headers(), errors='ignore') |
|
749 |
self.extra['response_content'] = force_text( |
|
750 |
response.content[:responses_max_size], errors='ignore') |
|
751 |
else: |
|
752 |
self.extra['response_content'] = force_text( |
|
753 |
str(response)[:responses_max_size], errors='ignore') |
|
754 |
try: |
|
755 |
with transaction.atomic(): |
|
756 |
self.save() |
|
757 |
except (DataError, TypeError): # py2, py3 |
|
758 |
self.extra['response_content'] = '<binary>' |
|
759 |
self.save() |
|
760 | ||
739 | 761 | |
740 | 762 |
STATUS_CHOICES = ( |
741 | 763 |
('unknown', _('Unknown')), |
742 | 764 |
('up', _('Up')), |
743 | 765 |
('down', _('Down')), |
744 | 766 |
) |
745 | 767 | |
746 | 768 |
class ResourceStatus(models.Model): |
... | ... | |
775 | 797 |
return self.__class__(self.connector, extra=dict(self.extra or {}, **kwargs)) |
776 | 798 | |
777 | 799 |
@property |
778 | 800 |
def level(self): |
779 | 801 |
return self._logger.getEffectiveLevel() |
780 | 802 | |
781 | 803 |
def _log(self, levelname, message, *args, **kwargs): |
782 | 804 |
force = kwargs.pop('force', False) |
805 |
ressource_log = None |
|
783 | 806 |
if self.connector.down() and not force: |
784 | 807 |
# don't log if the connector is known to be down |
785 | 808 |
return |
786 | 809 | |
787 | 810 |
# hide credentials in urls |
788 | 811 |
for url in re.findall(r'(https?://\S+)', message): |
789 | 812 |
try: |
790 | 813 |
parsed = urlparse(url) |
... | ... | |
831 | 854 |
else: |
832 | 855 |
sourceip = None |
833 | 856 |
attr['sourceip'] = sourceip |
834 | 857 | |
835 | 858 |
if kwargs.get('exc_info'): |
836 | 859 |
(exc_type, exc_value, tb) = sys.exc_info() |
837 | 860 |
attr['extra']['error_summary'] = traceback.format_exception_only(exc_type, exc_value) |
838 | 861 | |
839 |
ResourceLog.objects.create(**attr) |
|
862 |
ressource_log = ResourceLog.objects.create(**attr)
|
|
840 | 863 | |
841 | 864 |
admins = settings.ADMINS |
842 | 865 |
logging_parameters = self.connector.logging_parameters |
843 | 866 |
if logging_parameters.trace_emails: |
844 | 867 |
admins = [('', x) for x in logging_parameters.trace_emails.splitlines()] |
845 | 868 |
with override_settings(ADMINS=admins): |
846 | 869 |
getattr(self._logger, levelname.lower())(message, *args, **kwargs) |
870 |
return ressource_log |
|
847 | 871 | |
848 | 872 |
def exception(self, message, *args, **kwargs): |
849 | 873 |
kwargs['exc_info'] = 1 |
850 |
self._log('ERROR', message, *args, **kwargs) |
|
874 |
return self._log('ERROR', message, *args, **kwargs)
|
|
851 | 875 | |
852 | 876 |
def debug(self, message, *args, **kwargs): |
853 |
self._log('DEBUG', message, *args, **kwargs) |
|
877 |
return self._log('DEBUG', message, *args, **kwargs)
|
|
854 | 878 | |
855 | 879 |
def info(self, message, *args, **kwargs): |
856 |
self._log('INFO', message, *args, **kwargs) |
|
880 |
return self._log('INFO', message, *args, **kwargs)
|
|
857 | 881 | |
858 | 882 |
def warning(self, message, *args, **kwargs): |
859 |
self._log('WARNING', message, *args, **kwargs) |
|
883 |
return self._log('WARNING', message, *args, **kwargs)
|
|
860 | 884 | |
861 | 885 |
def critical(self, message, *args, **kwargs): |
862 |
self._log('CRITICAL', message, *args, **kwargs) |
|
886 |
return self._log('CRITICAL', message, *args, **kwargs)
|
|
863 | 887 | |
864 | 888 |
def error(self, message, *args, **kwargs): |
865 |
self._log('ERROR', message, *args, **kwargs) |
|
889 |
return self._log('ERROR', message, *args, **kwargs)
|
|
866 | 890 | |
867 | 891 |
def fatal(self, message, *args, **kwargs): |
868 |
self._log('FATAL', message, *args, **kwargs) |
|
892 |
return self._log('FATAL', message, *args, **kwargs)
|
|
869 | 893 | |
870 | 894 | |
871 | 895 |
class HTTPResource(models.Model): |
872 | 896 |
'''Mixin to add basic TLS/Basic HTTP authentication fields to any |
873 | 897 |
resource.''' |
874 | 898 |
basic_auth_username = models.CharField( |
875 | 899 |
max_length=128, |
876 | 900 |
verbose_name=_('Basic authentication username'), |
passerelle/views.py | ||
---|---|---|
439 | 439 |
connector_name, endpoint_name = kwargs['connector'], kwargs['endpoint'] |
440 | 440 |
connector = self.get_object() |
441 | 441 |
url = request.get_full_path() |
442 | 442 |
payload = request.body[:connector.logging_parameters.requests_max_size] |
443 | 443 |
try: |
444 | 444 |
payload = payload.decode('utf-8') |
445 | 445 |
except UnicodeDecodeError: |
446 | 446 |
payload = '<BINARY PAYLOAD>' |
447 |
connector.logger.info('endpoint %s %s (%r) ' % |
|
447 |
resource_log = connector.logger.info('endpoint %s %s (%r) ' %
|
|
448 | 448 |
(request.method, url, payload), |
449 | 449 |
extra={ |
450 | 450 |
'request': request, |
451 | 451 |
'connector': connector_name, |
452 | 452 |
'connector_endpoint': endpoint_name, |
453 | 453 |
'connector_endpoint_method': request.method, |
454 | 454 |
'connector_endpoint_url': url, |
455 | 455 |
'connector_payload': payload |
... | ... | |
457 | 457 | |
458 | 458 |
params = self.get_params(request, *args, **kwargs) |
459 | 459 |
if request.method == 'GET' and self.endpoint.endpoint_info.cache_duration: |
460 | 460 |
cache_key = hashlib.md5( |
461 | 461 |
force_bytes(repr(self.get_object().slug) + repr(self.endpoint) + repr(params)) |
462 | 462 |
).hexdigest() |
463 | 463 |
result = cache.get(cache_key) |
464 | 464 |
if result is not None: |
465 |
resource_log.log_response(result, from_cache=True, |
|
466 |
responses_max_size=connector.logging_parameters.responses_max_size) |
|
465 | 467 |
return result |
466 | 468 | |
467 | 469 |
result = self.endpoint(request, **params) |
470 |
resource_log.log_response(result, responses_max_size=connector.logging_parameters.responses_max_size) |
|
468 | 471 |
if request.method == 'GET' and self.endpoint.endpoint_info.cache_duration: |
469 | 472 |
cache.set(cache_key, result, self.endpoint.endpoint_info.cache_duration) |
470 | 473 |
return result |
471 | 474 | |
472 | 475 |
def get(self, request, *args, **kwargs): |
473 | 476 |
if self.endpoint.endpoint_info.pattern: |
474 | 477 |
pattern = url(self.endpoint.endpoint_info.pattern, self.endpoint) |
475 | 478 |
match = pattern.resolve(kwargs.get('rest') or '') |
tests/test_generic_endpoint.py | ||
---|---|---|
27 | 27 |
import pytest |
28 | 28 | |
29 | 29 |
import utils |
30 | 30 | |
31 | 31 |
from django.contrib.contenttypes.models import ContentType |
32 | 32 |
from django.core.urlresolvers import reverse |
33 | 33 | |
34 | 34 |
from passerelle.apps.arcgis.models import ArcGIS |
35 |
from passerelle.apps.opengis.models import OpenGIS |
|
35 | 36 |
from passerelle.base.models import ResourceLog, ProxyLogger, BaseResource, HTTPResource, LoggingParameters |
36 | 37 |
from passerelle.base.models import ResourceStatus |
37 | 38 |
from passerelle.apps.mdel.models import MDEL |
38 | 39 |
from passerelle.contrib.stub_invoices.models import StubInvoicesConnector |
39 | 40 |
from passerelle.utils.api import endpoint |
40 | 41 | |
41 | 42 |
from test_manager import login, admin_user, simple_user |
42 | 43 | |
... | ... | |
48 | 49 | |
49 | 50 |
@pytest.fixture |
50 | 51 |
def arcgis(db): |
51 | 52 |
instance = utils.setup_access_rights(ArcGIS.objects.create(slug='test')) |
52 | 53 |
instance.set_log_level('DEBUG') |
53 | 54 |
return instance |
54 | 55 | |
55 | 56 | |
57 |
@pytest.fixture |
|
58 |
def opengis(db): |
|
59 |
instance = utils.setup_access_rights(OpenGIS.objects.create(slug='test')) |
|
60 |
instance.set_log_level('DEBUG') |
|
61 |
return instance |
|
62 | ||
63 | ||
56 | 64 |
DEMAND_STATUS = { |
57 | 65 |
'closed': True, |
58 | 66 |
'status': 'accepted', |
59 | 67 |
'comment': 'dossier trait\xe9.' |
60 | 68 |
} |
61 | 69 | |
62 | 70 | |
63 | 71 |
@mock.patch('passerelle.apps.mdel.models.Demand.get_status', lambda x: DEMAND_STATUS) |
... | ... | |
89 | 97 | |
90 | 98 | |
91 | 99 |
@mock.patch('passerelle.utils.Request.get') |
92 | 100 |
def test_proxy_logger(mocked_get, caplog, app, arcgis): |
93 | 101 |
payload = open(os.path.join(os.path.dirname(__file__), 'data', 'nancy_arcgis', 'sigresponse.json')).read() |
94 | 102 |
mocked_get.return_value = utils.FakedResponse(content=payload, status_code=200) |
95 | 103 | |
96 | 104 |
# simple logger |
97 |
arcgis.log_evel = 'DEBUG' |
|
98 | 105 |
logger = ProxyLogger(connector=arcgis) |
99 | 106 |
logger.debug('this is a debug test') |
100 | 107 |
logger.info('this is an info test') |
101 | 108 | |
102 | 109 |
assert ResourceLog.objects.count() == 2 |
103 | 110 |
for log in ResourceLog.objects.all(): |
104 | 111 |
if log.levelno == 10: |
105 | 112 |
assert log.message == 'this is a debug test' |
... | ... | |
114 | 121 |
log = ResourceLog.objects.filter(appname='arcgis', slug='test').first() |
115 | 122 |
assert log.appname == 'arcgis' |
116 | 123 |
assert log.slug == 'test' |
117 | 124 |
assert log.levelno == 20 |
118 | 125 |
assert log.sourceip == '127.0.0.1' |
119 | 126 |
assert log.extra['connector'] == 'arcgis' |
120 | 127 |
assert log.extra['connector_endpoint'] == 'district' |
121 | 128 |
assert log.extra['connector_endpoint_method'] == 'GET' |
129 |
assert eval(log.extra['response_content'])['data']['text'] == 'HAUSSONVILLE / BLANDAN / MON DESERT / SAURUPT' |
|
122 | 130 |
assert '/arcgis/test/district?' in log.extra['connector_endpoint_url'] |
123 | 131 | |
124 | 132 |
# Resource Generic Logger |
125 | 133 |
for record in caplog.records: |
126 | 134 |
if record.name != 'passerelle.resource.arcgis.test': |
127 | 135 |
continue |
128 | 136 |
assert record.levelno == 20 |
129 | 137 |
assert record.levelname == 'INFO' |
... | ... | |
141 | 149 |
app.get('/arcgis/test/district', params={'lon': 6.172122, 'lat': 48.673836}, status=200) |
142 | 150 |
assert ResourceLog.objects.count() == 1 |
143 | 151 | |
144 | 152 |
arcgis.logger.warning('first warning') |
145 | 153 |
assert ResourceLog.objects.count() == 2 |
146 | 154 |
assert ResourceLog.objects.last().message == 'first warning' |
147 | 155 |
assert ResourceLog.objects.last().levelno == 30 |
148 | 156 | |
157 |
# truncate connector response on Resource Custom DB Logger |
|
158 |
ResourceLog.objects.all().delete() |
|
159 |
parameters = arcgis.logging_parameters |
|
160 |
parameters.responses_max_size = 20 |
|
161 |
parameters.save() |
|
162 |
app.get('/arcgis/test/district', params={'lon': 6.172122, 'lat': 48.673836}, status=200) |
|
163 |
assert ResourceLog.objects.count() == 1 |
|
164 |
log = ResourceLog.objects.filter(appname='arcgis', slug='test').first() |
|
165 |
assert len(log.extra['response_content']) == 20 |
|
166 |
assert log.extra.get('from_cache') == None |
|
167 | ||
168 |
# check connector response returned by cache |
|
169 |
ResourceLog.objects.all().delete() |
|
170 |
arcgis.district.endpoint_info.cache_duration = 5 |
|
171 |
app.get('/arcgis/test/district', params={'lon': 6.172122, 'lat': 48.673836}, status=200) |
|
172 |
app.get('/arcgis/test/district', params={'lon': 6.172122, 'lat': 48.673836}, status=200) |
|
173 |
assert ResourceLog.objects.count() == 2 |
|
174 |
log = ResourceLog.objects.filter(appname='arcgis', slug='test').all()[1] |
|
175 |
assert len(log.extra['response_content']) == 20 |
|
176 |
assert log.extra['from_cache'] == True |
|
177 | ||
178 |
@mock.patch('passerelle.utils.Request.get') |
|
179 |
def test_proxy_logger_receiving_binary(mocked_get, app, opengis): |
|
180 |
mocked_get.return_value = utils.FakedResponse(content=b'\x89PNG\r\n\x1a\n\x00\x00...', status_code=200) |
|
181 |
app.get('/opengis/test/tile' + '/16/33650/23378.png', status=200) |
|
182 |
# Resource Custom DB Logger |
|
183 |
assert ResourceLog.objects.count() == 1 |
|
184 |
log = ResourceLog.objects.filter(appname='opengis', slug='test').first() |
|
185 |
assert log.extra['response_status'] == 200 |
|
186 |
assert log.extra['response_headers'] == 'Content-Type: image/png' |
|
187 |
assert log.extra['response_content'] == '<binary>' |
|
149 | 188 | |
150 | 189 |
class FakeConnectorBase(object): |
151 | 190 |
slug = 'connector' |
152 | 191 | |
153 | 192 |
def get_connector_slug(self): |
154 | 193 |
return 'fake' |
155 | 194 | |
156 | 195 |
@endpoint() |
157 |
- |