398 lines
14 KiB
Python
398 lines
14 KiB
Python
# -*- coding: utf-8 -*-
|
|
|
|
import datetime
|
|
import itertools
|
|
import logging
|
|
|
|
import pytest
|
|
import requests
|
|
import utils
|
|
from django.core.exceptions import ValidationError
|
|
from django.utils.log import AdminEmailHandler
|
|
from django.utils.six import PY2
|
|
from httmock import HTTMock
|
|
from test_availability import down_mock, up_mock
|
|
|
|
from passerelle.apps.feeds.models import Feed
|
|
from passerelle.base.models import ProxyLogger, ResourceLog
|
|
from passerelle.contrib.stub_invoices.models import StubInvoicesConnector
|
|
from passerelle.utils.api import endpoint
|
|
from passerelle.utils.jsonresponse import APIError
|
|
|
|
|
|
@pytest.fixture
|
|
def connector():
|
|
connector, created = Feed.objects.get_or_create(slug='some-slug')
|
|
connector.set_log_level('DEBUG')
|
|
connector.url = 'http://example.net/'
|
|
connector.save()
|
|
return connector
|
|
|
|
|
|
@pytest.fixture
|
|
def email_handler():
|
|
root = logging.getLogger()
|
|
handler = AdminEmailHandler(include_html=True)
|
|
handler.level = logging.ERROR
|
|
root.handlers.append(handler)
|
|
try:
|
|
yield
|
|
finally:
|
|
root.handlers.remove(handler)
|
|
|
|
|
|
def test_proxy_logger_basic(db, connector):
|
|
pr = ProxyLogger(connector)
|
|
pr.debug(u'some message')
|
|
rl_query = ResourceLog.objects.all()
|
|
assert len(rl_query) == 1
|
|
rl = rl_query.first()
|
|
assert rl.message == u'some message'
|
|
assert rl.levelno == logging.DEBUG
|
|
assert rl.appname == u'feeds'
|
|
assert rl.slug == u'some-slug'
|
|
|
|
|
|
def test_proxy_logger_std_interpolation(db, connector):
|
|
ResourceLog.objects.all().delete()
|
|
pr = ProxyLogger(connector)
|
|
pr.debug(u'some message %s', u'some var')
|
|
rl_query = ResourceLog.objects.all()
|
|
rl = rl_query.first()
|
|
assert rl.message == u'some message some var'
|
|
|
|
|
|
def test_proxy_logger_dict_interpolation(db, connector):
|
|
ResourceLog.objects.all().delete()
|
|
pr = ProxyLogger(connector)
|
|
pr.debug(u'some message %(var_name)s', {u'var_name': u'some var'})
|
|
rl_query = ResourceLog.objects.all()
|
|
rl = rl_query.first()
|
|
assert rl.message == u'some message some var'
|
|
|
|
|
|
def test_proxy_logger_ignore(db, connector):
|
|
ResourceLog.objects.all().delete()
|
|
connector.set_log_level('INFO')
|
|
pr = ProxyLogger(connector)
|
|
pr.debug(u'some message')
|
|
assert len(ResourceLog.objects.all()) == 0
|
|
|
|
|
|
def test_proxy_logger_ignore_when_down(db, connector):
|
|
with HTTMock(down_mock): # set connector as down
|
|
connector.availability()
|
|
assert connector.down() is True
|
|
ResourceLog.objects.all().delete()
|
|
pr = ProxyLogger(connector)
|
|
pr.debug(u'some message')
|
|
assert len(ResourceLog.objects.all()) == 0
|
|
|
|
|
|
@pytest.mark.parametrize(
|
|
'error_msg, expected',
|
|
[
|
|
('Foo Bar', 'Foo Bar'),
|
|
('http://badurl', 'http://badurl'),
|
|
(
|
|
'GET http://tcl.example.net/tclpassagearret (=> 502)',
|
|
'GET http://tcl.example.net/tclpassagearret (=> 502)',
|
|
),
|
|
(
|
|
'GET https://tcl.example.net/tclpassagearret (=> 502)',
|
|
'GET https://tcl.example.net/tclpassagearret (=> 502)',
|
|
),
|
|
(
|
|
'GET http://username:password@tcl.example.net/tclpassagearret (=> 502)',
|
|
'GET http://***:***@tcl.example.net/tclpassagearret (=> 502)',
|
|
),
|
|
(
|
|
'GET https://username:password@tcl.example.net/tclpassagearret (=> 502)',
|
|
'GET https://***:***@tcl.example.net/tclpassagearret (=> 502)',
|
|
),
|
|
],
|
|
)
|
|
def test_proxy_logger_hide_url_credentials(
|
|
db, settings, email_handler, mailoutbox, connector, error_msg, expected
|
|
):
|
|
settings.ADMINS = [('admin', 'admin@example.net')]
|
|
|
|
pr = ProxyLogger(connector)
|
|
pr.error(error_msg)
|
|
assert len(mailoutbox) == 1
|
|
msg = mailoutbox[0]
|
|
assert msg.to == ['admin@example.net']
|
|
assert msg.subject == '[Django] ERROR: %s' % expected
|
|
assert expected in msg.body
|
|
rl = ResourceLog.objects.latest('pk')
|
|
assert rl.message == expected
|
|
|
|
|
|
def test_validate_notification_delays(db, connector):
|
|
def take(iterator, count):
|
|
return list(itertools.compress(iterator, range(1, count + 1)))
|
|
|
|
availability_parameters = connector.availability_parameters
|
|
assert availability_parameters.notification_delays == '0'
|
|
|
|
availability_parameters.full_clean()
|
|
assert availability_parameters.has_zero_delay()
|
|
assert list(availability_parameters.notification_delays_generator()) == [0]
|
|
|
|
availability_parameters.notification_delays = '0,5,100,1000'
|
|
availability_parameters.full_clean()
|
|
assert availability_parameters.has_zero_delay()
|
|
assert take(availability_parameters.notification_delays_generator(), 6) == [0, 5, 100, 1000, 2000, 3000]
|
|
|
|
availability_parameters.notification_delays = '5,100,1000'
|
|
availability_parameters.full_clean()
|
|
assert not availability_parameters.has_zero_delay()
|
|
assert take(availability_parameters.notification_delays_generator(), 6) == [
|
|
5,
|
|
100,
|
|
1000,
|
|
2000,
|
|
3000,
|
|
4000,
|
|
]
|
|
|
|
availability_parameters.notification_delays = '5'
|
|
availability_parameters.full_clean()
|
|
assert not availability_parameters.has_zero_delay()
|
|
assert take(availability_parameters.notification_delays_generator(), 3) == [5, 10, 15]
|
|
|
|
# validation errors
|
|
availability_parameters.notification_delays = '5,100,100'
|
|
with pytest.raises(ValidationError):
|
|
availability_parameters.full_clean()
|
|
|
|
availability_parameters.notification_delays = ''
|
|
with pytest.raises(ValidationError):
|
|
availability_parameters.full_clean()
|
|
|
|
availability_parameters.notification_delays = '1,x'
|
|
with pytest.raises(ValidationError):
|
|
availability_parameters.full_clean()
|
|
|
|
availability_parameters.notification_delays = '10,1'
|
|
with pytest.raises(ValidationError):
|
|
availability_parameters.full_clean()
|
|
|
|
|
|
@pytest.mark.parametrize('notification_delays', ['0', '0,5,100', '5,100'])
|
|
def test_log_on_connector_availability_change(db, connector, freezer, notification_delays):
|
|
connector.title = u'éléphant'
|
|
availability_parameters = connector.availability_parameters
|
|
availability_parameters.notification_delays = notification_delays
|
|
availability_parameters.save()
|
|
|
|
with HTTMock(up_mock): # set connector as up
|
|
connector.availability()
|
|
assert ResourceLog.objects.count() == 1
|
|
assert ResourceLog.objects.latest('id').level == 'info'
|
|
assert ResourceLog.objects.latest('id').message == 'GET http://example.net/ (=> 200)'
|
|
ResourceLog.objects.all().delete()
|
|
|
|
# move 5 minutes in the future
|
|
freezer.move_to(datetime.timedelta(seconds=60 * 5 + 1))
|
|
|
|
with HTTMock(down_mock): # set connector as down
|
|
connector.availability()
|
|
assert connector.down()
|
|
last_count1 = ResourceLog.objects.count()
|
|
assert last_count1 == 2
|
|
assert ResourceLog.objects.all()[0].message == 'GET http://example.net/ (=> 404)'
|
|
assert ResourceLog.objects.all()[1].level == 'error' if notification_delays.startswith('0') else 'warning'
|
|
assert u'connector "éléphant" (Feed) is now down: 404 Client' in ResourceLog.objects.all()[1].message
|
|
|
|
# move 5 minutes in the future
|
|
freezer.move_to(datetime.timedelta(seconds=60 * 5 + 1))
|
|
|
|
# second time log as error
|
|
with HTTMock(down_mock): # connector is still down
|
|
connector.availability()
|
|
assert connector.down()
|
|
last_count2 = ResourceLog.objects.count()
|
|
if notification_delays == '0':
|
|
assert last_count2 == last_count1
|
|
else:
|
|
assert last_count2 == last_count1 + 1
|
|
assert ResourceLog.objects.all()[2].level == 'error' if notification_delays != '0' else 'warning'
|
|
assert (
|
|
u'connector "éléphant" (Feed) has been down for 5 minutes: 404'
|
|
in ResourceLog.objects.all()[2].message
|
|
)
|
|
|
|
# move 3 minutes in the future
|
|
freezer.move_to(datetime.timedelta(seconds=60 * 3 + 1))
|
|
|
|
# third time no log
|
|
with HTTMock(down_mock): # connector is still down
|
|
connector.availability()
|
|
assert ResourceLog.objects.count() == last_count2
|
|
|
|
# move 3 minutes in the future
|
|
freezer.move_to(datetime.timedelta(seconds=60 * 3 + 1))
|
|
|
|
with HTTMock(up_mock): # set connector as up
|
|
connector.availability()
|
|
assert not connector.down()
|
|
last_count3 = ResourceLog.objects.count()
|
|
assert last_count3 == last_count2 + 1
|
|
assert ResourceLog.objects.latest('id').level == 'info'
|
|
assert ResourceLog.objects.latest('id').message == u'connector "éléphant" (Feed) is back up'
|
|
|
|
# move 3 minutes in the future
|
|
freezer.move_to(datetime.timedelta(seconds=60 * 3 + 1))
|
|
|
|
# last message is a GET
|
|
with HTTMock(up_mock): # set connector as up
|
|
connector.availability()
|
|
assert not connector.down()
|
|
last_count4 = ResourceLog.objects.count()
|
|
assert last_count4 == last_count3 + 1
|
|
assert ResourceLog.objects.latest('id').level == 'info'
|
|
assert ResourceLog.objects.latest('id').message == 'GET http://example.net/ (=> 200)'
|
|
|
|
|
|
def test_proxy_logger_context(db, connector):
|
|
base_logger = ProxyLogger(connector)
|
|
base_logger.debug('test')
|
|
log = ResourceLog.objects.latest('id')
|
|
assert log.extra == {}
|
|
|
|
context1_logger = base_logger.context(extra1='toto')
|
|
context1_logger.debug('test')
|
|
log = ResourceLog.objects.latest('id')
|
|
assert log.extra == {'extra1': 'toto'}
|
|
|
|
# Check extra is updated not overwritten
|
|
context2_logger = context1_logger.context(extra2='titi')
|
|
context2_logger.debug('test')
|
|
log = ResourceLog.objects.latest('id')
|
|
assert log.extra == {'extra1': 'toto', 'extra2': 'titi'}
|
|
|
|
# Check other logger were not modified
|
|
context1_logger.debug('test')
|
|
log = ResourceLog.objects.latest('id')
|
|
assert log.extra == {'extra1': 'toto'}
|
|
|
|
base_logger.debug('test')
|
|
log = ResourceLog.objects.latest('id')
|
|
assert log.extra == {}
|
|
|
|
|
|
def test_logged_requests_and_responses_max_size(app, db, monkeypatch, settings):
|
|
URL = 'http://whatever.invalid'
|
|
|
|
@endpoint(methods=['post'])
|
|
def httpcall(self, request):
|
|
connector_payload = {'connector_query_var': '2' * 20}
|
|
self.requests.post(URL, connector_payload)
|
|
raise APIError({'connector_error_var': '4' * 20})
|
|
|
|
monkeypatch.setattr(StubInvoicesConnector, 'httpcall', httpcall, raising=False)
|
|
connector = StubInvoicesConnector(slug='fake')
|
|
connector.save()
|
|
url = '/%s/%s/httpcall/' % (connector.get_connector_slug(), connector.slug)
|
|
user_payload = {'user_query_var': '1' * 20}
|
|
service_response = {'service_reply_var': '3' * 20}
|
|
service_headers = {'Content-Type': 'foo/bar'}
|
|
|
|
# default configuration
|
|
assert connector.logging_parameters.requests_max_size == None
|
|
assert connector.logging_parameters.responses_max_size == None
|
|
with utils.mock_url(URL, service_response, headers=service_headers):
|
|
app.post(url, params=user_payload, status=200)
|
|
assert len(ResourceLog.objects.all()) == 3
|
|
|
|
# - user POST query
|
|
assert ResourceLog.objects.all()[0].extra['connector_payload'] == 'user_query_var=11111111111111111111'
|
|
|
|
# - connector POST queries
|
|
assert not ResourceLog.objects.all()[1].extra.get('request_payload')
|
|
assert not ResourceLog.objects.all()[1].extra.get('response_headers')
|
|
assert not ResourceLog.objects.all()[1].extra.get('response_content')
|
|
|
|
# - connector error
|
|
if PY2:
|
|
assert ResourceLog.objects.all()[2].extra['body'] == "'user_query_var=11111111111111111111'"
|
|
else:
|
|
assert ResourceLog.objects.all()[2].extra['body'] == "b'user_query_var=11111111111111111111'"
|
|
assert (
|
|
ResourceLog.objects.all()[2].extra['exception'] == "{'connector_error_var': '44444444444444444444'}"
|
|
)
|
|
|
|
# log connector payload and service response
|
|
connector.set_log_level('DEBUG')
|
|
settings.LOGGED_CONTENT_TYPES_MESSAGES = 'foo/bar' # log response content
|
|
ResourceLog.objects.all().delete()
|
|
with utils.mock_url(URL, service_response, headers=service_headers):
|
|
app.post(url, params=user_payload, status=200)
|
|
assert len(ResourceLog.objects.all()) == 3
|
|
|
|
# - connector POST queries
|
|
assert (
|
|
ResourceLog.objects.all()[1].extra['request_payload'] == "'connector_query_var=22222222222222222222'"
|
|
)
|
|
assert ResourceLog.objects.all()[1].extra.get('response_headers') == {'Content-Type': 'foo/bar'}
|
|
if PY2:
|
|
assert (
|
|
ResourceLog.objects.all()[1].extra.get('response_content')
|
|
== '\'{"service_reply_var": "33333333333333333333"}\''
|
|
)
|
|
else:
|
|
assert (
|
|
ResourceLog.objects.all()[1].extra.get('response_content')
|
|
== 'b\'{"service_reply_var": "33333333333333333333"}\''
|
|
)
|
|
|
|
# log troncated payloads
|
|
parameters = connector.logging_parameters
|
|
parameters.requests_max_size = 25
|
|
parameters.save()
|
|
ResourceLog.objects.all().delete()
|
|
with utils.mock_url(URL, service_response, headers=service_headers):
|
|
app.post(url, params=user_payload, status=200)
|
|
assert len(ResourceLog.objects.all()) == 3
|
|
|
|
# - user POST query
|
|
assert ResourceLog.objects.all()[0].extra['connector_payload'] == 'user_query_var=1111111111'
|
|
|
|
# - connector POST queries
|
|
assert ResourceLog.objects.all()[1].extra['request_payload'] == "'connector_query_var=22222'"
|
|
|
|
# - connector error
|
|
if PY2:
|
|
assert ResourceLog.objects.all()[2].extra['body'] == "'user_query_var=1111111111'"
|
|
else:
|
|
assert ResourceLog.objects.all()[2].extra['body'] == "b'user_query_var=1111111111'"
|
|
|
|
# log troncated service response
|
|
parameters = connector.logging_parameters
|
|
parameters.responses_max_size = 25
|
|
parameters.save()
|
|
ResourceLog.objects.all().delete()
|
|
with utils.mock_url(URL, service_response, headers=service_headers):
|
|
app.post(url, params=user_payload, status=200)
|
|
assert len(ResourceLog.objects.all()) == 3
|
|
|
|
# - connector POST queries
|
|
if PY2:
|
|
assert ResourceLog.objects.all()[1].extra.get('response_content') == '\'{"service_reply_var": "33\''
|
|
else:
|
|
assert ResourceLog.objects.all()[1].extra.get('response_content') == 'b\'{"service_reply_var": "33\''
|
|
|
|
|
|
def test_proxy_logger_email_traceback(app, db, email_handler, settings, mailoutbox, connector, monkeypatch):
|
|
settings.ADMINS = [('admin', 'admin@example.net')]
|
|
endpoint_url = utils.generic_endpoint_url('feeds', 'json', slug=connector.slug)
|
|
|
|
@endpoint()
|
|
def json(self, request):
|
|
raise requests.ConnectionError('timeout')
|
|
|
|
monkeypatch.setattr(Feed, 'json', json)
|
|
resp = app.get(endpoint_url, status=500)
|
|
assert any('Traceback:' in mail.body for mail in mailoutbox)
|