php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #52948 Improper connection closing logic leads to TIME_WAIT sockets on server
Submitted: 2010-09-29 08:36 UTC Modified: 2010-10-01 19:56 UTC
From: gilles dot rayrat at continuent dot com Assigned:
Status: Not a bug Package: MySQLi related
PHP Version: 5.2.14 OS: Any
Private report: No CVE-ID: None
 [2010-09-29 08:36 UTC] gilles dot rayrat at continuent dot com
Description:
------------
Similarly to connector/j bug reported here: http://bugs.mysql.com/bug.php?
id=56979, there is a problem with mysql disconnection logic where the TCP 
connection TIME_WAIT state is found on the server rather than on the client. With 
multiple clients and multiple connection, the MySQL server can run out of file 
descriptors quickly.

The disconnect method should first set EOF to its input, then send the QUIT 
command, then set its output to EOF, then close the socket

Note: I guess the same bug appears in MySQL-non-i as well


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2010-09-30 05:14 UTC] cataphract@php.net
-Status: Open +Status: Feedback
 [2010-09-30 05:14 UTC] cataphract@php.net
I'm sorry, I didn't get this. If I understand correctly, you would prefer the web server to be in a TIME_WAIT, rather than the database server, and for that it would have to send the first FIN packet.

But why would you prefer the web server to be in a TIME_WAIT state? The front-end side typically needs to handle many more connections.

Additionally, it would be nice if you provided an example script and its ouput (in this case, a tcpdump).
 [2010-09-30 08:45 UTC] gilles dot rayrat at continuent dot com
-Status: Feedback +Status: Open
 [2010-09-30 08:45 UTC] gilles dot rayrat at continuent dot com
Thanks for your answer.

Yes, the webserver should get the time_wait connections, since you can have several web servers but generally only one database server
Furthermore, other mysql client (perl, CLI) will properly let the time_wait connection on the client side

After some more testing, it actually appears that the behavior is somehow unpredictable (or I didn't get the logic). I sometimes got time_wait on the client, sometimes 
on the server - the following shows the case where it appears on the server.

These tests are comparing regular mysql CLI client with a simple php script.
Host u1 is the client (or webapp)
Host u2 is the mysql server

Mysql command line is:
mysql -hu2 -utungsten -psecret -P3306 test

Php script is:
<?php 
# Simple script to demonstrate the TIME_WAIT issue
# Connects to the database, nothing more

$host = "u2";         # Host where the Tungsten Connector is running
$port = 3306;            # Using the Tungsten Connector port 
$username = "tungsten"; 
$password = "secret"; 
$dbname = "test"; 
echo "Connecting to $host $username $password $dbname $port\n";
# Make the connection 
$connection = mysqli_connect($host, $username, $password, $dbname, $port); 
$connection->close();
?> 

Command to check for time_wait:
netstat -nat| grep 3306| grep TIME_WAIT

Will attach both dumps taken with wireshark
 [2010-09-30 09:03 UTC] gilles dot rayrat at continuent dot com
php:
No.     Time        Source                Destination           Protocol Info
      1 0.000000    192.168.50.129        192.168.50.128        TCP      57338 > 
mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=88257291 TSER=0 WS=5
      2 0.000550    192.168.50.128        192.168.50.129        TCP      mysql > 
57338 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=170478509 TSER=88257291 
WS=5
      3 0.000574    192.168.50.129        192.168.50.128        TCP      57338 > 
mysql [ACK] Seq=1 Ack=1 Win=5856 Len=0 TSV=88257291 TSER=170478509
      4 0.001434    192.168.50.128        192.168.50.129        MySQL    Server 
Greeting proto=10 version=5.1.26-rc-log
      5 0.001960    192.168.50.129        192.168.50.128        TCP      57338 > 
mysql [ACK] Seq=1 Ack=64 Win=5856 Len=0 TSV=88257292 TSER=170478510
      6 0.005680    192.168.50.129        192.168.50.128        MySQL    Login 
Request user=tungsten db=test
      7 0.006010    192.168.50.128        192.168.50.129        TCP      mysql > 
57338 [ACK] Seq=64 Ack=72 Win=5792 Len=0 TSV=170478511 TSER=88257293
      8 0.006073    192.168.50.128        192.168.50.129        MySQL    
Response OK
      9 0.006383    192.168.50.129        192.168.50.128        MySQL    Request 
Quit
     10 0.006618    192.168.50.128        192.168.50.129        TCP      mysql > 
57338 [FIN, ACK] Seq=75 Ack=77 Win=5792 Len=0 TSV=170478511 TSER=88257293
     11 0.006672    192.168.50.129        192.168.50.128        TCP      57338 > 
mysql [FIN, ACK] Seq=77 Ack=76 Win=5856 Len=0 TSV=88257293 TSER=170478511
     12 0.007198    192.168.50.128        192.168.50.129        TCP      mysql > 
57338 [ACK] Seq=76 Ack=78 Win=5792 Len=0 TSV=170478511 TSER=88257293



mysql CLI:

No.     Time        Source                Destination           Protocol Info
      1 0.000000    192.168.50.129        192.168.50.128        TCP      57339 > 
mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=88268477 TSER=0 WS=5
      2 0.000453    192.168.50.128        192.168.50.129        TCP      mysql > 
57339 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=170489695 TSER=88268477 
WS=5
      3 0.000671    192.168.50.129        192.168.50.128        TCP      57339 > 
mysql [ACK] Seq=1 Ack=1 Win=5856 Len=0 TSV=88268477 TSER=170489695
      4 0.001337    192.168.50.128        192.168.50.129        MySQL    Server 
Greeting proto=10 version=5.1.26-rc-log
      5 0.001504    192.168.50.129        192.168.50.128        TCP      57339 > 
mysql [ACK] Seq=1 Ack=64 Win=5856 Len=0 TSV=88268477 TSER=170489695
      6 0.001685    192.168.50.129        192.168.50.128        MySQL    Login 
Request user=tungsten db=test
      7 0.001872    192.168.50.128        192.168.50.129        TCP      mysql > 
57339 [ACK] Seq=64 Ack=72 Win=5792 Len=0 TSV=170489695 TSER=88268477
      8 0.001984    192.168.50.128        192.168.50.129        MySQL    
Response OK
      9 0.003621    192.168.50.129        192.168.50.128        MySQL    Request 
Query
     10 0.004348    192.168.50.128        192.168.50.129        MySQL    
Response
     11 0.004764    192.168.50.129        192.168.50.128        MySQL    Request 
Query
     12 0.005434    192.168.50.128        192.168.50.129        MySQL    
Response
     13 0.005698    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     14 0.005941    192.168.50.128        192.168.50.129        MySQL    
Response
     15 0.006104    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     16 0.006336    192.168.50.128        192.168.50.129        MySQL    
Response
     17 0.006438    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     18 0.006650    192.168.50.128        192.168.50.129        MySQL    
Response
     19 0.006760    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     20 0.006975    192.168.50.128        192.168.50.129        MySQL    
Response
     21 0.007077    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     22 0.007325    192.168.50.128        192.168.50.129        MySQL    
Response
     23 0.007884    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     24 0.008327    192.168.50.128        192.168.50.129        MySQL    
Response
     25 0.008498    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     26 0.008752    192.168.50.128        192.168.50.129        MySQL    
Response
     27 0.008859    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     28 0.009156    192.168.50.128        192.168.50.129        MySQL    
Response
     29 0.009269    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     30 0.009541    192.168.50.128        192.168.50.129        MySQL    
Response
     31 0.009662    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     32 0.009892    192.168.50.128        192.168.50.129        MySQL    
Response
     33 0.010019    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     34 0.010301    192.168.50.128        192.168.50.129        MySQL    
Response
     35 0.010411    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     36 0.010637    192.168.50.128        192.168.50.129        MySQL    
Response
     37 0.010762    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     38 0.011006    192.168.50.128        192.168.50.129        MySQL    
Response
     39 0.011109    192.168.50.129        192.168.50.128        MySQL    Request 
Show Fields
     40 0.011342    192.168.50.128        192.168.50.129        MySQL    
Response
     41 0.011470    192.168.50.129        192.168.50.128        MySQL    Request 
Query
     42 0.011854    192.168.50.128        192.168.50.129        MySQL    
Response
     43 0.051473    192.168.50.129        192.168.50.128        TCP      57339 > 
mysql [ACK] Seq=312 Ack=1521 Win=8000 Len=0 TSV=88268490 TSER=170489698
     44 1.131630    192.168.50.129        192.168.50.128        MySQL    Request 
Quit
     45 1.131800    192.168.50.129        192.168.50.128        TCP      57339 > 
mysql [FIN, ACK] Seq=317 Ack=1521 Win=8000 Len=0 TSV=88268760 TSER=170489698
     46 1.132174    192.168.50.128        192.168.50.129        TCP      mysql > 
57339 [FIN, ACK] Seq=1521 Ack=318 Win=5792 Len=0 TSV=170489978 TSER=88268760
     47 1.132274    192.168.50.129        192.168.50.128        TCP      57339 > 
mysql [ACK] Seq=318 Ack=1522 Win=8000 Len=0 TSV=88268760 TSER=170489978
 [2010-10-01 03:10 UTC] cataphract@php.net
-Status: Open +Status: Feedback
 [2010-10-01 03:10 UTC] cataphract@php.net
I can't reproduce this. Are you using mysqlnd?

With the mysql client (package for Ubuntu 10.4), I sometimes get a simultaneous shutdown (which means TIME_WAIT on both sides):

(look only at the source, 192.168.1.102 is the client and 192.168.1.2 is the server; the varying destination is because of DNAT)

02:20:31.109223 IP (tos 0x8, ttl 64, id 30843, offset 0, flags [DF], proto TCP (6), length 57) 192.168.1.102.50375 > 79.168.249.157.3306: P 451:456(5) ack 5105 win 23584 <nop,nop,timestamp 549252121 211008142>
02:20:31.109535 IP (tos 0x8, ttl 64, id 30844, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.102.50375 > 79.168.249.157.3306: F, cksum 0xe3b8 (correct), 456:456(0) ack 5105 win 23584 <nop,nop,timestamp 549252121 211008142>
02:20:31.109766 IP (tos 0x0, ttl 128, id 7011, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.2.3306 > 192.168.1.1.50375: F, cksum 0xc83d (correct), 5105:5105(0) ack 456 win 64705 <nop,nop,timestamp 211008872 549252121>
02:20:31.110026 IP (tos 0x0, ttl 128, id 7012, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.2.3306 > 192.168.1.1.50375: ., cksum 0xc83c (correct), ack 457 win 64705 <nop,nop,timestamp 211008872 549252121>
02:20:31.112839 IP (tos 0x8, ttl 64, id 30845, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.102.50375 > 79.168.249.157.3306: ., cksum 0xe0dd (correct), ack 5106 win 23584 <nop,nop,timestamp 549252121 211008872>

Other times I get the same I get with your example script, a client initiated shutdown, with TIME_WAIT only on the client):

02:24:51.798486 IP (tos 0x0, ttl 64, id 18397, offset 0, flags [DF], proto TCP (6), length 57) 192.168.1.102.55529 > 79.168.249.157.3306: P 70:75(5) ack 79 win 5840 <nop,nop,timestamp 549278188 211034639>
02:24:51.798790 IP (tos 0x0, ttl 64, id 18398, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.102.55529 > 79.168.249.157.3306: F, cksum 0x3dd4 (correct), 75:75(0) ack 79 win 5840 <nop,nop,timestamp 549278188 211034639>
02:24:51.800286 IP (tos 0x0, ttl 128, id 8297, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.2.3306 > 192.168.1.1.55529: ., cksum 0xdd38 (correct), ack 76 win 65086 <nop,nop,timestamp 211034940 549278188>
02:24:51.800583 IP (tos 0x0, ttl 128, id 8298, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.2.3306 > 192.168.1.1.55529: F, cksum 0xdd37 (correct), 79:79(0) ack 76 win 65086 <nop,nop,timestamp 211034940 549278188>
02:24:51.802275 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 52) 192.168.1.102.55529 > 79.168.249.157.3306: ., cksum 0x3ca6 (correct), ack 80 win 5840 <nop,nop,timestamp 549278188 211034940>

Looking at the source code for mysqlnd, it just calls the PHP stream closing function, which, on Linux, is just a call to close(). I'm by no means a socket expert, but from what I read, unless someone messed with the linger options, close() will send the FIN as soon as it's emptied the send buffer. I don't see how calling shutdown explicitly could possibly help.
 [2010-10-01 17:18 UTC] gilles dot rayrat at continuent dot com
-Status: Feedback +Status: Open
 [2010-10-01 17:18 UTC] gilles dot rayrat at continuent dot com
I'm not sure what I'm using, I am not a php user. I run ubuntu 9.10 and got the 
package "php5-mysql". If you need further info, please advise on how to collect 
it.

I also encountered the case of double time_wait, I guess that the behavior is 
not fully predictable, and depends on whom between server and client starts the 
connection closing first.

Using, on client, shutdown(sock, SHUT_RD) before sending the quit command, then 
running shutdown(sock, SHUT_WR) will give more predictable (and, at least to me, 
appropriate) results
 [2010-10-01 17:26 UTC] gilles dot rayrat at continuent dot com
Re-reading my previous comment, I realized that the 1st paragraph can be misunderstood. No offense, I just need you to tell me how to provide more accurate 
info
Cheers,
Gilles.
 [2010-10-01 18:12 UTC] cataphract@php.net
-Status: Open +Status: Feedback
 [2010-10-01 18:12 UTC] cataphract@php.net
You can check if you're using mysqlnd with phpinfo() or php -i, if in the CLI. 

Example:

php -i | grep mysqlnd
Client API library version => mysqlnd 5.0.7-dev - 091210 - $Revision: 300533 $
mysqlnd
mysqlnd => enabled
Version => mysqlnd 5.0.7-dev - 091210 - $Revision: 300533 $

If you're not using mysqlnd, then it's not our problem to fix. See:

http://www.php.net/manual/en/mysqlnd.overview.php

As to the shutdown implementation in Linux, it doesn't seem to do a whole lot with SHUT_RD (in terms of packets sent):

http://lxr.free-electrons.com/source/net/ipv4/af_inet.c#L768 (note the how++ on line #776)
http://lxr.free-electrons.com/source/net/ipv4/tcp.c#L1852

SHUT_RW would force a FIN, but my tests show a FIN is always being sent by the client. The only variable is if the FIN reaches the server before it sends its own FIN. If it does reach it before, then we have a TIME_WAIT on the client; otherwise we have a simultaneous termination and TIME_WAIT on both. There's no way we would be able to prevent this. Web servers typically wait a few seconds to allow the client to disconnect and avoid the TIME_WAIT, maybe the mysql server could do the same. In any case, it's out of our hands.
 [2010-10-01 18:58 UTC] gilles dot rayrat at continuent dot com
-Status: Feedback +Status: Open
 [2010-10-01 18:58 UTC] gilles dot rayrat at continuent dot com
So I'm not using mysqlnd at all.

This behavior is not predictable and probably depends on the link and on the 
velocity of both ends. The shutdown calls allow better control over time_wait 
tcp connection state, so why not introducing an option so that the user can 
choose the behavior he wants. Note that there are some threads where sys admins 
complain about these numerous time_wait sockets and they might appreciate the 
trick.

For the record, here is the mysql (non i) code:


<?php 
# Simple script to demonstrate the TIME_WAIT issue
# Connects to the database, nothing more

$host = "u2";         # Host where the Tungsten Connector is running
$port = 3306;            # Using the Tungsten Connector port 
$username = "tungsten"; 
$password = "secret"; 
$dbname = "test"; 
echo "Connecting to $host $username $password $dbname $port\n";
# Make the connection 
$connection = mysql_connect($host, $username, $password); 
mysql_close($connection);
?>
 [2010-10-01 19:54 UTC] cataphract@php.net
-Status: Open +Status: Bogus
 [2010-10-01 19:54 UTC] cataphract@php.net
If you're not using mysqlnd, it's not under our control how the connection is closed. We just rely on the mysql library that's installed in the system; whatever socket is used, it's opaque to us.

I have serious doubts that calling shutdown() would make any difference whatsoever. See http://lxr.free-electrons.com/source/net/ipv4/tcp.c#L1871 and compare with tcp_shutdown.

In any case, I'm closing as bogus as this is not about mysql's C client library, not mysqlnd.
 [2010-10-01 19:56 UTC] cataphract@php.net
read: "this is about mysql's C client library, not mysqlnd."
 
PHP Copyright © 2001-2022 The PHP Group
All rights reserved.
Last updated: Sun Jan 23 07:03:33 2022 UTC