Merge branch 'dev_fix_pereodic_payment' into 'dev'

рефактор переодической задачи: транзакционность, логирование и продолжение цикла по всем платежам

See merge request !421

config_app/management/commands/for_test.py

@@ -0,0 +1,16 @@
+from django.core.management.base import BaseCommand
+
+
+class Command(BaseCommand):
+    help = 'Команда для тестов'
+
+    def handle(self, *args, **options):
+        from finance.loggers import FinanceLogger
+        logger = FinanceLogger()
+        try:
+            10 / 0
+        except Exception as exc:
+            logger.exception('FinanceLogger test log record', extra={'asdf': 3246523},
+                        invoice_id=42, exc={'a': 1, 'b': 3, 'привет': 'медвед'}
+            )
+

finance/loggers.py

@@ -0,0 +1,56 @@
+# -*- coding: utf-8 -*-
+
+import logging
+
+_logger = logging.getLogger('finance_data')
+
+
+class FinanceLogger:
+    """
+    Все kwargs попадют в %(finance_data)s и логируются
+    'format': '%(asctime)s - %(levelname)s - %(message)s - %(finance_data)s'
+    """
+
+    def __init__(self, prefix=None):
+        self.prefix = prefix
+
+    def log(self, level, msg, *args, **kwargs):
+        _logger.log(level=level, msg=self._get_msg(msg), *args, **self._make_kwargs(kwargs))
+
+    def _get_msg(self, msg):
+        if self.prefix:
+            msg = '{}: {}'.format(self.prefix, msg)
+        return msg
+
+    def _make_kwargs(self, kwargs):
+        new_kwargs = {}
+        for inspected_kwarg in ('exc_info', 'stack_info', 'extra'):
+            try:
+                new_kwargs[inspected_kwarg] = kwargs.pop(inspected_kwarg)
+            except KeyError:
+                pass
+        if 'extra' in new_kwargs:
+            new_kwargs['extra']['finance_data'] = kwargs
+        else:
+            new_kwargs['extra'] = dict(finance_data=kwargs)
+        return new_kwargs
+
+    def debug(self, msg, *args, **kwargs):
+        self.log(level=logging.DEBUG, msg=msg, *args, **kwargs)
+
+    def info(self, msg, *args, **kwargs):
+        self.log(level=logging.INFO, msg=msg, *args, **kwargs)
+
+    def warning(self, msg, *args, **kwargs):
+        self.log(level=logging.WARNING, msg=msg, *args, **kwargs)
+
+    # TODO отделить логирование ошибок в другой лог
+    def error(self, msg, *args, **kwargs):
+        self.log(level=logging.ERROR, msg=msg, *args, **kwargs)
+
+    def critical(self, msg, *args, **kwargs):
+        self.log(level=logging.CRITICAL, msg=msg, *args, **kwargs)
+
+    def exception(self, msg, *args, **kwargs):
+        kwargs['stack_info'] = True
+        _logger.exception(self._get_msg(msg), *args,  **self._make_kwargs(kwargs))

finance/management/commands/yandex_repeat_payment.py

@@ -1,15 +1,14 @@
-import logging
-
 from django.core.management.base import BaseCommand
 
+from finance.loggers import FinanceLogger
 from finance.tasks import periodic_billing
 
-logger_yandex = logging.getLogger('yandex_money')
+finance_logger = FinanceLogger()  # prefix='YandexMoney'
 
 
 class Command(BaseCommand):
 
     def handle(self, *args, **options):
-        logger_yandex.info("start console repeat payment command")
+        finance_logger.info("start console repeat payment command")
         print('Started')
         periodic_billing()

finance/tasks.py

@@ -1,28 +1,34 @@
 import logging
-
 import os
+
 import requests
-from dateutil.relativedelta import relativedelta
+from django.conf import settings
+from django.db import transaction
+from django.utils import timezone
 from yandex_money.models import Payment
 
+from finance.loggers import FinanceLogger
 from finance.models import InvoiceRebilling
 from lms import celery_app
-from django.conf import settings
-from django.utils import timezone
-
-logger_yandex = logging.getLogger('yandex_money')
 
+finance_logger = FinanceLogger()
 
 @celery_app.task
 def periodic_billing():
-    try:
-        logger_yandex.info("start periodic billing task")
+        finance_logger.info("start periodic billing task")
         invoices = InvoiceRebilling.objects.filter(method='Y').exclude(status='F')
+        for invoice in invoices.filter(expected_date__lt=timezone.now()):
+            # выбираем все необработанные из прошлого
+            with transaction.atomic():
+                try:
+                    _yandex_repeat_card_payment(invoice)
+                except Exception as exc:
+                    finance_logger.exception('YandexMoney repeatCardPayment Exception', invoice_id=invoice.id)
+                    invoice.comment = 'Ошибка при попытке повторного платежа, свяжитесь с клиентской службой'
+                invoice.save()
 
-        for invoice in invoices.filter(
-                expected_date__gt=timezone.now(), expected_date__lt=timezone.now() + relativedelta(days=1)):
-            # TODO выбирать все, даже прошлые неотработанные - что бы не потерять
 
+def _yandex_repeat_card_payment(invoice):
     user = invoice.bill.user
     yandex_pay = Payment.objects.create(
         order_amount=invoice.price,
@@ -33,18 +39,10 @@ def periodic_billing():
         scid=settings.YANDEX_MONEY_REBILLING_SCID
     )
     invoice.yandex_pay = yandex_pay
-            invoice.save()
 
-            repeat_card_payment(invoice)
-    except Exception as exc:
-        logger_yandex.error('periodic billing Exception', exc_info=True, extra={
-            'exc': exc
-        })
-        # TODO записывать в invoice.comments ошибку яндекса
-
-
-def repeat_card_payment(invoice):
-    resp = requests.post(settings.YANDEX_MONEY_MWS_URL + 'repeatCardPayment',
+    finance_logger.info('YandexMoney repeatCardPayment start', invoice_id=invoice.id)
+    resp = requests.post(
+        url=settings.YANDEX_MONEY_MWS_URL + 'repeatCardPayment',
         data={
             'clientOrderId': invoice.id,  # уникальное возрастающее целое число
             'invoiceId': invoice.key,
@@ -55,7 +53,8 @@ def repeat_card_payment(invoice):
             os.path.join(settings.SSL_ROOT, 'skillbox.cer'),
             os.path.join(settings.SSL_ROOT, 'skillbox.key')
         ),
-                         verify=os.path.join(settings.SSL_ROOT, 'yamoney_chain.cer'))
-    logger_yandex.info('periodic billing finish', exc_info=True, extra={
-        'response': resp.text, 'code': resp.status_code,
-    })
+        verify=os.path.join(settings.SSL_ROOT, 'yamoney_chain.cer')
+    )
+    # TODO тут проверять нет ли ошибки яндекса (даже при 200 ответе)
+    finance_logger.info('YandexMoney repeatCardPayment ended',
+                        invoice_id=invoice.id, response=resp.text, code=resp.status_code, )

finance/views.py

@@ -1,32 +1,32 @@
 import csv
-import logging
+import uuid
 
 import requests
+from django.conf import settings
 from django.contrib.auth import get_user_model
 from django.core.mail import EmailMessage
+from django.core.mail import EmailMultiAlternatives
 from django.db import IntegrityError
 from django.db.models import Q
 from django.http import HttpResponse, HttpResponseForbidden
 from django.shortcuts import redirect, render_to_response
+from django.template.loader import render_to_string
+from django.utils import timezone
+from django.utils.html import strip_tags
 from rest_framework.renderers import JSONRenderer
 from rest_framework.response import Response
 from rest_framework.views import APIView
 from yandex_money.models import Payment
-from django.conf import settings
-from django.core.mail import EmailMultiAlternatives
-from django.template.loader import render_to_string
-from django.utils.html import strip_tags
 
-from courses.models import Course
 from courses.api import CourseParamsApi
+from courses.models import Course
+from finance.loggers import FinanceLogger
 from finance.models import Bill, Invoice, InvoiceRebilling
 from finance.serializers import BillSerializer, InvoiceSerializer
 from lms.global_decorators import transaction_decorator
 from lms.tools import get_real_name
-from django.utils import timezone
-import uuid
 
-logger_yandex = logging.getLogger('yandex_money')
+finance_logger = FinanceLogger()  # prefix='YandexMoney'
 
 
 def test_pay(request):
@@ -337,9 +337,7 @@ class YandexPay(APIView):
 
                 msg.send()
             except Exception as exc:
-                logger_yandex.error('YandexPay: Email not sended', exc_info=True, extra={
-                    'exc': exc
-                })
+                finance_logger.exception('YandexPay: Email not sended')
 
             return redirect(r.url)
 
@@ -395,41 +393,35 @@ class YandexCheckView(APIView):
             val = i.split('=')[1]
             data[key] = val
 
-        logger_yandex.info('Проверка платежа запрос', exc_info=True, extra={
-            'request': data,
-        })
+        finance_logger.info('Проверка платежа запрос', request=data)
 
+        order_number = data['orderNumber']
         try:
-            pay = Payment.objects.get(order_number=data['orderNumber'])
+            pay = Payment.objects.get(order_number=order_number)
         except Payment.DoesNotExist:
-            logger_yandex.error('Ошибка проверки платежа', exc_info=True, extra={
-                'request': "Payment with id=%s not found" % data['orderNumber'],
-            })
+            finance_logger.error('Ошибка проверки платежа', exc_info=True,
+                                 request="Payment with id=%s not found" % order_number)
             return Response(status=204)
 
         if not pay.status == Payment.STATUS.PROCESSED:
-            logger_yandex.error('Ошибка проверки платежа', exc_info=True, extra={
-                'request': "Payment with id=%s have status %s" % (data['orderNumber'], pay.status),
-            })
+            finance_logger.error('Ошибка проверки платежа',
+                                 order_number=order_number,
+                                 request="Payment with id=%s have status %s" % (order_number, pay.status))
             return Response(status=204)
 
         if not pay.shop_id == int(data['shopId']):
-            logger_yandex.error('Ошибка проверки платежа', exc_info=True, extra={
-                'request': "ShopId=%s not match" % (data['shopId'],),
-            })
+            finance_logger.error('Ошибка проверки платежа',
+                                 request="ShopId=%s not match" % (data['shopId'],))
             return Response(status=204)
 
         if not pay.scid == int(data['scid']):
-            logger_yandex.error('Ошибка проверки платежа', exc_info=True, extra={
-                'request': "scid=%s not match" % (data['scid'],)
-            })
+            finance_logger.error('Ошибка проверки платежа',
+                                 request="scid=%s not match" % (data['scid'],))
             return Response(status=204)
 
         if not pay.order_amount == float(data['orderSumAmount']):
-            logger_yandex.error('Ошибка проверки платежа', exc_info=True, extra={
-                'request': "Expected amount is %s received amount is %s"
-                            % (pay.order_amount, data['orderSumAmount']),
-            })
+            finance_logger.error('Ошибка проверки платежа',
+                request="Expected amount is %s received amount is %s" % (pay.order_amount, data['orderSumAmount']))
             return Response(status=204)
 
         now = timezone.now()
@@ -439,9 +431,7 @@ class YandexCheckView(APIView):
         xml_res = """<checkOrderResponse performedDatetime="%s" code="0" invoiceId="%s" shopId="%s"/>
         """ % (pay.performed_datetime, str(data['invoiceId']), str(pay.shop_id))
 
-        logger_yandex.info('Проверка платежа ответ', exc_info=True, extra={
-            'response': xml_res,
-        })
+        finance_logger.info('Проверка платежа ответ', response=xml_res)
 
         return HttpResponse(xml_res, content_type='application/xml')
 
@@ -457,17 +447,16 @@ class YandexAvisoView(APIView):
             val = i.split('=')[1]
             data[key] = val
 
+        order_number = data['orderNumber']
         try:
-            pay = Payment.objects.get(order_number=data['orderNumber'])
+            pay = Payment.objects.get(order_number=order_number)
         except Payment.DoesNotExist:
-            logger_yandex.error('Ошибка подтверждения платежа', exc_info=True, extra={
-                'request': "Payment with invoice_id=%s not found" % data['orderNumber'],
-            })
+            finance_logger.error('Ошибка подтверждения платежа', exc_info=True,
+                                 request="Payment with invoice_id=%s not found" % order_number)
             return Response(status=204)
 
-        logger_yandex.info('Подтверждение платежа запрос', exc_info=True, extra={
-            'request': 'Get success pay with invoice_id(yandex) %s' % str(data['invoiceId']),
-        })
+        finance_logger.info('Подтверждение платежа запрос',
+            request='Get success pay with invoice_id(yandex) %s' % str(data['invoiceId']))
 
         pay.shop_amount = data['shopSumAmount']
         # invoice = pay.invoice
@@ -481,9 +470,7 @@ class YandexAvisoView(APIView):
         xml_res = """<paymentAvisoResponse performedDatetime="%s" code="0" invoiceId="%s" shopId="%s"/>
                 """ % (pay.performed_datetime, str(data['invoiceId']), str(pay.shop_id))
 
-        logger_yandex.info('Подтверждение платежа ответ', exc_info=True, extra={
-            'response': xml_res,
-        })
+        finance_logger.info('Подтверждение платежа ответ', response=xml_res)
 
         context = {
             'user_email': pay.invoice.bill.user.email,
@@ -518,7 +505,7 @@ class YandexFailView(APIView):
             val = i.split('=')[1]
             data[key] = val
 
-        logger_yandex.error(data)
+        finance_logger.error('YandexFailView', data=data)
 
         return redirect(to=settings.DOMAIN)
 
@@ -536,12 +523,10 @@ class DemoYandexCheckView(APIView):
                 val = i.split('=')[1]
                 data[key] = val
 
-            logger_yandex.info('Проверка демо платежа запрос', exc_info=True, extra={
-                'request': data,
-            })
+            finance_logger.info('Проверка демо платежа запрос', request=data)
 
         except IndexError:
-            logger_yandex.error("Непредвиденная ошибка проверки тестогого платежа")
+            finance_logger.exception("Непредвиденная ошибка проверки тестогого платежа")
             return Response(status=204)
 
         now = timezone.now()
@@ -552,14 +537,10 @@ class DemoYandexCheckView(APIView):
             else:
                 xml_res = """<checkOrderResponse performedDatetime="%s" code="100" invoiceId="%s" shopId="%s"
                 message="Неверный номер ордера"/>""" % (now.isoformat(), str(data['invoiceId']), str(data['shopId']))
-                logger_yandex.warning(
-                    "Ошибка проверки тестогого платежа" , exc_info=True, extra={
-                        "response": xml_res
-                    }
-                )
+                finance_logger.warning("Ошибка проверки тестового платежа", response=xml_res)
             return HttpResponse(xml_res, content_type='application/xml')
         except KeyError:
-            logger_yandex.error('Ошибка в данных checkYandex')
+            finance_logger.exception('Ошибка в данных checkYandex')
             return Response(status=204)
 
 
@@ -567,7 +548,7 @@ class DemoYandexAvisoView(APIView):
 
     @staticmethod
     def post(request):
-        logger_yandex.info('Начало тестирования avisoYandex')
+        finance_logger.info('Начало тестирования avisoYandex')
         data = dict()
         for i in request.body.decode('utf-8').split('&'):
             key = i.split('=')[0]
@@ -578,17 +559,11 @@ class DemoYandexAvisoView(APIView):
         if float(data['orderSumAmount']) < 1001:
             xml_res = """<paymentAvisoResponse performedDatetime="%s" code="0" invoiceId="%s" shopId="%s"/>
                 """ % (now.isoformat(), str(data['invoiceId']), str(data['shopId']))
-            logger_yandex.info('Подтверждение демо платежа ответ', exc_info=True, extra={
-                'response': xml_res,
-            })
+            finance_logger.info('Подтверждение демо платежа ответ', response=xml_res)
 
         else:
             xml_res = """<paymentAvisoResponse performedDatetime="%s" code="100" invoiceId="%s" shopId="%s"
             message="Нам не позволяет совесть принять от вас более 1000 рублей"/
             >""" % (now.isoformat(), str(data['invoiceId']), str(data['shopId']))
-            logger_yandex.warning(
-                "Ошибка подтверждения тестогого платежа", exc_info=True, extra={
-                    "response": xml_res
-                }
-            )
+            finance_logger.warning("Ошибка подтверждения тестогого платежа", response=xml_res)
         return HttpResponse(xml_res, content_type='application/xml')

lms/celery.py

@@ -21,9 +21,8 @@ register_signal(client)
 
 app.conf.beat_schedule = {
     'periodic_billing': {
-        'schedule': crontab(day_of_month='1', hour='1', minute='1'),  # заглушка на время отладки
-        # 'schedule': crontab(minute='*/1'),
-        # crontab(minute='0',hour='*/3',),
+        # 'schedule': crontab(day_of_month='1', hour='1', minute='1'),  # заглушка на время отладки
+        'schedule': crontab(minute='0', hour='*/3',),
         'task': 'finance.tasks.periodic_billing'
     }
 }

lms/settings.py

@@ -206,6 +206,9 @@ LOGGING = {
             'format': '%(levelname)s %(asctime)s %(module)s '
                       '%(process)d %(thread)d %(message)s'
         },
+        'finance_data_formatter': {
+            'format': '%(asctime)s - %(levelname)s - %(message)s - %(finance_data)s'
+        },
     },
     'handlers': {
         'sentry': {
@@ -213,15 +216,17 @@ LOGGING = {
             'class': 'raven.contrib.django.raven_compat.handlers.SentryHandler',
             'tags': {'custom-tag': 'x'},
         },
-        'yandex_money': {
+        'finance_data': {
             'level': 'DEBUG',
             'class': 'raven.contrib.django.raven_compat.handlers.SentryHandler',
-            'tags': {'custom-tag': 'yandex'},
+            'tags': {'custom-tag': 'yandex'},  # TODO переделать на finance_data
         },
-        'yandex_money_file': {
+        'finance_data_file': {
             'level': 'INFO',
-            'class': 'logging.FileHandler',
-            'filename': os.path.join(BASE_DIR, 'logs', 'yandex_money.log'),
+            'class': 'logging.handlers.RotatingFileHandler',
+            'filename': os.path.join(BASE_DIR, 'logs', 'finance_data.log'),
+            'maxBytes': 1024 * 1024 * 10,
+            'formatter': 'finance_data_formatter'
         },
         'business_rules': {
             'level': 'DEBUG',
@@ -239,8 +244,8 @@ LOGGING = {
             'level': 'WARNING',
             'handlers': ['sentry'],
         },
-        'yandex_money': {
-            'handlers': ['yandex_money', 'yandex_money_file', ],
+        'finance_data': {
+            'handlers': ['finance_data', 'finance_data_file', ],
             'level': 'DEBUG',
             'propagate': False
         },