Projet

Général

Profil

0002-logging-append-connector-response-to-ressource-log-3.patch

Nicolas Roche, 18 février 2020 18:38

Télécharger (13,3 ko)

Voir les différences:

Subject: [PATCH 2/2] logging: append connector response to ressource log
 (#31774)

 passerelle/base/models.py      | 40 ++++++++++++++++++++++++++-------
 passerelle/views.py            |  5 ++++-
 tests/test_generic_endpoint.py | 41 +++++++++++++++++++++++++++++++++-
 3 files changed, 76 insertions(+), 10 deletions(-)
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
-