Hi,

I'm trying to use httprl for a single GET against a webservice that sometimes hangs while servicing the request. I'm setting a timeout of 5 seconds. The server times out after 60 seconds naturally.

The call looks like:

httprl_request($url, array('timeout' => 5, 'blocking' => true));
$res = httprl_send_request();

The problem is that the timeout doesn't seem to apply to the time waiting for the server to turn the request around. What seems to be happening is that the write stream is closed on the first loop, since there's nothing for it to write. This sets $stream_write_count back to 0. On the next (and subsequent) loops, stream_select() returns immediately (with value 1), having emptied $read but with the stream still in $write. Because the code that checks the timeout only runs if there's something in $read or $stream_write_count > 0, neither of which are matching in this case, nothing seems to be decrementing or checking the timeout, and the loop is spinning empty until the server gives up.

I'm not too hot on how this all works, but to me I think the problem is that on a blocking request, the socket is not closed after writing, and so stream_select() continues to think it's changing? I imagine the desired behaviour would be for stream_select() to block until $read has data available, but even if it doesn't, it would still timeout with $read empty, and so the timeout wouldn't be checked. Maybe the timeout check needs to be moved into the main loop, not inside the read/write code?

The request eventually times out after 60 seconds, when the server gives up and writes a 500. The timeout then finally kicks in because there's something to read, and instead of returning the 500, I get the HTTP_REQUEST_TIMEOUT:

object(stdClass)#150 (8) {
  ["url"]=>
  string(157) "[removed]"
  ["request"]=>
  string(370) "GET /api/find.json?private_api_key=[removed]&address_line_1=______dsdastfsdr__dsdfswf__3__%29_____&type=All HTTP/1.0
Host: [removed]
User-Agent: Drupal (+http://drupal.org/)
Connection: close"
  ["status"]=>
  string(5) "Done."
  ["data"]=>
  string(0) ""
  ["options"]=>
  array(7) {
    ["timeout"]=>
    float(-56.50444)
    ["blocking"]=>
    bool(true)
    ["headers"]=>
    array(4) {
      ["Host"]=>
      string(20) "address.nzpost.co.nz"
      ["User-Agent"]=>
      string(28) "Drupal (+http://drupal.org/)"
      ["Connection"]=>
      string(5) "close"
      ["Referer"]=>
      string(123) "[removed]"
    }
    ["method"]=>
    string(3) "GET"
    ["data"]=>
    NULL
    ["max_redirects"]=>
    int(3)
    ["context"]=>
    NULL
  }
  ["chunk_size"]=>
  int(1024)
  ["error"]=>
  string(17) "request timed out"
  ["code"]=>
  string(20) "HTTP_REQUEST_TIMEOUT"
}

As you can see, the timeout in the result is now seriously negative.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

mikeytown2’s picture

Status: Active » Needs review
FileSize
2.36 KB

Semi-related, as right now I do not make the initial connection async; so it can timeout here in the httprl_request() function; but this shouldn't be your case.
#1317482: See if I can use stream_set_blocking() before creating the connection.

The read & write loops both contain the same pointer to the same stream. Closing the stream when we are done writing makes reading back impossible. That's the trick with non blocking mode, after we are done writing to the stream we ignore the response by closing the connection.

As for the bog report, I've added in some more verbose messages so it will let you know what part of the request timed out; the read, the write and I've now added in a no streams available timeout as well. I'm not 100% sure this patch will fix the timeout issue; at least with this we can pinpoint what is timing out.

neilnz’s picture

FileSize
2.42 KB

This didn't fix the issue. It still bailed after the 60 second server timeout with "request timed out, read".

Because if (!empty($n)) { still returns true ($n is 1), the new timeout checking code doesn't get run. I imagine that you didn't mean to add it there, as that's right before the loop is unconditionally broken anyway (which also causes a return).

By taking the timeout scanning code outside the else {} block it fixed the problem in my case (the loop bailed with "request timed out, no streams available" as it should, after 5 seconds waiting for the server.

I've attached a modified version of your patch that works for me.

mikeytown2’s picture

FileSize
9.17 KB

If we are putting the timeout checking code in the main event loop then I can simplify the code. I was assuming that the foreach ($read ... portion would be checking the timeout but it appears that is incorrect.

This patch cuts about 0.5kb from the module file.

mikeytown2’s picture

Status: Needs review » Fixed

committed #3; marking this as fixed.

Status: Fixed » Closed (fixed)

Automatically closed -- issue fixed for 2 weeks with no activity.

Anonymous’s picture

Issue summary: View changes

Adding information about the response