Page MenuHomePhabricator

Spike: Orphan logline conspicuously missing
Closed, ResolvedPublic

Description

Grepping for "Done!" lines, I found a gap:

Aug 4 05:15:18 payments1004 orphans: globalcollect_gateway_tr 27169494:398502881 Done! Final results: 0 destroyed via antimessage (called 1 times) 6 rectified orphans 0 errored out 0 false orphans caught Status 25 = 4 Status 20 = 2 Approximately 17 seconds to execute.
Aug 4 05:25:12 payments1004 orphans: globalcollect_gateway_tr 27169543:8017581992 Done! Final results: 0 destroyed via antimessage (called 1 times) 1 rectified orphans 0 errored out 0 false orphans caught Status 25 = 1 Approximately 11 seconds to execute.

This process happens every 5 minutes, so where is 05:20?

My guess is a fatal error, but I don't see any exceptions in /var/log/mw/debug since the DonationQueue anti-renormalization patch went out. Although that logfile doesn't have any timestamps, so who knows what's in there...

In payments.error,

Aug 4 05:20:34 payments1004 orphans: globalcollect_gateway_tr 27169500:5339245354 processResponse Error 21000050 : Blocking validation problems with this payment. Investigation required! {"ffname":null,"country":"JP","currency_code":"JPY","payment_method":"cc","payment_submethod":"jcb","recurring":"","gateway":"globalcollect","utm_source":"B1516_0727_jaJP_dsk_p1_lg_txt_cnt.no-LP.cc","referrer":"https:\/\/ja.wikipedia.org\/wiki\/Facebook"}

The last words in payments-orphan were,

Aug 4 05:20:35 payments1004 orphans: globalcollect_gateway_tr 27169526:6058477389 contribution_id:27169526 - duration:0.5973 - gateway:Global Collect - function:Confirm_CreditCard - vars: - additional:Confirm_CreditCard -

Event Timeline

awight claimed this task.
awight raised the priority of this task from to Medium.
awight updated the task description. (Show Details)
awight subscribed.
awight set Security to None.
awight updated the task description. (Show Details)
awight renamed this task from Orphan logline conspicuously missing to Spike: Orphan logline conspicuously missing.Aug 4 2015, 6:41 AM

Looking at orphans.php, I think I can narrow the failure down to rectifyOrphan, but nothing in the possible crash window between doTransaction( 'Confirm_CreditCard' ) and the next logging call makes any sense, I don't see how it could have caused an error. And no logging about this.

The next step is to make the error logs quieter and split out exceptions into their own stream, with timestamps. Then look for this happening again.

Could not find the issue. Closing until we have more information.