php 5.3.9 socket reads take minutes (instead of < seconds) #88

seguer · 2012-01-18T23:42:02Z

Last week we had a hiccup in our system as our PHP updated to 5.3.9 from the IUS testing repository (we've since disabled the testing repo and put it back to 5.3.8)

However 5.3.9 is now considered stable, and so we've upgraded again (automatically as we use puppet) and IUS have removed 5.3.8 from their repository.

When performing socket connections in PHP to talk to beanstalkd, reads take (in my tests) 2 minutes to complete, when they should be somewhat instant. The following code can be used to test:


$socket = fsockopen('10.98.35.118', 11300);
//$socket = fsockopen('google.com.au', 80);

if ($socket)
{
  echo "Can connect.\n";
  $data = "stats\r\n";
  $write = fwrite($socket, $data, strlen($data));

  if ($write)
  {
    echo "Can write.\n";
  }

  if (feof($socket))
  {
    echo "End of file\n";
  }
  else
  {
    $meta = stream_get_meta_data($socket);
    print_r($meta);
    //$read = fread($socket, 8192);
    echo date('r') . "\n";
    $read = stream_get_line($socket, 8192, "\r\n");
    print_r($read); echo "\n";
    echo date('r') . "\n";
  }
}

echo "\n";

My output for this:

Can connect.
Can write.
Array
(
    [stream_type] => tcp_socket/ssl
    [mode] => r+
    [unread_bytes] => 0
    [seekable] =>
    [timed_out] =>
    [blocked] => 1
    [eof] =>
)
Wed, 18 Jan 2012 15:36:01 -0800
OK 864
Wed, 18 Jan 2012 15:38:01 -0800

Note that it did come back with the expected response, but it took 2 minutes to do so.

If you switch the $socket line to use google, the result is instant.

The text was updated successfully, but these errors were encountered:

seguer · 2012-01-19T00:44:40Z

Also, connecting to the beanstalkd service via telnet has no issues with write/read. The issue only occurs from PHP 5.3.9.

mariuswilms · 2012-01-19T09:40:46Z

References:
Bug 398569, https://bugs.gentoo.org/show_bug.cgi?id=398569
Bug 60719, https://bugs.php.net/bug.php?id=60719

kr · 2012-01-21T06:56:56Z

A packet trace will tell you when the response was sent to the client.
If the response is sent immediately (which would be consistent with
what we see in telnet), then it is a bug in PHP.

In that case, the PHP developers will probably want a reduced test
case. You can run something like printf 'RESPONSE\r\n'|nc -l 11300
as a substitute for beanstalkd. You might need to edit the response
to reflect the actual data sent by beanstalkd.

Otherwise, it is a bug in beanstalkd, and I'd really like to see the
packet trace.

seguer · 2012-01-22T23:04:50Z

Using printf "OK\r\n" | nc -l 11300 and my test code above, I found that the response is immediate. Below is the packet trace from tcpdump

14:45:57.706321 IP (tos 0x0, ttl  64, id 64288, offset 0, flags [DF], proto: TCP (6), length: 48) localhost.20088 > localhost.11300: S, cksum 0xab54 (correct), 1264343638:1264343638(0) win 32792 <mss 16396,nop,wscale 9>
        0x0000:  4500 0030 fb20 4000 4006 41a5 7f00 0001  E..0..@.@.A.....
        0x0010:  7f00 0001 4e78 2c24 4b5c 5a56 0000 0000  ....Nx,$K\ZV....
        0x0020:  7002 8018 ab54 0000 0204 400c 0103 0309  p....T....@.....
14:45:57.707628 IP (tos 0x0, ttl  64, id 0, offset 0, flags [DF], proto: TCP (6), length: 48) localhost.11300 > localhost.20088: S, cksum 0x16e3 (correct), 3010126069:3010126069(0) ack 1264343639 win 32792 <mss 16396,nop,wscale 9>
        0x0000:  4500 0030 0000 4000 4006 3cc6 7f00 0001  E..0..@.@.<.....
        0x0010:  7f00 0001 2c24 4e78 b36a e0f5 4b5c 5a57  ....,$Nx.j..K\ZW
        0x0020:  7012 8018 16e3 0000 0204 400c 0103 0309  p.........@.....
14:45:57.706329 IP (tos 0x0, ttl  64, id 64289, offset 0, flags [DF], proto: TCP (6), length: 40) localhost.20088 > localhost.11300: ., cksum 0xfcdf (correct), 1:1(0) ack 1 win 65
        0x0000:  4500 0028 fb21 4000 4006 41ac 7f00 0001  E..(.!@.@.A.....
        0x0010:  7f00 0001 4e78 2c24 4b5c 5a57 b36a e0f6  ....Nx,$K\ZW.j..
        0x0020:  5010 0041 fcdf 0000                      P..A....
14:45:57.706766 IP (tos 0x0, ttl  64, id 64290, offset 0, flags [DF], proto: TCP (6), length: 47) localhost.20088 > localhost.11300: P, cksum 0xfe23 (incorrect (-> 0xaada), 1:8(7) ack 1 win 65
        0x0000:  4500 002f fb22 4000 4006 41a4 7f00 0001  E../."@.@.A.....
        0x0010:  7f00 0001 4e78 2c24 4b5c 5a57 b36a e0f6  ....Nx,$K\ZW.j..
        0x0020:  5018 0041 fe23 0000 7374 6174 730d 0a    P..A.#..stats..
14:45:57.706794 IP (tos 0x0, ttl  64, id 16768, offset 0, flags [DF], proto: TCP (6), length: 40) localhost.11300 > localhost.20088: ., cksum 0xfcd8 (correct), 1:1(0) ack 8 win 65
        0x0000:  4500 0028 4180 4000 4006 fb4d 7f00 0001  E..(A.@.@..M....
        0x0010:  7f00 0001 2c24 4e78 b36a e0f6 4b5c 5a5e  ....,$Nx.j..K\Z^
        0x0020:  5010 0041 fcd8 0000                      P..A....
14:45:57.707892 IP (tos 0x0, ttl  64, id 16769, offset 0, flags [DF], proto: TCP (6), length: 44) localhost.11300 > localhost.20088: P, cksum 0xfe20 (incorrect (-> 0xa077), 1:5(4) ack 8 win 65
        0x0000:  4500 002c 4181 4000 4006 fb48 7f00 0001  E..,A.@.@..H....
        0x0010:  7f00 0001 2c24 4e78 b36a e0f6 4b5c 5a5e  ....,$Nx.j..K\Z^
        0x0020:  5018 0041 fe20 0000 4f4b 0d0a            P..A....OK..
14:45:57.707922 IP (tos 0x0, ttl  64, id 64291, offset 0, flags [DF], proto: TCP (6), length: 40) localhost.20088 > localhost.11300: ., cksum 0xfcd4 (correct), 8:8(0) ack 5 win 65
        0x0000:  4500 0028 fb23 4000 4006 41aa 7f00 0001  E..(.#@.@.A.....
        0x0010:  7f00 0001 4e78 2c24 4b5c 5a5e b36a e0fa  ....Nx,$K\Z^.j..
        0x0020:  5010 0041 fcd4 0000                      P..A....
14:45:57.707949 IP (tos 0x0, ttl  64, id 16770, offset 0, flags [DF], proto: TCP (6), length: 40) localhost.11300 > localhost.20088: F, cksum 0xfcd3 (correct), 5:5(0) ack 8 win 65
        0x0000:  4500 0028 4182 4000 4006 fb4b 7f00 0001  E..(A.@.@..K....
        0x0010:  7f00 0001 2c24 4e78 b36a e0fa 4b5c 5a5e  ....,$Nx.j..K\Z^
        0x0020:  5011 0041 fcd3 0000                      P..A....
14:45:57.713647 IP (tos 0x0, ttl  64, id 64292, offset 0, flags [DF], proto: TCP (6), length: 40) localhost.20088 > localhost.11300: F, cksum 0xfcd2 (correct), 8:8(0) ack 6 win 65
        0x0000:  4500 0028 fb24 4000 4006 41a9 7f00 0001  E..(.$@.@.A.....
        0x0010:  7f00 0001 4e78 2c24 4b5c 5a5e b36a e0fb  ....Nx,$K\Z^.j..
        0x0020:  5011 0041 fcd2 0000                      P..A....
14:45:57.713757 IP (tos 0x0, ttl  64, id 16771, offset 0, flags [DF], proto: TCP (6), length: 40) localhost.11300 > localhost.20088: ., cksum 0xfcd2 (correct), 6:6(0) ack 9 win 65
        0x0000:  4500 0028 4183 4000 4006 fb4a 7f00 0001  E..(A.@.@..J....
        0x0010:  7f00 0001 2c24 4e78 b36a e0fb 4b5c 5a5f  ....,$Nx.j..K\Z_
        0x0020:  5010 0041 fcd2 0000                      P..A....

10 packets captured
20 packets received by filter
0 packets dropped by kernel

Output from my test code

Can connect.
Can write.
Array
(
    [stream_type] => tcp_socket/ssl
    [mode] => r+
    [unread_bytes] => 0
    [seekable] =>
    [timed_out] =>
    [blocked] => 1
    [eof] =>
)
Sun, 22 Jan 2012 14:45:57 -0800
OK
Sun, 22 Jan 2012 14:45:57 -0800

This was on a local test, however a remote test (Server A running nc and tcpdump with Server B running the test code) produced the same results (however is clouded with other beanstalk protocol data, so I couldn't copy just its stuff - the response was immediate however)

kr · 2012-01-23T00:03:06Z

Thanks. Unfortunately, since this isn't a trace of beanstalkd's traffic,
and it won't help us figure out where the problem lies. Before trying
to make a reduced testcase (with something like nc) it would be
good to look at a network trace of the buggy behavior you saw
between PHP and beanstalkd.

seguer · 2012-01-23T01:54:09Z

Ah, I will get on to that shortly then.

seguer · 2012-01-23T04:28:26Z

php 5.3.9 socket test (above code) to beanstalkd

https://gist.github.com/1660581

Hangs on the read line, but all of the packets in the gist appear immediately.

Note that there is a checksum error on line 23

kr · 2012-01-23T09:04:56Z

Ok, yeah, the timestamps in the gist suggest that beanstalkd
is behaving correctly.

Note that there is a checksum error on line 23

Interesting. Does that happen consistently?
If you wait long enough for PHP to receive its response,
does the packet get resent?

seguer · 2012-01-23T09:38:19Z

Eventually the read works, in my environment it takes 2 minutes. I'm not sure if it is "resent" however.

There's been an update to the PHP issue: https://bugs.php.net/bug.php?id=60817

I'm going to see if I can try their snapshot, but we've been using packages so far to install PHP.

I can run more tests to see if the checksum is consistent.

mariuswilms · 2012-01-29T16:38:33Z

I've tested this with the fix/patch for the PHP bug mentioned earlier. I can confirm that it works. As the PHP ticket has been closed and this probably originally never was a beanstalkd bug I think it's safe to close this ticket. Except you want to further investigate into the checksum issue (that might deserve a separate ticket).

Thanks everybody for helping to track this down and providing these nice test cases. beanstalkd is great!

kr · 2012-01-30T01:43:33Z

Thanks for confirming this. Sounds good.

(A wrong checksum is not too concerning; it's not beanstalkd's job
to compute the checksum. That happens in the kernel.)

kr closed this as completed Jan 30, 2012

mariuswilms mentioned this issue May 3, 2013

stream_get_line bug mariuswilms/beanstalk#6

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

php 5.3.9 socket reads take minutes (instead of < seconds) #88

php 5.3.9 socket reads take minutes (instead of < seconds) #88

seguer commented Jan 18, 2012

seguer commented Jan 19, 2012

mariuswilms commented Jan 19, 2012

kr commented Jan 21, 2012

seguer commented Jan 22, 2012

kr commented Jan 23, 2012

seguer commented Jan 23, 2012

seguer commented Jan 23, 2012

kr commented Jan 23, 2012

seguer commented Jan 23, 2012

mariuswilms commented Jan 29, 2012

kr commented Jan 30, 2012

php 5.3.9 socket reads take minutes (instead of < seconds) #88

php 5.3.9 socket reads take minutes (instead of < seconds) #88

Comments

seguer commented Jan 18, 2012

seguer commented Jan 19, 2012

mariuswilms commented Jan 19, 2012

kr commented Jan 21, 2012

seguer commented Jan 22, 2012

kr commented Jan 23, 2012

seguer commented Jan 23, 2012

seguer commented Jan 23, 2012

kr commented Jan 23, 2012

seguer commented Jan 23, 2012

mariuswilms commented Jan 29, 2012

kr commented Jan 30, 2012