Re: ICAP communication stalling

why dont you exclude some netflix content from the icap service?(just
throwing to the air)

what is the icap max connections?
i have used icap on a 50 max connections but you might need some more.

Eliezer

On 02/05/2012 00:03, Guy Helmer wrote:
>
> I have Squid (sync'ed with trunk as of -r12082 (2012-03-07 v3.2.0.16+)) running at a site where it is configured to use ICAP respmod to analyze several binary/executable content types, and as a result Squid was sending many large Netflix HTTP responses to the icap service.
>
> Under what seems to be a heavy load at the time, about 25 of the connections from squid to icap stalled in the midst of the respmod request. Based on packet traces, icap received roughly 50% to 90% of the encapsulated HTTP response before the connection went quiet. The stalled requests all look similar to this:
>
> 4 13:32:27.149901 127.0.0.1 -> 127.0.0.1 ICAP RESPMOD icap://127.0.0.1:1344/mw ICAP/1.0
>
> 0000 02 00 00 00 45 00 04 48 ec c1 40 00 40 06 00 00 ....E..H..@.@...
> 0010 7f 00 00 01 7f 00 00 01 2d 83 05 40 24 13 1b 0b ........-..@$...
> 0020 4e 06 72 f8 80 18 23 00 02 3d 00 00 01 01 08 0a N.r...#..=......
> 0030 0f 7e 72 cd d5 08 7b 9a 52 45 53 50 4d 4f 44 20 .~r...{.RESPMOD
> 0040 69 63 61 70 3a 2f 2f 31 32 37 2e 30 2e 30 2e 31 icap://127.0.0.1
> 0050 3a 31 33 34 34 2f 6d 77 20 49 43 41 50 2f 31 2e :1344/mw ICAP/1.
> 0060 30 0d 0a 48 6f 73 74 3a 20 31 32 37 2e 30 2e 30 0..Host: 127.0.0
> 0070 2e 31 3a 31 33 34 34 0d 0a 44 61 74 65 3a 20 4d .1:1344..Date: M
> 0080 6f 6e 2c 20 33 30 20 41 70 72 20 32 30 31 32 20 on, 30 Apr 2012
> 0090 31 37 3a 33 32 3a 32 37 20 47 4d 54 0d 0a 45 6e 17:32:27 GMT..En
> 00a0 63 61 70 73 75 6c 61 74 65 64 3a 20 72 65 71 2d capsulated: req-
> 00b0 68 64 72 3d 30 2c 20 72 65 73 2d 68 64 72 3d 35 hdr=0, res-hdr=5
> 00c0 33 34 2c 20 72 65 73 2d 62 6f 64 79 3d 38 36 33 34, res-body=863
> 00d0 0d 0a 58 2d 43 6c 69 65 6e 74 2d 49 50 3a 20 31 ..X-Client-IP: 1
> 00e0 30 2e 31 30 2e 30 2e 36 37 0d 0a 0d 0a 47 45 54 0.10.0.67....GET
> 00f0 20 68 74 74 70 3a 2f 2f 6e 66 6c 78 2e 69 2e 61 http://nflx.i.a
> 0100 33 39 39 66 30 30 33 2e 78 2e 6c 63 64 6e 2e 6e 399f003.x.lcdn.n
> 0110 66 6c 78 69 6d 67 2e 63 6f 6d 2f 31 38 32 2f 31 flximg.com/182/1
> 0120 30 33 38 37 33 34 31 38 32 2e 69 73 6d 76 2f 72 038734182.ismv/r
> 0130 61 6e 67 65 2f 36 38 30 38 36 39 37 32 34 2d 36 ange/680869724-6
> 0140 38 31 36 39 38 31 37 31 3f 65 74 69 6d 65 3d 32 81698171?etime=2
> 0150 30 31 32 30 35 30 31 30 31 32 32 30 38 26 6d 6f 0120501012208&mo
> 0160 76 69 65 48 61 73 68 3d 31 33 33 26 65 6e 63 6f vieHash=133&enco
> 0170 64 65 64 3d 30 37 33 61 63 37 65 32 31 39 31 38 ded=073ac7e21918
> 0180 39 33 32 38 37 33 64 32 31 26 72 61 6e 64 6f 6d 932873d21&random
> 0190 3d 31 32 39 36 33 30 33 35 36 36 20 48 54 54 50 =1296303566 HTTP
> 01a0 2f 31 2e 30 0d 0a 41 63 63 65 70 74 3a 20 2a 2f /1.0..Accept: */
> 01b0 2a 0d 0a 52 65 66 65 72 65 72 3a 20 68 74 74 70 *..Referer: http
> 01c0 3a 2f 2f 6d 6f 76 69 65 73 2e 6e 65 74 66 6c 69 ://movies.netfli
> 01d0 78 2e 63 6f 6d 2f 6c 61 79 6f 75 74 2f 73 69 6c x.com/layout/sil
> 01e0 76 65 72 6c 69 67 68 74 2f 53 4c 50 6c 61 79 65 verlight/SLPlaye
> 01f0 72 34 2e 78 61 70 3f 76 3d 32 2e 31 33 33 32 2e r4.xap?v=2.1332.
> 0200 35 32 30 2e 31 2d 32 0d 0a 41 63 63 65 70 74 2d 520.1-2..Accept-
> 0210 4c 61 6e 67 75 61 67 65 3a 20 65 6e 2d 75 73 0d Language: en-us.
> 0220 0a 55 73 65 72 2d 41 67 65 6e 74 3a 20 4d 6f 7a .User-Agent: Moz
> 0230 69 6c 6c 61 2f 34 2e 30 20 28 63 6f 6d 70 61 74 illa/4.0 (compat
> 0240 69 62 6c 65 3b 20 4d 53 49 45 20 38 2e 30 3b 20 ible; MSIE 8.0;
> 0250 57 69 6e 64 6f 77 73 20 4e 54 20 35 2e 31 3b 20 Windows NT 5.1;
> 0260 54 72 69 64 65 6e 74 2f 34 2e 30 3b 20 2e 4e 45 Trident/4.0; .NE
> 0270 54 20 43 4c 52 20 31 2e 31 2e 34 33 32 32 3b 20 T CLR 1.1.4322;
> 0280 2e 4e 45 54 20 43 4c 52 20 32 2e 30 2e 35 30 37 .NET CLR 2.0.507
> 0290 32 37 3b 20 2e 4e 45 54 20 43 4c 52 20 33 2e 30 27; .NET CLR 3.0
> 02a0 2e 34 35 30 36 2e 32 31 35 32 3b 20 2e 4e 45 54 .4506.2152; .NET
> 02b0 20 43 4c 52 20 33 2e 35 2e 33 30 37 32 39 3b 20 CLR 3.5.30729;
> 02c0 2e 4e 45 54 34 2e 30 43 3b 20 49 6e 66 6f 50 61 .NET4.0C; InfoPa
> 02d0 74 68 2e 32 29 0d 0a 48 6f 73 74 3a 20 6e 66 6c th.2)..Host: nfl
> 02e0 78 2e 69 2e 61 33 39 39 66 30 30 33 2e 78 2e 6c x.i.a399f003.x.l
> 02f0 63 64 6e 2e 6e 66 6c 78 69 6d 67 2e 63 6f 6d 0d cdn.nflximg.com.
> 0300 0a 0d 0a 48 54 54 50 2f 31 2e 31 20 32 30 30 20 ...HTTP/1.1 200
> 0310 4f 4b 0d 0a 43 61 63 68 65 2d 43 6f 6e 74 72 6f OK..Cache-Contro
> 0320 6c 3a 20 6e 6f 2d 73 74 6f 72 65 0d 0a 43 6f 6e l: no-store..Con
> 0330 74 65 6e 74 2d 54 79 70 65 3a 20 61 70 70 6c 69 tent-Type: appli
> 0340 63 61 74 69 6f 6e 2f 6f 63 74 65 74 2d 73 74 72 cation/octet-str
> 0350 65 61 6d 0d 0a 45 54 61 67 3a 20 22 65 64 30 39 eam..ETag: "ed09
> 0360 34 64 61 2d 32 63 31 33 39 61 62 37 2d 34 61 61 4da-2c139ab7-4aa
> 0370 62 31 33 65 30 66 64 31 38 30 22 0d 0a 45 78 70 b13e0fd180"..Exp
> 0380 69 72 65 73 3a 20 57 65 64 2c 20 31 37 20 41 75 ires: Wed, 17 Au
> 0390 67 20 32 30 31 31 20 31 37 3a 33 38 3a 30 31 20 g 2011 17:38:01
> 03a0 47 4d 54 0d 0a 4c 61 73 74 2d 4d 6f 64 69 66 69 GMT..Last-Modifi
> 03b0 65 64 3a 20 57 65 64 2c 20 31 37 20 41 75 67 20 ed: Wed, 17 Aug
> 03c0 32 30 31 31 20 31 30 3a 34 38 3a 35 34 20 47 4d 2011 10:48:54 GM
> 03d0 54 0d 0a 41 63 63 65 70 74 2d 52 61 6e 67 65 73 T..Accept-Ranges
> 03e0 3a 20 62 79 74 65 73 0d 0a 53 65 72 76 65 72 3a : bytes..Server:
> 03f0 20 4c 65 76 65 6c 2d 33 20 4f 72 69 67 69 6e 20 Level-3 Origin
> 0400 53 74 6f 72 61 67 65 2f 31 2e 35 0d 0a 44 61 74 Storage/1.5..Dat
> 0410 65 3a 20 4d 6f 6e 2c 20 33 30 20 41 70 72 20 32 e: Mon, 30 Apr 2
> 0420 30 31 32 20 31 37 3a 33 32 3a 32 37 20 47 4d 54 012 17:32:27 GMT
> 0430 0d 0a 43 6f 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 ..Content-Length
> 0440 3a 20 38 32 38 34 34 38 0d 0a 0d 0a : 828448….
>
> Followed by data, and then seven seconds into the request:
> 508 7.963216 127.0.0.1 -> 127.0.0.1 ICAP Continuation
> 509 8.063217 127.0.0.1 -> 127.0.0.1 TCP icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574111001 TSER=259953128
> 510 67.964832 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 511 67.964832 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260013128 TSER=3574111001
> 512 127.966453 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] 11651> icap [ACK] Seq=825599 Ack=1 Win=71680 Len=0
> 513 127.966453 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 514 127.966453 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574230901 TSER=260013128
> 515 127.966453 127.0.0.1 -> 127.0.0.1 TCP [TCP Dup ACK 512#1] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260073128 TSER=3574111001
> 516 187.968078 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] 11651> icap [ACK] Seq=825599 Ack=1 Win=71680 Len=0
> 517 187.968078 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 518 187.968078 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574290901 TSER=260073128
> 519 187.968078 127.0.0.1 -> 127.0.0.1 TCP [TCP Dup ACK 516#1] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260133128 TSER=3574230901
> 520 247.969707 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] 11651> icap [ACK] Seq=825599 Ack=1 Win=71680 Len=0
> 521 247.969707 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 522 247.969707 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574350901 TSER=260133128
> 523 247.969707 127.0.0.1 -> 127.0.0.1 TCP [TCP Dup ACK 520#1] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260193128 TSER=3574290901
> 524 307.971339 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] 11651> icap [ACK] Seq=825599 Ack=1 Win=71680 Len=0
> 525 307.971339 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 526 307.971339 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574410901 TSER=260193128
> 527 307.971339 127.0.0.1 -> 127.0.0.1 TCP [TCP Dup ACK 524#1] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260253128 TSER=3574350901
> 528 367.972974 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] 11651> icap [ACK] Seq=825599 Ack=1 Win=71680 Len=0
> 529 367.972974 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 530 367.972974 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574470901 TSER=260253128
> 531 367.972974 127.0.0.1 -> 127.0.0.1 TCP [TCP Dup ACK 528#1] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260313128 TSER=3574410901
> 532 427.974613 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] 11651> icap [ACK] Seq=825599 Ack=1 Win=71680 Len=0
> 533 427.974613 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 534 427.974613 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574530901 TSER=260313128
> 535 427.974613 127.0.0.1 -> 127.0.0.1 TCP [TCP Dup ACK 532#1] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260373128 TSER=3574470901
> 536 487.976255 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] 11651> icap [ACK] Seq=825599 Ack=1 Win=71680 Len=0
> 537 487.976255 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 538 487.976255 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574590901 TSER=260373128
> 539 487.976255 127.0.0.1 -> 127.0.0.1 TCP [TCP Dup ACK 536#1] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260433128 TSER=3574530901
> 540 547.977901 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] 11651> icap [ACK] Seq=825599 Ack=1 Win=71680 Len=0
> 541 547.977901 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive] icap> 11651 [ACK] Seq=0 Ack=825600 Win=71680 Len=0
> 542 547.977901 127.0.0.1 -> 127.0.0.1 TCP [TCP Keep-Alive ACK] icap> 11651 [ACK] Seq=1 Ack=825600 Win=71680 Len=0 TSV=3574650901 TSER=260433128
> 543 547.977901 127.0.0.1 -> 127.0.0.1 TCP [TCP Dup ACK 540#1] 11651> icap [ACK] Seq=825600 Ack=1 Win=71680 Len=0 TSV=260493128 TSER=3574590901
>
> Then squid reported:
> 2012/04/30 13:41:21 kid1| suspending ICAP service for too many failures
> 2012/04/30 13:41:21 kid1| essential ICAP service is suspended: icap://127.0.0.1:1344/mw[down,susp,fail11]
>
> But squid + icap handled a number of other ICAP REQMOD and RESPMOD requests in this period 13:32:27 to 13:41:21, including 28 or more RESPMOD requests to the mw service. We didn't see any other error reports about the mw icap service immediately prior to this error.
>
> Does this sound similar to Squid Bug #3191 http://bugs.squid-cache.org/show_bug.cgi?id=3191? Otherwise, any ideas on how to debug this? This installation is at a very busy site, so I'm not sure a debugging log is feasible...
>
> Thanks,
> Guy--------
> This message has been scanned by ComplianceSafe, powered by Palisade's PacketSure.

-- 
Eliezer Croitoru
https://www1.ngtech.co.il
IT consulting for Nonprofit organizations
eliezer <at> ngtech.co.il