Date: Thu, 26 Jul 2001 17:18:08 -0500 From: Michael Owens <owensmk@earthlink.net> To: freebsd-hackers@freebsd.org Subject: Missing incoming data using select() Message-ID: <01072617180808.00490@mike>
next in thread | raw e-mail | index | archive | help
I have a server that uses non-blocking I/O, and consists of a process which listens and calls accept(), and passes the accepted file descriptors down to child processes for handling the client connection. Currently, it uses select(), though I plan to rewrite it using kqueue. The problem I have is that when I connect from the client, if the client immediately writes to the socket after connect() (blocking), the server's select() does not report the descriptor as being ready for reading, (although tcpdump seems to indicate otherwise). If, however, the client does a sleep(1) after connect() and before write(), it always works. It looks like the data is being sent from the client to the server in all cases, but for some reason, the server looses track of the data if the client sends it right away. Does this have anything to do with passing the file descriptor between processes? Perhaps the postmaster receives the data just before the socket descriptor is passed down to the child server (and before postmaster closes it)? But wouldn't select() also reveal the data queued to the child server if the postmaster did not read it? I am having difficulty figuring out how to track it. Here is the tcpdump output for a successful connection (when the client calls sleep(1) after connect() and before write()) sending 34 bytes, which the server sends right back: 14:43:21.332838 mike.1654 > mike.postmaster: S 1995467003:1995467003(0) win 16384 <mss 16344> (DF) 14:43:21.332907 mike.postmaster > mike.1654: S 2036815264:2036815264(0) ack 1995467004 win 17520 <mss 16344> (DF) 14:43:21.332930 mike.1654 > mike.postmaster: . ack 1 win 17520 (DF) 14:43:22.358304 mike.1654 > mike.postmaster: P 1:35(34) ack 1 win 17520 (DF) 14:43:22.418249 mike.postmaster > mike.1654: P 1:69(68) ack 35 win 17520 (DF) 14:43:22.498603 mike.1654 > mike.postmaster: F 35:35(0) ack 69 win 17520 (DF) 14:43:22.498663 mike.postmaster > mike.1654: . ack 36 win 17520 (DF) 14:43:22.508506 mike.postmaster > mike.1654: F 69:69(0) ack 36 win 17520 (DF) 14:43:22.508566 mike.1654 > mike.postmaster: . ack 70 win 17520 (DF) Here are the results for an unsuccessful exchange (when the client immediately writes after connect()) 14:40:38.942493 localhost.xnmp > localhost.postmaster: S 3152358295:3152358295(0) win 16384 <mss 16344> (DF) 14:40:38.942559 localhost.postmaster > localhost.xnmp: S 3060360366:3060360366(0) ack 3152358296 win 57344 <mss 16344> (DF) 14:40:38.942583 localhost.xnmp > localhost.postmaster: . ack 1 win 57344 (DF) 14:40:38.957527 localhost.xnmp > localhost.postmaster: P 1:35(34) ack 1 win 57344 (DF) 14:40:39.054852 localhost.postmaster > localhost.xnmp: . ack 35 win 57344 (DF) In this case, it appears as if the server does receive the data, (but select() does not report it). Also, netstat does not show any data pending on either the client's or server's queue. This may or may not help, but here is the debug output for an unsuccessful transfer between client and server (with comments). Server Log ---------- mike@mike> ./postmaster /tmp/server # Postmaster listening 16:44:43.192909 PID 3646 : server_chassis : listen() # Postmaster accepts 16:44:44.616683 PID 3646 : mplxr 0x806b000 : accept(): Starting. 16:44:43.193343 PID 3647 : mplxr 0x806a000 : add_descriptor() : connections=1 # Postmaster sends sockfd to child (PID 3646) 16:44:44.622460 PID 3646 : srvr 0x806b000 : assign_socket(): No current child. Selecting first in list. 16:44:44.623868 PID 3646 : srvr 0x806b000 : assign_socket(): Using child 3647 # Server receives sockfd, sets readable & adjusts maxfd for select() 16:44:44.667682 PID 3647 : srvr 0x806a000 : process_packet() : Received socket descriptor: sockfd = 5 16:44:44.667872 PID 3647 : mplxr 0x806a000 : add_descriptor() : descriptor=5. maxfd=5 16:44:44.668082 PID 3647 : mplxr 0x806a000 : add_descriptor() : connections=2 # Many select cycles (100), client has already written data, yet select does not show it 16:44:45.147314 PID 3647 : mplxr 0x806a000 : loop(): Zero ready descriptors. 2 connections. maxfd = 5. 16:44:45.207246 PID 3646 : mplxr 0x806b000 : loop(): Zero ready descriptors. 1 connections. maxfd = 4. 16:44:46.326954 PID 3647 : mplxr 0x806a000 : loop() : Socket 5 set to read. # Client terminates, sockfd set readable for close() 16:44:46.335515 PID 3647 : conn 0x8078000 : close() : Closing descriptor 5 16:44:46.335836 PID 3647 : mplxr 0x806a000 : close() : Closed descriptor. New maxfd=4. Now have 1 clients. Client Log ---------- # Client connects 16:44:44.621727 PID 3653 : mplxr 0xbfbfee08 : add_descriptor() : descriptor=3. maxfd=3 16:44:44.622171 PID 3653 : mplxr 0xbfbfee08 : add_descriptor() : connections=1 # Writes data 16:44:44.622266 PID 3653 : client : test_server() : Loading packet # Enters select() loop 16:44:44.622347 PID 3653 : client 0xbfbfee08 : test_server() : Looping: 10 times. 16:44:44.637189 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. # Data written to socket 16:44:44.642790 PID 3653 : mplxr 0xbfbfee08 : loop() : Client 3 needs to write. 16:44:44.643267 PID 3653 : pque 0x806a200 : write() : Wrote 34 bytes to socket. 16:44:44.643365 PID 3653 : pque 0x806a200 : write() : Number of writes: 1 # Loop waiting for data to return 16:44:44.657179 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. 16:44:44.677186 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. 16:44:44.697165 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. 16:44:44.717168 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. 16:44:44.737244 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. 16:44:44.757233 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. 16:44:44.777165 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. 16:44:44.797171 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. . . . # Kill client 16:44:46.317192 PID 3653 : mplxr 0xbfbfee08 : loop(): Zero ready descriptors. 1 connections. maxfd = 3. To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-hackers" in the body of the message
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?01072617180808.00490>