Closed Upperholme closed 4 years ago
3 Dec 2019: Were you on 1.8 then, or 1.9beta2 - not sure when you upgraded to 1.9x? Note that a database upgrade was required by 1.9 (i.e. part of the extension upgrade process), but I don't think that's your problem.
It's complaining that there's no contact_id
in the API call Contribution.repeattransaction. Chasing back where that comes from:
The Payment Confirmed webhook sends a GoCardless subscription ID like SB0000000000001
This should match a Recurring Contribution record, and your logs suggest to me that this is found, since otherwise there would be an exception before the bit shown in your logs.
The contact_id
of that Recurring Contribution record is used for the new contribution template.
It then looks to see if there's a Pending Contribution for that Recurring Contribution (this is the case for the first contribution ever). This is not the case for the logged entry you've shared.
So then we add some other data to the contribution template (membership_id
, invoice_id
, the source
from the original Contribution, the payment_instrument_id
from the processor, and status Pending) - but we do not change or unset contact_id
. Finally, it uses the Contribution.repeattransaction
API to record the contribution.
That API is finding a missing contact_id
for some reason.
(I realise none of this is an answer to your problem, I'm just logging my investigation work.)
You may want to join https://chat.civicrm.org/civicrm/channels/gocardless
The Payment Confirmed webhook sends a GoCardless subscription ID like SB0000000000001
I assumed that this would be the case, as I see no other way for Civi to be able to match the Payment Confirmed webhook to any given recurring payment in Civi. However, looking at the content of the webhook sent by GC, I see no subscription ID mentioned. It seems to include only an event ID and payment ID, neither of which are of help to Civi.
The Payment Created webhook includes the subscription ID (which would enable Civi to link it to an existing recurring contribution), and a payment ID (which would enable Civi to subsequently match a Payment Confirmed webhook to the payment. But from the GC extension log I can clearly see that the Payment Created webhook is ignored (as confirmed by the README).
You're right. The payments.confirmed GC webhook provides a payment ID (like PM0000000001). This extension uses the GC API to look that up and obtain the subscription ID (SB00000000001
). If the payment coming in does not have a subscription, you'd see "Ignored payment that does not belong to a subscription." in the logs.
I can't account for this and I can't repeat it. I've checked three other sites and it's not happening on any of those. I can't immediately see that this would be related to the 1.9 - 1.91 gap, either, since that's an 12 day window max, and it's after the time things stopped working for you.
More data would be needed. Do you have access to the command line cv program? Otherwise use the apiv3 explorer.
Take one example where a payment was confirmed at GC but failed to be logged in Civi. Check if the payment exists in CiviCRM:
cv api Contribution.get trxn_id=PM1234567890
I'm assuming it does not.
Look up the subscription ID using the GC website for that payment. Then look up the recurring contrib for that:
cv api ContributionRecur.get processor_id=SB9876543210
There should be one found. It should (must?!) have a contact_id
.
Note the record ID for this contribution recur row (the id
field, NOT the contact_id
) it will be an integer, e.g. 12345), and look up previously Completed Contributions that belong to it with
cv api Contribution.get contribution_recur_id = 12345 contribution_status_id=1
If there are none - I think this is a legit edge case that's perhaps not covered by the current release.
OK. The first one I can find that failed and generated an error gives me no existing payment in Civi, and checking in the GC interface I can get a related subscription ID. Using that I find the recurring contribution record. The final cv command you've posted gives me a list of lots of contributions, from other people, so I'm checking that, but in the Civi UI I can see that the person linked to the subscription ID doe indeed have successful previous payments recorded.
Using:
cv api Contribution.get sequential=1 return="trxn_id" contribution_recur_id=25
I get the other contribution made by that contact using the same mandate (it's an annual payment).
So for some reason the extension doesn't seem to be getting the subscription id from GC or if it is, it isn't then able to identify the contact id.
Sorry, I think I accidentally put spaces around the =
, it should have been more like:
cv api Contribution.get contribution_recur_id=12345 contribution_status_id=1
contribution_status_id
of 1
Yes, the other contribution that is linked to that subscription has
"contribution_status_id": "1",
I'd add something like this (untested), resend the webhook, then remove this code again. (or comment it out).
CRM_Core_Error::debug_log_message("Webhook $this->now Upperholme:\n" . json_encode(['gc_payment_id' => $payment->id, 'recur' => $recur, 'contribution' => $contribution], JSON_PRETTY_PRINT), FALSE, 'GoCardless', PEAR_LOG_INFO);
Just before handleRepeatTransaction()
in CRM/GoCardless/Page/Webhook.php
e.g. here
I'd also add
CRM_Core_Error::debug_log_message("Webhook $this->now Upperholme2:\n" . json_encode(['recur' => $recur, 'contribution' => $contribution], JSON_PRETTY_PRINT), FALSE, 'GoCardless', PEAR_LOG_INFO);
on the line before the repeattransaction call in CRM/GoCardless/Page/Webhookphp
e.g. line before here
Then in the dedicated GoCardless log file we can see exactly what's being picked up. From what you have said, we would expect to see the following in the bit tagged Upperholme
gc_payment_id
to match the paymentID from the webhook body line (e.g. PM0065AZ7SD4ZH
in your original post)recur
to exist and to have a contact_id
and to have the processor_id
of the subscription, and to have a contribution_status_id
that corresponds to In Progress
contribution
to include the contact_id
from the recur
record and a trxn_id
that matches the payment id.is_test
field, which should be 1 for the recur
and the contribution
if this is a test record, or 0 otherwise.And in the bit tagged Upperholme2: you'd expect the recur to be the same as ↑ and the contribution
to still have its contact_id
.
I suspect that the issue is to do with the new code around finding the "template contribution" to use in the repeattransaction call.
The GoCardless extension uses the first Completed contribution related to the recurring contribution. The new core code does two: first it checks for a "template" contribution - I don't think these have been implemented yet (cv api Contribution.getcount is_template=1
probably returns zero). Then if that's not found, it picks the last contribution for that contrib recur record.
This means there's possibly three sources of data for the new contribution. The new core code takes the contact_id
from whatever it found for the template contribution. This could be where it's going wrong, perhaps. Anyway, the above will check what this extension is passing into the core Contribution.repeattransaction API, so that's probably where to start.
That's brilliant. Thanks for taking the time to look at this. I'll check this out ASAP and feed back.
Here's what got into the log file:
Feb 03 17:16:10 [info] Webhook 2020-02-03:17:16:10 body:
{"events":[{"id":"EV00X8QPM2JSHN","created_at":"2019-12-10T11:05:33.240Z","resource_type":"payments","action":"confirmed","links":{"payment":"PM00676Z9K01P6"},"details":{"origin":"gocardless","cause":"payment_confirmed","description":"Enough time has passed since the payment was submitted for the banks to return an error, so this payment is now confirmed."},"metadata":{}}]}
Feb 03 17:16:10 [info] Webhook 2020-02-03:17:16:10 headers:
{"Content-Length":"376","Host":"platform6.coop","Connection":"close","Webhook-Signature":"32123d6a89f1e239b6472b977b6e88230136338e140dc6ea9ce22d6cd3899385","Content-Type":"application\/json","Origin":"https:\/\/api.gocardless.com","User-Agent":"gocardless-webhook-service\/1.1","Accept":"*\/*","Accept-Encoding":"gzip;q=1.0,deflate;q=0.6,identity;q=0.3","Authorization":""}
Feb 03 17:16:11 [info] Webhook 2020-02-03:17:16:10 Upperholme:
{
"gc_payment_id": "PM00676Z9K01P6",
"recur": {
"id": "25",
"contact_id": "13",
"amount": "50.00",
"currency": "GBP",
"frequency_unit": "year",
"frequency_interval": "1",
"start_date": "2018-12-07 00:00:00",
"create_date": "2018-12-02 10:25:06",
"modified_date": "2018-12-10 11:30:16",
"processor_id": "SB0004PFTEMJ9S",
"trxn_id": "SB0004PFTEMJ9S",
"invoice_id": "09cce6565ede5140310055635f59710f",
"contribution_status_id": "5",
"is_test": "0",
"cycle_day": "1",
"next_sched_contribution_date": "2019-12-07 00:00:00",
"failure_count": "0",
"auto_renew": "1",
"payment_processor_id": "3",
"financial_type_id": "2",
"payment_instrument_id": "6",
"is_email_receipt": "1",
"contribution_type_id": "2",
"next_sched_contribution": "2019-12-07 00:00:00"
},
"contribution": {
"total_amount": "50.00",
"receive_date": "2019-12-09",
"trxn_date": "2019-12-09",
"trxn_id": "PM00676Z9K01P6",
"contribution_recur_id": "25",
"financial_type_id": "2",
"contact_id": "13",
"is_test": 0,
"is_email_receipt": 0
}
}
Feb 03 17:16:12 [info] Webhook 2020-02-03:17:16:10 Upperholme2:
{
"recur": {
"id": "25",
"contact_id": "13",
"amount": "50.00",
"currency": "GBP",
"frequency_unit": "year",
"frequency_interval": "1",
"start_date": "2018-12-07 00:00:00",
"create_date": "2018-12-02 10:25:06",
"modified_date": "2018-12-10 11:30:16",
"processor_id": "SB0004PFTEMJ9S",
"trxn_id": "SB0004PFTEMJ9S",
"invoice_id": "09cce6565ede5140310055635f59710f",
"contribution_status_id": "5",
"is_test": "0",
"cycle_day": "1",
"next_sched_contribution_date": "2019-12-07 00:00:00",
"failure_count": "0",
"auto_renew": "1",
"payment_processor_id": "3",
"financial_type_id": "2",
"payment_instrument_id": "6",
"is_email_receipt": "1",
"contribution_type_id": "2",
"next_sched_contribution": "2019-12-07 00:00:00"
},
"contribution": {
"total_amount": "50.00",
"receive_date": "2019-12-09",
"trxn_date": "2019-12-09",
"trxn_id": "PM00676Z9K01P6",
"contribution_recur_id": "25",
"financial_type_id": "2",
"contact_id": "13",
"is_test": 0,
"is_email_receipt": 0,
"original_contribution_id": "31",
"membership_id": "32",
"invoice_id": "PM00676Z9K01P6",
"source": "",
"payment_instrument_id": 6,
"contribution_status_id": "Pending"
}
}
Feb 03 17:16:12 [error] Webhook 2020-02-03:17:16:10 Failed event. Reason: failed to load related objectsMandatory key(s) missing from params array: contact_id
#0 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Contribute/BAO/Contribution.php(2581): civicrm_api3('Contribution', 'create', Array)
#1 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Contribute/BAO/Contribution.php(4501): CRM_Contribute_BAO_Contribution::repeatTransaction(Object(CRM_Contribute_BAO_Contribution), Array, Array, '3')
#2 /home/p6/sites/default/sites/all/modules/civicrm/api/v3/Contribution.php(679): CRM_Contribute_BAO_Contribution::completeOrder(Array, Array, Array, Object(CRM_Core_Transaction), Object(CRM_Contribute_BAO_Contribution), NULL)
#3 /home/p6/sites/default/sites/all/modules/civicrm/api/v3/Contribution.php(621): _ipn_process_transaction(Array, Object(CRM_Contribute_BAO_Contribution), Array, Array, Object(CRM_Contribute_BAO_Contribution))
#4 /home/p6/sites/default/sites/all/modules/civicrm/Civi/API/Provider/MagicFunctionProvider.php(85): civicrm_api3_contribution_repeattransaction(Array)
#5 /home/p6/sites/default/sites/all/modules/civicrm/Civi/API/Kernel.php(152): Civi\API\Provider\MagicFunctionProvider->invoke(Array)
#6 /home/p6/sites/default/sites/all/modules/civicrm/Civi/API/Kernel.php(83): Civi\API\Kernel->runRequest(Array)
#7 /home/p6/sites/default/sites/all/modules/civicrm/api/api.php(86): Civi\API\Kernel->runSafe('Contribution', 'repeattransacti...', Array)
#8 /home/p6/sites/default/sites/default/files/civicrm/ext/uk.artfulrobot.civicrm.gocardless/CRM/GoCardless/Page/Webhook.php(301): civicrm_api3('Contribution', 'repeattransacti...', Array)
#9 /home/p6/sites/default/sites/default/files/civicrm/ext/uk.artfulrobot.civicrm.gocardless/CRM/GoCardless/Page/Webhook.php(221): CRM_GoCardless_Page_Webhook->handleRepeatTransaction(Array, Array)
#10 /home/p6/sites/default/sites/default/files/civicrm/ext/uk.artfulrobot.civicrm.gocardless/CRM/GoCardless/Page/Webhook.php(86): CRM_GoCardless_Page_Webhook->doPaymentsConfirmed(Object(stdClass))
#11 /home/p6/sites/default/sites/default/files/civicrm/ext/uk.artfulrobot.civicrm.gocardless/CRM/GoCardless/Page/Webhook.php(72): CRM_GoCardless_Page_Webhook->processWebhookEvents()
#12 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Core/Invoke.php(268): CRM_GoCardless_Page_Webhook->run(Array, NULL)
#13 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Core/Invoke.php(68): CRM_Core_Invoke::runItem(Array)
#14 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Core/Invoke.php(36): CRM_Core_Invoke::_invoke(Array)
#15 /home/p6/sites/default/sites/all/modules/civicrm/drupal/civicrm.module(456): CRM_Core_Invoke::invoke(Array)
#16 /home/p6/sites/default/includes/menu.inc(527): civicrm_invoke('gocardless', 'webhook')
#17 /home/p6/sites/default/index.php(21): menu_execute_active_handler()
#18 {main}
Hi @Upperholme clearly the extension is passing contact_id
correctly.
However, as of 1.9.2beta - which you can download from https://github.com/artfulrobot/uk.artfulrobot.civicrm.gocardless/releases/tag/1.9.2beta
I'm using a different API call. Would you be OK to test this? Should you need to downgrade again, you can simply replace the codebase with the 1.9.1 version.
Thanks. I'll give it a try and feed back with any news.
@Upperholme pls use https://github.com/artfulrobot/uk.artfulrobot.civicrm.gocardless/releases/tag/1.9.2beta2 instead !!
1.9.2beta2 is giving me the same error when retrying the identical webhook as above.
doh!
Could you post your logs again? I want to see which (new) API call is made that triggers it - Payment.create or Contribution.create etc.
Sure. I'll re-add the additional lines and post the log.
I just meant the stack trace really
Feb 04 13:49:41 [info] Webhook 2020-02-04:13:49:41 body:
{"events":[{"id":"EV00X8QPM2JSHN","created_at":"2019-12-10T11:05:33.240Z","resource_type":"payments","action":"confirmed","links":{"payment":"PM00676Z9K01P6"},"details":{"origin":"gocardless","cause":"payment_confirmed","description":"Enough time has passed since the payment was submitted for the banks to return an error, so this payment is now confirmed."},"metadata":{}}]}
Feb 04 13:49:41 [info] Webhook 2020-02-04:13:49:41 headers:
{"Content-Length":"376","Host":"platform6.coop","Connection":"close","Webhook-Signature":"32123d6a89f1e239b6472b977b6e88230136338e140dc6ea9ce22d6cd3899385","Content-Type":"application\/json","Origin":"https:\/\/api.gocardless.com","User-Agent":"gocardless-webhook-service\/1.1","Accept":"*\/*","Accept-Encoding":"gzip;q=1.0,deflate;q=0.6,identity;q=0.3","Authorization":""}
Feb 04 13:49:41 [error] Webhook 2020-02-04:13:49:41 Failed event. Reason: failed to load related objectsMandatory key(s) missing from params array: contact_id
#0 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Contribute/BAO/Contribution.php(2581): civicrm_api3('Contribution', 'create', Array)
#1 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Contribute/BAO/Contribution.php(4501): CRM_Contribute_BAO_Contribution::repeatTransaction(Object(CRM_Contribute_BAO_Contribution), Array, Array, '3')
#2 /home/p6/sites/default/sites/all/modules/civicrm/api/v3/Contribution.php(679): CRM_Contribute_BAO_Contribution::completeOrder(Array, Array, Array, Object(CRM_Core_Transaction), Object(CRM_Contribute_BAO_Contribution), NULL)
#3 /home/p6/sites/default/sites/all/modules/civicrm/api/v3/Contribution.php(621): _ipn_process_transaction(Array, Object(CRM_Contribute_BAO_Contribution), Array, Array, Object(CRM_Contribute_BAO_Contribution))
#4 /home/p6/sites/default/sites/all/modules/civicrm/Civi/API/Provider/MagicFunctionProvider.php(85): civicrm_api3_contribution_repeattransaction(Array)
#5 /home/p6/sites/default/sites/all/modules/civicrm/Civi/API/Kernel.php(152): Civi\API\Provider\MagicFunctionProvider->invoke(Array)
#6 /home/p6/sites/default/sites/all/modules/civicrm/Civi/API/Kernel.php(83): Civi\API\Kernel->runRequest(Array)
#7 /home/p6/sites/default/sites/all/modules/civicrm/api/api.php(86): Civi\API\Kernel->runSafe('Contribution', 'repeattransacti...', Array)
#8 /home/p6/sites/default/sites/default/files/civicrm/ext/uk.artfulrobot.civicrm.gocardless/CRM/GoCardless/Page/Webhook.php(340): civicrm_api3('Contribution', 'repeattransacti...', Array)
#9 /home/p6/sites/default/sites/default/files/civicrm/ext/uk.artfulrobot.civicrm.gocardless/CRM/GoCardless/Page/Webhook.php(246): CRM_GoCardless_Page_Webhook->handleRepeatTransaction(Array, Array)
#10 /home/p6/sites/default/sites/default/files/civicrm/ext/uk.artfulrobot.civicrm.gocardless/CRM/GoCardless/Page/Webhook.php(86): CRM_GoCardless_Page_Webhook->doPaymentsConfirmed(Object(stdClass))
#11 /home/p6/sites/default/sites/default/files/civicrm/ext/uk.artfulrobot.civicrm.gocardless/CRM/GoCardless/Page/Webhook.php(72): CRM_GoCardless_Page_Webhook->processWebhookEvents()
#12 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Core/Invoke.php(268): CRM_GoCardless_Page_Webhook->run(Array, NULL)
#13 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Core/Invoke.php(68): CRM_Core_Invoke::runItem(Array)
#14 /home/p6/sites/default/sites/all/modules/civicrm/CRM/Core/Invoke.php(36): CRM_Core_Invoke::_invoke(Array)
#15 /home/p6/sites/default/sites/all/modules/civicrm/drupal/civicrm.module(456): CRM_Core_Invoke::invoke(Array)
#16 /home/p6/sites/default/includes/menu.inc(527): civicrm_invoke('gocardless', 'webhook')
#17 /home/p6/sites/default/index.php(21): menu_execute_active_handler()
#18 {main}
Ug. So it's still the Contribution.repeattransaction call that's failing. I'm at a bit of a loss about what could be causing this. You might need to get some paid help in to look at exactly what's going on here. We need to hunt down each of the lines in the stack trace to see when contact_id
goes missing. e.g. does CRM_Contribute_BAO_ContributionRecur::getTemplateContribution
return one? Or maybe the error we're seeing is misleading; perhaps it's trying to look up the contact via the membership and something's wrong there.
It sounds like my case is not the norm?
That makes me wonder about other extensions maybe getting in the way? I think I'll try maybe disabling other extensions to see if that might have an impact. The only things that have changed that I'm aware of is since early December - when it was all working - are updates to this extension and others, and updates to Civi and the CMS.
The only things that have changed ...
So... like... pretty much everything!
OK, fair point. But at least I've not been hacking away at core code.
Update. After disabling and/or uninstalling various extensions I've now got my web hooks working properly again, thankfully. The culprit seems to be the Membership Extras extension - https://github.com/compucorp/uk.co.compucorp.membershipextras
I had version 1.0b installed, and as far as I can see this had no negative impact on webhooks, but I'm guessing that it started causing issues after I updated CiviCRM. Disabling it seemed to make no difference, but after I uninstalled it everything started working.
I see they've now released a stable version 2 of that extension which may have resolved the issue, although I'm not inclined to start experimenting with it right away, much preferring to have a system that actually works. Thanks again for taking the time to investigate.
I'd be interested to hear of anyone using both extensions successfully.
Glad you found a solution (and glad it wasn't a fault with this extension!). I'm closing this now. Suggest mattermost might be a place to ask about the two extensions together.
Noting the problem with version 1.9 of the extension, I recently upgraded to 1.9.1, and have been checking my records against those in the GoCardless account, and I can see that no records of payments collected have been recorded in Civi since Dec 3 2019. So I went into the list of webhooks that GC provides and began retrying from that date. The webhooks are sent and I can see that the extension is logging that fact. However, it is logging an error for the important webhooks (e.g. payment_confirmed. Here's an example of the log entry:
Any clues as to what might be happening here most welcome. I've since updated the Civi install from 5.21.1 to 5.21.2 in case that might help and will retry webhooks again.