Add payment logging to orders

I'm trying to think when/if we would be concerned about sending through multiple refunds at a single time. I'm coming at this from an accounting perspective. it doesn't look like the current workflows allow for more than a single transition from 'partially_refunded'. Time to do some research.

Updating issue credits.

Linked to active PR: https://github.com/drupalcommerce/commerce/pull/797

I've converted the PR into a patch and then made a few changes:
1. I removed the modified PaymentListBuilder. Having the Order activity displayed on both the order canonical view page and the payments listing seemed strange, especially since not all the log entries apply to payments. It's easy enough for admin users to pop open a second browser window if they want to look at the Order Activity at the same time as the Payments listing.

2. All the logic for building the payment logs seemed a bit complicated to me. I've changed the log types to just INSERT, UPDATE, and DELETE. The "update" logs capture refunds, voids, etc. Displaying the payment state in the log as well as the current payment balance seems sufficiently clear to me. For example:

First entry:

Payment added: $50.00. State: Completed. Remote ID: 123456.

Second entry:

Payment updated. Payment balance: $40.00. State: Partially refunded. Remote ID: 123456.

So this second entry represents a refund of $10.

For deleted log entries, I display the payment method label when available, since the payment entity will no longer be there for reference:

Payment deleted: $40.00. [Visa ending in 1111] Remote ID: 123456.

There's an additional type of log entry I'd like to create, but I haven't worked out the details yet and perhaps it's better as a follow-up issue. It would be a new event: PaymentRejectedEvent that could be dispatched by the PaymentProcess checkout pane whenever the customer gets an error message as a result of a PaymentDeclineException or PaymentGatewayException. Payment gateway exceptions are already logged in the Commerce Payment channel, but I think it would be helpful (especially for less technical admin users) to also log an entry they can see right on the order page. So if an admin user is trying to help a customer, the user can track down the order, look at its activity log, see the error message, and then from there, possibly investigate whatever information was logged for the exception. I'm not sure what information could/should be displayed in the Order log listing, though. Perhaps just the payment gateway plugin label and payment amount? Or additional details about the exception?

Fixed the failing Kernel test as well as a few minor things.

Changed test base.

Fixing another issue with Kernel test.

This patch rolls in work from #2862339: No events thrown for Payment CRUD (from the PR I believe.) I wonder if we should add the events first (payment module) then logging in this one (log module.)

Let's postpone this on #2862339: No events thrown for Payment CRUD. There is code going into two modules and we need to test two things: events firing and log logging them.

Here's a patch with the payment CRUD event work removed. It requires #2862339: No events thrown for Payment CRUD

Kernel test has been implemented but not tested yet so likely needs work.

PaymentIntegrationTest has a few phpcs on " over ' for assertion strings.

+++ b/modules/log/commerce_log.commerce_log_templates.yml
@@ -27,3 +27,16 @@ order_assigned:
+payment_updated:
+  category: commerce_payment
+  label: 'Payment updated'
+  template: '<p>Payment updated. Payment balance: {{ amount|commerce_price_format }}. State: {{ state }}. {% if remote_id %}Remote ID: {{ remote_id }}{% else %}ID: {{ id }}{% endif %}.</p>'

I like this. It covers if moved from authorized to captured or to void/refunded easily.

+++ b/modules/log/config/install/views.view.commerce_activity.yml
@@ -288,7 +288,7 @@ display:
-      title: 'Order logs'
+      title: 'Order activity'

Any reason we changed this specifically? To be honest, it makes more sense especially since the view name is called "commerce_activity", but I think this could be a small nit in another issue.

This has been tested and vetted in a client's QA process as well. Looks good to go once #2862339: No events thrown for Payment CRUD lands.

      'id' => $payment->id(),
      'remote_id' => $payment->getRemoteId(),
      'amount' => $payment->getAmount(),
      'state' => $payment->getState()->getLabel(),

These seem like the right kind of defaults.

#2862339: No events thrown for Payment CRUD has landed.

This looks good at a glance. I would have preferred to see individual logs for authorize/capture/refund/void. But if Matt and Lisa prefer this option, then I'll defer to their judgement.

Nitpick:

+  template: '<p>Payment updated. Payment balance: {{ amount|commerce_price_format }}. State: {{ state }}. {% if remote_id %}Remote ID: {{ remote_id }}{% else %}ID: {{ id }}{% endif %}.</p>'

Would it make sense to put a few newlines in here?

Back to mglaman for a post-2.17 commit.

Rerolled patch with test fixes.

Fixed syntax errors in templates and errors in Kernel test.

I had trouble applying #18 with composer patches, maybe a whitespace error. Let's try this.Sorry, bad patch.

+++ b/modules/log/src/EventSubscriber/PaymentEventSubscriber.php
@@ -0,0 +1,102 @@
+    $this->logStorage->generate($payment->getOrder(), 'payment_deleted', [

I have had this fail during the teardown of a test, because $payment->getOrder() was returning NULL. Perhaps these should all be wrapped in a conditional

if ($order = $payment->getOrder()) {
  $this->logStorage->generate($order, 'payment_deleted', [...
}

.

Revisiting. So #18 should be correct, but per @jonathanshaw there was a bug where the payment didn't have an order attached. That smells like a test fixture problem, because all payments belong to an order.

Clarifying that this issue is about logging payment events to the order activity stream. Back to needs work because the latest patch shrunk without explanation or tests. 😬

Additionally, the current message templates don't provide sufficient information IMO.

We need to know when the payment was authorized, when it was refunded/captured/voided, what is the payment gateway / method.

Thanks for the patch!

Back to needs work because the latest patch shrunk without explanation or tests.

If that's re #20, I guess it's since been edited to show it's a bad patch. #18 still applies.

We need to know when the payment was authorized, when it was refunded/captured/voided, what is the payment gateway / method.

Just to mention that the user shows up in the activity log, and at least with some gateways you can use the remote ID to correlate different events to see when eg. auth/capture/refund/void happened on a transaction.

I've added the payment gateway and method to the payment added message.

Thanks!

Hi,

Testing #25 I'm having this error when using manual payment (for bank transfer):

Error: Call to a member function label() on null in Drupal\commerce_log\EventSubscriber\PaymentEventSubscriber->onPaymentAdd() (line 58 of modules/contrib/commerce/modules/log/src/EventSubscriber/PaymentEventSubscriber.php).

'method' => $payment->getPaymentMethod()->label(),

I think that both calls of $payment->getPaymentMethod()->label() and the following $payment->getPaymentGateway()->label() must check for nulls, the phpdoc on PaymentInterface says:

@return \Drupal\commerce_payment\Entity\PaymentMethodInterface|null
The payment method entity, or null if unknown.

I still think logging payment CRUD events isn't the right approach here (as pointed out in #24).

What I think we need instead is:

1. Logging payment authorized / refunded / captured/ voided events. Payment authorized or payment captured is clearer and more user friendly than "Payment added" or "Payment updated".
2. Logging the order paid event (not entirely sure about the message here. "Order paid with|via|using? Order fully paid?"

But knowing when the payment was authorized, captured, refunded from the activity log is a way better alternative to what's implemented in the current patch...

Thoughts?

Just to clarify, I'm not saying the log templates shouldn't be created from event subscribers reacting to inserts/updates/deletes but rather than the log templates themselves shouldn't be just about logging "a payment was inserted/updated/deleted" because that doesn't give valuable information to the merchant.

Agreed re: being a little more specific in our logs. When we generate the order log, we have the full Payment entity, which has field values set that we should be able to use to be a little more precise. What do we think of the following?

On Payment insert, if the Payment has an authorized timestamp but no completed timestamp, use:

<p>Payment authorized via {{ gateway }} for {{ amount|commerce_price_format }} using {{ method }}.{% if remote_id %}<br />Remote ID: {{ remote_id }}{% endif %}</p>

For the gateway and method labels, perhaps we should use italics? I can't decide ... I'm also not even sure if the method will have a reasonable label for every payment gateway:

On Payment insert, if the Payment has a completed timestamp use:

<p>Payment captured via {{ gateway }} for {{ amount|commerce_price_format }} using {{ method }}.{% if remote_id %}<br />Remote ID: {{ remote_id }}{% endif %}</p>

On Payment update, if the original Payment doesn't have a completed timestamp and the saved one does, use:

<p>Payment captured via {{ gateway }} for {{ amount|commerce_price_format }} using {{ method }}.{% if remote_id %}<br />Remote ID: {{ remote_id }}{% endif %}</p>

Also, we need to bear in mind the capture amount might be different from the authorization amount ... I'm pretty sure the amount field would be updated to reflect that, but we may need the "prior authorization capture" Payment template to include an authorization ID. 🧐

Let me consider the others more ... because our current concept of refund vs. void is a bit weak compared to how payment gateways operate. And we can easily spec. out a generic "failed payment attempt" template, but should we have one for each kind of failed attempt? Or just the ability to specify the operation in a template variable when the log is created ... e.g.:

• Payment request failed at PayPal; could not authorize $45.00 due to {{ error_message }}.
• Payment request failed at PayPal; could not capture $35.00 due to {{ error_message }}.
• Payment request failed at PayPal; could not capture $35.00 against transaction #### due to {{ error_message }}.
• Payment request failed at PayPal; could not refund $45.00 to Visa ending in 1111 due to {{ error_message }}.
• Payment request failed at PayPal; could not void transaction #### due to {{ error_message }}.

There are likely other permutations; just not sure if this should be a single "failed payment request" template using variables for the different message patterns or if we should have template for the individual types of failure.

Also, I know the field is named "Remote ID", but I'm inclined to suggest we use "Transaction ID" in the message itself ... let's just check a few payment gateways, but I'm pretty sure that's the label you'd use in the gateway's search interface to find the transaction.

@tBKoT: For determining that a payment is authorized or completed, we need to follow the same logic as in the Payment::presave() method.

For example, for determining that a payment is authorized, you need to do the following:

$state = $payment->getState()->getId();
$original_state = isset($payment->original) ? $payment->original->getState()->getId() : '';
if ($state === 'authorization' && $original_state !== 'authorization') {

For determining that a payment is completed, same principle:

if ($state === 'completed' && $original_state !== 'completed') {

So this means you should call a common method that is called from payment insert and payment update.

Also, I'm thinking we should react to PaymentEvents::PAYMENT_DELETE instead of PaymentEvents::PAYMENT_PREDELETE since it is invoked AFTER the deletion.

@tBKot: Looks good, we're close!

Did some manual testing and ended up with the following crash on checkout completion:

Error: Call to a member function label() on null in Drupal\commerce_log\EventSubscriber\PaymentEventSubscriber->onPaymentAdd()

Not all payments have a payment method so:
$payment->getPaymentMethod()->label() should be updated, we should ensure the payment method is set/exists before accessing it.

Also, let's rename onPaymentAdd() to onPaymentInsert().

And the payment event subscriber is missing an empty line at end of file.

Would be great if we could expand the tests to ensure creating a payment doesn't crash when the payment method is empty so we're covered :).

Also, in the tests we can remove the $payment = Payment::load() where applicable as reloadEntity() is basically doing that.

Also, we should be consistent with the variable names we use in templates (i.e we used "method" for "payment_authorized", "payment_completed" and "payment_updated", but we used payment_method_label for the "payment_deleted" template.

Additionally, I see that we don't include the gateway in the payment deletion template, which... is probably fine though.

Since the method can be NULL, I guess we need to adapt the templates to add conditions so "using" is only added when the method is known.

There are confusing comments in logs:

// Check that log was not added on creation.
 $payment->save();
 $logs = $this->logStorage->loadMultipleByEntity($this->order);
 $this->assertEquals(1, count($logs));

We're literally checking that a log was created here. Same with the method comment.

Decided to go ahead and commit this! We've been dragging this for too long :).

Thanks to everyone involved!

I'm wondering if we shouldn't revisit this already before it goes into the release as it doesn't really look good with manual payments;

This is how it looks for "manual" payments:

After checkout, when the order is placed:

When "receiving" the payment:

Perhaps we need specific templates for manual payments? Notice the extra docs and "capture" which isn't the right term as there isn't an actual capture occurring here...

I think it should say "Payment of $10 received using {{ payment_gateway }}" instead?
So maybe we need a new "payment_manual_received" template?

Also, wouldn't it make sense in general to log the order balance too? Perhaps on payment capture I guess?

Should we open a followup issue instead? Thoughts?

Made some changes to the patch.

The "payment_added" template wasn't built the same as the others, the attached patch is making it more consistent with the others. Also added a "payment_manual_received" template.

Minor tweaks, here's an example of the result:

Decided to commit the followup changes as it improves the current templates. The rest can be implemented via followup issues.