Debugging PayPal IPN postback failures in Magento

Today I found the solution to an interesting problem we were having for couple of days with a client e-commerce site running Magento Enterprise 1.12.0.2.

Every now and then, an order that was successfully paid with PayPal, would have it’s status stuck at “Pending Payment”. PayPal had received the payment and PayPal’s IPN (instant payment notification) service claimed it had notified Magento and even received a 200 OK response.

This issue would occur maybe once per 200 orders for a website with thousands of orders per month.

Finding the problem

As soon as I found out that this is happening, I enabled Magento’s logging as well as PayPal’s debug mode.

Cross referencing the transaction history in PayPal with the orders in Magento indicated another occurrence of this issue. The payment_paypal_standard.log contained the following error:

PayPal IPN postback failure. See paypal_unknown_ipn.log for details.

and exception.log contained:

 

2013-04-22T05:17:52+00:00 ERR (3): 
exception 'Exception' with message 'PayPal IPN postback failure. See paypal_unknown_ipn.log for details.' in /home/sitename/public_html/app/code/local/Mage/Paypal/Model/Ipn.php:193
Stack trace:
#0 /home/sitename/public_html/app/code/local/Mage/Paypal/Model/Ipn.php(118): Mage_Paypal_Model_Ipn->_postBack(Object(Varien_Http_Adapter_Curl))
#1 /home/sitename/public_html/app/code/core/Mage/Paypal/controllers/IpnController.php(43): Mage_Paypal_Model_Ipn->processIpnRequest(Array, Object(Varien_Http_Adapter_Curl))
#2 /home/sitename/public_html/app/code/core/Mage/Core/Controller/Varien/Action.php(419): Mage_Paypal_IpnController->indexAction()
#3 /home/sitename/public_html/app/code/core/Mage/Core/Controller/Varien/Router/Standard.php(250): Mage_Core_Controller_Varien_Action->dispatch('index')
#4 /home/sitename/public_html/app/code/core/Mage/Core/Controller/Varien/Front.php(176): Mage_Core_Controller_Varien_Router_Standard->match(Object(Mage_Core_Controller_Request_Http))
#5 /home/sitename/public_html/app/code/core/Mage/Core/Model/App.php(354): Mage_Core_Controller_Varien_Front->dispatch()
#6 /home/sitename/public_html/app/Mage.php(683): Mage_Core_Model_App->run(Array)
#7 /home/sitename/public_html/index.php(85): Mage::run('', 'store')
#8 {main}

 

(Note the error saying to look in paypal_unknown_ipn.log while such a file didn’t exist....)

Having accumulated the info in those log files, I could start debugging/simulating the IPN hit for the failed orders.

Short guide for debugging Magento’s IPN controller

Adding more logging in the Ipn controller or Ipn model is easy, but we want to actually step through the code to see what’s going on.

In order to do that, we can simulate an IPN call. 

We are doing this for testing/debugging purposes only, so there’s no need to extend Magento the correct way.

Grab a copy of the live Magento site and database and comment out 

if (!$this->getRequest()->isPost()) {
    return;
}

and

$data = $this->getRequest()->getPost();

in the 

Mage_Paypal_IpnController class in  app/code/core/Mage/PayPal/controllers/IpnController.php

Then, before the processIpnRequest method call, populate a new array called $data with the IPN request data: Find the order id you want to debug, find the corresponding IPN request data in the payment_paypal_standard.log file, copy the data and turn it into a PHP array. (Multiple select is very easy to do with Submlime Text 2 http://www.sublimetext.com/).

Now turn on debugging, place your breakpoints  and navigate to example.com/paypal/ipn

This should simulate a PayPal IPN. You can check in the magento backend if it hit successfully or not. If it did, you’ll see a new comment in the order comments history: IPN "Completed". Registered notification about captured amount of $318.00. Transaction ID: "12345...". and the order should have changed its status from pending to processing.

Back to our issue: PayPal IPN postback failure.

While simulating the PayPal IPN for the orders that had failed, I noticed that sometimes the response that curl (or the Varien_Http_Adapter_Curl ‘wrapper’) gave back, would be different than usual; It would add a HTTP/1.1 100 Continue Header on top of the usual HTTP/1.1 200 OK response.

While stepping through the code I saw that, if the response included a 100 Continue response, Magento’s code would fail at the following lines: 

$response = preg_split('/^\r?$/m', $response, 2);
$response = trim($response[1]);
if ($response != 'VERIFIED') {
    throw new Exception('PayPal IPN postback failure. See ' . self::DEFAULT_LOG_FILE . ' for details.');
}

Our response string looks sometimes like this:

HTTP/1.1 100 Continue
Set-Cookie: ...

HTTP/1.1 200 OK
Server: Apache
X-Frame-Options: SAMEORIGIN
Strict-Transport-Security: max-age=14400
Strict-Transport-Security: max-age=14400
Content-Type: text/html; charset=UTF-8
Date: Mon, 22 Apr 2013 09:52:36 GMT
Content-Length: 8
Connection: keep-alive
Set-Cookie: ...

VERIFIED

Instead of 

HTTP/1.1 200 OK
Server: Apache
X-Frame-Options: SAMEORIGIN
Strict-Transport-Security: max-age=14400
Strict-Transport-Security: max-age=14400
Content-Type: text/html; charset=UTF-8
Date: Mon, 22 Apr 2013 09:52:36 GMT
Content-Length: 8
Connection: keep-alive
Set-Cookie: ...

VERIFIED

The magento code compares everything after the first return with VERIFIED, this caused the if condition to evaluate to false, even when the curl response body contained VERIFIED!

Curl and HTTP/1.1 100 Continue

Curl sometimes sets the HTTP request-header field expect to 100 Continue, to make sure it can send the request.

It does this when the size of the data to send is larger than a certain threshold. This is useful if you want to send (large) files to make sure the server accepts it before sending the file itself. Also see http://www.w3.org/Protocols/rfc2616/rfc2616-sec8.html

The Fix

We could add something like the following before the $httpAdapter->write.. 

$curl_handle = $httpAdapter->getHandle() //implemented in Zend_Http_Client_Adapter_Curl

curl_setopt( $curl_handle, CURLOPT_HTTPHEADER, array( 'Expect:' ) );

This overwrites the Expect request-header field (that was previously: 100).

But because the HTTP client adapter implementation is abstracted away from the Ipn model, its not a good idea to do this. More importantly, the 100 continue expectation might actually be useful! 

A better way of improving this code would be to replace

$response = preg_split('/^\r?$/m', $response, 2);
$response = trim($response[1]);

with

$response = preg_split('/^\r?$/m', $response);
$response = trim(end($response));

That’s it! This should fix any PayPal IPN postback failures related to moments when Curl decides to add an "Expect: 100" field to the request-header.

1300 321 789