Re: [squid-users] daemon.log[squid-users] Squid stops responding-LTSP and WinXP clients

From: Avinash Rao <avinash.aol_at_gmail.com>
Date: Thu, 17 Sep 2009 17:45:39 +0530

On Thu, Sep 17, 2009 at 5:48 AM, Amos Jeffries <squid3_at_treenet.co.nz> wrote:
> On Wed, 16 Sep 2009 17:01:49 +0530, Avinash Rao <avinash.aol_at_gmail.com>
> wrote:
>> On Wed, Sep 16, 2009 at 4:30 PM, Amos Jeffries <squid3_at_treenet.co.nz>
>> wrote:
>>> Avinash Rao wrote:
>>>>
>>>> On Wed, Sep 16, 2009 at 4:20 PM, Amos Jeffries <squid3_at_treenet.co.nz>
>>>> wrote:
>>>>>
>>>>> Avinash Rao wrote:
>>>>>>
>>>>>> On Wed, Sep 16, 2009 at 1:49 PM, Avinash Rao <avinash.aol_at_gmail.com>
>>>>>> wrote:
>>>>>>>
>>>>>>> On Tue, Sep 15, 2009 at 4:46 AM, Henrik Nordstrom
>>>>>>> <henrik_at_henriknordstrom.net> wrote:
>>>>>>>>
>>>>>>>> mån 2009-09-14 klockan 19:33 +0530 skrev Avinash Rao:
>>>>>>>>
>>>>>>>>> I am having problems with Squid everyday.. twice everyday to be
>>>>>>>>> precise.
>>>>>>>>> Squid stops responding.. I have to restart squid service to resume
>>>>>>>>> service. Even the old cache_mem = 100MB setting had the same
>>>>>>>>> problem,
>>>>>>>>> the current setting of cache_dir = null /tmp is also giving the
>>>>>>>>> same
>>>>>>>>> problem.
>>>>>>>>>
>>>>>>>>> How do i resolve this?
>>>>>>>>
>>>>>>>> By first figuring out how and why it's stopping.
>>>>>>>>
>>>>>>>> Is the process still running?
>>>>>>>>
>>>>>>>> Is there anything in cache.log saying why it stopped?
>>>>>>>>
>>>>>>>> Regards
>>>>>>>> Henrik
>>>>>>>>
>>>>>>>>
>>>>>>> Hi,
>>>>>>>
>>>>>>> I don't see anything related to squid in /var/log/messages but there
>>>>>>> a
>>>>>>> lot of entries which says -Mark- and few entries of the below
>>>>>>>
>>>>>>> Sep 14 12:13:18 sunbox kernel: [  112.579221] system 00:0e: iomem
>>>>>>> range 0x100000 -0xdfffffff could not be reserved
>>>>>>>
>>>>>>> Sep 14 12:13:18 sunbox kernel: [    0.000000] swsusp: Registered
>>>>>>> nosave memory region: 000000000009f000 - 00000000000a0000
>>>>>>>
>>>>>>> The cache.log is not populated:
>>>>>>>
>>>>>>> root_at_sunbox:/var/log/squid# more cache.log.1
>>>>>>> 2009/09/15 08:02:19| storeDirWriteCleanLogs: Starting...
>>>>>>> 2009/09/15 08:02:19|   Finished.  Wrote 0 entries.
>>>>>>> 2009/09/15 08:02:19|   Took 0.0 seconds (   0.0 entries/sec).
>>>>>>> 2009/09/15 08:02:19| logfileRotate: /var/log/squid/store.log
>>>>>>> 2009/09/15 08:02:19| logfileRotate: /var/log/squid/access.log
>>>>>>> 2009/09/15 14:55:30| storeLocateVary: Not our vary marker object,
>>>>>>> 78ED95245D6EA8
>>>>>>> CBB231047CAEE1E30F = 'http://m1.2mdn.net/879366/flashwrite_1_2.js',
>>>>>>> 'accept-enco
>>>>>>> ding="gzip,deflate"'/'-'

>>>>>>> 2009/09/15 14:59:49| storeLocateVary: Not our vary marker object,
>>>>>>> 78ED95245D6EA8
>>>>>>> CBB231047CAEE1E30F = 'http://m1.2mdn.net/879366/flashwrite_1_2.js',
>>>>>>> 'accept-enco
>>>>>>> ding="gzip,deflate"'/'-'
>>>>>>>
>>>>>>>  more cache.log
>>>>>>> 2009/09/16 07:58:04| storeDirWriteCleanLogs: Starting...
>>>>>>> 2009/09/16 07:58:04|   Finished.  Wrote 0 entries.
>>>>>>> 2009/09/16 07:58:04|   Took 0.0 seconds (   0.0 entries/sec).
>>>>>>> 2009/09/16 07:58:04| logfileRotate: /var/log/squid/store.log
>>>>>>> 2009/09/16 07:58:04| logfileRotate: /var/log/squid/access.log
>>>>>>> 2009/09/16 08:38:01| httpReadReply: Excess data from "GET
>>>>>>> http://webcs.msg.yahoo
>>>>>>> .com/crossdomain.xml"
>>>>>>>
>>>>>>> Avinash
>>>>>>>
>>>>>> Daemon.log
>>>>>> Here's what the daemon.log file reads if i restart squid.
>>>>>>
>>>>>> Sep 16 15:14:28 sunbox squid[6382]: Preparing for shutdown after
> 38603
>>>>>> requests
>>>>>> Sep 16 15:14:28 sunbox squid[6382]: Waiting 30 seconds for active
>>>>>> connections to finish
>>>>>> Sep 16 15:14:28 sunbox squid[6382]: FD 10 Closing HTTP connection
>>>>>> Sep 16 15:14:59 sunbox squid[6382]: Shutting down...
>>>>>> Sep 16 15:14:59 sunbox squid[6382]: FD 11 Closing ICP connection
>>>>>> Sep 16 15:14:59 sunbox squid[6382]: WARNING: Closing client
>>>>>> 10.10.10.200 connection due to lifetime timeout
>>>>>> Sep 16 15:14:59 sunbox squid[6382]:
>>>>>>
>>>>>>
>>>>>>
> ^Ihttp://mail.google.com/a/aolcep.org/channel/bind?VER=6&it=200825&at=xn3j31vv6ibmsnkg4qg2ctmvxmdqru&RID=rpc&SID=EBB5D5B4EDA6065B&CI=0&AID=163&TYPE=xmlhttp&zx=z3okb8-nrvdq2&t=1
>>>>>> Sep 16 15:14:59 sunbox squid[6382]: WARNING: Closing client
>>>>>> 10.10.10.200 connection due to lifetime timeout
>>>>>> Sep 16 15:14:59 sunbox squid[6382]:
>>>>>>
>>>>>>
>>>>>>
> ^Ihttp://mail.google.com/mail/channel/bind?VER=6&it=417745&at=xn3j2ue36lbqrpvy8tuyo5qm4yr368&RID=rpc&SID=ACC227B9816E025D&CI=0&AID=561&TYPE=xmlhttp&zx=ag3xlj-tk3pkm&t=1
>>>>>> 6Zb3tnokBgp5TovAALAIKL_Q2qeeRC_OTEe6m9cmy-U67iM3IF8j0TdQQ==
>>>>>> Sep 16 15:14:59 sunbox squid[6382]: storeDirWriteCleanLogs:
>>>>>> Starting...
>>>>>> Sep 16 15:14:59 sunbox squid[6382]:   Finished.  Wrote 0 entries.
>>>>>> Sep 16 15:14:59 sunbox squid[6382]:   Took 0.0 seconds (   0.0
>>>>>> entries/sec).
>>>>>> Sep 16 15:14:59 sunbox squid[6382]: Squid Cache (Version
>>>>>> 2.6.STABLE18): Exiting normally.
>>>>>> Sep 16 15:14:59 sunbox squid[6379]: Squid Parent: child process 6382
>>>>>> exited with status 0
>>>>>> Sep 16 15:15:01 sunbox squid[17927]: Creating Swap Directories
>>>>>> Sep 16 15:15:01 sunbox squid[17931]: Squid Parent: child process
> 17934
>>>>>> started
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Starting Squid Cache version
>>>>>> 2.6.STABLE18 for amd64-debian-linux-gnu...
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Process ID 17934
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: With 1024 file descriptors
>>>>>> available
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Using epoll for the IO loop
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: DNS Socket created at 0.0.0.0,
>>>>>> port 57386, FD 7
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Adding nameserver 192.168.1.1
>>>>>> from /etc/resolv.conf
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: User-Agent logging is disabled.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Referer logging is disabled.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Swap maxSize 0 KB, estimated 0
>>>>>> objects
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Target number of buckets: 0
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Using 8192 Store buckets
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Max Mem  size: 8192 KB
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Max Swap size: 0 KB
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Local cache digest enabled;
>>>>>> rebuild/rewrite every 3600/3600 sec
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Using Least Load store dir
>>>>>> selection
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Set Current Directory to
>>>>>> /var/spool/squid
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Loaded Icons.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Accepting proxy HTTP connections
>>>>>> at 10.10.10.200, port 3128, FD 10.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Accepting ICP messages at
>>>>>> 0.0.0.0, port 3130, FD 11.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: HTCP Disabled.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: WCCP Disabled.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Ready to serve requests.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Finished rebuilding storage from
>>>>>> disk.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:         0 Entries scanned
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:         0 Invalid entries.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:         0 With invalid flags.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:         0 Objects loaded.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:         0 Objects expired.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:         0 Objects cancelled.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:         0 Duplicate URLs purged.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:         0 Swapfile clashes
>>>>>> avoided.
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:   Took 0.0 seconds (   0.0
>>>>>> objects/sec).
>>>>>> Sep 16 15:15:01 sunbox squid[17934]: Beginning Validation Procedure
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:   Completed Validation Procedure
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:   Validated 0 Entries
>>>>>> Sep 16 15:15:01 sunbox squid[17934]:   store_swap_size = 0k
>>>>>> Sep 16 15:15:02 sunbox squid[17934]: storeLateRelease: released 0
>>>>>> objects
>>>>>
>>>>> Looks annoyingly normal :(
>>>>> Nothing to indicate any problems yet.
>>>>>
>>>>> Is your traffic load small enough or disk space large enough to run
>>>>> Squid
>>>>> with -X (full debug output to the logs) command line option?
>>>>>
>>>>> Amos
>>>>> --
>>>>> Please be using
>>>>>  Current Stable Squid 2.7.STABLE6 or 3.0.STABLE19
>>>>>  Current Beta Squid 3.1.0.13
>>>>>
>>>>
>>>>
>>>> Yes, I don;t see a network traffic problem cox i have 4 network ports
>>>> enabled on my server and one is dedicated for squid and about 20 WinXP
>>>> + 5 LTSP users using internet at all times so its not all that big
>>>> traffic.
>>>>
>>>> Yes, I have lots of HDD space that can be used to enable full debug,
>>>> how do i do this? and how much space do i need.
>>>
>>> I would guess a few dozen KB per request is dumping to the logs for the
>>> time
>>> it takes Squid to stop responding.
>>>
>>> It's done by adding "-X" to the command line options Squid starts with.
>>> Locate how Squid us starting and see if the startup command or script
>>> (maybe
>>> /etc/init.d/squid ?) can be added to the other options passed to Squid.
>>>
>>> Amos
>>> --
>>> Please be using
>>>  Current Stable Squid 2.7.STABLE6 or 3.0.STABLE19
>>>  Current Beta Squid 3.1.0.13
>>>
>>
>> Is this same as using debug_option ALL, 1 in squid.conf.
>
> No its similar to using debug_options ALL,9 in squid.conf and additionally
> dumping the same level of debug during startup/shutdown to daemon.log when
> cache.log is not available.
>
> Amos

Let me get this working, currently, i have the debug_options ALL, 1 in
my squid.conf, will set it to 9 and check wat happens.

>
Received on Thu Sep 17 2009 - 12:15:49 MDT

This archive was generated by hypermail 2.2.0 : Thu Sep 17 2009 - 12:00:03 MDT