entrouvert
/
combo
16
1
Fork 0
Code Issues Pull Requests 11 Releases Wiki Activity

lingo: always log notification content on errors (#61401) 

- rename models.PaymentException to LingoException to prevent confusion
- attach transaction to exceptions when possible
- log in views instead of model methods, it's a better point to make
  decisions on logging
This commit is contained in:
Benjamin Dauvergne 2022-02-03 16:50:30 +01:00
parent 30d1483f03
commit 5accf65139
4 changed files with 84 additions and 70 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
combo/apps/lingo/management/commands/lingo-poll-backend.py
View File

@ -19,7 +19,7 @@ import logging
from django.core.management.base import BaseCommand, CommandError
from combo.apps.lingo.models import PaymentBackend, PaymentException
from combo.apps.lingo.models import LingoException, PaymentBackend
logger = logging.getLogger('combo.apps.lingo')
@ -88,7 +88,7 @@ class Command(BaseCommand):
print('Polling backend', backend, '... ', end='')
try:
backend.poll_backend(max_age=max_age_in_days and datetime.timedelta(days=max_age_in_days))
except PaymentException:
except LingoException:
logger.exception('polling failed')
if interactive:
# show error

52
combo/apps/lingo/models.py
View File

@ -61,17 +61,17 @@ except ImportError:
logger = logging.getLogger('combo.apps.lingo')
class PaymentException(Exception):
class LingoException(Exception):
def __init__(self, msg=None, *, transaction=None):
self.transaction = transaction
super().__init__(msg)
class UnsignedPaymentException(LingoException):
pass
class UnsignedPaymentException(PaymentException):
def __init__(self, transaction, *args, **kwargs):
super().__init__(*args, **kwargs)
self.transaction = transaction
class UnknownPaymentException(PaymentException):
class UnknownPaymentException(LingoException):
pass
@ -222,11 +222,6 @@ class PaymentBackend(models.Model):
try:
transaction = Transaction.objects.get(order_id=response.order_id)
except Transaction.DoesNotExist:
logger.warning(
'lingo: transaction not found for payment response with id %s',
response.order_id,
extra=eopayment_response_to_extra_info(response),
)
raise UnknownPaymentException('Received unknown payment response')
else:
logger.debug(
@ -240,13 +235,7 @@ class PaymentBackend(models.Model):
# check if transaction belong to the right payment backend
if not transaction.regie.payment_backend == self:
logger.warning(
'lingo: backend "%s" received payment for backend "%s"',
self.regie.payment_backend,
self,
extra=eopayment_response_to_extra_info(response),
)
raise PaymentException('Invalid payment backend')
raise LingoException('Invalid payment backend', transaction=transaction)
transaction.handle_backend_response(response, callback=callback)
return transaction
@ -933,14 +922,7 @@ class Transaction(models.Model):
)
if not response.signed and not response.result == eopayment.CANCELLED:
# we accept unsigned cancellation requests as some platforms do
# that :/
logger.warning(
'lingo: regie "%s" received unsigned payment response with id %s',
self.regie,
response.order_id,
)
raise UnsignedPaymentException(self, 'Received unsigned payment response')
raise UnsignedPaymentException('Received unsigned payment response', transaction=self)
self.status = response.result
self.bank_transaction_id = response.transaction_id
self.bank_data = response.bank_data
@ -964,15 +946,6 @@ class Transaction(models.Model):
self.save()
logger.info(
'lingo: regie "%s" received %s payment notification for transaction %s(%s)',
self.regie,
'synchronous' if callback else 'asynchronous',
self.order_id,
self.id,
extra=eopayment_response_to_extra_info(response),
)
if response.result == eopayment.WAITING:
# mark basket items as waiting for payment confirmation
self.items.all().update(waiting_date=timezone.now())
@ -1039,7 +1012,7 @@ class Transaction(models.Model):
exc_info=True,
)
return
raise PaymentException('polling failed')
raise LingoException('polling failed', transaction=self)
logger.debug(
'lingo: regie "%s" polling backend for transaction "%s(%s)"',
@ -1051,6 +1024,9 @@ class Transaction(models.Model):
if self.status != response.result:
self.handle_backend_response(response)
def __str__(self):
return f'transaction "{self.order_id}" of regie "{self.regie}"'
class TransactionOperation(models.Model):
OPERATIONS = [

85
combo/apps/lingo/views.py
View File

@ -55,15 +55,14 @@ from .models import (
EXPIRED,
BasketItem,
LingoBasketCell,
LingoException,
PaymentBackend,
PaymentException,
Regie,
RemoteInvoiceException,
RemoteItem,
SelfDeclaredInvoicePayment,
Transaction,
TransactionOperation,
UnknownPaymentException,
UnsignedPaymentException,
)
from .utils import signing_dumps, signing_loads
@ -71,7 +70,7 @@ from .utils import signing_dumps, signing_loads
logger = logging.getLogger(__name__)
class EmptyPaymentResponse(PaymentException):
class EmptyPaymentResponse(LingoException):
pass
@ -647,35 +646,45 @@ class PaymentView(View):
if not backend_response and not payment.has_empty_response:
raise EmptyPaymentResponse
logger.info('received payment response: %r', backend_response)
eopayment_response_kwargs = {'redirect': not callback}
if transaction is not None:
eopayment_response_kwargs.update(
{
'order_id_hint': transaction.order_id,
'order_status_hint': transaction.status,
}
)
try:
eopayment_response_kwargs = {'redirect': not callback}
if transaction is not None:
eopayment_response_kwargs.update(
{
'order_id_hint': transaction.order_id,
'order_status_hint': transaction.status,
}
)
payment_response = payment.response(backend_response, **eopayment_response_kwargs)
except eopayment.PaymentException as e:
logger.error(
'failed to process payment response: %s',
e,
extra={'eopayment_raw_response': repr(backend_response)},
)
raise PaymentException('Failed to process payment response')
raise LingoException('eopayment exception: %s' % e)
return payment_backend.handle_backend_response(payment_response)
class CallbackView(PaymentView):
def handle_callback(self, request, backend_response, **kwargs):
try:
self.handle_response(request, backend_response, **kwargs)
except UnknownPaymentException as e:
raise Http404(force_text(e))
except PaymentException as e:
transaction = self.handle_response(request, backend_response, **kwargs)
except LingoException as e:
if e.transaction:
logger.warning(
'lingo: received synchronous payment notification for '
'%s: failure "%s" with method "%s" and content %r',
e.transaction,
e,
request.method,
backend_response,
)
else:
logger.warning(
'lingo: received synchronous payment notification for '
'an unknown transaction: failure "%s" with method "%s" and content %r',
e,
request.method,
backend_response,
)
return HttpResponseBadRequest(force_text(e))
logger.info('lingo: received synchronous payment notification for %s', transaction)
return HttpResponse()
def get(self, request, *args, **kwargs):
@ -714,25 +723,53 @@ class ReturnView(PaymentView):
transaction = Transaction.objects.filter(id=transaction_id).first()
response_is_ok = True
exception = None
try:
transaction = self.handle_response(
request, backend_response, callback=False, transaction=transaction, **kwargs
)
except (EmptyPaymentResponse, UnsignedPaymentException):
except EmptyPaymentResponse:
response_is_ok = False
except UnsignedPaymentException as e:
# some payment backends do not sign return URLs, don't mark this as
# an error, they will provide a notification to the callback
# endpoint.
response_is_ok = False
except PaymentException:
exception = e
except LingoException as e:
response_is_ok = False
exception = e
messages.error(
request, _('We are sorry but the payment service failed to provide a correct answer.')
)
if exception:
transaction = transaction or exception.transaction
if transaction:
logger.warning(
'lingo: error on asynchronous payment notification for '
'%s: failure "%s" with method "%s" and content %r',
transaction,
exception,
request.method,
backend_response,
)
else:
logger.warning(
'lingo: error on asynchronous payment notification for '
'an unknown transaction: failure "%s" with method "%s" and content %r',
exception,
request.method,
backend_response,
)
if not response_is_ok:
if transaction_id:
return HttpResponseRedirect(get_payment_status_view(transaction_id))
return HttpResponseRedirect(get_basket_url())
logger.info('lingo: received asynchronous payment notification for %s', transaction)
if transaction and transaction.status in (eopayment.PAID, eopayment.ACCEPTED):
messages.info(request, transaction.regie.get_text_on_success())

13
tests/test_lingo_payment.py
View File

@ -1,4 +1,5 @@
import json
import re
import urllib.parse
import uuid
from contextlib import contextmanager
@ -25,9 +26,9 @@ from combo.apps.lingo.models import (
EXPIRED,
BasketItem,
LingoBasketCell,
LingoException,
LingoRecentTransactionsCell,
PaymentBackend,
PaymentException,
Regie,
Transaction,
TransactionOperation,
@ -53,7 +54,7 @@ def get_url(with_payment_backend, view_name, regie):
def check_log(caplog, message):
idx = len(caplog.records)
yield
assert any(message in record.message for record in caplog.records[idx:]), (
assert any(re.search(message, record.message) for record in caplog.records[idx:]), (
'%r not found in log records' % message
)
@ -1021,7 +1022,7 @@ def test_nonexisting_transaction(app, regie, user, with_payment_backend):
# call callback with GET
callback_url = get_url(with_payment_backend, 'lingo-callback', regie)
app.get(callback_url, params=data, status=404)
app.get(callback_url, params=data, status=400)
@pytest.mark.parametrize('with_payment_backend', [False, True])
@ -1086,7 +1087,7 @@ def test_payment_no_callback_just_return(caplog, app, basket_page, regie, user,
return_url = qs['return_url'][0]
# call return with unsigned POST
with check_log(caplog, 'received unsigned payment'):
with check_log(caplog, 'Received unsigned payment response'):
with mock.patch('combo.utils.requests_wrapper.RequestsSession.request') as request:
get_resp = app.post(return_url, params=data)
assert request.call_count == 0
@ -1095,7 +1096,7 @@ def test_payment_no_callback_just_return(caplog, app, basket_page, regie, user,
assert Transaction.objects.get(order_id=transaction_id).status == 0 # not paid
# call return with missing data
with check_log(caplog, 'failed to process payment response: missing transaction_id'):
with check_log(caplog, 'missing transaction_id.*amount=10'):
baddata = data.copy()
del baddata['transaction_id']
with mock.patch('combo.utils.requests_wrapper.RequestsSession.request') as request:
@ -2201,7 +2202,7 @@ class TestPolling:
transaction = Transaction.objects.get()
assert transaction.status != eopayment.PAID
with pytest.raises(PaymentException): # from combo.apps.lingo.models
with pytest.raises(LingoException): # from combo.apps.lingo.models
call_command('lingo-poll-backend', all_backends=True)
def test_cli_ok(self):