Another wierd squid 1.0.5 problem

From: Edward Moy <moy@dont-contact.us>
Date: Tue, 20 Aug 1996 23:08:26 PDT

Occassionally, fails to connect to a site, and this persists forever. In
the cache.log file, there are lines like:

[20/Aug/1996:22:52:17 -0700] comm.c:372: connect: 127.0.0.1:35456: (146) Connection refused.

In this case the URL was ftp://ftp.winsite.com/. If I run ftpget directly,
it works fine. Here is a trace after sending a SIGUSR2:

------------------------------------------------------------------------
[20/Aug/1996:22:52:17 -0700] icp.c:1737: asciiProcessInput: size = 52
[20/Aug/1996:22:52:17 -0700] icp.c:1564: parseHttpRequest: Method is 'GET'
[20/Aug/1996:22:52:17 -0700] icp.c:1573: parseHttpRequest: Request is 'ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] icp.c:1585: parseHttpRequest: HTTP version is 'HTTP/1.0'
[20/Aug/1996:22:52:17 -0700] icp.c:1601: parseHttpRequest: Request Header is

---
Accept: */*
---
[20/Aug/1996:22:52:17 -0700] icp.c:1685:	 parseHttpRequest: Complete request received
	(acl lines removed)
[20/Aug/1996:22:52:17 -0700] acl.c:733:	 aclCheck: match found, returning 1
[20/Aug/1996:22:52:17 -0700] mime.c:122:	 mime_get_header: looking for 'If-Modified-Since'
[20/Aug/1996:22:52:17 -0700] mime.c:122:	 mime_get_header: looking for 'Pragma'
[20/Aug/1996:22:52:17 -0700] mime.c:122:	 mime_get_header: looking for 'Authorization'
[20/Aug/1996:22:52:17 -0700] icp.c:670:	 icp_hit_or_miss: GET <URL:ftp://ftp.winsite.com/>
[20/Aug/1996:22:52:17 -0700] icp.c:697:	 icp_hit_or_miss: REQ_NOCACHE = NOT SET
[20/Aug/1996:22:52:17 -0700] icp.c:699:	 icp_hit_or_miss: REQ_CACHABLE = SET
[20/Aug/1996:22:52:17 -0700] icp.c:701:	 icp_hit_or_miss: REQ_HIERARCHICAL = SET
[20/Aug/1996:22:52:17 -0700] store.c:608:	 storeGeneratePublicKey: type=1 ftp://ftp.winsite.com/
[20/Aug/1996:22:52:17 -0700] store.c:573:	 storeGet: looking up ftp://ftp.winsite.com/
[20/Aug/1996:22:52:17 -0700] icp.c:755:	 icp_hit_or_miss: TCP_MISS for 'ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] icp.c:820:	 icpProcessMISS: 'GET ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] icp.c:822:	 icpProcessMISS: request_hdr:
Accept: */*
[20/Aug/1996:22:52:17 -0700] store.c:717:	 storeCreateEntry: 'ftp://ftp.winsite.com/' icp flags=51
[20/Aug/1996:22:52:17 -0700] store.c:1890:	 storeGetMemSpace: Starting...
[20/Aug/1996:22:52:17 -0700] store.c:1925:	 storeGetMemSpace: Can't purge   28884 bytes: http://home.netscape.com/home/whats-cool.html
[20/Aug/1996:22:52:17 -0700] store.c:1930:	 storeGetMemSpace: --> e->lock_count 1
[20/Aug/1996:22:52:17 -0700] store.c:1933:	 storeGetMemSpace: Current size:       28884 bytes
[20/Aug/1996:22:52:17 -0700] store.c:1934:	 storeGetMemSpace: High W Mark:      30198960 bytes
[20/Aug/1996:22:52:17 -0700] store.c:1935:	 storeGetMemSpace: Low W Mark:       25165800 bytes
[20/Aug/1996:22:52:17 -0700] store.c:1936:	 storeGetMemSpace: Entry count:        22943 items
[20/Aug/1996:22:52:17 -0700] store.c:1937:	 storeGetMemSpace: Scanned:                1 items
[20/Aug/1996:22:52:17 -0700] store.c:1938:	 storeGetMemSpace: In memory:              1 items
[20/Aug/1996:22:52:17 -0700] store.c:1939:	 storeGetMemSpace: Hot vm count:           2 items
[20/Aug/1996:22:52:17 -0700] store.c:1940:	 storeGetMemSpace: Expired:                0 items
[20/Aug/1996:22:52:17 -0700] store.c:1941:	 storeGetMemSpace: Negative Cached:        0 items
[20/Aug/1996:22:52:17 -0700] store.c:1942:	 storeGetMemSpace: Can't purge:            1 items
[20/Aug/1996:22:52:17 -0700] store.c:1943:	 storeGetMemSpace: Can't purge size:   28884 bytes
[20/Aug/1996:22:52:17 -0700] store.c:1944:	 storeGetMemSpace: Sorting LRU_list:       0 items
[20/Aug/1996:22:52:17 -0700] store.c:1977:	 storeGetMemSpace: After freeing size:   28884 bytes
[20/Aug/1996:22:52:17 -0700] store.c:1978:	 storeGetMemSpace: Purged:                   0 items
[20/Aug/1996:22:52:17 -0700] store.c:1979:	 storeGetMemSpace: Released:                 0 items
[20/Aug/1996:22:52:17 -0700] store.c:1985:	 storeGetMemSpace: Done.
[20/Aug/1996:22:52:17 -0700] store.c:228:	 new_MemObject: returning 217de0
[20/Aug/1996:22:52:17 -0700] store.c:241:	 new_StoreEntry: returning 241228
[20/Aug/1996:22:52:17 -0700] store.c:595:	 storeGeneratePrivateKey: 'ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] store.c:339:	 storeHashInsert: Inserting Entry 241228 key '125486/GET/ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] store.c:295:	 new_MemObjectData: calling memInit()
[20/Aug/1996:22:52:17 -0700] store.c:831:	 storeRegister: FD 21 '125486/GET/ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] proto.c:286:	 protoDispatch: GET URL: ftp://ftp.winsite.com/
[20/Aug/1996:22:52:17 -0700] proto.c:287:	 request_hdr: 
Accept: */*
[20/Aug/1996:22:52:17 -0700] comm.c:859:	 comm_add_close_handler: fd=21 handler=0x31e4c data=0xf17570
[20/Aug/1996:22:52:17 -0700] proto.c:309:	 protoDispatch: inside_firewall = 2 (NO_FIREWALL)
[20/Aug/1996:22:52:17 -0700] proto.c:312:	 protoDispatch: query_neighbors = 8192
[20/Aug/1996:22:52:17 -0700] proto.c:313:	 protoDispatch:         n_edges = 0
[20/Aug/1996:22:52:17 -0700] proto.c:314:	 protoDispatch:   single_parent = N/A
[20/Aug/1996:22:52:17 -0700] ipcache.c:899:	 ipcache_nbgethostbyname: FD 21: Name 'ftp.winsite.com'.
[20/Aug/1996:22:52:17 -0700] ipcache.c:924:	 ipcache_nbgethostbyname: HIT for 'ftp.winsite.com'
[20/Aug/1996:22:52:17 -0700] proto.c:499:	 getFromCache: FD 21 <URL:ftp://ftp.winsite.com/>
[20/Aug/1996:22:52:17 -0700] proto.c:500:	 getFromCache: --> type = GET
[20/Aug/1996:22:52:17 -0700] proto.c:502:	 getFromCache: --> getting from 'source'
[20/Aug/1996:22:52:17 -0700] proto.c:412:	 protoCancelTimeout: FD 21 <URL:ftp://ftp.winsite.com/>
[20/Aug/1996:22:52:17 -0700] ftp.c:597:	 FtpStart: FD 21 <URL:ftp://ftp.winsite.com/>
[20/Aug/1996:22:52:17 -0700] store.c:479:	 storeLockObject: locks 2: '125486/GET/ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] ftp.c:606:	 FtpStart: FD 21, host=ftp.winsite.com, path=/, user=anonymous, passwd=webmaster@parc.xerox.com
[20/Aug/1996:22:52:17 -0700] comm.c:859:	 comm_add_close_handler: fd=23 handler=0x21c30 data=0x29010f0
[20/Aug/1996:22:52:17 -0700] comm.c:372:	 connect: 127.0.0.1:35456: (146) Connection refused.
[20/Aug/1996:22:52:17 -0700] store.c:1703:	 storeAbort: '125486/GET/ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] store.c:479:	 storeLockObject: locks 3: '125486/GET/ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] store.c:1020:	 storeAppend: appending 800 bytes for '125486/GET/ftp://ftp.winsite.com/'
[20/Aug/1996:22:52:17 -0700] store.c:1025:	 storeAppend: growing store_mem_size by 800
[20/Aug/1996:22:52:17 -0700] store.c:1026:	 storeAppend: store_mem_size = 29684
[20/Aug/1996:22:52:17 -0700] stmem.c:212:	 memAppend: len 800
[20/Aug/1996:22:52:17 -0700] store.c:1031:	 storeAppend: e_current_len = 800
[20/Aug/1996:22:52:17 -0700] icp.c:478:	 icpHandleStore: FD 21: off 0: <URL:ftp://ftp.winsite.com/>
[20/Aug/1996:22:52:17 -0700] icp.c:483:	 icpHandleStore: abort_code=19
[20/Aug/1996:22:52:17 -0700] icp.c:372:	 icpSendERROR: code 4: port 8000: msg: 'HTTP/1.0 400 Cache Detected Error
Server: squid/1.0.5
Date: Wednesday, 21-Aug-96 05:52:17 GMT
Expires: Wednesday, 21-Aug-96 05:57:17 GMT
Last-Modified: Wednesday, 21-Aug-96 05:52:17 GMT
Content-Type: text/html
Content-Length: 565
<TITLE>ERROR: The requested URL could not be retrieved</TITLE>
<H2>The requested URL could not be retrieved</H2>
<HR>
<P>
While trying to retrieve the URL:
<A HREF="ftp://ftp.winsite.com/">ftp://ftp.winsite.com/</A>
<P>
The following error was encountered:
<UL>
<LI><STRONG>Connection Failed</STRONG>
</UL>
<P>The system returned:
<PRE><I>    (146) Connection refused</I></PRE>
<P>This means that:
<PRE>
    The remote site or server may be down.  Please try again soon.
</PRE>
<P> <HR>
<ADDRESS>
Generated by squid/1.0.5@wwwproxy0.parc.xerox.com
</ADDRESS>
'
[20/Aug/1996:22:52:17 -0700] comm.c:1362:	 comm_write: FD 21: sz 800: tout 30: hndl 273e4: data 27afd0.
[20/Aug/1996:22:52:17 -0700] store.c:538:	 storeUnlockObject: key '125486/GET/ftp://ftp.winsite.com/' count=2
[20/Aug/1996:22:52:17 -0700] comm.c:305:	 comm_set_fd_lifetime: FD 23 lft -1
[20/Aug/1996:22:52:17 -0700] comm.c:471:	 comm_close: FD 23
[20/Aug/1996:22:52:17 -0700] store.c:538:	 storeUnlockObject: key '125486/GET/ftp://ftp.winsite.com/' count=1
[20/Aug/1996:22:52:17 -0700] ipcache.c:562:	 ipcache_call_pending: Called 1 handlers.
------------------------------------------------------------------------
Anyone seen this?  I have to restart the server to clear this.
Oh yes, this is on a SunOS 5.5 (Solaris) system.
Edward Moy
Xerox Palo Alto Research Center
3333 Coyote Hill Rd.
Palo Alto, CA  94304
Email: moy@parc.xerox.com
WWW: http://www.parc.xerox.com/moy/
PGP key fingerprint: AA A1 12 00 9B 13 07 45  19 61 26 A1 AF AF 99 F3
Received on Tue Aug 20 1996 - 23:10:51 MDT

This archive was generated by hypermail pre-2.1.9 : Tue Dec 09 2003 - 16:32:49 MST