Re: Updated: pipelined/halfclosed connections

On Thu, Feb 26, 2004, Adrian Chadd wrote:
> On Thu, Feb 26, 2004, Henrik Nordstrom wrote:
> > On Wed, 25 Feb 2004, Adrian Chadd wrote:
> >
> > > Ok. I've tested it and, thus far, I think I've got all the cases
> > > right. I'm having trouble convincing nc to actaully _do_ half-closed
> > > connections - instead, I have to ctrl-C it partway through a request.
> >
> > Works here.. using the procedure described with netcat-1.10.
>
> Right, ok. I'm not seeing any half-closed logic popping up in the
> squid logfiles.
>

Here is the entire exchange in the squid logfiles from this testfile2:

adrian@mierda:~$ cat testfile2
GET http://localhost/cgi-bin/test.cgi HTTP/1.1
Host: localhost
Connection: keep-alive

GET http://localhost/cgi-bin/test.cgi HTTP/1.1
Host: localhost
Connection: keep-alive

.. logging info is:

adrian@mierda:~/work/squid/run3$ cat var/logs/cache.log
2004/02/26 16:59:07| Starting Squid Cache version 3.0-PRE3-CVS for i686-pc-linux-gnu...
2004/02/26 16:59:07| Process ID 1054
2004/02/26 16:59:07| With 8192 file descriptors available
2004/02/26 16:59:07| DNS Socket created at 0.0.0.0, port 33361, FD 5
2004/02/26 16:59:07| Adding nameserver 130.95.128.2 from /etc/resolv.conf
2004/02/26 16:59:07| Adding nameserver 130.95.128.1 from /etc/resolv.conf
2004/02/26 16:59:07.992| commSetTimeout: FD 9 timeout -1
2004/02/26 16:59:07.992| commSetTimeout: FD 8 timeout -1
2004/02/26 16:59:07.992| commSetTimeout: FD 7 timeout -1
2004/02/26 16:59:08.242| commSetTimeout: FD 7 timeout -1
2004/02/26 16:59:08.242| commSetTimeout: FD 10 timeout -1
2004/02/26 16:59:08.242| Unlinkd pipe opened on FD 10
2004/02/26 16:59:08.242| Swap maxSize 8388608 KB, estimated 645277 objects
2004/02/26 16:59:08.242| Target number of buckets: 32263
2004/02/26 16:59:08.242| Using 32768 Store buckets
2004/02/26 16:59:08.242| Max Mem size: 8192 KB
2004/02/26 16:59:08.242| Max Swap size: 8388608 KB
2004/02/26 16:59:08.242| Store logging disabled
2004/02/26 16:59:08.247| commSetTimeout: FD 9 timeout -1
2004/02/26 16:59:08.248| commSetTimeout: FD 8 timeout -1
2004/02/26 16:59:08.248| commSetTimeout: FD 8 timeout -1
2004/02/26 16:59:08.248| Rebuilding storage in /home/adrian/work/squid/run3/cache (DIRTY)
2004/02/26 16:59:08.257| commSetTimeout: FD 13 timeout -1
2004/02/26 16:59:08.257| commSetTimeout: FD 12 timeout -1
2004/02/26 16:59:08.257| commSetTimeout: FD 12 timeout -1
2004/02/26 16:59:08.257| Rebuilding storage in /home/adrian/work/squid/run3/cache2 (DIRTY)
2004/02/26 16:59:08.260| commSetTimeout: FD 16 timeout -1
2004/02/26 16:59:08.260| commSetTimeout: FD 15 timeout -1
2004/02/26 16:59:08.260| commSetTimeout: FD 15 timeout -1
2004/02/26 16:59:08.260| Rebuilding storage in /home/adrian/work/squid/run3/cache3 (DIRTY)
2004/02/26 16:59:08.267| commSetTimeout: FD 19 timeout -1
2004/02/26 16:59:08.268| commSetTimeout: FD 18 timeout -1
2004/02/26 16:59:08.268| commSetTimeout: FD 18 timeout -1
2004/02/26 16:59:08.268| Rebuilding storage in /home/adrian/work/squid/run3/cache4 (DIRTY)
2004/02/26 16:59:08.268| Using Least Load store dir selection
2004/02/26 16:59:08.268| Current Directory is /home/adrian/work/squid/squid3/src
2004/02/26 16:59:08.268| Loaded Icons.
2004/02/26 16:59:08.268| Accepting HTTP connections at 0.0.0.0, port 3128, FD 21.
2004/02/26 16:59:08.268| WCCP Disabled.
2004/02/26 16:59:08.268| Ready to serve requests.
2004/02/26 16:59:08.268| Store rebuilding is 2.9% complete
2004/02/26 16:59:14| Done reading /home/adrian/work/squid/run3/cache3 swaplog (140345 entries)
2004/02/26 16:59:14| Done reading /home/adrian/work/squid/run3/cache swaplog (140714 entries)
2004/02/26 16:59:14| Done reading /home/adrian/work/squid/run3/cache2 swaplog (141774 entries)
2004/02/26 16:59:14| Done reading /home/adrian/work/squid/run3/cache4 swaplog (150305 entries)
2004/02/26 16:59:14| Finished rebuilding storage from disk.
2004/02/26 16:59:14| 531394 Entries scanned
2004/02/26 16:59:14| 0 Invalid entries.
2004/02/26 16:59:14| 0 With invalid flags.
2004/02/26 16:59:14| 531394 Objects loaded.
2004/02/26 16:59:14| 0 Objects expired.
2004/02/26 16:59:14| 0 Objects cancelled.
2004/02/26 16:59:14| 2480 Duplicate URLs purged.
2004/02/26 16:59:14| 0 Swapfile clashes avoided.
2004/02/26 16:59:14| Took 6.7 seconds (79307.3 objects/sec).
2004/02/26 16:59:14| Beginning Validation Procedure
2004/02/26 16:59:15| 262144 Entries Validated so far.
2004/02/26 16:59:15| 524288 Entries Validated so far.
2004/02/26 16:59:15| Completed Validation Procedure
2004/02/26 16:59:15| Validated 528914 Entries
2004/02/26 16:59:15| store_swap_size = 8305152k
2004/02/26 16:59:15| storeLateRelease: released 0 objects
2004/02/26 16:59:18.952| httpAccept: FD 14: accepted
2004/02/26 16:59:18.952| commSetTimeout: FD 14 timeout 300
2004/02/26 16:59:18.952| clientReadSomeData: FD 14: reading request...
2004/02/26 16:59:18.953| comm_read_try: fd 14, size 4095, retval 174, errno 0
2004/02/26 16:59:18.953| clientParseRequestMethod: Method is 'GET'
2004/02/26 16:59:18.953| parseHttpRequest: URI is 'http://localhost/cgi-bin/test.cgi'
2004/02/26 16:59:18.953| parseHttpRequest: req_hdr = {Host: localhost
Connection: keep-alive

}
2004/02/26 16:59:18.953| parseHttpRequest: end = {}
2004/02/26 16:59:18.953| parseHttpRequest: prefix_sz = 87, req_line_sz = 47
2004/02/26 16:59:18.953| parseHttpRequest: Request Header is
Host: localhost
Connection: keep-alive

2004/02/26 16:59:18.953| parseHttpRequest: Complete request received
2004/02/26 16:59:18.953| commSetTimeout: FD 14 timeout 86400
2004/02/26 16:59:18.953| conn->in.notYetUsed = 87
2004/02/26 16:59:18.953| clientSetKeepaliveFlag: http_ver = 1.1
2004/02/26 16:59:18.953| clientSetKeepaliveFlag: method = GET
2004/02/26 16:59:18.954| store_client::doCopy: co: 0, hi: 0
2004/02/26 16:59:18.954| commSetTimeout: FD 17 timeout 120
2004/02/26 16:59:18.954| commConnectStart: FD 17, data 0x8520390, localhost:80
2004/02/26 16:59:18.954| clientParseRequestMethod: Method is 'GET'
2004/02/26 16:59:18.954| parseHttpRequest: URI is 'http://localhost/cgi-bin/test.cgi'
2004/02/26 16:59:18.954| parseHttpRequest: req_hdr = {Host: localhost
Connection: keep-alive

}
2004/02/26 16:59:18.954| parseHttpRequest: end = {}
2004/02/26 16:59:18.954| parseHttpRequest: prefix_sz = 87, req_line_sz = 47
2004/02/26 16:59:18.954| parseHttpRequest: Request Header is
Host: localhost
Connection: keep-alive

2004/02/26 16:59:18.954| parseHttpRequest: Complete request received
2004/02/26 16:59:18.954| commSetTimeout: FD 14 timeout 86400
2004/02/26 16:59:18.954| conn->in.notYetUsed = 0
2004/02/26 16:59:18.954| clientSetKeepaliveFlag: http_ver = 1.1
2004/02/26 16:59:18.954| clientSetKeepaliveFlag: method = GET
2004/02/26 16:59:18.954| store_client::doCopy: co: 0, hi: 0
2004/02/26 16:59:18.954| commSetTimeout: FD 19 timeout 120
2004/02/26 16:59:18.954| commConnectStart: FD 19, data 0x85203e4, localhost:80
2004/02/26 16:59:18.954| clientReadSomeData: FD 14: reading request...
2004/02/26 16:59:18.954| commConnectCallback: fd 19, data 0x85203e4
2004/02/26 16:59:18.954| commSetTimeout: FD 19 timeout -1
2004/02/26 16:59:18.954| commConnectFree: FD 19
2004/02/26 16:59:18.954| commConnectCallback: fd 17, data 0x8520390
2004/02/26 16:59:18.954| commSetTimeout: FD 17 timeout -1
2004/02/26 16:59:18.955| commConnectFree: FD 17
2004/02/26 16:59:18.955| commSetTimeout: FD 17 timeout 900
2004/02/26 16:59:18.955| commSetTimeout: FD 19 timeout 900
2004/02/26 16:59:20.963| comm_read_try: fd 19, size 87379, retval 247, errno 0
2004/02/26 16:59:20.963| commSetTimeout: FD 19 timeout 900
2004/02/26 16:59:20.964| store_client::doCopy: co: 0, hi: 247
2004/02/26 16:59:20.964| clientSocketRecipient: Deferring request http://localhost/cgi-bin/test.cgi
2004/02/26 16:59:20.964| commSetTimeout: FD 19 timeout -1
2004/02/26 16:59:20.964| commSetTimeout: FD 19 timeout 120
2004/02/26 16:59:20.965| comm_read_try: fd 17, size 87379, retval 247, errno 0
2004/02/26 16:59:20.965| commSetTimeout: FD 17 timeout 900
2004/02/26 16:59:20.965| store_client::doCopy: co: 0, hi: 247
2004/02/26 16:59:20.965| commSetTimeout: FD 17 timeout -1
2004/02/26 16:59:20.965| commSetTimeout: FD 17 timeout 120
2004/02/26 16:59:20.966| clientWriteComplete: FD 14, sz 303, err 0, off 303, len 0x406c8a60
2004/02/26 16:59:20.966| clientWriteComplete: FD 14 Keeping Alive
2004/02/26 16:59:20.966| ClientSocketContext::keepaliveNextRequest: FD 14
2004/02/26 16:59:20.966| httpRequestFree: http://localhost/cgi-bin/test.cgi
2004/02/26 16:59:20.966| ClientSocketContext:: FD 14: calling PushDeferredIfNeeded
2004/02/26 16:59:20.966| ClientSocketContextPushDeferredIfNeeded: FD 14 Sending next
2004/02/26 16:59:20.966| clientWriteComplete: FD 14, sz 303, err 0, off 303, len 0x406c8a2c
2004/02/26 16:59:20.966| clientWriteComplete: FD 14 Keeping Alive
2004/02/26 16:59:20.966| ClientSocketContext::keepaliveNextRequest: FD 14
2004/02/26 16:59:20.966| httpRequestFree: http://localhost/cgi-bin/test.cgi
2004/02/26 16:59:20.966| ClientSocketContext:: FD 14: calling conn->readNextRequest()
2004/02/26 16:59:20.966| ConnStateData::readNextRequest: FD 14 reading next req
2004/02/26 16:59:20.966| commSetTimeout: FD 14 timeout 60
2004/02/26 16:59:37.876| comm_read_try: fd 19, size 8192, retval 0, errno 0
2004/02/26 16:59:37.876| comm_read_try: fd 17, size 8192, retval 0, errno 0
2004/02/26 16:59:37.876| commSetTimeout: FD 19 timeout -1
2004/02/26 16:59:37.876| commSetTimeout: FD 17 timeout -1
2004/02/26 17:00:20.045| requestTimeout: FD 14: lifetime is expired.
2004/02/26 17:00:20.045| commSetTimeout: FD 14 timeout -1
2004/02/26 17:00:20.045| ConnStateData::close: FD 14
2004/02/26 17:00:20.045| ConnStateData::~ConnStateData: FD 14

.. Any ideas?

Adrian
Received on Thu Feb 26 2004 - 02:02:28 MST