Log charge errors at INFO level
[blender-dev-fund.git] / looper / clock.py
1 import abc
2 import datetime
3 import logging
4 import typing
5
6 from django.conf import settings
7 import django.db.models
8 import django.db.transaction
9 import django.utils.timezone
10
11 from . import admin_log, exceptions, models, signals
12
13 log = logging.getLogger(__name__)
14
15 RENEWABLE_SUBSCRIPTION_STATUSES = {'active'}
16 CANCELLABLE_SUBSCRIPTION_STATUSES = {'pending-cancellation'}
17
18 CollectionFunc = typing.Callable[[models.Subscription, typing.Optional[models.Order]], bool]
19
20
21 class AbstractClock(metaclass=abc.ABCMeta):
22     """Interface for time-based subscription updates.
23
24     NOTE(Sybren): this interface is provisionary and will be extended/changed.
25     """
26     log = log.getChild('AbstractClock')
27
28     def tick(self) -> None:
29         """Main entry point for running the clock."""
30
31         for subscription in self.queryset_renewal():
32             self.renew_subscription(subscription)
33
34         for subscription in self.queryset_cancel():
35             self.cancel_subscription(subscription)
36
37     def now(self) -> datetime.datetime:
38         """Return what is considered to be 'now'.
39
40         This can be any timestamp. Subclasses can override this method for
41         simulating events rather than executing them.
42         """
43         return django.utils.timezone.now()
44
45     def queryset_renewal(self) -> django.db.models.QuerySet:
46         """Return a QuerySet of all subscriptions that need renewal."""
47         my_log = self.log.getChild('queryset_renewal')
48         now = self.now()
49
50         from django.db.models import F
51         qs = models.Subscription.objects \
52             .filter(status__in=RENEWABLE_SUBSCRIPTION_STATUSES, next_payment__lt=now) \
53             .exclude(order__retry_after__gt=now) \
54             .exclude(collection_method='managed', next_payment__gt=now) \
55             .exclude(collection_method='managed', last_notification__gt=F('next_payment'))
56         my_log.info('Found %d subscriptions with status in %s and next_payment < %s',
57                     len(qs), RENEWABLE_SUBSCRIPTION_STATUSES, now)
58         return qs
59
60     def queryset_cancel(self) -> django.db.models.QuerySet:
61         """Return a QuerySet of all subscriptions that need cancellation."""
62         my_log = self.log.getChild('queryset_cancel')
63         now = self.now()
64
65         qs = models.Subscription.objects \
66             .filter(status__in=CANCELLABLE_SUBSCRIPTION_STATUSES, next_payment__lt=now)
67         my_log.info('Found %d subscriptions with status in %s and next_payment < %s',
68                     len(qs), CANCELLABLE_SUBSCRIPTION_STATUSES, now)
69         return qs
70
71     def renew_subscription(self, subscription: models.Subscription) -> None:
72         my_log = self.log.getChild('renew_subscription')
73
74         try:
75             order = self.order_to_renew(subscription)
76         except Exception as ex:
77             self.on_order_creation_failed(subscription, ex)
78             return
79
80         # Deal with the collection depending on the collection method.
81         collection_method = order.collection_method if order else subscription.collection_method
82         collection_funcs: typing.Mapping[str, CollectionFunc] = {
83             'automatic': self.collect_automatic,
84             'manual': self.collect_manual,
85             'managed': self.collect_managed,
86         }
87         try:
88             collection_func = collection_funcs[collection_method]
89         except KeyError:
90             self.log.error("No known way to handle collection method %r for subscription %r"
91                            " order %r, handling as 'managed'",
92                            collection_method, subscription.pk, order)
93             collection_func = collection_funcs['managed']
94
95         try:
96             collection_ok = collection_func(subscription, order)
97         except Exception as ex:
98             self.on_order_charge_failed(subscription, order, ex)
99             return
100
101         if not collection_ok:
102             return
103
104         subscription.bump_next_payment()
105         my_log.info('Renewal of subscription %d successful', subscription.pk)
106         self.on_subscription_renewal_ok(subscription)
107
108     def order_to_renew(self, subscription) -> typing.Optional[models.Order]:
109         """Determine which order to use for renewals.
110
111         This can be an existing order (when retrying), a new one (when not
112         retrying), or None (for managed subscriptions).
113         """
114         my_log = self.log.getChild('order_to_renew')
115
116         # Figure out whether this is a fresh renewal or the re-try of a previously failed one.
117         order = subscription.latest_order()
118         is_retry = order and order.status == 'soft-failed'
119
120         if is_retry:
121             my_log.info('Retrying renewal of subscription %d with status %r and '
122                         'collection method %r',
123                         subscription.pk, subscription.status, subscription.collection_method)
124             return order
125
126         my_log.info('Renewing subscription %d with status %r and collection method %r',
127                     subscription.pk, subscription.status, subscription.collection_method)
128         subscription.intervals_elapsed += 1
129
130         if subscription.collection_method == 'managed':
131             # Don't bother creating a renewal order for managed subscriptions.
132             return None
133
134         return self.create_renewal_order(subscription)
135
136     @abc.abstractmethod
137     def cancel_subscription(self, subscription: models.Subscription) -> None:
138         """Cancel a pending-cancellation or on-hold-for-too-long subscription."""
139
140     @abc.abstractmethod
141     def create_renewal_order(self, subscription: models.Subscription) -> models.Order:
142         """Create a new order for the subscription renewal."""
143
144     @abc.abstractmethod
145     def collect_automatic(self, subscription: models.Subscription,
146                           order: typing.Optional[models.Order]) -> bool:
147         """Create a Transaction and try to charge it.
148
149         :return: True when the charge was succesful, False otherwise.
150         """
151
152     @abc.abstractmethod
153     def collect_manual(self, subscription: models.Subscription,
154                        order: typing.Optional[models.Order]) -> bool:
155         """Create a Transaction but don't charge it yet.
156
157         :return: True when the creation was succesful, False otherwise.
158         """
159
160     @abc.abstractmethod
161     def collect_managed(self, subscription: models.Subscription,
162                         order: typing.Optional[models.Order]) -> bool:
163         """Handle managed subscriptions surpassing their next_payment date.
164
165         This can send a `managed_subscription_notification` signal.
166
167         :return: always False, as managed collections never actually charge the account.
168         """
169
170     @abc.abstractmethod
171     def on_order_creation_failed(self, subscription: models.Subscription, ex: Exception) -> None:
172         """Called when creating the renewal order failed."""
173
174     @abc.abstractmethod
175     def on_order_charge_failed(self, subscription: models.Subscription,
176                                order: typing.Optional[models.Order], ex: Exception) -> None:
177         """Called when charging the renewal order failed.
178
179         This covers unexpected errors, and not GatewayErrors. These are
180         handled in `collect_automatic()` itself.
181         """
182
183     @abc.abstractmethod
184     def on_subscription_renewal_ok(self, subscription: models.Subscription) -> None:
185         """Called after a succesful (probably automatic) renewal of the subscription."""
186
187
188 class SimulatingClock(AbstractClock):
189     log = log.getChild('SimulatingClock')
190
191     def tick(self) -> None:
192         self.log.info('Performing simulated tick')
193         super().tick()
194         self.log.info('Simulated tick done')
195
196     def cancel_subscription(self, subscription: models.Subscription) -> None:
197         """Cancel a pending-cancellation or on-hold-for-too-long subscription."""
198
199         self.log.info('Simulating cancellation of subscription %d with status %r',
200                       subscription.pk, subscription.status)
201
202     def create_renewal_order(self, subscription: models.Subscription) -> models.Order:
203         """Create a new order for the subscription renewal."""
204         self.log.info('Creating fake renewal order for subscription %d', subscription.pk)
205         order = subscription.generate_order(save=False)
206         return order
207
208     def collect_automatic(self, subscription: models.Subscription,
209                           order: typing.Optional[models.Order]) -> bool:
210         """Create an in-memory Transaction.
211
212         :return: always True.
213         """
214         self.log.info('Simulating renewal order charge for subscription %d', subscription.pk)
215         assert order is not None, 'Automatically-renewing subscriptions should always have an order'
216         order.collection_attempts += 1
217         order.generate_transaction(save=False)
218         return True
219
220     def collect_manual(self, subscription: models.Subscription,
221                        order: typing.Optional[models.Order]) -> bool:
222         """Create an in-memory Transaction.
223
224         :return: always False as manual collections never actually charge the account.
225         """
226         self.log.info('Simulating renewal order creation for subscription %d',
227                       subscription.pk)
228         return False
229
230     def collect_managed(self, subscription: models.Subscription,
231                         order: typing.Optional[models.Order]) -> bool:
232         """Handle managed subscriptions surpassing their next_payment date.
233
234         This can send a `managed_subscription_notification` signal.
235
236         :return: always False, as managed collections never actually charge the account.
237         """
238         self.log.info('Simulating managed subscription notification for subscription %d',
239                       subscription.pk)
240         return False
241
242     def on_order_creation_failed(self, subscription: models.Subscription, ex: Exception) -> None:
243         """Called when creating the renewal order failed."""
244         self.log.info('Simulated error creating renewal order for subscription %d', subscription.pk)
245
246     def on_order_charge_failed(self, subscription: models.Subscription,
247                                order: typing.Optional[models.Order], ex: Exception) -> None:
248         """Called when charging the renewal order failed."""
249         self.log.info('Simulated error charging renewal order %s for subscription %d',
250                       order.pk if order else '-no order-', subscription.pk)
251
252     def on_subscription_renewal_ok(self, subscription: models.Subscription) -> None:
253         pass
254
255
256 class Clock(AbstractClock):
257     log = log.getChild('Clock')
258
259     @django.db.transaction.atomic()
260     def renew_subscription(self, subscription: models.Subscription) -> None:
261         super().renew_subscription(subscription)
262         subscription.save()
263
264     @django.db.transaction.atomic()
265     def cancel_subscription(self, subscription: models.Subscription) -> None:
266         """Cancel a pending-cancellation or on-hold-for-too-long subscription."""
267         my_log = self.log.getChild('cancel_subscription')
268         old_status = subscription.status
269         my_log.info('Cancelling subscription %d with status %r',
270                     subscription.pk, old_status)
271         subscription.status = 'cancelled'
272         subscription.save(update_fields={'status'})
273         admin_log.attach_log_entry(subscription,
274                                    f'Subscription period ended, transitioning from '
275                                    f'{old_status!r} to {subscription.status!r}')
276
277     def create_renewal_order(self, subscription: models.Subscription) -> models.Order:
278         """Create a new order for the subscription renewal."""
279         my_log = self.log.getChild('create_renewal_order')
280         my_log.info('Creating renewal order for subscription %d', subscription.pk)
281
282         order = subscription.generate_order()
283
284         admin_log.attach_log_entry(subscription, f'Created order {order.pk} for renewal')
285         return order
286
287     def collect_automatic(self, subscription: models.Subscription,
288                           order: typing.Optional[models.Order]) -> bool:
289         """Create a transaction and try to charge it."""
290         my_log = self.log.getChild('collect_automatic')
291
292         assert order is not None, 'Automatic collection always has an order.'
293
294         trans: models.Transaction = order.generate_transaction()
295         my_log.info('Charging transaction %d for subscription %d and order %d',
296                     trans.pk, order.subscription.pk, order.pk)
297
298         order.collection_attempts += 1
299         charge_ok = trans.charge(customer_ip_address=None)
300         if not charge_ok:
301             self.on_collect_automatic_failed(order, trans)
302         else:
303             order.retry_after = None
304             signals.automatic_payment_succesful.send(sender=order, transaction=trans)
305
306         order.save(update_fields={'collection_attempts', 'status', 'retry_after'})
307         return charge_ok
308
309     def collect_manual(self, subscription: models.Subscription,
310                        order: typing.Optional[models.Order]) -> bool:
311         """Just deactivate the subscription.
312
313         :return: Always False, because we don't collect the payment in this function.
314         """
315         my_log = self.log.getChild('collect_manual')
316         assert order is not None, 'Manually-collected subscriptions should always have an order'
317
318         my_log.info('Placing subscription %d with order %d on-hold '
319                     'for manual renewal', order.pk, subscription.pk)
320
321         if not subscription.may_transition_to('on-hold'):
322             my_log.warning("Unable to transition subscription %d from %r to 'on-hold' "
323                            "for manual renewal with order %d.",
324                            subscription.pk, subscription.status, order.pk)
325             admin_log.attach_log_entry(
326                 subscription,
327                 f"Unable to transition subscription from {subscription.status} to 'on-hold' for "
328                 f"manual renewal with order {order.pk}")
329
330             return False
331
332         subscription.status = 'on-hold'
333         subscription.save(update_fields={'status'})
334
335         admin_log.attach_log_entry(subscription, f"Transitioned subscription to 'on-hold' "
336                                                  f"awaiting manual payment of order {order.pk}")
337
338         return False
339
340     def collect_managed(self, subs: models.Subscription,
341                         order: typing.Optional[models.Order]) -> bool:
342         """Handle managed subscriptions surpassing their next_payment date.
343
344         This can send a `managed_subscription_notification` signal.
345         """
346         my_log = self.log.getChild('collect_managed')
347
348         if not subs.notification_required:
349             my_log.info("Not notifying for 'managed' subscription %d", subs.pk)
350             return False
351
352         my_log.info('Notifying manager that managed subscription pk=%r surpassed its next_payment',
353                     subs.pk)
354         subs.last_notification = self.now()
355         subs.save(update_fields={'last_notification'})
356         signals.managed_subscription_notification.send(sender=subs)
357         return False
358
359     def on_order_creation_failed(self, subscription: models.Subscription, ex: Exception) -> None:
360         """Called when creating the renewal order failed."""
361         my_log = self.log.getChild('on_order_creation_failed')
362
363         if isinstance(ex, exceptions.GatewayError):
364             prefix = 'Error'
365             logger = my_log.error
366         else:
367             prefix = 'Unexpected error'
368             logger = my_log.exception
369         logger(f'{prefix} creating renewal order for subscription %d: %s', subscription.pk, ex)
370         admin_log.attach_log_entry(subscription, f'{prefix} creating renewal order: {ex}')
371         self._deactivate_subscription(subscription)
372
373     def on_order_charge_failed(self, subscription: models.Subscription,
374                                order: typing.Optional[models.Order], ex: Exception) -> None:
375         """Called when charging the renewal order failed."""
376         my_log = self.log.getChild('on_order_charge_failed')
377         my_log.exception('Unexpected error charging renewal order %s for subscription %d: %s',
378                          order.pk if order else '-no order-', subscription.pk, ex)
379
380         # Don't deactivate the subscription here; this could very well be an issue on our
381         # end (bad Braintree credentials, network connection gone down, etc.), so we
382         # shouldn't punish our customers for this.
383         if order:
384             admin_log.attach_log_entry(order, f'Unexpected error charging order: {ex}')
385         else:
386             admin_log.attach_log_entry(subscription, f'Unexpected error charging order: {ex}')
387
388     def on_collect_automatic_failed(self,
389                                     order: models.Order,
390                                     trans: models.Transaction) -> None:
391         """Update the order and transaction for the failure."""
392         max_attempts: int = settings.LOOPER_CLOCK_MAX_AUTO_ATTEMPTS
393
394         # This is logged at info level, because it is actually expected to happen frequently.
395         my_log = self.log.getChild('on_collect_automatic_failed')
396         msg = f'Error charging transaction {trans.pk} for renewal order {order.pk} for ' \
397               f'subscription {order.subscription.pk}, attempt {order.collection_attempts} ' \
398               f'of {max_attempts}: {trans.failure_message}'
399         my_log.info(msg)
400
401         if order.collection_attempts >= max_attempts:
402             admin_log.attach_log_entry(
403                 order, f'{msg}\nDeactivating subscription and failing order.')
404             self._deactivate_subscription(order.subscription)
405             order.status = 'failed'
406             signals.automatic_payment_failed.send(sender=order, transaction=trans)
407         else:
408             admin_log.attach_log_entry(
409                 order, f'{msg}\nKeeping subscription status {order.subscription.status!r} '
410                        f'and retrying later')
411
412             now = django.utils.timezone.now()
413             order.retry_after = now + settings.LOOPER_ORDER_RETRY_AFTER
414             order.status = 'soft-failed'
415
416             signals.automatic_payment_soft_failed.send(sender=order, transaction=trans)
417
418     def _deactivate_subscription(self, subscription: models.Subscription) -> None:
419         """Set a subscription to 'on-hold' after a failure.
420
421         This is a no-op when the subscription status is not 'active'.
422         """
423         if subscription.status != 'active':
424             return
425
426         subscription.status = 'on-hold'
427         my_log = self.log.getChild('_deactivate_subscription')
428         my_log.info('Setting subscription %d to %r due to renewal failure.',
429                     subscription.pk, subscription.status)
430         subscription.save(update_fields={'status'})
431
432     def on_subscription_renewal_ok(self, subscription: models.Subscription) -> None:
433         """Called after a succesful (probably automatic) renewal of the subscription."""
434         admin_log.attach_log_entry(
435             subscription,
436             f"{subscription.collection_method.title()} renewal successful. Updated "
437             f"next payment to {subscription.next_payment}")