Bug #52948 [Opn]: Improper connection closing logic leads to TIME_WAIT sockets on server

2010-10-01 Thread gilles dot rayrat at continuent dot com
Edit report at http://bugs.php.net/bug.php?id=52948edit=1

 ID: 52948
 User updated by:gilles dot rayrat at continuent dot com
 Reported by:gilles dot rayrat at continuent dot com
 Summary:Improper connection closing logic leads to TIME_WAIT
 sockets on server
 Status: Open
 Type:   Bug
 Package:MySQLi related
 Operating System:   Any
 PHP Version:5.2.14
 Block user comment: N

 New Comment:

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.


Previous Comments:

[2010-10-01 17:18:55] 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 03:10:15] cataphr...@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-09-30 09:03:39] gilles dot rayrat at continuent dot com

php:

No. TimeSourceDestination   Protocol
Info

  1 0.00192.168.50.129192.168.50.128TCP 
57338  

mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=88257291 TSER=0 WS=5

  2 0.000550192.168.50.128192.168.50.129TCP 
mysql  

57338 [SYN, ACK] Seq=0 Ack=1 Win=5792 

Bug #52948 [Opn]: Improper connection closing logic leads to TIME_WAIT sockets on server

2010-09-30 Thread gilles dot rayrat at continuent dot com
Edit report at http://bugs.php.net/bug.php?id=52948edit=1

 ID: 52948
 User updated by:gilles dot rayrat at continuent dot com
 Reported by:gilles dot rayrat at continuent dot com
 Summary:Improper connection closing logic leads to TIME_WAIT
 sockets on server
 Status: Open
 Type:   Bug
 Package:MySQLi related
 Operating System:   Any
 PHP Version:5.2.14
 Block user comment: N

 New Comment:

php:

No. TimeSourceDestination   Protocol
Info

  1 0.00192.168.50.129192.168.50.128TCP 
57338  

mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=88257291 TSER=0 WS=5

  2 0.000550192.168.50.128192.168.50.129TCP 
mysql  

57338 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=170478509
TSER=88257291 

WS=5

  3 0.000574192.168.50.129192.168.50.128TCP 
57338  

mysql [ACK] Seq=1 Ack=1 Win=5856 Len=0 TSV=88257291 TSER=170478509

  4 0.001434192.168.50.128192.168.50.129MySQL   
Server 

Greeting proto=10 version=5.1.26-rc-log

  5 0.001960192.168.50.129192.168.50.128TCP 
57338  

mysql [ACK] Seq=1 Ack=64 Win=5856 Len=0 TSV=88257292 TSER=170478510

  6 0.005680192.168.50.129192.168.50.128MySQL   
Login 

Request user=tungsten db=test

  7 0.006010192.168.50.128192.168.50.129TCP 
mysql  

57338 [ACK] Seq=64 Ack=72 Win=5792 Len=0 TSV=170478511 TSER=88257293

  8 0.006073192.168.50.128192.168.50.129MySQL   


Response OK

  9 0.006383192.168.50.129192.168.50.128MySQL   
Request 

Quit

 10 0.006618192.168.50.128192.168.50.129TCP 
mysql  

57338 [FIN, ACK] Seq=75 Ack=77 Win=5792 Len=0 TSV=170478511
TSER=88257293

 11 0.006672192.168.50.129192.168.50.128TCP 
57338  

mysql [FIN, ACK] Seq=77 Ack=76 Win=5856 Len=0 TSV=88257293
TSER=170478511

 12 0.007198192.168.50.128192.168.50.129TCP 
mysql  

57338 [ACK] Seq=76 Ack=78 Win=5792 Len=0 TSV=170478511 TSER=88257293







mysql CLI:



No. TimeSourceDestination   Protocol
Info

  1 0.00192.168.50.129192.168.50.128TCP 
57339  

mysql [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=88268477 TSER=0 WS=5

  2 0.000453192.168.50.128192.168.50.129TCP 
mysql  

57339 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1460 TSV=170489695
TSER=88268477 

WS=5

  3 0.000671192.168.50.129192.168.50.128TCP 
57339  

mysql [ACK] Seq=1 Ack=1 Win=5856 Len=0 TSV=88268477 TSER=170489695

  4 0.001337192.168.50.128192.168.50.129MySQL   
Server 

Greeting proto=10 version=5.1.26-rc-log

  5 0.001504192.168.50.129192.168.50.128TCP 
57339  

mysql [ACK] Seq=1 Ack=64 Win=5856 Len=0 TSV=88268477 TSER=170489695

  6 0.001685192.168.50.129192.168.50.128MySQL   
Login 

Request user=tungsten db=test

  7 0.001872192.168.50.128192.168.50.129TCP 
mysql  

57339 [ACK] Seq=64 Ack=72 Win=5792 Len=0 TSV=170489695 TSER=88268477

  8 0.001984192.168.50.128192.168.50.129MySQL   


Response OK

  9 0.003621192.168.50.129192.168.50.128MySQL   
Request 

Query

 10 0.004348192.168.50.128192.168.50.129MySQL   


Response

 11 0.004764192.168.50.129192.168.50.128MySQL   
Request 

Query

 12 0.005434192.168.50.128192.168.50.129MySQL   


Response

 13 0.005698192.168.50.129192.168.50.128MySQL   
Request 

Show Fields

 14 0.005941192.168.50.128192.168.50.129MySQL   


Response

 15 0.006104192.168.50.129192.168.50.128MySQL   
Request 

Show Fields

 16 0.006336192.168.50.128192.168.50.129MySQL   


Response

 17 0.006438192.168.50.129192.168.50.128MySQL   
Request 

Show Fields

 18 0.006650192.168.50.128192.168.50.129MySQL   


Response

 19 0.006760192.168.50.129192.168.50.128MySQL   
Request 

Show Fields

 20 0.006975192.168.50.128192.168.50.129MySQL   


Response

 21 0.007077192.168.50.129192.168.50.128MySQL   
Request 

Show Fields

 22 0.007325192.168.50.128192.168.50.129MySQL   


Response

 23 0.007884192.168.50.129192.168.50.128MySQL   
Request 

Show Fields

 24 0.008327192.168.50.128192.168.50.129MySQL   


Response

 25 0.008498192.168.50.129192.168.50.128MySQL   
Request 

Show Fields

 26 0.008752