Re: squid 1.1.21 dies every hour, reason found (long, 16k)

> >> Since it seems to die exactly on the hour, you could try to enable debug
> >> logging before it dies (squid -k debug). run squid -k debug at 2
> >> miniutes before full hour, and we should get a quite clear picture of
> >> what Squid was doing when it dies (if it does). If it doesn't die you
> >> can run squid -k debug again to return the logging to normal.
> >
> >Thanks again for the hint! All people who wrote about the crontab were
> >partially right: There IS a crontab job but NOT on the squid machine.
> >
> >There is some client who does periodically request a URL to see if
> >it has changed. This is done with a perl script. When this perl script
> >is run, squid dies immediately. I still have to find out what's
> >happening here but I think this perl script does something strange
> >which confuses squid and it dies.
> >
> >This script was also running a long time with 1.1.20 and never caused
> >a problem; so I am really curious finding out what has changed from
> >version 1.1.20 --> 1.1.21 to cause this behaviour...
>
> Thank you for the great debugging. Please try this patch:

Thank YOU for the quick patch.

Unfortunately, it doesn't help. But I found a way to reproduce the
problem and can definitely say now that it's NOT an error of the perl
script.

Here is how I reproduce the crash:

1. Prepare a blank cache (with squid -z). (this isn't needed, but helps
   me to start squid faster than with my 2.5GB cache :-)).

2. Start squid

3. In another windows: telnet squid_host squid_port

4. Enter the following:

   GET http://www.freebsd.org/index.html HTTP/1.0

   press RETURN two times. Now the object is fetched and displayed.
   The telnet session terminates.

5. CTRL-C to stop squid.

6. Start squid. Now the object is on the disk but NOT in memory.

7. In another windows: telnet squid_host squid_port

8. Enter the following (careful, it's HEAD not GET):

   HEAD http://www.freebsd.org/index.html HTTP/1.0

   press RETURN two times. Now squid dies...

It dies with other (but not all) URLs, too. It doesn't die always
but often.

Important is the fact that the object must reside in the diskcache
(done with the first GET) and must not be in the memory (done
by restating squid). When changing HEAD to GET it works without errors.

I have now setup a second cache only for tracking down the problem. I have
no great knowledge about squid internals but would be very pleased if can
track down the porblem with your help.

Again, here the interesting part of the logfile (ALL,9) from the above example:

1998/03/31 13:48:13| clientRedirectDone: 'http://www.freebsd.org/index.html' result=
1998/03/31 13:48:13| mime_get_header: looking for 'If-Modified-Since'
1998/03/31 13:48:13| mime_get_header: looking for 'Pragma'
1998/03/31 13:48:13| mime_get_header: looking for 'Range'
1998/03/31 13:48:13| mime_get_header: looking for 'Request-Range'
1998/03/31 13:48:13| mime_get_header: looking for 'Authorization'
1998/03/31 13:48:13| mime_get_header: looking for 'Via'
1998/03/31 13:48:13| mime_get_header: looking for 'Cache-control'
1998/03/31 13:48:13| icpProcessRequest: HEAD 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| icpProcessRequest: REQ_NOCACHE = NOT SET
1998/03/31 13:48:13| icpProcessRequest: REQ_CACHABLE = SET
1998/03/31 13:48:13| icpProcessRequest: REQ_HIERARCHICAL = NOT SET
1998/03/31 13:48:13| storeGeneratePublicKey: type=1 http://www.freebsd.org/index.html
1998/03/31 13:48:13| storeGet: looking up http://www.freebsd.org/index.html
1998/03/31 13:48:13| refreshCheck: 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| refreshCheck: Matched '^http:// 14400 40% 12096000'
1998/03/31 13:48:13| refreshCheck: age = 52417
1998/03/31 13:48:13| refreshCheck: factor = 19
1998/03/31 13:48:13| refreshCheck: NO: factor < pct
1998/03/31 13:48:13| storeLockObject: key 'http://www.freebsd.org/index.html' count=1
1998/03/31 13:48:13| storeLockObject: OK: swap_status is SWAP_OK
1998/03/31 13:48:13| new_MemObject: returning 0xd2400
1998/03/31 13:48:13| storeSwapInStart: initialized swap file '/usr/local/squid/ct/00/00/00000000' for 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| new_MemObjectData: calling memInit()
1998/03/31 13:48:13| icpProcessRequest: TCP_HIT for 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| icpSendMoreData: 'http://www.freebsd.org/index.html' sz 12617: len 0: off 0.
1998/03/31 13:48:13| comm_write: FD 19: sz 0: tout 30: hndl 0x18140: data 0xd3800.
1998/03/31 13:48:13| comm_select: 2 sockets ready at 891344893
1998/03/31 13:48:13| comm_select: FD 19 ready for writing
1998/03/31 13:48:13| commHandleWrite: FD 19: state=0x975c0, off 0, sz 0.
1998/03/31 13:48:13| clientWriteComplete: FD 19, sz 0, err 0, off 0, len 12617
1998/03/31 13:48:13| storeRegister: FD 19 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| comm_select: FD 22 ready for reading
1998/03/31 13:48:13| storeSwapInHandle: 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| storeSwapInHandle: e->swap_offset = 0
1998/03/31 13:48:13| storeSwapInHandle: e->e_current_len = 0
1998/03/31 13:48:13| storeSwapInHandle: e->object_len = 12617
1998/03/31 13:48:13| httpParseReplyHeaders: HTTP/1.1 200 OK
1998/03/31 13:48:13| httpParseReplyHeaders: Date: Mon, 30 Mar 1998 21:14:36 GMT
1998/03/31 13:48:13| httpParseReplyHeaders: Server: Apache/1.2.5
1998/03/31 13:48:13| httpParseReplyHeaders: Last-modified: Fri, 27 Mar 1998 19:50:50 GMT
1998/03/31 13:48:13| httpParseReplyHeaders: Etag: "2742ba-2fe1-351c031a"
1998/03/31 13:48:13| httpParseReplyHeaders: Content-length: 12257
1998/03/31 13:48:13| httpParseReplyHeaders: Accept-ranges: bytes
1998/03/31 13:48:13| httpParseReplyHeaders: Content-type: text/html
1998/03/31 13:48:13| httpParseReplyHeaders: Connection: close
1998/03/31 13:48:13| httpParseReplyHeaders: Etag: "2742ba-2fe1-351c031a"
1998/03/31 13:48:13| httpParseReplyHeaders: Cache-last-checked: Tuesday, 31-Mar-98 11:15:37 GMT
1998/03/31 13:48:13| httpParseReplyHeaders: Proxy-agent: Netscape-Proxy/2.53
1998/03/31 13:48:13| storeAppend: appending 8192 bytes for 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| memAppend: len 8192
1998/03/31 13:48:13| icpHandleStore: FD 19 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| icpSendMoreData: 'http://www.freebsd.org/index.html' sz 12617: len 8192: off 0.
1998/03/31 13:48:13| memCopy: offset 0: size 4096
1998/03/31 13:48:13| comm_write: FD 19: sz 360: tout 30: hndl 0x18140: data 0xd3800.
1998/03/31 13:48:13| comm_select: 2 sockets ready at 891344893
1998/03/31 13:48:13| comm_select: FD 19 ready for writing
1998/03/31 13:48:13| commHandleWrite: FD 19: state=0x975c0, off 0, sz 360.
1998/03/31 13:48:13| clientWriteComplete: FD 19, sz 360, err 0, off 8192, len 12617
1998/03/31 13:48:13| storeRegister: FD 19 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| comm_select: FD 22 ready for reading
1998/03/31 13:48:13| storeSwapInHandle: 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| storeSwapInHandle: e->swap_offset = 8192
1998/03/31 13:48:13| storeSwapInHandle: e->e_current_len = 8192
1998/03/31 13:48:13| storeSwapInHandle: e->object_len = 12617
1998/03/31 13:48:13| storeAppend: appending 4425 bytes for 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| memAppend: len 4425
1998/03/31 13:48:13| icpHandleStore: FD 19 'http://www.freebsd.org/index.html'
1998/03/31 13:48:13| icpSendMoreData: 'http://www.freebsd.org/index.html' sz 12617: len 12617: off 8192.
1998/03/31 13:48:13| memCopy: offset 8192: size 4096
FATAL: Received Segment Violation...dying.
1998/03/31 13:48:13| storeWriteCleanLog: Starting...
1998/03/31 13:48:13| comm_set_fd_lifetime: FD 20 lft -1
1998/03/31 13:48:13| Finished. Wrote 2 lines.
1998/03/31 13:48:13| Took 0 seconds ( 2.0 lines/sec).
1998/03/31 13:48:13| comm_set_fd_lifetime: FD 21 lft -1
CPU Usage: user 0 sys 0
Maximum Resident Size: 1352 KB
Page faults with physical i/o: 9
Received on Tue Mar 31 1998 - 04:00:28 MST