Page MenuHomePhabricator

Ingenico transactions stuck at 600 without fraud scores
Closed, ResolvedPublic

Description

(was "Transactions stopped for Fraud are unscored" )

Since 12/2 I am seeing an increasing pattern of transactions stopped for fraud that are not being scored at all or are only partially scored. On 12/2 volume it was the case on ~12 out of 70 transactions. On 12/3 I am seeing this being the case on ~40 out of 170 transactions. I assume this is due to the credit balance with Maxmind/Minfraud which is being addressed (per Erika, by Thurs 12/5 or so) but I thought I would raise it in case it is related to something else.

Event Timeline

EMartin created this task.Dec 4 2019, 12:22 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptDec 4 2019, 12:22 AM
EBjune added a subscriber: EBjune.Dec 4 2019, 3:50 AM

The credit balance still has 789,697 minFraud scoring credits left (as of 12/3 7:49PM PST), so the balance should not be the problem.

Ejegg added a subscriber: Ejegg.Dec 4 2019, 5:29 PM

We apply all of our in-house filters first, then skip the MinFraud check if we've already decided not to process the donation.

Can you paste in a few examples of contribution tracking IDs for ones that seem to be missing MinFraud?

Some recent examples from 12/4: 73143616.1, 73137282.1, 73091579.1, 73080482.1,73080991.1,73070725.1,73073754.1. Issue started on 12/2.

In many cases they are missing more than minfraud. Also missing our
checks. See examples. Thanks for looking at this.

XenoRyet added a subscriber: XenoRyet.EditedDec 4 2019, 6:18 PM

@EMartin could you give me some example donations, or point me at a list of them somewhere? I'll dig around the logs and see what I can find.

Edit: Nevermind, just saw the post above with the examples. I hadn't refreshed the page.

Hi, I put a few in the Phab task earlier. Please let me know if you need
more. https://phabricator.wikimedia.org/T239769

Ejegg added a comment.Dec 4 2019, 7:29 PM

We didn't stop any of those for fraud - they're all listed with a near-zero risk score and validation_action=process. What made them appear as stopped for fraud to you?

I pulled them out of Ingenico's console where I search for anything with a
status 600, usually from the prior day to give things time to settle.
Oddly, I haven't seen these unscored transactions appear previous to
12.2.2019....?

Ejegg added a comment.Dec 4 2019, 9:06 PM

Ahh, while our fraud filters are one way things stop at 600, they're not the only way. If there's an error redirecting the user to our site, or if our API calls to capture / approve the payment fail, that can also leave the payment in limbo. I'll take a look at the logs to see if these donors all got back to our site and whether they are among the people affected by those sporadic API errors.

I see....I'm settling those caught where I can but the volumes are getting
too big to capture all of those at 0 any longer...that's a good tidbit to
know that it may be indicative of an API error. Learn something new every
day around here. Thanks

More of these 600's appearing in the fraud search today 12.5: 73517561.1
73485102.1
73484895.1
73484088.1
73516052.3
73481987.1
73480663.1
73515520.2
73514644.1
73513909.1

Ejegg added a comment.Dec 5 2019, 8:38 PM

OK, so most of these people got back to payments-wiki with a dead session. Not sure if that means our session storage is filling up or if it's just browser quirks.

73485102.1 - got back to payments with dead session
73484895.1 - got back to payments with dead session
73484088.1 - got back to payments with dead session
73516052.3 - got back to payments with dead session
73481987.1 - got back to payments with dead session
73480663.1 - got back to payments-wiki in frame, loaded framebuster script, doesn't seem to have reloaded in top frame
73515520.2 - got back to payments-wiki with dead session
73514644.1 - never got back to payments-wiki
73513909.1 - got back to payments-wiki with dead session

Will now investigate whether the orphan rectifier tried to do anything to push these payments through. It doesn't look like there's too bad a backlog of pending donations for it to process (just 1144 rows in the pending table with gateway=ingenico) so it's not a matter of being too backed up.

Ejegg added a comment.Dec 5 2019, 9:08 PM

73485102.1 - orphan rectified failed because it was trying to warn us of low MinFraud queries and hit a codepath that doesn't work under Civi.
73484895.1 - looks weird in the orphan rectifier logs - rectified with result (emtpy array) and has no contrib ID.
73484088.1 - looks weird in the orphan rectifier logs - rectified with result (emtpy array) and has no contrib ID.
73516052.3 - orphan rectified at 17:39:59, stored as contrib ID 41561786
73481987.1 - looks weird in the orphan rectifier logs - rectified with result (emtpy array) and has no contrib ID.
73480663.1 - looks weird in the orphan rectifier logs - rectified with result (emtpy array) and has no contrib ID.
73515520.2 - orphan rectified at 17:39:08 UTC and stored with contrib ID 41561566
73514644.1 - was pushed through by orphan rectifier at 17:38:54 UTC and stored with contrib ID 41561515
73513909.1 - pushed through via the orphan rectifier at 17:38:27 UTC (maybe after you listed it) and is stored as contribution ID 41561415

So about half of them got rectified a bit later - maybe just search for 600 status that's older than two hours?

I've turned on debug logging for the ingenico orphan rectifier in the hopes of understanding better the ones that log a result of (empty array).

Hi Elliott, The examples I sent were from yesterday so definitely longer
than 2 hours delayed.

Ejegg added a comment.Dec 5 2019, 10:41 PM

@EMartin I can look up yesterday's examples too, but if you search in the Ingenico console now I believe you will see 73513909.1, 73514644.1, 73515520.2, and 73516052.3 out of status 600.

@Ejegg
More examples from yesterday to chew on:
73514644.1 US USD 5.35 12/5/19 17:30
73515520.2 US USD 5.35 12/5/19 17:29
73513909.1 GB GBP 10.4 12/5/19 17:25
73513825.1 US USD 20.8 12/5/19 17:23
73513305.1 US USD 17.01 12/5/19 17:21
73511980.1 US USD 10.4 12/5/19 17:18
73510741.1 US USD 52 12/5/19 17:14
73508868.2 US USD 3.1 12/5/19 17:12
73508578.2 CA CAD 20.8 12/5/19 17:09

Ejegg renamed this task from Transactions stopped for Fraud are unscored to Ingenico transactions stuck at 600 without fraud scores.Dec 6 2019, 9:51 PM
Ejegg triaged this task as Medium priority.
Ejegg moved this task from Backlog to Doing on the Fundraising Sprint X-rays board.
Ejegg updated the task description. (Show Details)
Ejegg claimed this task.Dec 7 2019, 11:35 PM
Ejegg removed Ejegg as the assignee of this task.

Current examples from 12.8
74199693.1
74198321.2
74177728.1
74012707.2
74011082.1
73779706.1
73778693.1
73778875.1
73777604.1

Ejegg claimed this task.Dec 10 2019, 12:31 AM
Ejegg added a comment.Dec 11 2019, 2:10 AM

For at least one of these, it looks like the donor found a way to enter their card info a second time after entering the wrong expiration date. In the logs for 74011082.1, I see the donor coming back to our site and our status query comes back as 'failed'. On the Ingenico console, I see they made a second attempt a minute later under the same merchant reference ID. I'm guessing they were on safari and got the full redirect, so when they saw the error on our side they were able to use the back button to see the credit card form again.
Our site saw the 'failed' status for the first attempt and passed that failure along to Civi, which wiped out the 'pending' entry. Then when the donor came back from the second attempt, our site saw it as a repeat processing attempt (since it had the same merchant reference ID) and didn't bother to ask for the status again.
Maybe we should only skip repeat processing when we have actually captured a payment?

Change 556453 had a related patch set uploaded (by Ejegg; owner: Ejegg):
[wikimedia/fundraising/crm@master] Log failure reason in orphan slayer

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

OK, most of the ones from the 5th and 6th which did not involve the user clicking the back button would have been due to the hosted checkout session being too old by the time we checked on it. I see 1,959 orphan rectification attempts ending in 'Error 1010: UNKNOWN_HOSTED_CHECKOUT_ID.' on the 5th and 2,901 ending in that on the 6th. I haven't seen any of that error since.

Potential fix: run the orphan rectifier more often during English campaign, so checkouts aren't timed out before we get to them?

@EMartin are you still seeing a lot of these? Of the three causes I've seen, two don't seem to be an issue any more. The third (donors using the back button after a failed card entry) will take a bit of work to deal with.

Elliott, I was thinking about this....I am actively settling some of these
orphans to try to recover them, along with some of the legitimate 600's
stopped for fraud. Am I clouding the picture for you at all while you try
to diagnose this? I've settled dozens in the last week.

No, I only saw 3 orphans today out of 68 which I notated in the task. As
the volume is lowering, so are the orphans. I like your idea of running
the rectifier more during high volume events.

Ejegg added a comment.Dec 12 2019, 3:11 AM

Am I clouding the picture for you at all while you try to diagnose this?

Thanks for thinking of that! It's OK to keep resolving them. I did get a bit confused by one at first, but the Ingenico console makes it pretty easy to see the history of a transaction, so I can tell the difference between ones you've manually resolved and ones the orphan rectifier catches.

current examples are far fewer as of 12.10 volume which was reduced only 3 out of 68 stopped transactions:74887627.1,
as of 12.11 I am seeing 7 out of 70 orphans not rectified. I'll close this per our stand up today that this seems to be volume related and maybe we can just run the orphan rectifier more often during peak periods?

Change 556453 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Log failure reason in orphan slayer

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

Ejegg closed this task as Resolved.Jan 6 2020, 8:14 PM
EMartin reopened this task as Open.Mar 2 2020, 7:52 PM

Hi all,
I am seeing a number of orphan's NOT rectified during the Sweden campaign. This is ala the Big English trend I spotted above. I am reopenning this as I suggest it's worth revisiting this before BE2020 as this problem scales with volume and impacts valid donors. Recent examples from Sweden in the last few days:

79388584.2 SE SEK 50 3/1/20 16:53 y past 79388584.2
79388254.1 SE SEK 208 3/1/20 13:51 y past 79388254.1
79388173.1 SE SEK 500 3/1/20 12:59 y past 79388173.1
79384824.1 SE SEK 104 2/29/20 17:50 y past 79384824.1
79380244.1 SE SEK 53 2/28/20 16:01 y past 79380244.1
79380154.1 SE SEK 208 2/28/20 15:35 y past 79380154.1
79378894.1 SE SEK 100 2/28/20 12:51 y past 79378894.1
79372835.1 SEK SEK 53 2/27/20 20:29 y 79372835.1
79372483.1 SEK SEK 312 2/27/20 19:42 y past 79372483.1
79372070.1 SEK SEK 53 2/27/20 19:04 y past 79372070.1
79370727.1 SEK SEK 200 2/27/20 17:20 y past 79370727.1
79370675.1 SEK SEK 200 2/27/20 17:12 y past 79370675.1
79370188.1 SEK SEK 100 2/27/20 16:41 y past 79370188.1
79367543.1 SEK SEK 104 2/27/20 15:49 y past 79367543.1
79368612.1 SEK SEK 53 2/27/20 14:56 y past 79368612.1
79367944.1 SEK SEK 104 2/27/20 14:14 y past 79367944.1
79367028.1 SEK SEK 520 2/27/20 13:27 y past 79367028.1
79366901.1 SEK SEK 30 2/27/20 13:20 y past 79366901.1
79366634.1 SEK SEK 104 2/27/20 13:09 y past 79366634.1

DStrine added a subscriber: DStrine.Mar 2 2020, 8:24 PM

I split the new donations into a new task: T246710

DStrine closed this task as Resolved.Mar 2 2020, 8:24 PM