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

longwave’s picture

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?

JamesOakley’s picture

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.

longwave’s picture

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.

jamestombs’s picture

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.

longwave’s picture

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.

jamestombs’s picture

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.

$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:

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

longwave’s picture

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

jamestombs’s picture

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?

jamestombs’s picture

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

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

jamestombs’s picture

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.

longwave’s picture

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.

longwave’s picture

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

jamestombs’s picture

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.

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

jamestombs’s picture

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.

jamestombs’s picture

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.

jamestombs’s picture

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.

jamestombs’s picture

Scrap that, still happening.

TR’s picture

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.

jamestombs’s picture

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

DanZ’s picture

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.

jamestombs’s picture

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.

jamestombs’s picture

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

longwave’s picture

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

jamestombs’s picture

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.

jamestombs’s picture

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.

longwave’s picture

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.

jamestombs’s picture

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'

jamestombs’s picture

Status: Fixed » Postponed (maintainer needs more info)

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

Back to the start...

JamesOakley’s picture

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.

longwave’s picture

@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:

  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;
  }
JamesOakley’s picture

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.

jamestombs’s picture

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.

longwave’s picture

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.

longwave’s picture

jamestombs’s picture

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

We haven't had one since my last post.

longwave’s picture

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.

jamestombs’s picture

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.

jamestombs’s picture

Issue summary: View changes

spelling wrong

Anonymous’s picture

Issue summary: View changes

I started to have this same issue couple of days ago on 2 different sites on same hosting environment. Some orders goes trough but some will stay in state "in checkout" or "pending" in Ubercart, and "Completed" in Paypal.

What I get in Drupal logs are:
IPN failed with HTTP error Connection timed out, code -110.
Server ip: 173.0.81.1

Also this came today:
IPN failed with HTTP error error opening connection ssl://www.paypal.com:443, code 0.

What should I do? Can this be a problem in Paypal end or in my end? I think no server configuration settings have been done lately, atleast my hosting provider didnt inform any.

Settings are:

Drupal 7.26 Ubercart 7.x-3.6
Php 5.4.27

Apache/2.2.22 (Debian) DAV/2 mod_fcgid/2.3.9 mod_jk/1.2.37 mod_python/3.3.1 Python/2.7.3 mod_ssl/2.2.22 OpenSSL/1.0.1e mod_perl/2.0.7 Perl/v5.14.2

Anonymous’s picture

Again after one week same error log from uc_paypal:
IPN failed with HTTP error .... ssl://www.paypal.com:443, code 0.
ip: 173.0.81.1

In paypal the payment is completed, but order is "pending" and user new role is not activated.

Can this be a hosting issue? I have Drupal on shared hosting.

Please somebody help..

daften’s picture

What I got from my hosting provider (ubercart 7.x):

PayPal disabled SSLv3 in response to the "POODLE" vunerability. You'll have to switch the cURL request to use TLS 1.2 in order to use the PayPal sandbox. You can read more about this change at https://devblog.paypal.com/upcoming-security-changes-notice/

You can force the SSLVERSION to TLS 1.2 with the following command before any PayPal calls:
curl_setopt($curl, CURLOPT_SSLVERSION, 6);

JamesOakley’s picture

That's true, @daften.

Although, as I understand it, that change from PayPal affects calls made from your website to PayPal.

The IPN problem is the other way - it affects calls that PayPal makes back to your website. So this change should not affect you.

... Except: They now only call IPN on SSL sites, so you'd need to make sure that your site can accept IPN calls over https. That said, if your site wasn't able to receive https traffic, PayPal IPNs would always fail, so that still wouldn't account for the problem in this issue whereby IPN can sometimes fail.