Dear Users,

I noticed something strange lately, I have had 2 payments this week with paypal that did not complete. (but they are transfered correctly to my business paypal account, so the user payed correct.) I checked the log and i see the following message:

Type uc_paypal
Date Wednesday, January 2, 2013 - 22:54
User Anonymous
Location https://www.mydomainhere.com/uc_paypal/ipn/70150
Referrer
Message IPN failed with HTTP error , code 0.
Severity error
Hostname 173.0.81.1

I never had this before.. any idee? This happend suddenly, normally all paypal payments go well, i normally have around 10-20 payments with paypal a day, i didn't change anything on my VPS and i checked my firewall and can't find any issues.
(to make it clear, all payments go still well... but this error happends ±1 time a day, because it happend in 2 days 2 times.)

Comments

Status:Active» Postponed (maintainer needs more info)

"IPN failed with HTTP error , code 0." means that drupal_http_request() reported an error, and the error code was 0 - which isn't a valid HTTP error code. This shouldn't happen in normal operation, and I am not sure why it happened here, nor why it works for you most of the time. Are there any other errors recorded in the log around the same time?

I just had this happen to me once.

@janton - what version of PHP are you using? The only server configuration change that I made recently is to upgrade from PHP 5.3 to PHP 5.4. Any explanation still leaves the erratic nature of the error in need of explanation, but it's the only change I can think of.

Status:Postponed (maintainer needs more info)» Closed (cannot reproduce)

If anyone can reproduce this, please reopen with more information - but I am not sure what we can do about it, it would appear to be either server specific or an issue at PayPal's end.

Status:Closed (cannot reproduce)» Active

We get this occasionally too. We've had it twice in the last two days but have had hundreds of other transactions go through without a problem.

HTTP Access log has the following:

173.0.81.1 - - [06/Mar/2013:17:39:33 +0000] "POST /uc_paypal/ipn/127203 HTTP/1.0" 200 -

No errors reported from PHP/Apache.

PayPal IPN history shows the below:

Instant Payment Notification (IPN) details
Message ID: 6GBXXXXXXXXXXXXX
Date/time created: 06/03/2013 17:39 GMT
Original/Resent: Original
Latest delivery attempt date/time: 06/03/2013 17:39 GMT
Notification URL: https://domain/uc_paypal/ipn/127203
HTTP response code: 200
Delivery status: Sent
No. of retries: 0
Transaction ID: 25DXXXXXXXXXXXXX
IPN type: Transaction made

So as far as PHP/Apache and PayPal are concerned the payment went through fine and there were no HTTP errors.

Status:Active» Postponed (maintainer needs more info)

Are you also on 6.x-2.x? Can you post the watchdog entry as well? Is there anything else in the watchdog around the same time that looks relevant? I am guessing this is a (very) intermittent connection failure back to PayPal that will be practically impossible to reproduce, I wonder if we can do anything to mitigate against it in code though.

Initial entry

Type uc_paypal
Date 6 March 2013
User Anonymous
Location https://domain/uc_paypal/ipn/127203
Referrer
Message Receiving IPN at URL for order 127203.
Severity notice
Hostname 173.0.81.1
Operations

Error
Type uc_paypal
Date 6 March 2013
User Anonymous
Location https://domain/uc_paypal/ipn/127203
Referrer
Message IPN failed with HTTP error , code 0.
Severity error
Hostname 173.0.81.1
Operations

Nothing else in watchdog around that time nor anything in HTTP access log.

We are using 2.x-dev although it is an old version (26 Aug 2011). A few minor changes had to be made to various Ubercart modules including PayPal to save additional data which is just adding the following below the $order being loaded.

<?php
$order
->paypal = $_POST;
?>

Then that data is processed elsewhere. I can probably update our dev site with the latest dev version but that won't really help with such an intermittent issues.

I have updated the PayPal module to have the following:

<?php
// TODO: Change this to property_exists when we have a PHP requirement >= 5.1.
 
if (array_key_exists('error', $response)) {
   
watchdog('uc_paypal', '<pre>'. print_r($response, TRUE) .'</pre>', array(), WATCHDOG_ERROR); // See what the make up of the $response is for the errors
   
watchdog('uc_paypal', 'IPN failed with HTTP error @error, code @code.', array('@error' => $response->error, '@code' => $response->code), WATCHDOG_ERROR);
    return;
  }
?>

I will update the issue when the next one comes through.

Thank you for helping debug this, I'm interested to know what the actual problem is here.

Just had two in quick succession (within 1 min of each other).

Watchdog entry (same for both):

Type uc_paypal
Date 8 March 2013
User Anonymous
Location https://domain/uc_paypal/ipn/127561
Referrer
Message
stdClass Object
(
    [code] => 0
    [error] =>
)
Severity error
Hostname 173.0.81.1
Operations

I have put some extra code in to record $req which is passed through as the data variable in drupal_http_request(). Any other places where you would think debug code could be useful?

Have added the following to drupal_http_request() within if (!$fp) {}. I suspect for whatever reason the socket isn't being opened.

<?php
watchdog
('debug', 'fsockopen - failed to open the socket<br /><pre>'. print_r($uri, TRUE) .'</pre>', array(), WATCHDOG_ERROR);
?>

That was quick, just had another one. fsockopen isn't working (although there are still other transactions going through between the errors).

Watchdog:

Type debug
Date 8 March 2013
User Anonymous
Location https://domain/uc_paypal/ipn/127574
Referrer
Message fsockopen - failed to open the socket
Array
(
    [scheme] => https
    [host] => www.paypal.com
    [path] => /cgi-bin/webscr
)
Severity error
Hostname 173.0.81.1
Operations

The request that is passed through looks fine.

fsockopen() documentation says "If the value returned in errno is 0 and the function returned FALSE, it is an indication that the error occurred before the connect() call. This is most likely due to a problem initializing the socket."

So I wonder if this is a specific configuration issue with the server or network stack? Not sure what else we can do, except somehow add retry code around drupal_http_request() - but it feels like drupal_http_request() should handle this for us.

#193073: drupal_http_request - socket not initialized also appears related to this, but won't directly deal with the problem you are seeing here.

drupal_http_request won't retry if the socket isn't opened. So I have updated the PayPal module to do a retry, but I'm not holding out much hope.

<?php
// TODO: Change this to property_exists when we have a PHP requirement >= 5.1.
if (array_key_exists('error', $response)) {
 
// If we get a socket failure, try to do another request
 
watchdog('uc_paypal', 'IPN(1) failed with HTTP error @error, code @code.', array('@error' => $response->error, '@code' => $response->code), WATCHDOG_ERROR);
 
$response = drupal_http_request($host, array(), 'POST', $req);
  if (
array_key_exists('error', $response)) {
   
watchdog('uc_paypal', 'IPN(2) failed with HTTP error @error, code @code.', array('@error' => $response->error, '@code' => $response->code), WATCHDOG_ERROR);
    return;
  }
}
?>

I guess the alternative would be to try using CURL (although the 6.x backport hasn't been recoded from the D7 version) rather than fsockopen.

Had quite a few yesterday and they always fail on the second attempt too.

Have put some more code in to check to make sure that fsockopen is getting the right parameters.

Finally got some more errors.

The data that fsockopen() is being passed is always the same whether it fails or completes so there is likely to be an underlying issue with PHP or a configuration issue, so I would suggest closing this issue as it doesn't appear to be an issue with the Ubercart code.

The alternative would be to use cURL or provide an option to use different services for the resending IPN data.

Rackspace have replied and think it may be down a soft-limit on Apache's file descriptor limit which we were close to when the last couple of errors occurred.

We will wait to see if that has stopped it, but it may be worth anyone else having the same issues to look in to increasing it.

Scrap that, still happening.

cURL has to use fsockopen() as well, so that's nota solution. I was going to suggest looking at your server resource limits - file descriptors are just one of the things aside from memory that are limited.

Rackspace have increased the limits again as apparently we were hitting the new limits even though they had been doubled from the default.

What's causing all the open file descriptors? Just ordinary incoming connections? Are the connections closing promptly (and freeing up the descriptors)? Lsof might tell you something.

If you double the available descriptors and still use them up, it makes me think that they aren't getting freed up quickly enough.

This sounds like it's not directly related to Ubercart, but it's certainly interesting. I get rare customers randomly complaining that they get bumped back to the cart page after hitting the "Review order" button. They succeed when they try later. So, I wonder if a similar issue (but with Authorize.net) could be the culprit.

We've had another since so Rackspace have run some tests in a separate script using fsockopen() and have found that SSL addresses occasionally fail whereas non-SSL don't appear to have a problem.

They are going to update the server to see if an update to openSSL will solve the issue.

Update of openSSL packages didn't work. Still investigating.

Thanks for keeping us updated on this, I hope you eventually get to the bottom of it.

May have jumped the gun on the last one.

openSSL may have been the problem, not 100% sure yet. There was a single error the day after the update was done although there is no error in watchdog which is strange (I got notification through a custom script to email the error through).

Rackspace have run a test script through 5,000 then 10,000 iterations which was previously failing which is now working fine.

We will just have to wait to see if any more come in.

It's not a bad idea to make sure the OS is up to date anyway as I am sure there will be security fixes available for a lot of the software and an update to openSSL may (hopefully) have solved it.

Status:Postponed (maintainer needs more info)» Fixed

Marking this as fixed. We've had no problems for the last two weeks since openSSL has been updated.

Thanks for the update, hopefully this will be a pointer for anyone else with the same issue. Out of interest, if you know the versions you upgraded from and to, that information might be helpful for anyone else.

Server was updated from RHEL 5.6 to RHEL 5.8.

Current openSSL version is reported as 'OpenSSL 0.9.8e-fips-rhel5 01 Jul 2008'

Status:Fixed» Postponed (maintainer needs more info)

Typical. Spoke too soon, had another one at 21:32 last night.

Back to the start...

I would have been surprised if updating OpenSSL had fixed this for every configuration, as I had it happen on a site that does not use SSL at all, so the IPN would not be sent over https. I'm no nearer to any explanation - but I'll keep following this thread in case the diagnostics move in a direction I can help with.

@JamesOakley: The error is caused when Ubercart tries to acknowledge the IPN, which is always done over HTTPS, so it appears to be either a TCP socket or SSL client issue. The code in question:

<?php
 
if (variable_get('uc_paypal_wpp_server', '') == 'https://api-3t.paypal.com/nvp') {
   
$host = 'https://www.paypal.com/cgi-bin/webscr';
  }
  else {
   
$host = variable_get('uc_paypal_wps_server', 'https://www.sandbox.paypal.com/cgi-bin/webscr');
  }
 
$response = drupal_http_request($host, array(
   
'method' => 'POST',
   
'data' => $req,
  ));
 
// TODO: Change this to property_exists when we have a PHP requirement >= 5.1.
 
if (array_key_exists('error', $response)) {
   
watchdog('uc_paypal', 'IPN failed with HTTP error @error, code @code.', array('@error' => $response->error, '@code' => $response->code), WATCHDOG_ERROR);
    return;
  }
?>

OK - that makes more sense now.

I've not had this for a while, but it's a very quiet store so that may not mean much. Is jamestamr's OpenSSL the most up to date for his version of RHEL?

# yum list installed | grep ssl
openssl.x86_64                                    1.0.0-27.el6_4.2     @updates
openssl-devel.x86_64                              1.0.0-27.el6_4.2     @updates

As you can see, I'm on Centos 6.4, so the environment is not exactly the same, but it seem's there's a 1.0 release of OpenSSL, which is more recent than 0.9.8. It's worth a shot.

Rackspace have done another test of 10,000 iterations without issue. They have replied with the following:

I can see that this is Drupal's own code, is it at all doable to extract more information when it fails? What I'm looking for is more verbosity as well as where the call is failing, if on the code level (and getting catched), if on PHP level, if on Apache level or if on kernel level.

Any thoughts on what can be done to try and get more verbose errors? The website is fairly busy so doing anything to PHP/Apache is likely to be a no-go.

You have already added all the debugging code that is possible earlier in this issue, as far as I can tell. In #10 and #11 we tracked down the failure to somewhere inside PHP when fsockopen() is being called; it is returning FALSE or NULL instead of a valid pointer, but is not setting the error code or string, which suggests there was an error initialising the socket - however I have no idea how you would debug this further from within PHP, especially when it is intermittent.

You would have thought that it would fail every time, not sporadically.

We haven't had one since my last post.

Status:Postponed (maintainer needs more info)» Closed (won't fix)

Still not sure what caused this except a failure deep inside PHP or the network stack somewhere, and at this point I am pretty certain there is nothing we can do to prevent it in Ubercart, unfortunately.

We had two more shortly after my last post but none since then. There haven't been any server changes in that time nor updates to the PayPal/Ubercart code.

Issue summary:View changes

spelling wrong