Hi Eliezer/All,
Thanks for your help.
PFA log snippets.
Log1.txt is having sample 1 of cache.log in which you can find the time gap.
Log2.txt is having sample 2 of client output and cache.log showing the time gap.
It seems that there is some in memory operation "StatHistCopy" which
is causing this issue, not sure though.
Squid version is: Squid Cache: Version 3.1.6.
Please let me know that if these logs are helpfull.
Thanks & Regards,
On Wed, Nov 20, 2013 at 6:11 PM, Eliezer Croitoru <eliezer@xxxxxxxxxxxx> wrote:
> Hey,
>
> Can you try another test?
> It is very nice to use wget but there are couple options that needs to be
> consider.
> Just to help you if was not there until now add: --delete-after
> to the wget command line.
>
> It's not related to squid but it helps a lot.
> Now If you are up to it I will be happy to see the machine specs and OS.
> Also what is "squid -v" output?
>
> Can you ping the machine at the time it got stuck? what about tcp-ping or
> "nc -v squid_ip port" ?
> we need to verify also in the access logs that it's not naukri.com that
> thinks your client is trying to covert it into a DDOS target.
> What about trying to access other resources?
> What is written in this 503 response page?
>
> Eliezer
>
>
> On 20/11/13 12:35, Bhagwat Yadav wrote:
>>
>> Hi,
>>
>> I enable the logging but didn't find any conclusive or decisive logs
>> so that I can forward you.
>>
>> In my testing, I am accessing same URL 500 times in a loop from the
>> client using wget.
>> Squid got hanged sometimes after 120 requests ,sometimes after 150
>> requests as:
>>
>> rm: cannot remove `index.html': No such file or directory
>> --2013-11-20 03:52:37--http://www.naukri.com/
>> Resolvingwww.naukri.com... 23.72.136.235, 23.72.136.216
>> Connecting towww.naukri.com|23.72.136.235|:80... connected.
>>
>> HTTP request sent, awaiting response... 503 Service Unavailable
>> 2013-11-20 03:53:39 ERROR 503: Service Unavailable.
>>
>>
>> Whenever it got hanged, it resumes after 1 minute e.g in above example
>> after 03:52:37 the response came at 03:53:39.
>>
>> Please provide more help.
>>
>> Many Thanks,
>> Bhagwat
>
>
This is gap of ~1 min visible in log file:
2013/11/21 00:42:44.246| fwdComplete: server FD -1 not re-forwarding status 503
status 503
2013/11/21 00:43:45.175| fwdComplete: server FD -1 not re-forwarding status 503
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
Also in below lines a two lines showing gap is observed at:
2013/11/21 00:42:44.260| clientReadSomeData: FD 8: reading request...
2013/11/21 00:43:28.921| AuthUser::cacheCleanup: Cleaning the user cache now
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
2013/11/21 00:42:44.260| PconnPool::pop: lookup for key {www.naukri.com:80-192.168.5.22} failed.
2013/11/21 00:42:44.260| FilledChecklist.cc(168) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7fff61ed2990
2013/11/21 00:42:44.260| ACLChecklist::~ACLChecklist: destroyed 0x7fff61ed2990
2013/11/21 00:42:44.260| fwdConnectStart: got outgoing addr 192.168.5.22, tos 0
2013/11/21 00:42:44.260| comm_openex: Attempt open socket for: 192.168.5.22
2013/11/21 00:42:44.260| comm_openex: Opened socket FD 10 : family=2, type=1, protocol=6
2013/11/21 00:42:44.260| fd_open() FD 10 http://www.naukri.com/
2013/11/21 00:42:44.260| fwdConnectStart: got TCP FD 10
2013/11/21 00:42:44.260| The AsyncCall SomeCloseHandler constructed, this=0x12ca220 [call97241]
2013/11/21 00:42:44.260| comm.cc(1195) commSetTimeout: FD 10 timeout 60
2013/11/21 00:42:44.260| The AsyncCall SomeTimeoutHandler constructed, this=0x13bc920 [call97242]
2013/11/21 00:42:44.260| comm.cc(1206) commSetTimeout: FD 10 timeout 60
2013/11/21 00:42:44.260| The AsyncCall SomeCommConnectHandler constructed, this=0xe37dc0 [call97243]
2013/11/21 00:42:44.260| commConnectStart: FD 10, cb 0xe37dc0*1, www.naukri.com:80
2013/11/21 00:42:44.260| The AsyncCall SomeCloseHandler constructed, this=0x12c7ba0 [call97244]
2013/11/21 00:42:44.260| ipcache_nbgethostbyname: Name 'www.naukri.com'.
2013/11/21 00:42:44.260| ipcache_nbgethostbyname: HIT for 'www.naukri.com'
2013/11/21 00:42:44.260| StoreEntry::unlock: key '5502B1298080D6C371128B36A03F5C69' count=2
2013/11/21 00:42:44.260| FilledChecklist.cc(168) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xe3d8e8
2013/11/21 00:42:44.260| ACLChecklist::~ACLChecklist: destroyed 0xe3d8e8
2013/11/21 00:42:44.260| FilledChecklist.cc(168) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xe3d688
2013/11/21 00:42:44.260| ACLChecklist::~ACLChecklist: destroyed 0xe3d688
2013/11/21 00:42:44.260| clientReadSomeData: FD 8: reading request...
2013/11/21 00:43:28.921| AuthUser::cacheCleanup: Cleaning the user cache now
2013/11/21 00:43:28.921| AuthUser::cacheCleanup: Current time: 1385016208
2013/11/21 00:43:28.921| AuthUser::cacheCleanup: Finished cleaning the user cache.
2013/11/21 00:43:29.368| statHistCopy: Dest=0x8e94a8, Orig=0x936168
2013/11/21 00:43:29.368| statHistCopy: capacity 300 300
2013/11/21 00:43:29.368| statHistCopy: min 0.00 0.00
2013/11/21 00:43:29.368| statHistCopy: max 10800000.00 10800000.00
2013/11/21 00:43:29.368| statHistCopy: scale 18.52 18.52
2013/11/21 00:43:29.368| statHistCopy: copying 1200 bytes to 0xc660b0 from 0xd99460
2013/11/21 00:43:29.368| statHistCopy: Dest=0x8e93c8, Orig=0x936088
2013/11/21 00:43:29.368| statHistCopy: capacity 300 300
2013/11/21 00:43:29.368| statHistCopy: min 0.00 0.00
Below are the prints from our script output doing wget:
First refrence is finished on same time i.e. 00:59:57 but in second reference it took 1 min
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
168
--2013-11-21 00:59:57-- http://www.naukri.com/
Resolving www.naukri.com... 198.47.108.32, 198.47.108.33
Connecting to www.naukri.com|198.47.108.32|:80... connected.
HTTP request sent, awaiting response... 503 Service Unavailable
2013-11-21 00:59:57 ERROR 503: Service Unavailable.
169
--2013-11-21 00:59:57-- http://www.naukri.com/
Resolving www.naukri.com... 198.47.108.33, 198.47.108.32
Connecting to www.naukri.com|198.47.108.33|:80... connected.
HTTP request sent, awaiting response... 503 Service Unavailable
2013-11-21 01:00:58 ERROR 503: Service Unavailable.
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
2013/11/21 01:02:18.074| ipcache_nbgethostbyname: Name 'www.naukri.com'.
2013/11/21 01:02:18.074| ipcache_nbgethostbyname: HIT for 'www.naukri.com'
2013/11/21 01:02:18.074| StoreEntry::unlock: key '013910C614B5FD6130E4EFBF093C7004' count=2
2013/11/21 01:02:18.074| FilledChecklist.cc(168) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xe3d8e8
2013/11/21 01:02:18.074| ACLChecklist::~ACLChecklist: destroyed 0xe3d8e8
2013/11/21 01:02:18.074| FilledChecklist.cc(168) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0xe3d688
2013/11/21 01:02:18.074| ACLChecklist::~ACLChecklist: destroyed 0xe3d688
2013/11/21 01:02:18.074| clientReadSomeData: FD 8: reading request...
2013/11/21 01:02:29.370| statHistCopy: Dest=0x8e94a8, Orig=0x936168
2013/11/21 01:02:29.370| statHistCopy: capacity 300 300
2013/11/21 01:02:29.370| statHistCopy: min 0.00 0.00
2013/11/21 01:02:29.370| statHistCopy: max 10800000.00 10800000.00
2013/11/21 01:02:29.370| statHistCopy: scale 18.52 18.52
2013/11/21 01:02:29.370| statHistCopy: copying 1200 bytes to 0xc33540 from 0xd99460
2013/11/21 01:02:29.370| statHistCopy: Dest=0x8e93c8, Orig=0x936088
2013/11/21 01:02:29.370| statHistCopy: capacity 300 300
2013/11/21 01:02:29.370| statHistCopy: min 0.00 0.00
2013/11/21 01:02:29.370| statHistCopy: max 10800000.00 10800000.00
2013/11/21 01:02:29.370| statHistCopy: scale 18.52 18.52
2013/11/21 01:02:29.370| statHistCopy: copying 1200 bytes to 0xc33a00 from 0xd99920
2013/11/21 01:02:29.370| statHistCopy: Dest=0x8e9400, Orig=0x9360c0
2013/11/21 01:02:29.370| statHistCopy: capacity 300 300
2013/11/21 01:02:29.370| statHistCopy: min 0.00 0.00
2013/11/21 01:02:29.370| statHistCopy: max 10800000.00 10800000.00
2013/11/21 01:02:29.370| statHistCopy: scale 18.52 18.52
2013/11/21 01:02:29.371| statHistCopy: copying 1200 bytes to 0xc3a070 from 0xd99de0
2013/11/21 01:02:29.371| statHistCopy: Dest=0x8e9438, Orig=0x9360f8
2013/11/21 01:02:29.371| statHistCopy: capacity 300 300
2013/11/21 01:02:29.371| statHistCopy: min 0.00 0.00
2013/11/21 01:02:29.371| statHistCopy: max 10800000.00 10800000.00
2013/11/21 01:02:29.371| statHistCopy: scale 18.52 18.52
2013/11/21 01:02:29.371| statHistCopy: copying 1200 bytes to 0xc3a530 from 0xd9a2a0
2013/11/21 01:02:29.371| statHistCopy: Dest=0x8e9470, Orig=0x936130
2013/11/21 01:02:29.371| statHistCopy: capacity 300 300
2013/11/21 01:02:29.371| statHistCopy: min 0.00 0.00
2013/11/21 01:02:29.371| statHistCopy: max 10800000.00 10800000.00
2013/11/21 01:02:29.371| statHistCopy: scale 18.52 18.52
2013/11/21 01:02:29.371| statHistCopy: copying 1200 bytes to 0xc3a9f0 from 0xd9a760
2013/11/21 01:02:29.371| statHistCopy: Dest=0x8e9608, Orig=0x9362c8
2013/11/21 01:02:29.371| statHistCopy: capacity 300 300
2013/11/21 01:02:29.371| statHistCopy: min 0.00 0.00
2013/11/21 01:02:29.371| statHistCopy: copying 1200 bytes to 0xc371a0 from 0xd9b0e0
2013/11/21 01:02:29.371| statHistCopy: Dest=0x8e9690, Orig=0x936350
2013/11/21 01:02:29.371| statHistCopy: capacity 300 300
2013/11/21 01:02:29.371| statHistCopy: min 0.00 0.00
2013/11/21 01:02:29.371| statHistCopy: max 600000.00 600000.00
2013/11/21 01:02:29.371| statHistCopy: scale 22.55 22.55
2013/11/21 01:02:29.371| statHistCopy: copying 1200 bytes to 0xc37660 from 0xd9b5a0
2013/11/21 01:02:29.371| statHistCopy: Dest=0x8e9720, Orig=0x9363e0
2013/11/21 01:02:29.371| statHistCopy: capacity 7 7
2013/11/21 01:02:29.371| statHistCopy: min -1.00 -1.00
2013/11/21 01:02:29.371| statHistCopy: max 6.00 6.00
2013/11/21 01:02:29.371| statHistCopy: scale 1.00 1.00
2013/11/21 01:02:29.371| statHistCopy: copying 28 bytes to 0xc91160 from 0xd9ba60
2013/11/21 01:02:29.371| statHistCopy: Dest=0x8e9790, Orig=0x936450
2013/11/21 01:02:29.371| statHistCopy: capacity 18 18
2013/11/21 01:02:29.371| statHistCopy: min -1.00 -1.00
2013/11/21 01:02:29.371| statHistCopy: max 17.00 17.00
2013/11/21 01:02:29.371| statHistCopy: scale 1.00 1.00
2013/11/21 01:02:29.371| statHistCopy: copying 72 bytes to 0x13bcc50 from 0xd9ba90
2013/11/21 01:02:29.371| statHistCopy: Dest=0x8e9800, Orig=0x9364c0
2013/11/21 01:02:29.371| statHistCopy: capacity 13 13
2013/11/21 01:02:29.371| statHistCopy: min -1.00 -1.00
2013/11/21 01:02:29.371| statHistCopy: max 12.00 12.00
2013/11/21 01:02:29.372| statHistCopy: scale 1.00 1.00
2013/11/21 01:02:29.372| statHistCopy: copying 52 bytes to 0xc33490 from 0xd9bb30
2013/11/21 01:02:29.372| statHistCopy: Dest=0x8e9838, Orig=0x9364f8
2013/11/21 01:02:29.372| statHistCopy: capacity 256 256
2013/11/21 01:02:29.372| statHistCopy: min 0.00 0.00
2013/11/21 01:02:29.372| statHistCopy: max 255.00 255.00
2013/11/21 01:02:29.372| statHistCopy: scale 1.00 1.00
2013/11/21 01:02:29.372| statHistCopy: copying 1024 bytes to 0xc33ec0 from 0xd9bb70
2013/11/21 01:03:18.186| comm.cc(2190) will call SomeTimeoutHandler(FD 10, data=0xe3f2e8) [call114014]
2013/11/21 01:03:19.187| entering SomeTimeoutHandler(FD 10, data=0xe3f2e8)
2013/11/21 01:03:19.187| AsyncCall.cc(32) make: make call SomeTimeoutHandler [call114014]
2013/11/21 01:03:19.187| fwdConnectTimeout: FD 10: 'http://www.naukri.com/'
