Page MenuHomePhabricator

Investigate why Ingenico donation did not recur on 6/14
Closed, ResolvedPublic4 Story Points

Description

Ingenico 5110919531 is a recurring donation created on May 14th. It looks like it did not attempt to process a second time, as there's no EffortID past 1 at Ingenico. It shows as canceled in Civi at cid=4055788, though it was not canceled by a human agent. Can we determine why this did not process? The donor is following up, and there's no indication that the error is from their card. I'd like to have confidence that when we invite them to create a new recurring the same thing won't happen.

Event Timeline

MBeat33 created this task.Jul 11 2018, 2:11 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJul 11 2018, 2:11 PM
mepps added a subscriber: mepps.Jul 11 2018, 9:24 PM

Hmm so the question is why was this cancelled. I'm seeing a few of these from that date range but haven't found a common cause.

Ejegg added a subscriber: Ejegg.Jul 11 2018, 11:52 PM

Ut-oh, there may be a bunch more of these!

I'm seeing a new type of error in the logs for the DO_PAYMENT requests we use in our recurring charges:
<RESULT>NOK</RESULT><CODE>400300</CODE><MESSAGE>REQUEST (MERCHANTID=XXXX, ORDERID=5110919531, EFFORTID=1, ATTEMPTID=) NOT FOUND</MESSAGE>

They seem to have started on 5/24/2018. Looking to see if we deployed something funky then.

Thanks, @Ejegg Do you know if that error is related to the donors' cards? Should we hold off on inviting anyone affected to make a new recurring donation?

Ejegg added a comment.Jul 19 2018, 1:09 AM

@MBeat33 oh gosh, it looks like this is affecting ALL recurring credit card donations started since 4/24.

I think the issue is with this patch: https://gerrit.wikimedia.org/r/424141. That was deployed on 4/24, one month before the errors started.

Globalcollect recurring donations have been misusing a field called payment_processor_id to track the installment count (it's actually supposed to be the ID of the payment processor account configured in CIvi). We send that number to their API as EFFORTID. The first payment, charged via payments-wiki while the donor is at our site, should have EFFORTID=1. The second payment, charged a month later via the recurring job, should have EFFORTID=2.

That patch updated the way we create the records in civicrm_contribution_recur so that we could handle tokenized recurring for the new Ingenico API. This included using the payment_processor_id field correctly, at least for recurring payments coming from the new API. I haven't unpacked it all yet, but I think it had the side effect of setting that value to 0 for recurring cc donations added via the old API, rather than 1. That means that after a month when the recurring job tries to make the next payment, it sends EFFORTID=1 instead of EFFORTID=2.

I think it'll be a straightforward fix:

  1. fix the queue consumer to initialize payment_processor_id to 1 for old-API recurring as long as we're using that
  2. for the records created since 4/24 that have payment_processor_id = 0, update that to 1
  3. un-cancel the mistakenly canceled subscriptions
  4. (maybe) as the un-canceled subscriptions are charged over the course of the next month, figure out how to tag all their next donations as 'recurring-restarted' to get the extra 'oops' text into the thank you letter.

Change 446710 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Fix processor_id for old-style recurring

https://gerrit.wikimedia.org/r/446710

Ejegg triaged this task as Unbreak Now! priority.Jul 19 2018, 1:55 AM
Ejegg claimed this task.
Restricted Application added subscribers: Liuxinyu970226, TerraCodes. · View Herald TranscriptJul 19 2018, 1:55 AM

Change 446710 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Fix processor_id for old-style recurring

https://gerrit.wikimedia.org/r/446710

Ejegg added a comment.EditedJul 19 2018, 3:11 AM

@MBeat33 the job really should be automatically reporting these failure numbers someplace: T199390

I'm not sure how you usually track failures, but these seem to have failed in a way that doesn't leave a trace at the GC console. I guess re-using the effort ID doesn't create any new records there, just a failed API response. The only UI-visible thing I can think of would be the elevated number of canceled subscriptions in Civi, but I'm not even sure how you'd search for that.

Ejegg added a comment.Jul 19 2018, 3:31 AM

OK @MBeat33 , I deployed step 1) of the fix, so old-GC-API / WebCollect subscriptions created from now on should recur correctly. I'll work on 2, 3, and 4 tomorrow.

Please let the donor know we will try to restart the subscription on our own - they don't need to create a new one.

Side note: it turns out I've been slandering the original coder of our recur module - they weren't misusing the payment_processor_id field, they were using the processor_id field in a totally normal way and I got the two fields confused. Sorry!
I do wish those field names were a bit more distinguishable.

Great, many thanks for the update and the fixes, @Ejegg

Change 446883 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Fix processor_id for subscriptions not yet canceled

https://gerrit.wikimedia.org/r/446883

Change 446883 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Fix processor_id for subscriptions not yet canceled

https://gerrit.wikimedia.org/r/446883

Ejegg added a comment.Jul 19 2018, 7:27 PM

@MBeat33 all the WebCollect subscriptions created in the past month (not yet canceled) have been fixed and should recur just fine over the next 30 days. There are still 663 subscriptions created between 4/24 and 6/18 that are in 'canceled' state, and have missed at least 1 installment, including the one that inspired this ticket. Currently working on un-canceling those and making it so they get the RecurringRestarted tag when they get charged.

Change 446979 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Add RecurringRestartedUncharged tag

https://gerrit.wikimedia.org/r/446979

Change 446980 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Generalize get_tag_names util, move to wmf_civicrm

https://gerrit.wikimedia.org/r/446980

Change 446983 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Use RecurringRestartedUncharged tag in charge

https://gerrit.wikimedia.org/r/446983

Change 446979 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Add RecurringRestartedUncharged tag

https://gerrit.wikimedia.org/r/446979

Change 446980 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Generalize get_tag_names util, move to wmf_civicrm

https://gerrit.wikimedia.org/r/446980

Change 446983 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Use RecurringRestartedUncharged tag in charge

https://gerrit.wikimedia.org/r/446983

Change 446993 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Fix remaining misrecorded contribution_recur records

https://gerrit.wikimedia.org/r/446993

Change 446993 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Fix remaining misrecorded contribution_recur records

https://gerrit.wikimedia.org/r/446993

Change 447006 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Fix next charge date for canceled subscriptions

https://gerrit.wikimedia.org/r/447006

Change 447006 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Fix next charge date for canceled subscriptions

https://gerrit.wikimedia.org/r/447006

@MBeat33 OK, I think everything is fixed. The canceled subscriptions have been un-canceled and rescheduled for their next cycle_day. If they started on the 1st-19th, they will be charged in August. If they started on the 20th-31st, they will be charged next in July. In addition, the contribution_recur records have been given a new tag RecurringRestartedUncharged, that should add the RecurringRestarted tag to the first contribution created after the hiatus.

Thank you, @Ejegg, and I appreciate the explanation of the restart timings.

Ejegg closed this task as Resolved.Jul 23 2018, 5:09 PM
MBeat33 reopened this task as Open.Aug 3 2018, 7:28 PM
MBeat33 added a subscriber: Ppena.

@Ejegg I'm reopening this, as it looks like these restarted recurring donations are not settling at Ingenico. They do show as settled in Civi, but at Ingenico they get to status 800, and then drop back down to status 190 SETTLEMENT REJECTED.

There are 119 of these. Samples are Order IDs 380844346, 400174014, 712250785, 1026134918. I can put the spreadsheet on the server if that's helpful.

@krobinson first noticed this while following up with donor cid=26405662. We canceled his recurring donation at his request before the batch restart. When the batch restarted, the next Order ID 3503848824 reached Civi but reverted to status 190. Now he'd like us to refund the final donation, but at the console it looks like we never received the funds.

I will follow up with Ingenico to see how these funds will make it back to his bank, maybe they have already. But is there anything we can do to make the rest of these recurrings settle fully at Ingenico?

Restricted Application added a subscriber: Pcoombe. · View Herald TranscriptAug 3 2018, 7:28 PM
Ejegg added a comment.Aug 6 2018, 7:40 PM

Reassuring go-ahead for Wednesday's test: let's find at least one good recurring donation that we WERE able to charge, maybe not one of these.

Ejegg added a comment.Aug 9 2018, 7:34 PM

So, there are at least 7 recurring donations from the initial test on 5/11 that we were able to charge successfully. Not a great rate, but it shows that it's theoretically possible to tokenize after the fact.

select * from civicrm_contribution
where contribution_recur_id in (
select cr.id from civicrm_contribution_recur cr
inner join civicrm_contribution cc on cc.contribution_recur_id=cr.id
where cr.payment_token_id is not null
group by cr.id
having count(*) > 1
);

@MBeat33 Looking at the sample order IDs you give there makes me think there's a separate problem. 380844346, 400174014, 712250785, 1026134918 are all order IDs I'd expect from the old WebCollect integration. The order IDs for Ingenico Connect all start with 4 and some zeros, like 4000001065 or 4000010380.

Ejegg added a comment.Aug 9 2018, 7:48 PM

@MBeat33 I looked at the last nightly charge jobs for 380844346, 400174014, 712250785, and 1026134918, and they all look totally normal. Our DO_PAYMENT call comes back with RESULT OK, our GET_ORDERSTATUS call comes back with STATUSID 600, then our SET_PAYMENT call comes back with RESULT OK.

Ejegg added a comment.Aug 9 2018, 10:02 PM

@MBeat33 want to put a csv file of order IDs on the server? I think I can come up with a batch query to sort out if any of them are related to the original group we tried to fix in this ticket.

Sure thing, @Ejegg it's called GC190sJul1-Aug9.csv in Fundraising/Donor Services

MBeat33 added a comment.EditedAug 14 2018, 2:40 PM

Hi @Ejegg For Ingenico Webcollect recurring 6788825229, we canceled the recurring function in cid=21950455 on 2018-07-11 03:02:12 , but the donation processed again on August 9th, 2018 7:01 AM. We've canceled it again in Civi, and refunded the extra donation, but do you know why this happened? Is this related to the deployment on 4/24/2018, and if not should I spin it off into a separate Phab task?

Also, the recurring donation for cid=26431023 looks kind of curious:

  1. Is it normal for the OrderID number to change month to month for recurring donations in the new integration?
  2. If so is the MerchantReference number going to increase like #.2, #.3, #.4? Will the initial donation typically be #.2?
  3. Also, the donor PII is incomplete for the second attempt: if you click into the details for 57995299.3, there is no email address listed - just fyi in case continuity of donor details is possibly not happening.

Change 452867 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Add personal details to repeat payment attempts

https://gerrit.wikimedia.org/r/452867

Hi @MBeat33, of the payments in the CSV, only one of them is from the new integration:
Order ID 4000012878 / Merchant Reference 58116445.1

Change 452867 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Add personal details to repeat payment attempts

https://gerrit.wikimedia.org/r/452867

@MBeat33 Are the various problems listed on this ticket resolved? If there's more to do on any of them, let's break it out into a new ticket.

mepps added a comment.Sep 13 2018, 8:33 PM

@Ejegg can we close this?

I'm going to go ahead and close it. Seems like at this point any additional work should be under a new ticket as mentioned above.

XenoRyet closed this task as Resolved.Sep 17 2018, 7:23 PM
DStrine set the point value for this task to 4.Sep 18 2018, 8:24 PM