Openfoodnetwork: Partial refund not available (refund amount is greater than unrefunded amount) - Initial/successful partial refund in Stripe not registered in OFN

[RachL]

Description

A big user in France is having this problem on two orders. This user don't want us to try the refund through Stripe directly. I'm a bit stuck on what to do next.

When you try to refund you get a message saying the amount you are trying to refund is greater than the unrefunded amount. Yet the unrefunded amount is a figure that is not known...

Hub is number 922 and they are not on Stripe SCA yet.

Steps to Reproduce

1. On FR prod orders R287174615 and R288734641 are in credit
2. When hitting the credit button this message is displayed:

1. Yet both orders seem fine: the amount to refund is lower than what the buyer paid:

Workaround

I have no idea if trying on stripe works, they don't want me to test it....

Severity

Not sure what the severity is....

Your Environment

• Version used: v2.9.8
• Browser name and version: Firefox
• Operating System and version (desktop or mobile):

Possible Fix

[kristinalim]

Here are some details for R288734641:

• order item_total - 56.66
• order total - 48.8
• order adjustment_total - -7.86 (consistent with adjustments amount)
• order adjustments included_tax - -0.45
• line item adjustments amount - 2.95
• line item adjustments included_tax - 2.95
• line items price sum - 49.89
• payments amount sum - 57.51

[kristinalim]

@RachL It looks like the Stripe refund succeeded but there was a problem in the OFN side. The Stripe charge has these data, and the difference explains the 5.25 amount:

  "amount": 5751,
  "amount_refunded": 5226,

The total refund consisting of 6 refunds worth 8.71, which was the amount attempted to refund.

[kristinalim]

The 8.71 amount comes from payment made minus the adjusted order total.

[RachL]

😱 sooo... these people now owe the hub money? Thank you so much for looking into it @kristinalim

[kristinalim]

sooo... these people now owe the hub money? Thank you so much for looking into it @kristinalim

That looks like it, @RachL. And there doesn't seem to be a way to cancel refund in the Stripe side: https://support.stripe.com/questions/canceling-a-refund

[RachL]

Ok so I'm guessing this is an s2... I will ask on Slack.

[luisramos0]

ah, nice finding Kristina 57.51 - (6*8.71) = 5.25 :tada:
So, the refund of 8.71 worked but it was not flagged on the OFN side. So the user clicked 6 times on the refund button before the error appeared, right?

I am working on the SCA refunds issue #5258, maybe I can have a look at this as well.

[luisramos0]

If this is correct, the customer needs to pay 5 * 8.71 = 43.55eur back to the hub.

[RachL]

So, the refund of 8.71 worked but it was not flagged on the OFN side. So the user clicked 6 times on the refund button before the error appeared, right?

yes :(

If this is correct, the customer needs to pay 5 * 8.71 = 43.55eur back to the hub.

Exactly.

[luisramos0]

I just came back to this one now: but why was the refund amount 8.71 in the first place?
I guess that's what I need to find out...

[RachL]

@luisramos0 maybe not at all related, but for the same hub I have an order with a credit owed, but no possibility to refund or void it. Order number is R875367600.

[luisramos0]

Rachel, this last order is not related R875367600. The credit card used for the original payment was deleted so the refund is not available.

[luisramos0]

I just tested and multiple partial refunds on an order are working correctly.
I can see the different refunds on stripe.

Can you share the Stripe page details for the payment in R288734641?

[RachL]

Rachel, this last order is not related R875367600. The credit card used for the original payment was deleted so the refund is not available.

Ah interesting!

[luisramos0]

One fact about this specific order/payment is that the order/payment are from 14th April and the first refund is issues on the 11th of May, almost a month later....

The data in the DB

The problem is that normally a refund in Stripe will be registered in the OFN DB, it will look like this in the DB:

Where the first row in the image, the refund, will have a source which is the payment, the original payment in the second row.

In this case, in the FR DB, we can see the successful refund for order R288734641 in Stripe but they are not registered in the OFN DB. In the OFN DB there's only the original payment, no refunds.

For some reason, the refund is being issued correctly to Stripe but not registered in our database...
I have updated the title of the issue to reflect this finding.

The code

Spree code is taking care of this for us in a class called Processing which is part of the Payment model, the credit! code calls the stripe gateway and then logs the response into spree_log_entries :tada: before persisting the payment (the refund) in the database.

The DB logs

I found all the responses from Stripe to the refund requests the user did in this log table spree_log_entries.
For each payment done with Stripe, we will have the response there (select details from spree_log_entries where source_id = 75145 order by udpated_at asc;).
The response for the first refund is actually a success:

So, I don't understand how we don't have the refund in the payments table:
https://github.com/openfoodfoundation/spree/blob/e10ca1f689b1658040b081939b7523f6fb68895a/core/app/models/spree/payment/processing.rb#L96

No log file for early May

I couldn't find the log files for this old events, we only have logs from 20th May on, this issue happened on the 11th of May... I think logs could have helped us here.

What's next?

We could downgrade to S3 and wait to see if it happens again @RachL ?
It's an edge case but the situation can go unnoticed if the manager hits the refund button twice for example, that leaves us with two refunds on Stripe and none in OFN...

Or I can move back to Dev Ready so that another dev can take a look.

[sauloperez]

Thanks for your investigation @kristinalim and that report @luisramos0 :clap: :clap:

The only thing I can think of is that the payment creation for the first refund failed some validations and so it wasn't persisted. Patching Spree replacing the create call with create! in #credit! will result in a bugsnag notification which will hopefully tell us which one failed. Now it may fail silently.

Then, I think it'd be possible to reproduce the exact create call that may have failed because we have the data: order, payment, credit_amount, etc.

[luisramos0]

ah, yes, nice, let's do that!

[sauloperez]

vaya vayita! I had a play with the data I could infer from the log entries reproducing what Spree does and this is what I found. I'm reproducing it here in case there's something wrong and for you to see the result:

irb(main):001:0> order = Spree::Order.find_by_number 'R288734641'jj
irb(main):003:0> source = order.payments.first
irb(main):010:0> payment_method = source.payment_method # I'm guessing the refund uses the same payment method as the original payment
irb(main):012:0> credit_amount = 8.71
irb(main):013:0> auth = 'XXX' # skipping this just in case it's sensitive information
irb(main):015:0> test = Spree::Payment.new(order: order, source: source, payment_method: payment_method, amount: credit_amount.abs * -1, response_code: auth, state: 'completed')

irb(main):027:0> test = Spree::Payment.new
=> nil
irb(main):029:0> test.valid?
=> false
irb(main):030:0> test.errors
=> #<ActiveModel::Errors:0x00005595acad5e70 @base=#<Spree::Payment id: nil, amount: #<BigDecimal:5595acb0bed0,'-0.871E1',18(36)>, order_id: 954187, created_at: nil, updated_at: nil, source_id: 75145, source_type: "Spree::Payment", payment_method_id: 376, state: "completed", response_code: "re_1GheEwFC9lkZ0AOj4hB40CEz", avs_response: nil, identifier: nil, cvv_response_code: nil, cvv_response_message: nil>, @messages={:Payment=>["translation missing: fr.activerecord.attributes.spree/payment.Credit Card Carte de crédit a expiré"]}>

{:Payment=>["translation missing: fr.activerecord.attributes.spree/payment.Credit Card Carte de crédit a expiré"]} is the bit that matters. It's the second time in a week I see that an expired card bites us. @RachL you should tell the user.

I'm 90% sure this is caused by the validation implemented in https://github.com/openfoodfoundation/spree/blob/fe0a1311abb097bf3ac8001a24246c6cff5ecdbb/core/app/models/spree/payment.rb#L109-L117. It's pretty clear now that we need to solve this in Spree or find out if they did in a future commit.

[RachL]

@sauloperez I'm struggling on something: so the card expired but Stripe still succeeded in refunding the user?

[sauloperez]

ah how stupid! You are right, that doesn't seem very feasible. Even more than that, we don't know when that expiration happened. It could have happened between the date of the refund and today :see_no_evil: I would check with the user anyway. It may bring in some clues.

Anyway, Spree's team found the same solution so I'm just backporting it from the 2-2-0-stable branch to ours.

[Matt-Yorkley]

Moving back to in-dev, see: https://github.com/openfoodfoundation/spree/pull/46#pullrequestreview-434351568

[RachL]

@sauloperez @luisramos0 the same issue just happened again for the same user. Maybe we can check now that we should still have logs?

Hub ID: 922

Order: R851000230

Stripe shows me that they already have refunded 5 times the user, while OFN is still saying nothing happened 😭

[sauloperez]

Ok, I'll take a look now. For the record, I've been working on improving the situation with #5678 but v3 is delaying it.

[sauloperez]

Bingo! we found a feasible explanation!

The order was placed on 2020-06-17, the charge went through successfully but Stripe already told us the credit card was expiring that month in the response

payment_method_details:                                                                                                                
  card:                                                                                                                                
    brand: visa                                                                                                                        
    checks:                                                                                                                            
      address_line1_check:                                                                                                             
      address_postal_code_check:                                                                                                       
      cvc_check: pass                                                                                                                  
    country: FR                                                                                                                        
    exp_month: 6                                                                                                                       
    exp_year: 2020         

The subsequent refunds were successful on Stripe but failed to be persisted on our side because of the credit card being expired. Exactly the same I managed to reproduce in https://github.com/openfoodfoundation/openfoodnetwork/issues/5449#issuecomment-646699893. Now I dug a bit further and the validation error is caused by

      def validate_source
        if source && !source.valid?
          source.errors.each do |field, error|
            field_name = I18n.t("activerecord.attributes.#{source.class.to_s.underscore}.#{field}")
            self.errors.add(Spree.t(source.class.to_s.demodulize.underscore), "#{field_name} #{error}")
          end
        end
        return !errors.present?
      end

https://github.com/openfoodfoundation/spree/blob/fe0a1311abb097bf3ac8001a24246c6cff5ecdbb/core/app/models/spree/payment.rb#L109-L117

as of today, 2020-07-03, the source (the original payment) is invalid because the credit card is indeed expired. Therefore, the refund payment is not valid thus, never persisted. Indeed, trying to reproduce the body of that validation I get:

irb(main):021:0> test_payment.source.errors.each {|field, error| puts "#{field} => #{error}" }
Credit Card => Carte de crédit a expiré

What's more, we don't see any trace of this error because there's no error handling logic in the method responsible for creating the payment record. The fact that the user clicked the button N times confirms this case is not handled. Spree doesn't have a test case for this either, so double confirmation. The user only realizes when we hit the point where Stripe has no money left to refund.

In a nutshell, we desperately need to finish #5678 and then extend #validate_source to account for this scenario, which seems legit to me. We need to confirm that's the legal behavior for an expired credit card. Accept refunds but not payments.

Depending on your workload you might want to resume #5678 if I don't get back to it by Tuesday afternoon. I think I'm becoming a bottleneck here although there's not very much left. Ping me if you do.

[luisramos0]

This specific case is fixed by #5780 :+1: