Bug report: M2P IPN processing reports success on fail (and consequent problems)

We recently deployed M2P v1.0.0.8 in network mode with PayPal Standard as the payment gateway. More than a dozen people have signed up and paid in the last few days but, in just two cases, it looks like M2P rejected IPN messages (that, so far as I can tell, are perfectly valid) from PayPal.

More worryingly, manually changing the invoice status doesn't appear to be be updating the member relationship metadata, and I can't tell whether M2P considers the membership to be paid for the purposes of enforcing membership protections or not.

There is also what is probably a relatively minor cosmetic bug (see very end of this post) to do with the transaction log. Though minor, it will confuse M2P admins.

Here's what I'm seeing:
• PayPal shows that these individuals have, in fact, paid.
• but those members' invoices still show as 'new' .
• The message "Response Error: Unexpected transaction response" appears twice for each of the two cases, next to the same invoice ID in the transaction log.
• (In every other case, I see two tx log entries associated with each invoice with the messages, "| Paypal subscripton profile has been created." followed by "Payment successful | Paypal subscripton profile has been created.")
• There are no entries relating to these two transactions is the event log.
• Perhaps by chance, perhaps not, the two fault-cases happen to be consecutive and within about 10 minutes of each other.
• One is domestic (ie, within the US), the other is from Canada.
• PayPal's IPN history shows that both messages were transmitted successfully (HTTP status 200) with 0 retries.
• Having verified with PayPal that the payments were made, I manually set the invoice status to 'paid' with the "Execute status change actions on Save (add/remove membership)" checkbox checked, but the MS relationships apparently aren't being updated.

Side note: only the most recent 20 transactions are available via the M2P web interface. Is that deliberate, or have the page nav buttons been omitted?

In order to diagnose as much as possible what's going on before filing this report, I spent some time getting to grips with how M2P stores membership relationships and invoice data in the SQL DB, then wrote a CLI tool that generates reports of members, invoices, transactions and events directly from SQL (because as great as the new UI is, it isn't so hot at reporting and doesn't have the sort of flexibility require to investigate weirdnesses like this).

I have cross-checked the reports from my M2P query tool with data exported from PayPal, and only these two cases appear to have failed. See attached a rather heavily redacted version of the tx log.

Having manually updated the invoices from 'new' to 'paid', my M2P query tool invoice report shows the invoices paid, the event log shows same, but the membership report still shows these two cases as unpaid because meta_key 'payments' for the relationship post is still empty.

Bug 1: IPN handling

The "Response Error: Unexpected transaction response" message is generated in the block of code at lines 270–275 of ./app/gateway/paypalstandard/class-ms-gateway-paypalstandard.php, which is executed when the conditional at lines 104–109 fail. Those conditions are:

104                         if ( ! is_wp_error( $response )
105                                 && 200 == $response['response']['code']
106                                 && ! empty( $response['body'] )
107                                 && 'VERIFIED' == $response['body']
108                                 && $invoice->id == $invoice_id
109                         ) {

Evidently, one of those failed in these four cases. The fact that the four failure cases occurred within 10 minutes of each other suggests that there could have been a transient error, either network or at PayPal.

The problem is, the error handling code:

270                         } else {
271                                 $notes = 'Response Error: Unexpected transaction response';
272                                 MS_Helper_Debug::log( $notes );
273                                 MS_Helper_Debug::log( $response );
274                                 $exit = true;
275                         }

doesn't set the HTTP response code, so PayPal gets an HTTP status of 200, thinks all is well, and doesn't retry the IPN.

» This block of code should call status_header(), just as another block of code (line 287) does.

Bug 2: Manual payment processing

I don't know enough about M2P's internals, but it would appear that the "execute status change" is not updating the relationship's payment metadata appropriately.

This one, I have to leave to the dev to investigate.

Bug 3: Successful IPNs recorded as failures in the tx log

My M2P query txlog report shows a large number of records as having failed (ie meta_key '_success' unset).

Every PayPal recurring subscription generates two IPNs, one indicating the successful creation of a recurring payment profile, the other indicating an actual payment. It seems that M2P is flagging payment IPNs as successful, but profile creation IPNs as failures (hence why in the transaction log, you see a mixture of successes and failures).

I'm not quite sure why, but I'd say that the code at lines 185–187 are suspect. Contrast:

122                                                 case 'Completed':
123                                                 case 'Processed':
124                                                         if ( $amount == $invoice->total ) {
125                                                                 $success = true;
126                                                                 $notes .= __( 'Payment successful', MS_TEXT_DOMAIN );

with

181                                                 case 'subscr_signup':
182                                                 case 'subscr_payment':
183                                                         // Payment was received
184                                                         $notes_txn = __( 'Paypal subscripton profile has been created.', MS_TEXT_DOMAIN );
185                                                         if ( 0 == $invoice->total ) {
186                                                                 $success = true;
187                                                         }

line 125 sets $success when $invoice->total == $amount (for payment IPNs), but line 186 only sets $success when $invoice->total == 0. How can both comparisons be true? Should line 185 read something similar to:

185                                                         if ( $_POST['mc_amount3'] == $invoice->total ) {

Bugs 1 and 3 are probably easily fixed. Bug 2.. requires some input from the dev.

  • Michelle Shull

    First off, this is really impressive. Like super impressive, I just showed two colleagues with a "This guy is Bug Report Master of the Universe." NICE WORK, and THANKS!

    Second, this is a known issue, the dev has been digging in for a while on this one, but I believe your details here will be extremely helpful to him. I am passing it on as we speak.

    Thanks so much for the detailed, beautiful, awe-inspiring bug report here. We should hire you.

  • David King

    Thanks for your kind words :wink: Glad I could help, especially if it provides the key to the problem for the dev.

    BTW, which of the bugs I reported is a known issue? The IPN processing problem? If so, then I think I identified the problem and the fix should be as simple as the addition of 1 line of code :slight_smile: (And a review to see any other failure cases that need to be signalled to PayPal.)

    The dev has my sympathies on this one, though: reproducing the problem, or at least getting data post mortem is crucial to finding the problem but these are not the sort of data many people would be willing to share, even with a trusted partner like WPMUdev, and especially not access to PayPal to see IPN logs. Without those things? Finding that problem would be bloody difficult.

    The 3rd bug is also easy to fix, though I daren't submit a patch without knowing more about the codebase. That's best left for the dev, who'll have enough information in their head about the wider picture to know what is the right thing to do.

    The 2nd bug, the dev can probably answer fairly easily for the same reason: knowing how the codebase fits together, s/he should be able to indicate fairly quickly how M2P determines whether a relationship is valid or not.

    M2P is fairly complex, and I've stared at parts of it, but much of it is a mystery to me.

  • David King

    » This block of code should call status_header(), just as another block of code (line 287) does.

    Looking back on it and reviewing the code, I've got a better idea to suggest to the dev:

    There is at least one other code path leading to exit() that wouldn't set the HTTP status code, so I propose that the call to status_header() on line 287 be moved to a new if( $exit ) check before the do_action() on line 294, that way you're guaranteed to emit a non-200 error should $exit ever be set, even if somebody hooks that action and emits output that would otherwise force a 200 result.

    Also, I'd suggest returning an HTTP status code of 503 rather that 404 so that anybody inspecting the IPN logs can distinguish between a bad URL and a rejected IPN. Here is an (untested) diff illustrating what I mean, and also showing my proposed correction for bug 3:

    --- ./app/gateway/paypalstandard/class-ms-gateway-paypalstandard.php    2015-07-02 08:09:42.719775172 -0500
    +++ /tmp/class-ms-gateway-paypalstandard.php    2015-07-11 07:39:17.617207158 -0500
    @@ -182,7 +182,8 @@
                                                    case 'subscr_payment':
                                                            // Payment was received
                                                            $notes_txn = __( 'Paypal subscripton profile has been created.', MS_TEXT_DOMAIN );
    -                                                       if ( 0 == $invoice->total ) {
    +                                                       if ( (isset( $_POST['mc_gross'])   && $_POST['mc_gross']   == $invoice->total ) ||
    +                                                            (isset( $_POST['mc_amount3']) && $_POST['mc_amount3'] == $invoice->total ) ) {
                                                                    $success = true;
                                                            }
                                                            break;
    @@ -284,12 +285,15 @@
                                    $redirect = home_url();
                            } else {
                                    // PayPal did provide invalid details...
    -                               status_header( 404 );
                                    $notes = 'Error: Missing POST variables. Identification is not possible.';
                                    MS_Helper_Debug::log( $notes );
                            }
                            $exit = true;
                    }
    +
    +               if ( $exit ) {
    +                       status_header( 503 );
    +               }
    
                    do_action(
                            'ms_gateway_transaction_log',
  • David King

    Another addendum: I'd like to draw attention to the following, because I don't think I adequately pointed to it as a 4th bug:

    Having manually updated the invoices from 'new' to 'paid', my M2P query tool invoice report shows the invoices paid, the event log shows same, but the membership report still shows these two cases as unpaid because meta_key 'payments' for the relationship post is still empty.

    » Bug 4: manually changing invoice payment status doesn't update the relationship meta_key 'payments'

    Changing the invoice status updated the invoice record (post_type = 'ms_invoice-n'), but it doesn't update the relationship record (post_type = 'ms_relationship-n') to indicate that the payment has, indeed, been received.

    I haven't looked at the code but I presume meta_key 'payments' would be updated when gateway_id = manual, but it definitely isn't when gateway_id = 'paypalstandard'.

    This is a bug because if the invoice has been marked paid (whether by IPN or manually), then meta_key payments should reflect this (or that meta data is worse than useless because it is misleading).

    That said, I asked the two users affected (only one response) but, according to him, he has access to the features (actually, suppression of ads) expected with the membership.

    I don't know why, though, because I haven't figured out how M2P decides whether a relationship has been paid or not if not by the payments meta_key.

    If the dev can spare the time to explain how M2P determines the difference between an active relationship that is paid versus one that is unpaid, I'd be grateful, so I can update my reporting script appropriately.

    And if s/he wants a copy of the reporting script, he is welcome to it :wink:

  • Philipp Stracker

    Hi there,

    I did not read the whole thread, just a short info on the next update that's released in a few days.
    In the new version (1.0.1) the following bugs are fixed:

    1. Confirming Manual payments will correctly set the subscription to Active.
    2. Only unprocessed IPN calls are marked as error in the transaction logs. Most IPN calls that are currently marked error will have status "ignored" in the future.
    3. In Transaction logs you get the option to change the status of transactions to "ignored" or "ok"
    4. Handling of PayPal IPN responses has improved, also the error messages in Transaction Log are clearer in future.

    As all issues are fixed or at least handled in a better/different way in the next version I'd suggest to test those things again after the update was released and if any issue persists let us know (preferably in a new thread to not mix solved issues with open ones)

    About the question in your last post: How M2 determines which subscription is paid/not paid?
    - When a payment gateway reports an incoming payment then it will instruct the invoice to be marked as paid via function MS_Model_Invoice->pay_it();
    - The pay_it function will record the payment by calling MS_Model_Relationship->add_payment();
    - While adding the payment the subscription will update the status to "active" and calculate the expire date.

    So you see, the subscription status is not created by evaluating invoices/entries in the database. Instead it is set to "active" once the payment gateway notifies us about an incoming payment. As an addition we started to record the payments in transaction logs and in the "payments" property of Subscriptions, but those details are meant for reporting/debugging and not to reliably calculate a subscription status.

    I hope this helps you to understand M2 and also that all things will work correctly for you with the next version :wink:
    Philipp

  • David King

    @Michelle Shull, @Philipp Stracker,

    Thank you both for your updates, and apologies for the delay in getting back to you.

    A lot has changed since I filed this original bug report and so I'm going to assume that the problems have been fixed. Certainly, IPN handling has very evidently improved.

    We're still having a couple of odd-ball problems, but I don't think they're IPN-related, so I'll file a new ticket.

    @Philipp Stracker, thanks for the additional detail on how payments are processed. It's been too long since I wrote the CLI tool but, if I can find time, I'll go have another look to see what/how I am checking for that (this is purely for reporting and for debugging purposes).

    Thanks again to you both.

Thank NAME, for their help.

Let NAME know exactly why they deserved these points.

Gift a custom amount of points.