Civi returning 500 errors to Paypal Pro request to civicrm/extern/ipn.php

changed the description

Huh, that Expected one ContributionRecur but found 25 error message suggests that the old IPN handler may be missing some expected parameter (eg it expects to get the original contribution ID for ContributionRecur.get API, doesn't detect the missing / invalid input, and CiviCRM API returns a default matching resultset instead of the specific contribution).

Of interest here is that we don't check that and identify the problem in that code path. Since your site has >1 recurring contributions, you wind up at an exception and Civi bails out. But other unexpected things might be possible there - eg if:

site had 2 contributions
site deleted 1 recurring contribution
IPN got hit and found all 1 remaining contributions

... would Civi continue happily because it got 1 result back even though it wasn't the right contribution? Contrived example, but I feel like it shouldn't be possible to get to that point without better input checking.

EDIT: Oh, this isn't even for a recurring transaction! We definitely shouldn't end up there then (but the issue still applies, it just makes the example less contrived as we could end up there if a site had a single recurring contribution and was getting IPN for regular one-off payments).

Not sure I entirely follow @xurizaemon :-) but I can confirm:

this error occurred for a new, one-time (single) transaction processed just today
this client does process approx 25 recurring transaction per month. The number in Dec was 26 actually, but that may be where the 25 comes from

changed the description

So looking at the code maybe its winding up in here https://github.com/civicrm/civicrm-core/blob/8b9a8f4abb25cfa7a498eaaa3e459e4d313e350a/CRM/Core/Payment/PayPalProIPN.php#L561 which seems consistent with the findings on the SE Post

@Stoob - the 25 is CiviCRM's default result paging size, and is what will happen if you execute eg Contact.get if you meant to pass in Contact.get id=123.

To me it's suggestive of some code path being executed to try and see if there's a recurring contribution - but that path shouldn't be evaluated unless there's a known recur ID or contribution ID, because (1) you might IPN the contribution one if you lucked into getting exactly 1 result, and (2) it throws a fatal error when there's no input value and it retrieves 25 results. It's also possible that there's exactly 25 results, but I think we can agree CiviCRM ought to not throw a fatal exception looking up recur IDs on a non-recurring transaction.

Noting these three rather recent SE reports on PayPal IPN issues via SE - not a clear smoking gun, but it'd make me wonder if something got borked recently ...

@seamuslee How in the heck are we ending up in the method handlePaymentExpress() of PayPal's IPN? Payment Express is a payment provider from NZ .. unless it's also a PayPal feature, this is utterly bonkers to me.

OK: here we set $this->_isPaymentExpress if we receive rp_invoice_id from PayPal. That's perfectly normal data to expect from PayPal IPN. Is it just another of CiviCRM's "words mean nothing to me" naming schemes at work? Or is there such a thing as "paypal payment express"?

wut?

public function handlePaymentExpress() {
  // loads of copy & paste / code duplication but as this not going into core need to try to
  // keep discreet

OK - looks like handlePaymentExpress here means PayPal Express (via CRM-12679) not PaymentExpress.

added needs:concept approval needs:steps to replicate triaged type:request labels

@Stoob, are you able to supply (sufficiently fake/anonymised) IPN variables and PayPal config to trigger this code path on a test instance?

I'm not exactly sure what you mean by that sorry @xurizaemon. The Paypal Pro account isn't mine and I haven't authority to offer its credentials/keys. I thought that the Core Team has credentials for testing purposes?

I can include (attached) here an anonymized version of the POST that Paypal sent to ipn.php for a real $1000 one-time transaction. The attached was written to CiviCRM.log at the same time that CiviCRM was returning a 500 error to Paypal and recording "Expected one ContributionRecur but found 25" in error_log.

post_paypal_pro_single.txt

That looks like exactly what I was asking for @Stoob! Thanks.

@xurizaemon OK so I think I get it!

paypal sends many different ipns with different messages
we ignore some of them
we ignore paypal express ipns unless they are for recurring - these have traditionally failed at the point where they check for recurrings - with an api exception
ipn.php catches core exceptions but not api exceptions
some change happened at some point I believe to treat uncaught api exceptions as 500 errors

Given the above I think this one word change will fix it.

--- a/extern/ipn.php
+++ b/extern/ipn.php
@@ -58,7 +58,7 @@ try {
   }
   $paypalIPN->main();
 }
-catch (CRM_Core_Exception $e) {
+catch (Exception $e) {
   CRM_Core_Error::debug_log_message($e->getMessage());
   CRM_Core_Error::debug_var('error data', $e->getErrorData(), TRUE, TRUE);
   CRM_Core_Error::debug_var('REQUEST', $_REQUEST, TRUE, TRUE);
(END)

@Stoob are you able to try changing the ipn.php file on your site & change CRM_Core_Exception to just Exception ?

A nicer thing to do might be to explicitly say why we ignore various IPNs in the handler - but I'd only propose that feature be added to the new IPN handler, because for various reasons including the TZ issues reported in extern/ipn.php by jgillmanjr recently, we do want people moved over to the properly bootstrapped and routed IPN processor.

Eg if an IPN lands, we should either process it or say (via Civi::log()->warning() etc),

ignored IPN because of invalid signature
ignored IPN because it's a repeat
ignored IPN because that IPN isn't implemented in CiviCRM yet ...

@xurizaemon tz issue isn't to do with the IPN path. I got it even with the new format of IPN URLs

Cool, not trying to threadjack just think it's simpler (for reasons stated elsewhere, cloud-native#16 (moved)) to not have multiple entry points. Eliminating alternate Civi boot makes debugging that TZ issue simpler because we don't need to know if it's the boot approach or something else.

I think the issue with getting rid of ipn.php is that it needs a paypal config change - we have to keep it limping along but I don't want to do more than that on it

@eileen I have been seeing this with our clients. I tested yourchange. IPN messages are generating this error

PHP Fatal error: Uncaught Error: Call to undefined method CiviCRM_API3_Exception::getErrorData()

We also are seeing this with one of our clients, and tested the class change that @eileen suggested. Before we made the change, we saw this error message:

[Mon Feb 25 17:59:32.404290 2019] [php7:error] [pid 9999] [client 867.5.30.9:99999] PHP Fatal error: Uncaught CiviCRM_API3_Exception: [undefined: Expected one ContributionRecur but found 25\n\n thrown in /var/www/example.org/htdocs/sites/all/modules/civicrm/api/api.php on line 45

And after applying the class change and re-sending the failed IPN, it looks different:

[Thu Feb 28 22:05:25.672972 2019] [php7:error] [pid 99999] [client 867.5.30.9:9999] PHP Fatal error: Uncaught Error: Call to undefined method CiviCRM_API3_Exception::getErrorData() in /var/www/example.org/htdocs/sites/all/modules/civicrm/extern/ipn.php:63\nStack trace:\n#0 {main}\n thrown in /var/www/example.org/htdocs/sites/all/modules/civicrm/extern/ipn.php on line 63

Those are from the Apache error log. In ConfigAndLog, there's no error in the log for the first failure (just the array). The second failure has the array and the error:

Feb 28 22:05:25 [info] Expected one ContributionRecur but found 25

Instead of changing the exception class... add a new catch to avoid the error on getErrorData()

catch (CRM_Core_Exception $e) {
  CRM_Core_Error::debug_log_message($e->getMessage());
  CRM_Core_Error::debug_var('error data', $e->getErrorData(), TRUE, TRUE);
  CRM_Core_Error::debug_var('REQUEST', $_REQUEST, TRUE, TRUE);
  //@todo give better info to logged in user - ie dev
  echo "The transaction has failed. Please review the log for more detail";
}
catch (Exception $e) {
  CRM_Core_Error::debug_log_message($e->getMessage());
  CRM_Core_Error::debug_var('REQUEST', $_REQUEST, TRUE, TRUE);
}

Post 5.10.4 upgrade...getting 500 errors again. /civicrm/payment/ipn/1 is the URL Nothing changed on the Paypal config. @tommybobo you seeing the same thing for some of yours? @eileen how can I help get some closure on the Paypal Pro issues here, testing, sponsorship?

@Stoob I just started getting reports of 500 errors on PayPal. A few were on the old format and I updated, but a number were on /civicrm/payment/ipn/xx I have not found a reason on my end.

added regression label

tagged as possible regression as it seems there may be a new issue. @kcristiano you can replay them with the NotificationLog extension - that might help flush it out

@eileen I will monitor, I asked my clients that are affected not manually update and let me know.

Update @eileen and @kcristiano, all clients who use Paypal pro are receiving a similar error message [Fri Mar 08 12:58:47.723771 2019] [fcgid:warn] [pid 63208] [client 173.0.81.1:24876] mod_fcgid: stderr: PHP Fatal error: Uncaught CiviCRM_API3_Exception: [undefined: Expected one ContributionRecur but found 25 [Fri Mar 08 12:58:47.749751 2019] [fcgid:warn] [pid 63208] [client 173.0.81.1:24876] mod_fcgid: stderr: thrown in /home/site/public_html/sites/all/modules/civicrm/api/api.php on line 45 This is identical to the issue posted above #659 (comment 12636) with post attached, but the workaround of using /civicrm/payment/ipn/x no longer appears to be effective.

@Stoob is the contribution_recur_id set on the relevant records (ie. the associated contribution)

I appreciate you checking in on this on a Saturday @eileen. To answer your question. Yes, of the recurring contributions that have happened since the 5.10.4 upgrade, 100% of them are listed as contribution_recur_id IS NOT NULL, and 100% of them are complete in CiviCRM. The problem continues to be that, despite CiviCRM apparently getting all it needs in the communication, CiviCRM is continuing to return a 500 error to Paypal, when then interprets the communication as failure and eventually shuts off IPN entirely.

This is a serious issue but I'm mindful of the nature of your volunteerism, what's the best way to get traction on a fix here? All options are on the table, including paid consultancy, MIH, and Bitcoin. ;-) Seriously though, what's the next step for a fix, how can I help?

@Stoob if you find the file CRM_Utils_System.php you & edit it so that the function civiExit has 2 changes

add this line CRM_Core_Error::backtrace('backTrace', TRUE); - that will cause a backtrace to be logged to the file in ConfigAndLog so we can get a backtrace to diagnose
comment out http_response_code(500); - this should give you temporary relief


  /**
   * Exit with provided exit code.
   *
   * @param int $status
   *   (optional) Code with which to exit.
   */
  public static function civiExit($status = 0) {

    CRM_Core_Error::backtrace('backTrace', TRUE);
    if ($status > 0) {
      //http_response_code(500);
    }

@michaelmcandrew FYI 500 error issues

This MIGHT be the right fix - @kcristiano I'll need you to look at it https://github.com/civicrm/civicrm-core/pull/13796

I commented on the PR. I have added the fix to our testing site and will monitor recurring transactions. I ahve also added to a client site with the issue and hope to add at least one more. I am not getting the issue consistently - but this is probably due to the fact that our sites have less recurring transactions. The fix makes sense and should give relief in that PayPal should not get sent a 500 error.

@Stoob are all of your issues recurring that date back before the change to the new ipn handler?

Civi was sending 100% 500 errors for recurring in Civi 5.6 prior to changing the URL to civicrm/payment/ipn/X. civicrm/payment/ipn/X resolved this issue in 5.6, 500 errors dropped to 0%. After the upgrade to 5.10 the 500 errors started again 100%, and the URL hasn't changed. Does that answer the question @kcristiano

Thanks @Stoob It does answer the question. Are you able to test the PR on any of the affected sites?

@kcristiano Thanks I've applied the PR on two sites and will wait to hear back from client if the errors have stopped. They both have recurring payments in the upcoming days.

@kcristiano early reports are that https://github.com/civicrm/civicrm-core/pull/13796 does not stop Civi from showing 500 errors to Paypal. But what is different is the IPN History within Paypal.com shows these latest IPNs processed by the patch file as status "Queued" rather than "Failed".

@eileen I then used your code above to suppress 500s and generate this attached error.paypal_error.txt

OK those lines imply the issue is with PaypalExpress payments?

  public function handlePaymentExpress() {
    //@todo - loads of copy & paste / code duplication but as this not going into core need to try to
    // keep discreet
    // also note that a lot of the complexity above could be removed if we used
    // http://stackoverflow.com/questions/4848227/validate-that-ipn-call-is-from-paypal
    // as membership id etc can be derived by the load objects fn
    $objects = $ids = $input = array();
    $isFirst = FALSE;
    $input['invoice'] = self::getValue('i', FALSE);
    $input['txnType'] = $this->retrieve('txn_type', 'String');
    $contributionRecur = civicrm_api3('contribution_recur', 'getsingle', array(
      'return' => 'contact_id, id, payment_processor_id',
      'invoice_id' => $input['invoice'],
    ));

The sole configured 'real' processor on this Civi is Paypal Pro. (attached screnshots) I'm not sure why the code says what it says - there are no customization to the payment process on this Civi. I appreciate the volunteerism but I feel like we're going round and 'round.

I really really want to shove a lot of money in someone's hand and say "fix it". Is that even possible?

@Stoob when the paypal processor is 'Paypal Pro' a paypal express button is displayed and the user can still click on it - I suspect these ones where they have clicked on the button - but are not recurring contributions & so we actually ignore the IPNS from Paypal (hence the failure to process is no problem for us) so simply getting rid of the 500 errors is what is needed

Happy to help test. We are on 5.11.0 but our issue is that Paypal WPP is not updating Civis recurring payment contributions. Not sure if it is due to an IPN issue mentioned above or not.

@zkrebs that sounds slightly different - but if you log into paypal you can see the status & possibly re-send the IPNs

I just verified we are getting the IPN's sent in the CiviCRM System Log table, but they are not updating the records. Seems like a different problem. I contacted the module dev, feel free to delete my post(s) if needed.

@zkrebs so you are dealing with something other than paypal from the sounds of it - ah no you said paypal - ok

@eileen thanks but I'm not sure I follow what you're saying. But let me add a few points of clarity that hopefully help:

not 100% of recurring IPN have been generating a 500 error, I was mistaken. I asked the client to double-check and there is ONE single IPN that hasn't generated an error since 5.10.4, but one is the only recurring that is Paypal Express. The others are Paypal Pro (credit card), and these are all failing.
an error in the log always seems to show this phrase string(20) "handlePaymentExpress" whether or not Paypal Express (the orange button) was actually the method used
there are different versions of the error, here is another referencing paypal_error2.txt "Could not find an entry for txn_type in POST"

@jitendra and @mattwire do either of you have interest in this as a paid consultancy? There are lots of challenges here, both technical and psychological, but I think you would enjoy the project

mentioned in commit 3bfd7fa1

I'm going to close this against 5.12 - I believe there may be a separate issue affecting @Stoob - I'm unsure but this issue is about 500 errors being returned to Paypal & we have resolved that.

THIS issues is summed up as follows

we do not process all paypal ipns
we used to quietly ignore the ones we don't process
a fix a while caused us to start giving 500 errors for ones we don't process
this upset paypal
we no longer give 500 errors for ones we don't process

@Stoob please create a follow up issue regarding related issues - it might be that this DOES actually resolve your issues - ie. the errors in the log are red herrings and relate to IPNs that we would normally ignore and as long as we ignore them quietly it's OK - or it may be there is another issue in there. Ideally work with Kevin if you can to narrow down more info on it - or possible contract Jitendra or Matt as discussed

closed

changed milestone to %5.12.0

@Stoob were any related issues created? Want to link them here if so?

@jitendra and Fuzion's patch has been applied on production for a few weeks with no unwanted side-effect issues that I'm aware of.

Here it is @xurizaemon https://github.com/civicrm/civicrm-core/pull/13867

mentioned in issue #1931 (closed)

Civi returning 500 errors to Paypal Pro request to civicrm/extern/ipn.php

Child items 0

Activity