Home Blog Two-Phase Logging of Critical Events

DEV

Two-Phase Logging of Critical Events

Posted by alex on Dec. 12, 2016, 1:26 p.m.

Frequently, logging that an event has taken place is just as important
as the event being triggered in the first place. For example, logging
that a credit card has been charged is just as important as charging
the credit card. If either of these two important tasks fails, an end
user could either be overcharged or undercharged. Neither of these
outcomes is ideal. This scenario can be overcome however, with
the use of two-phase logging in such a way that a failure in either
prevents any further processing.

In database parlance, there exists the concept of a two-phase commit
which is used to maintain database consistency across multiple
servers. While the similarities fall apart at a deep level, the
overarching theme is there: Some primary process attempts to do its
job, waits for a secondary process to either succeed or fail, and
finally the primary process either succeeds or fails as a result of
the secondary process. In essence, we need something that meets the
following criteria:

1. If the charge cannot be logged, the card must not be charged
2. If the charge does not go through, the failure must be logged
3. If the charge goes through, the success must be logged

To implement two-phase logging to a database, we'll create a model in
Django:

    class CardChargeLog(models.Model):
        product = models.ForeignKey(Product)
        created_at = models.DateTimeField(auto_now_add=True)
        user = models.ForeignKey(User)
        card = models.ForeignKey(CreditCard)
        success = models.NullBooleanField()

We'll hold relevant details about the charge such as which product the
customer bought, as well as whether or not the transaction succeeded.

Our charge card function might look something like this:

    def charge_card(self, product, user, card):
        charge_log = CardChargeLog.objects.create(
            product=product,
            user=user,
            card=card,
            success=None
        )

        charge_log.save()

        try:
            charge_card(product, user, card)
        except ChargeError as e:
            charge_log.success = False
            # Log error to sentry
        else:
            charge_log.success = True
        finally:
            charge_log.save()

This code satisfies all three of our previous criteria. A log object
is created before the card is charged, making sure that the entry in
the database will satisfy all consistency constraints and that the
connection to the database is available. Only once the log object is
created does the card get charged.

After we try charging the card, the log object is updated to either
report success or failure, so the program can know whether to retry
the charge in the future.

Of course, there is still a small risk of the database not being available again
after the card is charged to record the success. This risk is much
smaller here than at the beginning of the function, since we know the
database is up just moments before, but it is non zero.

With this logging setup, a failure to save the log object the second
time will leave a "null" in the charge log, which is an obvious sign
that something has gone wrong. From here, a manual audit is possible
to see whether the charge went through, or perhaps it might be
possible to program something to check with the card services provider
automatically to update the state of the transaction.

In either scenario, this Python code is a much better defense against over or
undercharging a credit card than a one-phase log, and will allow any
errors to surface much more quickly.