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.

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.

@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

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....?

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

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.

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.

@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

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

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.

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

I split the new donations into a new task: T246710