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.
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.
@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:
- fix the queue consumer to initialize payment_processor_id to 1 for old-API recurring as long as we're using that
- for the records created since 4/24 that have payment_processor_id = 0, update that to 1
- un-cancel the mistakenly canceled subscriptions
- (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.
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.
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.
@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.
@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.
@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?
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.
@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.
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:
- Is it normal for the OrderID number to change month to month for recurring donations in the new integration?
- If so is the MerchantReference number going to increase like #.2, #.3, #.4? Will the initial donation typically be #.2?
- 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.