passerelle/tests/test_proxylogger.py

# passerelle - uniform access to multiple data sources and services
# Copyright (C) 2023  Entr'ouvert
#
# This program is free software: you can redistribute it and/or modify it
# under the terms of the GNU Affero General Public License as published
# by the Free Software Foundation, either version 3 of the License, or
# (at your option) any later version.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU Affero General Public License for more details.
#
# 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 datetime
import itertools
import logging

import pytest
import requests
from django.core.exceptions import ValidationError
from django.db import transaction
from django.utils.log import AdminEmailHandler
from httmock import HTTMock

import tests.utils
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.defer import run_later_scope
from passerelle.utils.jsonresponse import APIError
from tests.test_availability import down_mock, up_mock


@pytest.fixture
def connector():
    connector, _ = 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('some message')
    rl_query = ResourceLog.objects.all()
    assert len(rl_query) == 1
    rl = rl_query.first()
    assert rl.message == 'some message'
    assert rl.levelno == logging.DEBUG
    assert rl.appname == 'feeds'
    assert rl.slug == 'some-slug'


def test_proxy_logger_std_interpolation(db, connector):
    ResourceLog.objects.all().delete()
    pr = ProxyLogger(connector)
    pr.debug('some message %s', 'some var')
    rl_query = ResourceLog.objects.all()
    rl = rl_query.first()
    assert rl.message == 'some message some var'


def test_proxy_logger_dict_interpolation(db, connector):
    ResourceLog.objects.all().delete()
    pr = ProxyLogger(connector)
    pr.debug('some message %(var_name)s', {'var_name': 'some var'})
    rl_query = ResourceLog.objects.all()
    rl = rl_query.first()
    assert rl.message == '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('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('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 = 'é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 '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 (
            '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 == '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'], perm='OPEN')
    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 is None
    assert connector.logging_parameters.responses_max_size is None
    with tests.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
    assert ResourceLog.objects.all()[2].extra['body'] == '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 tests.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'}
    assert (
        ResourceLog.objects.all()[1].extra.get('response_content')
        == '{"service_reply_var": "33333333333333333333"}'
    )

    # log troncated payloads
    parameters = connector.logging_parameters
    parameters.requests_max_size = 25
    parameters.save()
    ResourceLog.objects.all().delete()
    with tests.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
    assert ResourceLog.objects.all()[2].extra['body'] == 'user_query_var=1111111111'

    # log troncated service response
    parameters = connector.logging_parameters
    parameters.responses_max_size = 25
    parameters.save()
    ResourceLog.objects.all().delete()
    with tests.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.get('response_content') == '{"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 = tests.utils.generic_endpoint_url('feeds', 'json', slug=connector.slug)

    @endpoint(perm='OPEN')
    def json(self, request):
        raise requests.ConnectionError('timeout')

    monkeypatch.setattr(Feed, 'json', json)
    app.get(endpoint_url, status=500)

    assert any('Exception Type: ConnectionError' in mail.body for mail in mailoutbox)


def test_proxy_logger_bytes(db, connector):
    base_logger = ProxyLogger(connector)
    base_logger.debug('test', extra={'payload': b'bytes'})
    log = ResourceLog.objects.latest('id')
    assert log.extra == {'payload': 'bytes'}

    base_logger = ProxyLogger(connector)
    base_logger.debug('test', extra={'payload': b'\xff\xff'})
    log = ResourceLog.objects.latest('id')
    assert log.extra == {'payload': '\\xff\\xff'}


def test_log_in_transaction(transactional_db, connector):
    qs = ResourceLog.objects.all()
    assert not qs.exists()

    class MyError(Exception):
        pass

    # without run_later_scope logs inside transactions are lost
    try:
        with transaction.atomic():
            connector.logger.info('info')
            connector.logger.warning('warning')
            raise MyError
    except MyError:
        pass
    assert qs.count() == 0

    # with run_later_scope logs inside transaction are kept, because they
    # inserted in the db after the rollback
    try:
        with run_later_scope():
            with transaction.atomic():
                connector.logger.info('info')
                connector.logger.warning('warning')
                raise MyError
    except MyError:
        pass
    assert qs.count() == 2