Environment:
CiviCRM 5.5.x is the version that created the ones that are now trying to update, but we are now on the latest version 5.11.00 Drupal 7.x
Webform CiviCRM 7.x-4.20+16-dev
Issue:
The first payment made via Webform CiviCRM with 4 1-year terms (Annual) is correctly made in CiviCRM with the payment profile created successfully in Paypal Website Payment Pro. One year after the original transaction, an IPN appears to be sent back from Paypal WPP (copied below) but there is no change on the CiviCRM Recurring Contribution to show the transaction.
Suggestions? Can someone triage this as a Webform CiviCRM issue, CiviCRM bug, or Paypal WPP issue?
At first, I thought the IPN wasn't sending, so I ran the Civi upgrade to 5.11.00 and had Paypal resend the IPN. I checked the CiviCRM System Log table and found the IPN there. The contribution record, however, shows no update.
IPN log:
"{"amount":"100.00","initial_payment_amount":"0.00","profile_status":"Active","payer_id":"E42LJNE93RWRS","product_type":"1","ipn_track_id":"ea7354b7cadf0","outstanding_balance":"0.00","shipping":"0.00","charset":"windows-1252","period_type":" Regular","payment_gross":"100.00","currency_code":"USD","receipt_id":"1095-1202-0757-8493","verify_sign":"ARTWVaUGckuviK6HZ-Of6l88vDtdApgb5SsBR5toeMzYD61j13z0iSqX","payment_cycle":"Yearly","txn_type":"recurring_payment","receiver_id":"XBC22BNDGX5QA","payment_fee":"3.00","mc_currency":"USD","transaction_subject":"Webform Payment: 100 Per 1 year","protection_eligibility":"Ineligible","payer_status":"unverified","first_name":"First","product_name":"Webform Payment: : 100 Per 1 year","amount_per_cycle":"100.00","mc_gross":"100.00","payment_date":"04:11:20 Mar 04, 2019 PST","rp_invoice_id":"i=287cdb784fe4fcdd731906c53e048cdc&m=contribute&c=4729&r=178&b=&p=","payment_status":"Completed","business":"ouremail@ourdomain","last_name":"Last","txn_id":"6EH773960F7425301","mc_fee":"3.00","time_created":"16:30:53 Mar 04, 2018 PST","resend":"true","payment_type":"instant","notify_version":"3.8","recurring_payment_id":"I-1PBATXDD4H0C","payer_email":"[email protected]","receiver_email":"[email protected]","next_payment_date":"02:00:00 Mar 04, 2020 PST","tax":"0.00","residence_country":"US"}"
My rationale for posting it here is I'm not sure where the issue lies so I am happy to report/test anything needed to clear it up.
Update 3/19/2019 - on the latest version of Civi and Webform CiviCRM I created a new recurring profile of $1.00/day and it successfully processed in Paypal each time. CiviCRM only has a record of the first transaction and is receiving the IPN's for the followups but is not doing anything with them. Here are some IPN below (edited for privacy)
The cancellation from Paypal did not cancel anything in Civi:
{"payment_cycle":"Daily","txn_type":"recurring_payment_profile_cancel","last_name":"last","next_payment_date":"N/A","residence_country":"US","initial_payment_amount":"0.00","rp_invoice_id":"i=c83d98a31d0e2c2a5cf3173493e24e3b&m=contribute&c=16014&r=830&b=&p=","currency_code":"USD","time_created":"14:16:08 Mar 14, 2019 PDT","verify_sign":"AyT1wi4GzlURUfQbTmQWfTBcmyeoAgAjHAleKj2b1QyzJd-.4gNAHVEt","period_type":" Regular","payer_status":"unverified","tax":"0.00","payer_email":"[email protected]","first_name":"first","receiver_email":"[email protected]","payer_id":"S5E6YRTVCSZTQ","product_type":"1","shipping":"0.00","amount_per_cycle":"1.00","profile_status":"Cancelled","charset":"windows-1252","notify_version":"3.9","amount":"1.00","outstanding_balance":"0.00","recurring_payment_id":"I-F4WEDCKXYUFS","product_name":"Webform Payment","ipn_track_id":"c7efd7f383b01"}
One of the Payment notices did not create a Contribution in Civi:
{"mc_gross":"1.00","period_type":" Regular","outstanding_balance":"0.00","next_payment_date":"03:00:00 Mar 19, 2019 PDT","protection_eligibility":"Ineligible","payment_cycle":"Daily","tax":"0.00","payer_id":"S5E6YRTVCSZTQ","payment_date":"05:09:39 Mar 18, 2019 PDT","payment_status":"Completed","product_name":"Webform Payment: Membership Forms Debugging Page: 1 Per 1 day","charset":"windows-1252","rp_invoice_id":"i=c83d98a31d0e2c2a5cf3173493e24e3b&m=contribute&c=16014&r=830&b=&p=","recurring_payment_id":"I-F4WEDCKXYUFS","first_name":"first","mc_fee":"0.33","notify_version":"3.9","amount_per_cycle":"1.00","payer_status":"unverified","currency_code":"USD","business":"[email protected]","verify_sign":"AFgGSSN7T0eV820ZsLG2eXpvjHjxA2u3dUQBLcGbSQLiJfOaSXghKIV-","payer_email":"[email protected]","initial_payment_amount":"0.00","profile_status":"Active","amount":"1.00","txn_id":"5489090059341273U","payment_type":"instant","last_name":"last","receiver_email":"[email protected]","payment_fee":"0.33","receiver_id":"XBC22BNDGX5QA","txn_type":"recurring_payment","mc_currency":"USD","residence_country":"US","receipt_id":"5598-9968-4788-6393","transaction_subject":"Webform Payment","payment_gross":"1.00","shipping":"0.00","product_type":"1","time_created":"14:16:08 Mar 14, 2019 PDT","ipn_track_id":"195d7793815d3"}
Edit 2: I've installed https://github.com/eileenmcnaughton/nz.co.fuzion.notificationlog and retried an IPN that failed with a backtrace. Any thoughts?
drush cvapi NotificationLog.retry system_log_id=12638 debug=1
PayPalFailure: Missing Parameter b [error]
Array
(
[trace] => #0 /myserver/public_html/sites/all/modules/civicrm/CRM/Core/Payment/PayPalProIPN.php(436): CRM_Core_Payment_PayPalProIPN->getValue('b', true)
#1 /myserver/public_html/sites/all/modules/civicrm_extensions/nz.co.fuzion.notificationlog-master/api/v3/NotificationLog/Retry.php(75): CRM_Core_Payment_PayPalProIPN->main()
#2 /myserver/public_html/sites/all/modules/civicrm_extensions/nz.co.fuzion.notificationlog-master/api/v3/NotificationLog/Retry.php(24): _civicrm_api3_notification_log_process(Array)
#3 /myserver/public_html/sites/all/modules/civicrm/Civi/API/Provider/MagicFunctionProvider.php(100): civicrm_api3_notification_log_retry(Array)
#4 /myserver/public_html/sites/all/modules/civicrm/Civi/API/Kernel.php(169): Civi\API\Provider\MagicFunctionProvider->invoke(Array)
#5 /myserver/public_html/sites/all/modules/civicrm/Civi/API/Kernel.php(100): Civi\API\Kernel->runRequest(Array)
#6 /myserver/public_html/sites/all/modules/civicrm/api/api.php(23): Civi\API\Kernel->runSafe('NotificationLog', 'retry', Array, NULL)
#7 /myserver/public_html/sites/all/modules/civicrm/drupal/drush/civicrm.drush.inc(1558): civicrm_api('NotificationLog', 'retry', Array)
#8 [internal function]: drush_civicrm_api('NotificationLog...', 'system_log_id=1...', 'debug=1')
#9 /usr/share/php/drush/includes/command.inc(334): call_user_func_array('drush_civicrm_a...', Array)
#10 /usr/share/php/drush/includes/command.inc(208): _drush_invoke_hooks('civicrm-api', Array, 'civicrm')
#11 [internal function]: drush_command('NotificationLog...', 'system_log_id=1...', 'debug=1')
#12 /usr/share/php/drush/includes/command.inc(175): call_user_func_array('drush_command', Array)
#13 /usr/share/php/drush/drush.php(92): drush_dispatch(Array)
#14 /usr/share/php/drush/drush.php(61): _drush_bootstrap_and_dispatch()
#15 /usr/share/php/drush/drush.php(16): drush_main()
#16 {main}
[is_error] => 1
[error_message] => Failure: Missing Parameter b
)