Page MenuHomePhabricator

Date bug on Aug 31st causing recurring Ingenico donations to process in error
Closed, ResolvedPublic

Description

Recurring Ingenico donations are processing twice:

9448589551-24 processed 8/31
9448589551-25 processed again 9/1

7320050734-10 processed 8/31
7320050734-11 processed again 9/1

icinga alerts are saying:
Notification Type: ACKNOWLEDGEMENT
Service: check_recurring_gc_failures_missed

Details

Related Gerrit Patches:
mediawiki/extensions/DonationInterface : masterRefund "country" argument is option, omit it
wikimedia/fundraising/crm : deploymentFix the 8 contributions which would still re-try based on date bug.
wikimedia/fundraising/crm : masterFix the 8 contributions which would still re-try based on date bug.

Event Timeline

MBeat33 created this task.Sep 1 2016, 1:24 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptSep 1 2016, 1:24 PM
MBeat33 triaged this task as Unbreak Now! priority.Sep 1 2016, 1:26 PM
Restricted Application added subscribers: Jay8g, Luke081515, TerraCodes. · View Herald TranscriptSep 1 2016, 1:26 PM

the issue appears to be mis-setting of the next_sched_contribution_date in the contribution_recur table - I think it relates to the subtle difference between the patch ejegg did for us

https://phabricator.wikimedia.org/rWFCHc54b898d54dc35b6b5bcbb7135801df00d111eb6
and for core

https://github.com/civicrm/civicrm-core/commit/48f50324642fa04a915b8930ad1e2e456f751266

I don't know if the difference was on purpose but I didn't pick it up earlier - the <= vs ==

select * from log_civicrm_contribution_recur where id = 69971;

It appears to have miscalculated when run at 2016-08-31 00:07:57

awight added a comment.Sep 1 2016, 7:41 PM

@MBeat33
Can I help provide lists of affected subscriptions or anything else?

totally! I was just pinging @Eileenmcnaughton about that > a rough total of affected donors would be great

Actually, this started bang on the start of 31 Aug - I think is a date calculation issue not caused by code change but triggered by the advent of a month with 31 days prior to a 30 day month.

1303 recurs affected
SELECT count(*) as c, contribution_recur_id, contact_id, group_concat(receive_date) FROM civicrm_contribution WHERE receive_date > '2016-08-30' AND contribution_recur_id IS NOT NULL AND trxn_id LIKE 'RECURRING GLOBALCOLLECT%' GROUP BY contribution_recur_id having c > 1;

Eileenmcnaughton renamed this task from Civi upgrade causing recurring Ingenico donations to process in error to Date bug on Aug 31st causing recurring Ingenico donations to process in error.Sep 1 2016, 8:34 PM

Change 308027 had a related patch set uploaded (by Eileen):
Fix the 8 contributions which would still re-try based on date bug.

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

Change 308027 merged by jenkins-bot:
Fix the 8 contributions which would still re-try based on date bug.

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

Change 308072 had a related patch set uploaded (by Awight):
Fix the 8 contributions which would still re-try based on date bug.

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

Change 308072 merged by jenkins-bot:
Fix the 8 contributions which would still re-try based on date bug.

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

@Eileenmcnaughton
Do you expect that there are an infinite number of historical occurrences of this bug?

At the moment my money is on this having altered behaviour in some way I don't yet understand.... https://phabricator.wikimedia.org/rWFCHc54b898d54dc35b6b5bcbb7135801df00d111eb6

I think we saw that @MBeat33 DID get told when there was a problem pretty quickly. The data didn't become bad before yesterday from what I can tell

awight added a comment.EditedSep 1 2016, 10:41 PM
create table awight.t144489_duplicate_pairs
    select
        count(*) as c,
        contribution_recur_id,
        contact_id,
        group_concat(receive_date)
    from civicrm.civicrm_contribution
    where
        receive_date > '2016-08-30'
        and contribution_recur_id is not null
        and trxn_id like 'RECURRING GLOBALCOLLECT%'
    group by contribution_recur_id
    having c > 1;

set @base_url = 'https://HOST/civicrm/contact/view/contribution?reset=1&force=1&cid=';

create table awight.t144489_to_refund
    select
        p.display_name,
        p.id as contact_id,
        concat(@base_url, p.id) as civi_url,
        e.email,
        c.receive_date,
        x.gateway_txn_id,
        x.original_currency,
        x.original_amount
    from awight.t144489_duplicate_pairs d
    join civicrm.civicrm_contribution c on c.contribution_recur_id = d.contribution_recur_id
    join civicrm.wmf_contribution_extra x on x.entity_id = c.id
    join civicrm.civicrm_contact p on c.contact_id = p.id
    join civicrm.civicrm_email e on e.contact_id = p.id and e.is_primary = 1
    where c.receive_date > '2016-09-01';
mysql awight -B -e 'select * from t144489_to_refund' > t144489_to_refund.tsv

@MBeat33
smb://filesrv1/fundraising/Tech/T144489/t144489_to_refund.tsv

Thanks @awight that looks perfect. Here are the ones DS canceled manually today, not sure if they need to be removed before running the script:

Line in .tsv filetrx ID
1649448589551-25
434821897420-13
5919435103601-11
687307928929-11
7055490476483-11
743630520923-11
8037320050734-11
8046745362076-11
11043647297338-10

Change 308114 had a related patch set uploaded (by Awight):
Make refund "country" argument optional

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

awight added a comment.EditedSep 2 2016, 1:46 AM
# Snip base transaction IDs into a file suitable for fgrep.
cut -f 6 t144489_to_refund.tsv  | cut -d '-' -f 1 | head +1 > t144489_base_txn_id.txt

LC_ALL=C zgrep -a -F -f ~/t144489_base_txn_id.txt 20160831/GlobalCollect_Recurring_Donations* > ~/t144489_recur_job_lines.txt

grep GET_ORDERSTATUS ~/t144489_recur_job_lines.txt > ~/t144489_get_orderstatus.txt

import re
fields = [
    'MERCHANTREFERENCE',
    'ORDERID',
    'EFFORTID',
    'PAYMENTMETHODID',
    'AMOUNT',
    'CURRENCYCODE',
    'PAYMENTPRODUCTID',
]
f = open('t144489_get_orderstatus.txt')
for line in f.readlines():
    mapped=[]
    for field in fields:
        pattern = '{' + field + '}([^{]+){/' + field + '}'
        matches = re.search(pattern, line)
        if not matches:
            #raise Exception("Couldn't find field in line: " + pattern + " " + line)
            mapped.append("")
        else:
            mapped.append(matches.group(1))
    print "\t".join(mapped)

python search.py  < t144489_do_payment.txt > t144489_details_do.tsv
python search.py  < t144489_set_payment.txt > t144489_details_set.tsv

create table t144489_details (
    merchantreference varchar(255),
    orderid varchar(255),
    effortid int,
    amount int,
    currencycode varchar(255),
    paymentproductid int
);  
load data infile '/home/adamw/work/t144489_details_do.tsv' into table t144489_details fields terminated by '\t';

create table t144489_details_set (
    merchantreference varchar(255),
    orderid varchar(255),
    effortid int,
    amount int,
    currencycode varchar(255),
    paymentproductid int
);
load data infile '/home/adamw/work/t144489_details_set.tsv' into table t144489_details_set fields terminated by '\t';

# Transfer last details over.
update t144489_details d, t144489_details_set d2 set d.paymentproductid=d2.paymentproductid where d.orderid=d2.orderid;

# Remove the already refunded transactions
delete from t144489_details where orderid in ('9448589551','821897420','9435103601','307928929','5490476483','630520923','7320050734','6745362076','3647297338');
awight added a comment.EditedSep 2 2016, 2:07 AM
# Columns formatted for the globalcollect_gateway/scripts/refund.php tool.
create table t144489_refund
    select
        d.orderid as order_id,
        d.merchantreference as merchant_reference,
        d.effortid as effort_id,
        (case paymentproductid
            when 1 then 'visa'
            when 2 then 'amex'
            when 3 then 'mc'
            when 125 then 'jcb'
            when 128 then 'discover'
        end) as payment_submethod,
        d.currencycode as currency_code,
        d.amount/100.0 as amount
    from t144489_details d;

SELECT *
FROM t144489_refund
INTO OUTFILE '/tmp/t144489_refund.csv'
FIELDS TERMINATED BY ','
LINES TERMINATED BY '\n';

... then ready to try running the refund script.

@MBeat33
I'm using orderid 11153649.76200 / ctid 2247088637 as my pilot refund, so please give it extra review. In fact, I tried to double-refund it intentionally in order to test whether this could potentially happen, and happily found that we can only refund once.

Fellow techsen:
In other good news, I was able to sneak a run on payments1004, so the full transcript is logged in the regular payments-globalcollect bucket.

Mentioned in SAL [2016-09-02T02:57:41Z] <awight> Began bulk refund for T144489

Change 308114 merged by jenkins-bot:
Refund "country" argument is option, omit it

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

awight added a comment.Sep 2 2016, 4:01 AM

All 1,294 refunds were successful.

awight added a comment.Sep 2 2016, 3:17 PM

@MBeat33
Strange. At the end of the day I may have attempted and succeeded in double-refunding the 9 that you also refunded in the console. Worth a spot-check at least, sorry for the extra work!

thanks @awight I refunded these 5 probably an extra time in error (the GC console doesn't make it clear which in a series of recurring donations has been refunded, so I wanted to make sure the trx in the list were all set):
238798
238800
238812
238831
238825

awight closed this task as Resolved.Sep 13 2016, 10:36 PM

Closing this - but there is a follow up task

mmodell removed a subscriber: awight.Jun 22 2017, 9:34 PM