Add datasync logging (Z#23225588) (#5928)

* Fix inconsistent log messages

* Add logging for successfully synced orders

(debugging orders that might get silently skipped)

src/pretix/base/datasync/datasync.py

@@ -216,7 +216,10 @@ class OutboundSyncProvider:
 
             try:
                 mapped_objects = self.sync_order(sq.order)
-                if not all(all(not res or res.sync_info.get("action", "") == "nothing_to_do" for res in res_list) for res_list in mapped_objects.values()):
+                actions_taken = [res and res.sync_info.get("action", "") for res_list in mapped_objects.values() for res in res_list]
+                should_write_logentry = any(action not in (None, "nothing_to_do") for action in actions_taken)
+                logger.info('Synced order %s to %s, actions: %r, log: %r', sq.order.code, sq.sync_provider, actions_taken, should_write_logentry)
+                if should_write_logentry:
                     sq.order.log_action("pretix.event.order.data_sync.success", {
                         "provider": self.identifier,
                         "objects": {
@@ -237,7 +240,7 @@ class OutboundSyncProvider:
                     sq.set_sync_error("exceeded", e.messages, e.full_message)
                 else:
                     logger.info(
-                        f"Could not sync order {sq.order.code} to {type(self).__name__} "
+                        f"Could not sync order {sq.order.code} to {sq.sync_provider} "
                         f"(transient error, attempt #{sq.failed_attempts}, next {sq.not_before})",
                         exc_info=True,
                     )

src/pretix/base/models/datasync.py

@@ -86,7 +86,7 @@ class OrderSyncQueue(models.Model):
 
     def set_sync_error(self, failure_mode, messages, full_message):
         logger.exception(
-            f"Could not sync order {self.order.code} to {type(self).__name__} ({failure_mode})"
+            f"Could not sync order {self.order.code} to {self.sync_provider} ({failure_mode})"
         )
         self.order.log_action(f"pretix.event.order.data_sync.failed.{failure_mode}", {
             "provider": self.sync_provider,

src/pretix/plugins/paypal2/payment.py

@@ -802,31 +802,37 @@ class PaypalMethod(BasePaymentProvider):
                             all_captures_completed = False
                         else:
                             any_captures = True
-            if not (any_captures and all_captures_completed):
+
+            # Payment has at least one capture, but it is not yet completed
+            if any_captures and not all_captures_completed:
                 messages.warning(request, _('PayPal has not yet approved the payment. We will inform you as '
                                             'soon as the payment completed.'))
                 payment.info = json.dumps(pp_captured_order.dict())
                 payment.state = OrderPayment.PAYMENT_STATE_PENDING
                 payment.save()
                 return
+            # Payment has at least one capture and all captures are completed
+            elif any_captures and all_captures_completed:
+                if pp_captured_order.status != 'COMPLETED':
+                    payment.fail(info=pp_captured_order.dict())
+                    logger.error('Invalid state: %s' % repr(pp_captured_order.dict()))
+                    raise PaymentException(
+                        _('We were unable to process your payment. See below for details on how to proceed.')
+                    )
 
-            if pp_captured_order.status != 'COMPLETED':
-                payment.fail(info=pp_captured_order.dict())
-                logger.error('Invalid state: %s' % repr(pp_captured_order.dict()))
-                raise PaymentException(
-                    _('We were unable to process your payment. See below for details on how to proceed.')
-                )
+                if payment.state == OrderPayment.PAYMENT_STATE_CONFIRMED:
+                    logger.warning('PayPal success event even though order is already marked as paid')
+                    return
 
-            if payment.state == OrderPayment.PAYMENT_STATE_CONFIRMED:
-                logger.warning('PayPal success event even though order is already marked as paid')
+                try:
+                    payment.info = json.dumps(pp_captured_order.dict())
+                    payment.save(update_fields=['info'])
+                    payment.confirm()
+                except Quota.QuotaExceededException as e:
+                    raise PaymentException(str(e))
+            # Payment has not any captures yet - so it's probably in created status
+            else:
                 return
-
-            try:
-                payment.info = json.dumps(pp_captured_order.dict())
-                payment.save(update_fields=['info'])
-                payment.confirm()
-            except Quota.QuotaExceededException as e:
-                raise PaymentException(str(e))
         finally:
             if 'payment_paypal_oid' in request.session:
                 del request.session['payment_paypal_oid']
@@ -836,7 +842,7 @@ class PaypalMethod(BasePaymentProvider):
         try:
             if (
                     payment.info
-                    and payment.info_data['purchase_units'][0]['payments']['captures'][0]['status'] == 'pending'
+                    and payment.info_data['purchase_units'][0]['payments']['captures'][0]['status'] == 'PENDING'
             ):
                 retry = False
         except (KeyError, IndexError):