Page MenuHomePhabricator

Paypal EC Pending Transaction Resolver failed (missing 'date' param)
Open, HighPublic

Description

Today we got a few failmails due to a missing 'date' param during the Paypal PTR run.

civi1001:/var/log/process-control/paypal_pending_resolver/paypal_pending_resolver-20230317-125001.log

2023-03-17 12:50:04,774 ERROR   Undefined index: date Api.php:138                                       [notice]
2023-03-17 12:50:05,417 ERROR   WD php: TypeError: Return value of                                       [error]
2023-03-17 12:50:05,417 INFO    TypeError: Return value of Civi\Api4\Action\PendingTransaction\Resolve::startRecurringPaymentAndReturnStatus() must be of the type string, null returned in Civi\Api4\Action\Pendin
gTransaction\Resolve->startRecurringPaymentAndReturnStatus() (line 654 of /srv/org.wikimedia.civicrm/drupal/sites/default/civicrm/extensions/wmf-civicrm/Civi/Api4/Action/PendingTransaction/Resolve.php).
2023-03-17 12:50:05,417 ERROR   Civi\Api4\Action\PendingTransaction\Resolve::startRecurringPaymentAndReturnStatus()
2023-03-17 12:50:05,417 ERROR   must be of the type string, null returned in
2023-03-17 12:50:05,417 ERROR   Civi\Api4\Action\PendingTransaction\Resolve->startRecurringPaymentAndReturnStatus()
2023-03-17 12:50:05,417 ERROR   (line 654 of
2023-03-17 12:50:05,417 ERROR   /srv/org.wikimedia.civicrm/drupal/sites/default/civicrm/extensions/wmf-civicrm/Civi/Api4/Action/PendingTransaction/Resolve.php).
2023-03-17 12:50:05,418 ERROR   Drush command terminated abnormally due to an unrecoverable error.       [error]
2023-03-17 12:50:05,432 INFO    ----------- end command output

It looks like we can fix this by passing in the missing 'date' param needed for the failing Smashpig call SmashPig Paypal/Api::createRecurringPaymentsProfile()

Event Timeline

Change 900660 had a related patch set uploaded (by Jgleeson; author: Jgleeson):

[wikimedia/fundraising/crm@master] PayPal Pending Trxn Resolver Fix: missing 'date' param

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

From IRC:

14:03 <jgleeson> ok I guess we could fix this two ways
14:04 <jgleeson> we could update the calling code in the civi extension to send in the expected date format of a string 
14:05 <jgleeson> or we could update both the civi extension to send over the date param verbatim as a timestamp, and smashpig to expect a timestamp
14:06 --> mbeattie (~mbeattie@c-71-192-33-82.hsd1.ma.comcast.net) has joined #wikimedia-fundraising
14:08 <jgleeson> hmm I might go with option one even though it's ugly. the latter would require a smashpig verson bump and an update to civi to pull in the library updates alongside the new date param so I'll defer that for now and add a ticket to follow on with the more complete fix

Let's refactor the calling and library code related to this.

Currently, the calling code in CiviCRM is picking up a timestamp from the queue message and then converting it to a date string:

https://gerrit.wikimedia.org/r/c/wikimedia/fundraising/crm/+/900660/1/drupal/sites/default/civicrm/extensions/wmf-civicrm/Civi/Api4/Action/PendingTransaction/Resolve.php#653

protected function startRecurringPaymentAndReturnStatus(
  IRecurringPaymentProfileProvider $provider
): string {
  $profileResult = $provider->createRecurringPaymentsProfile([
    'gateway_session_id' => $this->message['gateway_session_id'],
    'description' => \Civi::settings()->get('wmf_resolved_charge_descriptor'),
    'order_id' => $this->message['order_id'],
    'amount' => $this->message['gross'],
    'currency' => $this->message['currency'],
    'email' => $this->message['email'],
    'date' => date('Y-m-d H:i:s', $this->message['date']), <<<---
  ]);
  return $profileResult->getStatus();
}

The library code then converts it from a string back to a timestamp and then back to a paypal-specific date string:

https://github.com/wikimedia/wikimedia-fundraising-SmashPig/blob/2e331abfad41160e96cc3cec538556f49bd7fdee/PaymentProviders/PayPal/Api.php#L132

public function createRecurringPaymentsProfile( array $params ) {
	$requestParams = [
		'METHOD' => 'CreateRecurringPaymentsProfile',
		// A timestamped token, the value of which was returned in the response to the first call to SetExpressCheckout or SetCustomerBillingAgreement response.
		// Tokens expire after approximately 3 hours.
		'TOKEN' => $params['gateway_session_id'],
		'PROFILESTARTDATE' => gmdate( "Y-m-d\TH:i:s\Z", strtotime( $params['date'] ) ), <<<---
		'DESC' => $params['description'],
		'PROFILEREFERENCE' => $params['order_id'],
		'BILLINGPERIOD' => 'Month',
		'BILLINGFREQUENCY' => 1,
		'AMT' => $params['amount'],
		'CURRENCYCODE' => $params['currency'],
		'EMAIL' => $params['email'],
		'AUTOBILLOUTAMT' => 'NoAutoBill', // PayPal does not automatically bill the outstanding balance if payments fail.
		'TOTALBILLINGCYCLES' => 0, // Forever.
		'MAXFAILEDPAYMENTS' => 0, // Just keep trying
	];

	return $this->makeApiCall( $requestParams );
}

Thanks so much for this @jgleeson! The attached patch looks great.

Just trying to understand the root cause here: as far as I can tell, this is due to a bug introduced in this patch, which created Civi\Api4\Action\PendingTransaction\Resolve::startRecurringPaymentAndReturnStatus().

The commit message for that change says, "This just emulates the existing code in paypal_express.adapter.php which calls the profile creation API." It looks like the bug was just that no date key was sent in on the $params array when calling createRecurringPaymentsProfile(). This is the cause of the "Undefined index: date Api.php:138" in the log quoted above.

The patch with the error was merged into the crm deploy branch on 2023-02-28, however, I imagine some related job might not have been turned on until later? Perhaps that would explain that the first failmail was got about this was on 2023-03-16?

(I have no failmails before that date with the same title, "Paypal EC Pending Transaction Resolver failed with code 1".)

Change 900660 merged by jenkins-bot:

[wikimedia/fundraising/crm@master] PayPal Pending Trxn Resolver Fix: missing 'date' param

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

jgleeson moved this task from Ready for Review to Done on the Fundraising Tech - Chaos Crew board.
jgleeson updated Other Assignee, added: AndyRussG.
jgleeson renamed this task from Paypal EC Pending Transaction Resolver failed to Paypal EC Pending Transaction Resolver failed (missing 'date' param).Mon, Mar 20, 1:58 PM

Change 901232 had a related patch set uploaded (by Ejegg; author: Ejegg):

[wikimedia/fundraising/SmashPig@master] Expect timestamp for PP profile start date

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

Change 901232 merged by jenkins-bot:

[wikimedia/fundraising/SmashPig@master] Expect timestamp for PP profile start date

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

Change 901244 had a related patch set uploaded (by Ejegg; author: Ejegg):

[wikimedia/fundraising/crm@master] Update SmashPig + DonationInterface

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

Change 901244 merged by jenkins-bot:

[wikimedia/fundraising/crm@master] Update SmashPig + DonationInterface

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