Page MenuHomePhabricator

Benevity Import Error
Closed, ResolvedPublic

Description

Hi sorry I thought we had avoided any Benevity import issues, we received the large Benevity file for December 2020 and I tried to import the file and received the error message attached.

Screen Shot 2021-01-07 at 12.25.08 PM.png (458×1 px, 29 KB)

I'm happy to divide the file up if needed but wanted to let you know since I haven't seen this message before when importing files of this size.

File size $660k worth of gifts and rows = 6421.

Event Timeline

@RLewis check the above image - I think it's not what you meant to upload

@Eileenmcnaughton thanks for the heads up haha added the correct image now.

@RLewis ok - that looks like the problem Dallas recently fixed to do with the actual file size - let's see how it goes next month

@Eileenmcnaughton I've just tried to upload a file for Benevity with 7000 row, totaling $680k worth of gifts and got this error message:

Screen Shot 2021-02-11 at 3.22.10 PM.png (217×1 px, 64 KB)

I don't think I've seen this error message before. I did divide the file into two files to import and the first file imported fine with no issues.

Let me know if you'd like me to put the files on the server for you.

When I check the Benevity Report in Civi it shows this much for February:

February 2021 4088 $252,256.69 when it should be $680k

Thanks,

@RLewis the csv with the error messages should have the detail about the errors - they are per row - but it gave up after hitting 10 rows in a row with errors

I can see this as the error message Import aborted due to 10 consecutive errors, last error was at row 1471: Duplicate error - existing contribution record(s) have a matching Transaction ID or Invoice ID. Contribution record ID(s) are: 57827712.

@Eileenmcnaughton - shall I put the file with the error messages on the server?

Screen Shot 2021-02-11 at 8.43.36 PM.png (564×1 px, 90 KB)

For the 2381 Ignored rows logged to file. - the message for all the rows in this file was IMPORT_CONTRIB Error limit reached

3846 not imported rows logged to file - the message for all the rows in this file was either Duplicate OR Error: Duplicate error - existing contribution record(s) have a matching Transaction ID or Invoice ID. Contribution record ID(s) are: 57827683 OR Ignored: IMPORT_CONTRIB Error limit reached

I've since imported a few other benevity files for international currency which imported fine, but the files were much smaller.

@Eileenmcnaughton - here's the file path, there are three files:

smb://filesrv1.corp.wikimedia.org/Fundraising/Tech/Major Gifts/Benevity Example/February 2021

@Eileenmcnaughton did you need anything else from me to help with this issue? Can I try and reimport?

@RLewis yes sorry - please try again - the first error is on this contact civicrm/contact/view?reset=1&cid=50372691 and is

Error: Duplicate error - existing contribution record(s) have a matching Transaction ID or Invoice ID. Contribution record ID(s) are: 57827679

  • so that HAS been imported but instead of skipping the row as a duplicate it gave and error - so I would like to see if that happens again

Screen Shot 2021-02-23 at 11.57.46 AM.png (266×1 px, 64 KB)
- this is the import screen I had when it completed the import.

@Eileenmcnaughton I'm not convinced that everything is imported though as the total for Feb in Civi is $623k but the wire amount and the file amount was $680k?

@Eileenmcnaughton it's now up to $671k but I'm unsure of what is missing.

@RLewis so according to that screenshot everything imported except the 20 rows that are in the error file - do they add up to the missing amount?

@Eileenmcnaughton unfortunately not, these 20 were Orgs not already in Civi, so I created the new contacts and reimported. We're up to $691k for February 2021, but I had previously imported the international benevity files on 02/11/2021 and everything for the month should total around $760k. I've gone back and reimported all the international currency files to double check I haven't missed anything and I hadn't missed anything with these files.

@Eileenmcnaughton I went back and reimported the large files with the $680k worth of gifts and everything was imported so I think we're all set. But I'd like some tips on what I did wrong and how I can avoid these issues going forward.

DStrine triaged this task as Medium priority.Mar 2 2021, 9:28 PM

@RLewis when do you get the next file? We could catch up on hangout when you go to import it

@Eileenmcnaughton I got a new file now but I'm waiting for confirmation from finance on the date it was received. Once I have the date I'll schedule a hangout.

I imported this file. It didn't fail for me and all rows are imported now. I did get 4 deadlock errors but not in a row so it finished and I re-imported those 4.

I also tried on staging but hit an unrelated issue that I need to discuss with Dallas / Jeff so I couldn't verify or otherwise there.

So why did I hit and you didn't?

There are 2 reasons I can think of

  1. there was something special about the rows that failed and only them (replicating on staging might have ruled that out)
  2. server contention at the time - I did it a few hours later

Working on the second theory one thing I noticed was that it was slower than I expected - my initial thought was that it was because it was slow on a high valuume donor - 2123835. That donor is not exclueded from our most expensive queries like 19855599 and 12513 are and excluding it might speed it up a bit - more testing on staging (when I sort out the problem- might give us a clue there)

It seems likely that a deep dive into our deadlock handling will help but it might be worth testing at different times of day first - perhaps try very early in your day with the next file?

I'm going to try to talk myself through this error in the hope it can make some sort of sense

  • the error message is

Import aborted due to 10 consecutive errors, last error was at row 1499: Duplicate error - existing contribution record(s) have a matching Transaction ID or Invoice ID. Contribution record ID(s) are: 58388539.

This error is hit in CRM_Contribute_BAO_Contribution::add when the following query returns a result

SELECT id FROM civicrm_contribution WHERE trxn_id = 'BENEVITY 2FL6BF3A2M';

And prevents the same contribution from being created twice.
The found contribution was created at 2021-03-09 20:42:38 and the error occurred at 2021-03-09 20:42:42. The only way I can think of that this happened is that for some reason it retried the creation for some reason. I am trying to think how that could be possible as I can't think of any code of ours that retries after a failure to insert. At the sql level that could happen - but that would be after the create line is attempted.

select 'cont', trxn_id ,log_conn_id, log_date, log_user_id, log_action FROM log_civicrm_contribution WHERE id IN(  58388539, 58388540) UNION select 'extra', gateway_txn_id as trxn_id, log_conn_id, log_date, log_user_id, log_action FROM log_wmf_contribution_extra WHERE entity_id IN(  58388539, 58388540);
+-------+-----------------------------+---------------+---------------------+-------------+------------+
| cont  | trxn_id                     | log_conn_id   | log_date            | log_user_id | log_action |
+-------+-----------------------------+---------------+---------------------+-------------+------------+
| cont  | BENEVITY 2FL6BF3A2M         | 6047dce0a0cff | 2021-03-09 20:42:38 |     3686198 | Insert     |
| cont  | BENEVITY 2FL6BF3A2M_MATCHED | 6047dce0a0cff | 2021-03-09 20:42:38 |     3686198 | Insert     |
| extra | 2FL6BF3A2M                  | 6047dce0a0cff | 2021-03-09 20:42:38 |     3686198 | Insert     |
| extra | 2FL6BF3A2M_MATCHED          | 6047dce0a0cff | 2021-03-09 20:42:42 |     3686198 | Insert     |

Note that ALL the failed contributions are matched by the donor we might want to skip for calc purposes

Ok I maybe found something I didn't quite expect - it looks like the contribution tracking entry was processed after the error was logged - hard to see any significance there though

2021-03-09 20:43:02,641 ERROR   WD contribution-tracking: Beginning processing of                         [info]
2021-03-09 20:43:02,641 ERROR   contribution-tracking message 100624726:
2021-03-09 20:43:02,641 ERROR   {"id":100624726,"contribution_id":"58388539","source_name":"CiviCRM","source_type":"direct","source_
host":"civi1001","source_run_id":4173,"source_version":"unknown","source_enqueued_time":1615322558}

And in the table

MariaDB [drupal]> SELECT * FROM contribution_tracking WHERE id = 100624726\G

  • 1. row ******* id: 100624726

contribution_id: 58388539

  form_amount: NULL
   usd_amount: NULL
         note: NULL
     referrer: NULL
    anonymous: NULL
   utm_source: ..EFT
   utm_medium: civicrm
 utm_campaign: NULL
      utm_key: NULL
payments_form: NULL
       optout: NULL
     language: NULL
      country: US
           ts: 20210303000000
  owa_session: NULL
      owa_ref: NULL

1 row in set (0.001 sec)

@Eileenmcnaughton thanks so much for your clear response here. I will definitely try importing during my morning next time we get a large file and see if the issue is replicated. Also our internet here is absolutely awful, would that have any impact at all when I try to import versus you importing?

I can't think of a way in which the internet being slow could lead to that specific error

Change 672584 had a related patch set uploaded (by Eileen; owner: Eileen):
[wikimedia/fundraising/crm@master] Exclude Apple from wmf_donor total

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

@EYener I have pushed up a patch to exclude Apple from our wmf_donor totals as with our other largest matching gifts donors.

So my thoughts on this are that we should try removing Apple per ^^ & see if it makes a difference. Otherwise we might be better to tie this into a big overhaul (whereby we queue the donations for processing - which would be part of drupal 8 upgrade prep too)

I did think about trying a mysql lock but it got weird pretty quickly

Change 672584 merged by jenkins-bot:
[wikimedia/fundraising/crm@master] Exclude Apple from wmf_donor total

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

@Dwisehaupt can you please load the trigger file drupal/sites/all/modules/wmf_civicrm/scripts/contribution_triggers.mysql

It just has one very small change - see

https://gerrit.wikimedia.org/r/c/wikimedia/fundraising/crm/+/674460/

@RLewis I've made one change & the other will be made soon - basically

  1. the only thing I can think of to explain the error you hit was 2 processes being kicked off at the same time by your browser
  2. I've added code so that if that if that appears to be happening it will skip ahead and keep trying with later contributions
  3. if that happens you should see a message saying that it did - in which case you should re-upload the file at the end - note that it rattles through pretty quickly when the contributions have already been imported so that re-upload should be much quicker
  4. in addition we will no longer be calculating all the wmf_donor stuff for Apple which should speed it up at least a bit

@Eileenmcnaughton I have applied the triggers. I see the change that you made but also some removals of 'COLLATE utf8mb4_bin' on some of the triggers. I have to assume this is expected cleanup from stopgaps put in during the utf8mb4 conversion. I have the before and after status captured so I can provide the diff if you would like to review.

@Eileenmcnaughton FYI I imported a Benevity file this am and reported no error issues. I'll have another larger file to import next week and i'll add to this ticket if there's any issues.