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.”:wink:

• 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.