PayPal Express log shows empty responses

Question

I am diagnosing an issue that has been happening since PayPal stopped supporting SSL3. I am guessing that it is simply a coincidence that it started happening at that time, and that SSL3's retirement is not the cause, but I find it an interesting coincidence nonetheless.

Note, the server has not used SSL3, so it really should be a non-issue. The store is running Magento 1.7.

So the symptoms are that customers are checking out on the store and orders are being created in Magento; however, there are no payments captured by PayPal. Reviewing the payment_paypal_express.log reveals some interesting facts.

1. There are entries where SetExpressCheckout does not return a response. When this happens, subsequent requests finally do return a response and the payment process continues.
2. Occasionally, there are some entries where GetExpressCheckoutDetails does not return a response. There are no subsequent calls to DoExpressCheckoutPayment for this transaction but there is a fresh call to SetExpressCheckout afterwards where a new transaction is created.
3. Some orders (the ones causing problems for CSRs) are getting through SetExpressCheckout and GetExpressCheckoutDetails just fine, but then the response from DoExpressCheckoutPayment is never received. The logs just show an empty response. When this happens, a new order is created in Magento but since there was no response, there is no transaction id tied to the order and payment is never captured.

Again, it is a bit curious that the first evidence of these symptoms started happening the same day that PayPal retired SSL3 (even though the server does not/has not used SSL3).

Of course, this is a difficult bug for me to actually test and I can't just start spamming the server with dummy requests.

My gut tells me Apache is having problems allocating sufficient resources, but I wonder if anyone has some diagnostic advice for pinning the precise problem down instead of just randomly trying different Apache settings until something 'seems' to work.

---

Update

Getting my hands dirty, I started to dig through a few core files and drop some logging in here and there to try and get some more info about these failed responses. It was all sort of useful, but the key thing I came across was this snip from Paypal's NVP model:

Nvp.php::call() (1.7.0.1)

I've noticed some really nasty coding practices in other files on the server, so I'm expecting to see more if I start looking. Going through the code, I notice a crucial change between the server's file and the file provided in the core 1.7.0.0 release:

    // Unmodified code
    $response = preg_split('/^\r?$/m', $response, 2);
    $response = trim($response[1]);
    $response = $this->_deformatNVP($response);

    $debugData['response'] = $response;
    $this->_debug($debugData);

    // handle transport error
    if ($http->getErrno()) {
        Mage::logException(new Exception(
            sprintf('PayPal NVP CURL connection error #%s: %s', $http->getErrno(), $http->getError())
        ));
        $http->close();

        Mage::throwException(Mage::helper('paypal')->__('Unable to communicate with the PayPal gateway.'));
    }

    // cUrl resource must be closed after checking it for errors
    $http->close();

Now, the code from the server:

    $http->close();

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

    $debugData['response'] = $response;
    $this->_debug($debugData);

    // handle transport error
    if ($http->getErrno()) {
        Mage::logException(new Exception(
            sprintf('PayPal NVP CURL connection error #%s: %s', $http->getErrno(), $http->getError())
        ));
        Mage::throwException(Mage::helper('paypal')->__('Unable to communicate with the PayPal gateway.'));
    }

If you're paying attention, that call to $http->close() is happening before the transport errors are handled. Also notice that the comment explaining why was removed. The curl adapter is being closed before the errors are handled, meaning any errors I should be finding in exception.log are never getting there. This also explains why new orders are created in Magento even though there were errors receiving the response from Paypal. Those errors are never handled.

After I have reverted the code, I am now receiving some useful errors for these Paypal transactions that fail:

PayPal NVP CURL connection error #35: Unknown SSL protocol error in connection to api-3t.paypal.com:443

At this point, I have some additional info to look into. I'm not sure why some orders are failing and not others, as this error leads me to believe that all orders should fail in the same manner.

Answer 1

I don't believe this question will find an answer, as I suspect the issue was too localized to pinpoint.

There have been a number of server modifications on that machine that have alleviated other symptoms, and I have not seen this error in some time so I am guessing it is fixed?

In the spirit of a high answer rate, I'm going to mark this, but am happy to change down the road if there are further developments.