I'm seeing something odd with icap REQMOD requests for HTTP POST requests in Squid 3.3.4: the encapsulated body appears to not be terminated by \r\n0\r\n. This seems to occur consistently with bumped SSL requests to graph.facebook.com:
000019A7 52 45 51 4d 4f 44 20 69 63 61 70 3a 2f 2f 31 32 REQMOD i cap://12
000019B7 37 2e 30 2e 30 2e 31 3a 31 33 34 34 2f 63 61 20 7.0.0.1: 1344/ca
000019C7 49 43 41 50 2f 31 2e 30 0d 0a 48 6f 73 74 3a 20 ICAP/1.0 ..Host:
000019D7 31 32 37 2e 30 2e 30 2e 31 3a 31 33 34 34 0d 0a 127.0.0. 1:1344..
000019E7 44 61 74 65 3a 20 57 65 64 2c 20 31 35 20 4d 61 Date: We d, 15 Ma
000019F7 79 20 32 30 31 33 20 31 34 3a 32 31 3a 32 30 20 y 2013 1 4:21:20
00001A07 47 4d 54 0d 0a 45 6e 63 61 70 73 75 6c 61 74 65 GMT..Enc apsulate
00001A17 64 3a 20 72 65 71 2d 68 64 72 3d 30 2c 20 72 65 d: req-h dr=0, re
00001A27 71 2d 62 6f 64 79 3d 35 32 32 0d 0a 41 6c 6c 6f q-body=5 22..Allo
00001A37 77 3a 20 32 30 34 0d 0a 58 2d 43 6c 69 65 6e 74 w: 204.. X-Client
00001A47 2d 49 50 3a 20 31 39 32 2e 31 36 38 2e 31 2e 31 -IP: 192 .168.1.1
00001A57 30 34 0d 0a 0d 0a 50 4f 53 54 20 68 74 74 70 73 04....PO ST https
00001A67 3a 2f 2f 67 72 61 70 68 2e 66 61 63 65 62 6f 6f ://graph .faceboo
00001A77 6b 2e 63 6f 6d 2f 20 48 54 54 50 2f 31 2e 31 0d k.com/ H TTP/1.1.
00001A87 0a 48 6f 73 74 3a 20 67 72 61 70 68 2e 66 61 63 .Host: g raph.fac
00001A97 65 62 6f 6f 6b 2e 63 6f 6d 0d 0a 43 6f 6e 74 65 ebook.co m..Conte
00001AA7 6e 74 2d 54 79 70 65 3a 20 61 70 70 6c 69 63 61 nt-Type: applica
00001AB7 74 69 6f 6e 2f 78 2d 77 77 77 2d 66 6f 72 6d 2d tion/x-w ww-form-
00001AC7 75 72 6c 65 6e 63 6f 64 65 64 0d 0a 41 63 63 65 urlencod ed..Acce
00001AD7 70 74 3a 20 2a 2f 2a 0d 0a 43 6f 6e 74 65 6e 74 pt: */*. .Content
00001AE7 2d 4c 65 6e 67 74 68 3a 20 31 30 31 30 34 0d 0a -Length: 10104..
00001AF7 58 2d 46 42 2d 43 6f 6e 6e 65 63 74 69 6f 6e 2d X-FB-Con nection-
00001B07 54 79 70 65 3a 20 77 69 66 69 0d 0a 43 6f 6e 74 Type: wi fi..Cont
00001B17 65 6e 74 2d 45 6e 63 6f 64 69 6e 67 3a 20 67 7a ent-Enco ding: gz
00001B27 69 70 0d 0a 41 63 63 65 70 74 2d 4c 61 6e 67 75 ip..Acce pt-Langu
00001B37 61 67 65 3a 20 65 6e 2d 75 73 0d 0a 41 63 63 65 age: en- us..Acce
00001B47 70 74 2d 45 6e 63 6f 64 69 6e 67 3a 20 67 7a 69 pt-Encod ing: gzi
00001B57 70 2c 20 64 65 66 6c 61 74 65 0d 0a 55 73 65 72 p, defla te..User
00001B67 2d 41 67 65 6e 74 3a 20 4d 6f 7a 69 6c 6c 61 2f -Agent: Mozilla/
00001B77 35 2e 30 20 28 69 50 68 6f 6e 65 3b 20 43 50 55 5.0 (iPh one; CPU
00001B87 20 69 50 68 6f 6e 65 20 4f 53 20 36 5f 31 5f 33 iPhone OS 6_1_3
00001B97 20 6c 69 6b 65 20 4d 61 63 20 4f 53 20 58 29 20 like Ma c OS X)
00001BA7 41 70 70 6c 65 57 65 62 4b 69 74 2f 35 33 36 2e AppleWeb Kit/536.
00001BB7 32 36 20 28 4b 48 54 4d 4c 2c 20 6c 69 6b 65 20 26 (KHTM L, like
00001BC7 47 65 63 6b 6f 29 20 4d 6f 62 69 6c 65 2f 31 30 Gecko) M obile/10
00001BD7 42 33 32 39 20 5b 46 42 41 4e 2f 46 42 49 4f 53 B329 [FB AN/FBIOS
00001BE7 3b 46 42 41 56 2f 36 2e 31 2e 31 3b 46 42 42 56 ;FBAV/6. 1.1;FBBV
00001BF7 2f 32 30 32 39 34 39 3b 46 42 44 56 2f 69 50 68 /202949; FBDV/iPh
00001C07 6f 6e 65 34 2c 31 3b 46 42 4d 44 2f 69 50 68 6f one4,1;F BMD/iPho
00001C17 6e 65 3b 46 42 53 4e 2f 69 50 68 6f 6e 65 20 4f ne;FBSN/ iPhone O
00001C27 53 3b 46 42 53 56 2f 36 2e 31 2e 33 3b 46 42 53 S;FBSV/6 .1.3;FBS
00001C37 53 2f 32 3b 20 46 42 43 52 2f 41 54 26 54 3b 46 S/2; FBC R/AT&T;F
00001C47 42 49 44 2f 70 68 6f 6e 65 3b 46 42 4c 43 2f 65 BID/phon e;FBLC/e
00001C57 6e 5f 55 53 3b 46 42 4f 50 2f 31 5d 0d 0a 0d 0a n_US;FBO P/1]....
00001C67 66 66 66 0d 0a 1f 8b 08 00 00 00 00 00 00 03 ed fff..... ........
00001C77 5d db 72 db 48 92 fd 17 c7 aa 9f 3a b4 12 25 59 ].r.H... ...:..%Y
[… elided to reduce size and protect content …]
00002C47 c5 d6 79 34 e5 7e 1c 5b 9a d3 42 7a 47 e3 64 19 ..y4.~.[ ..BzG.d.
00002C57 a6 1e 49 a9 b3 b6 f4 f5 99 47 7e b9 71 37 6b 20 ..I..... .G~.q7k
00002C67 be eb c9 18 0d 0a ...…
After 15 seconds, my ICAP server times out:
00000192 49 43 41 50 2f 31 2e 30 20 34 30 30 20 42 61 64 ICAP/1.0 400 Bad
000001A2 20 52 65 71 75 65 73 74 0d 0a 53 65 72 76 69 63 Request ..Servic
000001B2 65 3a 20 50 61 6c 69 73 61 64 65 20 53 79 73 74 e: Palis ade Syst
000001C2 65 6d 73 20 50 61 63 6b 65 74 53 75 72 65 20 49 ems Pack etSure I
000001D2 43 41 50 20 53 65 72 76 65 72 20 31 2e 30 0d 0a CAP Serv er 1.0..
000001E2 49 53 54 61 67 3a 20 22 32 30 31 33 2d 30 35 2d ISTag: " 2013-05-
000001F2 31 35 3a 30 32 3a 32 36 3a 30 37 2d 32 22 0d 0a 15:02:26 :07-2"..
00000202 0d 0a ..
The cache.log around similar transactions with debug_options 93,9:
2013/05/15 09:34:10.134 kid1| AsyncCall.cc(30) make: make call Adaptation::Icap::Xaction::noteCommConnected [call10111409]
2013/05/15 09:34:10.134 kid1| AsyncJob.cc(117) callStart: Adaptation::Icap::ModXact status in: [FD 47;rw(1)YG/R job532523]
2013/05/15 09:34:10.134 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x48c67bf0 [call10111410]
2013/05/15 09:34:10.134 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommClosed constructed, this=0x48db0fb0 [call10111411]
2013/05/15 09:34:10.134 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommRead constructed, this=0x48c6cdc0 [call10111412]
2013/05/15 09:34:10.134 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x4a261330 [call10111413]
2013/05/15 09:34:10.134 kid1| ModXact.cc(1482) makeAllowHeader: Will write Allow: 204
2013/05/15 09:34:10.134 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommWrote constructed, this=0x48c6ce20 [call10111414]
2013/05/15 09:34:10.134 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x4a261380 [call10111415]
2013/05/15 09:34:10.134 kid1| AsyncJob.cc(146) callEnd: Adaptation::Icap::ModXact status out: [FD 47wr;rw(2)YG/R job532523]
2013/05/15 09:34:10.134 kid1| AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Icap::Xaction::noteCommConnected(local=127.0.0.1:44683 remote=127.0.0.1:1344 FD 47 flags=1, data=0x4a257050)
2013/05/15 09:34:10.134 kid1| AsyncCall.cc(85) ScheduleCall: IoCallback.cc(127) will call Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:44683 remote=127.0.0.1:1344 FD 47 flags=1, data=0x4a257050) [call10111414]
2013/05/15 09:34:10.134 kid1| AsyncCallQueue.cc(51) fireNext: entering Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:44683 remote=127.0.0.1:1344 FD 47 flags=1, data=0x4a257050)
2013/05/15 09:34:10.135 kid1| AsyncCall.cc(30) make: make call Adaptation::Icap::Xaction::noteCommWrote [call10111414]
2013/05/15 09:34:10.135 kid1| AsyncJob.cc(117) callStart: Adaptation::Icap::ModXact status in: [FD 47wr;rw(2)YG/R job532523]
2013/05/15 09:34:10.135 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Icap::Xaction::noteCommTimedout constructed, this=0x48c678d0 [call10111416]
2013/05/15 09:34:10.135 kid1| ModXact.cc(201) handleCommWrote: Wrote 1120 bytes
2013/05/15 09:34:10.135 kid1| AsyncJob.cc(146) callEnd: Adaptation::Icap::ModXact status out: [FD 47r;rYG/Rw job532523]
2013/05/15 09:34:10.135 kid1| AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Icap::Xaction::noteCommWrote(local=127.0.0.1:44683 remote=127.0.0.1:1344 FD 47 flags=1, data=0x4a257050)
2013/05/15 09:34:10.136 kid1| AsyncCall.cc(85) ScheduleCall: IoCallback.cc(127) will call Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:44683 remote=127.0.0.1:1344 FD 47 flags=1, data=0x4a257050, size=126, buf=0x59611000) [call10111412]
2013/05/15 09:34:10.136 kid1| AsyncCallQueue.cc(51) fireNext: entering Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:44683 remote=127.0.0.1:1344 FD 47 flags=1, data=0x4a257050, size=126, buf=0x59611000)
2013/05/15 09:34:10.136 kid1| AsyncCall.cc(30) make: make call Adaptation::Icap::Xaction::noteCommRead [call10111412]
2013/05/15 09:34:10.136 kid1| AsyncJob.cc(117) callStart: Adaptation::Icap::ModXact status in: [FD 47r;rYG/Rw job532523]
2013/05/15 09:34:10.136 kid1| Xaction.cc(414) noteCommRead: read 126 bytes
2013/05/15 09:34:10.136 kid1| Xaction.cc(74) disableRetries: Adaptation::Icap::ModXact from now on cannot be retried [FD 47;rYG/Rw job532523]
2013/05/15 09:34:10.136 kid1| ModXact.cc(646) parseMore: have 126 bytes to parse [FD 47;rYG/Rw job532523]
2013/05/15 09:34:10.136 kid1| ModXact.cc(647) parseMore:
ICAP/1.0 204 No modifications needed
Service: Palisade Systems PacketSure ICAP Server 1.0
ISTag: "2013-05-15:02:26:07-2"
2013/05/15 09:34:10.136 kid1| ModXact.cc(742) parseHeaders: parse ICAP headers
2013/05/15 09:34:10.136 kid1| ModXact.cc(1073) parseHead: have 126 head bytes to parse; state: 0
2013/05/15 09:34:10.136 kid1| ModXact.cc(1088) parseHead: parse success, consume 126 bytes, return true
2013/05/15 09:34:10.136 kid1| Xaction.cc(81) disableRepeats: Adaptation::Icap::ModXact still cannot be repeated because preparing to echo content [FD 47;YG/Rwrp job532523]
2013/05/15 09:34:10.136 kid1| Xaction.cc(503) setOutcome: ICAP_ECHO
2013/05/15 09:34:10.136 kid1| Xaction.cc(81) disableRepeats: Adaptation::Icap::ModXact still cannot be repeated because sent headers [FD 47;/RwrpS job532523]
2013/05/15 09:34:10.136 kid1| Answer.cc(23) Forward: forwarding: 0x4a6e7c00
2013/05/15 09:34:10.136 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x48c6ce20 [call10111417]
2013/05/15 09:34:10.136 kid1| AsyncCall.cc(85) ScheduleCall: Initiate.cc(77) will call Initiator::noteAdaptationAnswer(0) [call10111417]
2013/05/15 09:34:10.136 kid1| ModXact.cc(542) readMore: returning from readMore because reader or doneReading()
2013/05/15 09:34:10.136 kid1| Xaction.cc(343) callEnd: Adaptation::Icap::ModXact done with I/O [FD 47;/RwrpS job532523]
2013/05/15 09:34:10.136 kid1| AsyncCall.cc(48) cancel: will not call Adaptation::Icap::Xaction::noteCommClosed [call10111411] because comm_remove_close_handler
2013/05/15 09:34:10.136 kid1| Xaction.cc(74) disableRetries: Adaptation::Icap::ModXact still cannot be retried [FD 47;/RwrpS job532523]
2013/05/15 09:34:10.136 kid1| ServiceRep.cc(126) putConnection: pushing pconn [FD 47;/RwrpS job532523]
2013/05/15 09:34:10.136 kid1| AsyncJob.cc(131) callEnd: Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:44683 remote=127.0.0.1:1344 FD 47 flags=1, data=0x4a257050, size=126, buf=0x59611000) ends job [/RwrpS job532523]
2013/05/15 09:34:10.136 kid1| ModXact.cc(1236) swanSong: swan sings [/RwrpS job532523]
2013/05/15 09:34:10.136 kid1| Initiate.cc(58) swanSong: swan sings [/RwrpS job532523]
2013/05/15 09:34:10.136 kid1| Initiate.cc(65) swanSong: swan sang [/RwrpS job532523]
2013/05/15 09:34:10.137 kid1| Xaction.cc(60) ~Xaction: Adaptation::Icap::ModXact destructed, this=0x4a257050 [icapxjob532523]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x4a257154 type=Adaptation::Icap::ModXact [job532523]
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:44683 remote=127.0.0.1:1344 FD 47 flags=1, data=0x4a257050, size=126, buf=0x59611000)
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(51) fireNext: entering Initiator::noteAdaptationAnswer(0)
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(30) make: make call Initiator::noteAdaptationAnswer [call10111417]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(117) callStart: Adaptation::Icap::ModXactLauncher status in: [ job532522]
2013/05/15 09:34:10.137 kid1| Launcher.cc(58) noteAdaptationAnswer: launches: 1 answer: 0
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x48c6cdc0 [call10111420]
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(85) ScheduleCall: Initiate.cc(77) will call Initiator::noteAdaptationAnswer(0) [call10111420]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(131) callEnd: Initiator::noteAdaptationAnswer(0) ends job [ job532522]
2013/05/15 09:34:10.137 kid1| ModXact.cc(1952) swanSong: swan sings
2013/05/15 09:34:10.137 kid1| Initiate.cc(58) swanSong: swan sings [ job532522]
2013/05/15 09:34:10.137 kid1| Initiate.cc(65) swanSong: swan sang [ job532522]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x58bcc77c type=Adaptation::Icap::ModXactLauncher [job532522]
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(53) fireNext: leaving Initiator::noteAdaptationAnswer(0)
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(51) fireNext: entering Initiator::noteAdaptationAnswer(0)
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(30) make: make call Initiator::noteAdaptationAnswer [call10111420]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(117) callStart: Iterator status in: [ job532521]
2013/05/15 09:34:10.137 kid1| ServiceGroups.cc(181) findService: url_service has no matching services
2013/05/15 09:34:10.137 kid1| Iterator.cc(49) step: #2 plan: url_service[1..1.]
2013/05/15 09:34:10.137 kid1| Answer.cc(23) Forward: forwarding: 0x4a6e7c00
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Initiator::noteAdaptationAnswer constructed, this=0x48c6ce20 [call10111421]
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(85) ScheduleCall: Initiate.cc(77) will call Initiator::noteAdaptationAnswer(0) [call10111421]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(131) callEnd: Initiator::noteAdaptationAnswer(0) ends job [ job532521]
2013/05/15 09:34:10.137 kid1| Initiate.cc(58) swanSong: swan sings [ job532521]
2013/05/15 09:34:10.137 kid1| Initiate.cc(65) swanSong: swan sang [ job532521]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x567dcb08 type=Iterator [job532521]
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(53) fireNext: leaving Initiator::noteAdaptationAnswer(0)
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(51) fireNext: entering Initiator::noteAdaptationAnswer(0)
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(30) make: make call Initiator::noteAdaptationAnswer [call10111421]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(117) callStart: ClientHttpRequest status in: [ job532519]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x5ac50914 type=HttpStateData [job532524]
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x48da8b00 [call10111424]
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(85) ScheduleCall: AsyncJob.cc(20) will call AsyncJob::start() [call10111424]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(146) callEnd: ClientHttpRequest status out: [ job532519]
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(53) fireNext: leaving Initiator::noteAdaptationAnswer(0)
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(51) fireNext: entering AsyncJob::start()
2013/05/15 09:34:10.137 kid1| AsyncCall.cc(30) make: make call AsyncJob::start [call10111424]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(117) callStart: HttpStateData status in: [ job532524]
2013/05/15 09:34:10.137 kid1| AsyncJob.cc(146) callEnd: HttpStateData status out: [ job532524]
2013/05/15 09:34:10.137 kid1| AsyncCallQueue.cc(53) fireNext: leaving AsyncJob::start()
2013/05/15 09:34:10.192 kid1| AsyncJob.cc(28) AsyncJob: AsyncJob constructed, this=0x58bda86c type=AccessCheck [job532525]
2013/05/15 09:34:10.192 kid1| AccessCheck.cc(49) AccessCheck: AccessCheck constructed for RESPMOD PRECACHE
2013/05/15 09:34:10.192 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x48db2c00 [call10111429]
2013/05/15 09:34:10.192 kid1| AsyncCall.cc(85) ScheduleCall: AsyncJob.cc(20) will call AsyncJob::start() [call10111429]
2013/05/15 09:34:10.192 kid1| AsyncCallQueue.cc(51) fireNext: entering AsyncJob::start()
2013/05/15 09:34:10.192 kid1| AsyncCall.cc(30) make: make call AsyncJob::start [call10111429]
2013/05/15 09:34:10.192 kid1| AsyncJob.cc(117) callStart: AccessCheck status in: [ job532525]
2013/05/15 09:34:10.192 kid1| AccessCheck.cc(96) check: start checking
2013/05/15 09:34:10.192 kid1| ServiceGroups.cc(136) findService: ca_service serves another location
2013/05/15 09:34:10.192 kid1| ServiceGroups.cc(136) findService: url_service serves another location
2013/05/15 09:34:10.192 kid1| AccessCheck.cc(102) check: check: rule '9' is a candidate
2013/05/15 09:34:10.192 kid1| AccessCheck.cc(118) checkCandidates: has 1 rules
2013/05/15 09:34:10.192 kid1| AsyncJob.cc(146) callEnd: AccessCheck status out: [ job532525]
2013/05/15 09:34:10.192 kid1| AsyncCallQueue.cc(53) fireNext: leaving AsyncJob::start()
2013/05/15 09:34:10.192 kid1| AccessCheck.cc(163) noteAnswer: 9 answer=DENIED
2013/05/15 09:34:10.192 kid1| AccessCheck.cc(118) checkCandidates: has 0 rules
2013/05/15 09:34:10.193 kid1| AccessCheck.cc(133) checkCandidates: NO candidates left
2013/05/15 09:34:10.193 kid1| AccessCheck.cc(184) callBack: NULL
2013/05/15 09:34:10.193 kid1| AsyncCall.cc(18) AsyncCall: The AsyncCall Adaptation::Initiator::noteAdaptationAclCheckDone constructed, this=0x48db2c00 [call10111431]
2013/05/15 09:34:10.193 kid1| AsyncCall.cc(85) ScheduleCall: AccessCheck.cc(186) will call Adaptation::Initiator::noteAdaptationAclCheckDone(NULL) [call10111431]
2013/05/15 09:34:10.193 kid1| AsyncJob.cc(78) mustStop: AccessCheck will stop, reason: done
2013/05/15 09:34:10.193 kid1| AsyncJob.cc(131) callEnd: Adaptation::AccessCheck::noteAnswer(DENIED) ends job [Stopped, reason:done job532525]
2013/05/15 09:34:10.193 kid1| AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x58bda86c type=AccessCheck [job532525]
2013/05/15 09:34:10.193 kid1| AsyncCallQueue.cc(51) fireNext: entering Adaptation::Initiator::noteAdaptationAclCheckDone(NULL)
2013/05/15 09:34:10.193 kid1| AsyncCall.cc(30) make: make call Adaptation::Initiator::noteAdaptationAclCheckDone [call10111431]
2013/05/15 09:34:10.193 kid1| AsyncJob.cc(117) callStart: HttpStateData status in: [ job532524]
2013/05/15 09:34:10.193 kid1| AsyncJob.cc(146) callEnd: HttpStateData status out: [ job532524]
2013/05/15 09:34:10.193 kid1| AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Initiator::noteAdaptationAclCheckDone(NULL)
2013/05/15 09:34:20.350 kid1| AsyncJob.cc(49) deleteThis: ConnStateData will NOT delete in-call job, reason: ConnStateData::connStateClosed
2013/05/15 09:34:20.350 kid1| AsyncJob.cc(131) callEnd: ConnStateData::connStateClosed(FD -1, data=0x4ac4ded0) ends job [Stopped, reason:ConnStateData::connStateClosed job532428]
2013/05/15 09:34:20.350 kid1| AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x4ac4dfb8 type=ConnStateData [job532428]
2013/05/15 09:34:21.222 kid1| AsyncCall.cc(85) ScheduleCall: IoCallback.cc(127) will call Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:44851 remote=127.0.0.1:1344 FD 18 flags=1, data=0x4a7f0550, size=114, buf=0x4a5d8000) [call10111248]
2013/05/15 09:34:21.222 kid1| AsyncCallQueue.cc(51) fireNext: entering Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:44851 remote=127.0.0.1:1344 FD 18 flags=1, data=0x4a7f0550, size=114, buf=0x4a5d8000)
2013/05/15 09:34:21.222 kid1| AsyncCall.cc(30) make: make call Adaptation::Icap::Xaction::noteCommRead [call10111248]
2013/05/15 09:34:21.222 kid1| AsyncJob.cc(117) callStart: Adaptation::Icap::ModXact status in: [FD 18r;Rrw(5)BG/ job532500]
2013/05/15 09:34:21.222 kid1| Xaction.cc(414) noteCommRead: read 114 bytes
2013/05/15 09:34:21.222 kid1| Xaction.cc(74) disableRetries: Adaptation::Icap::ModXact from now on cannot be retried [FD 18;Rrw(5)BG/ job532500]
2013/05/15 09:34:21.222 kid1| ModXact.cc(646) parseMore: have 114 bytes to parse [FD 18;Rrw(5)BG/ job532500]
2013/05/15 09:34:21.222 kid1| ModXact.cc(647) parseMore:
ICAP/1.0 400 Bad Request
Service: Palisade Systems PacketSure ICAP Server 1.0
ISTag: "2013-05-15:02:26:07-2"
2013/05/15 09:34:21.222 kid1| ModXact.cc(742) parseHeaders: parse ICAP headers
2013/05/15 09:34:21.222 kid1| ModXact.cc(1073) parseHead: have 114 head bytes to parse; state: 0
2013/05/15 09:34:21.222 kid1| ModXact.cc(1088) parseHead: parse success, consume 114 bytes, return true
2013/05/15 09:34:21.222 kid1| ModXact.cc(808) parseIcapHead: ICAP status 400
2013/05/15 09:34:21.222 kid1| Xaction.cc(81) disableRepeats: Adaptation::Icap::ModXact still cannot be repeated because consumed content [FD 18;Rw(5)G/rp job532500]
2013/05/15 09:34:21.222 kid1| ../../../src/base/AsyncJobCalls.h(169) dial: Adaptation::Icap::Xaction::noteCommRead threw exception: Unsupported ICAP status code
2013/05/15 09:34:21.222 kid1| Xaction.cc(503) setOutcome: ICAP_ERR_OTHER
2013/05/15 09:34:21.222 kid1| ServiceRep.cc(74) noteFailure: failure 4 out of 25 allowed in 10000sec [up,fail4]
2013/05/15 09:34:21.222 kid1| AsyncJob.cc(78) mustStop: Adaptation::Icap::ModXact will stop, reason: exception
2013/05/15 09:34:21.222 kid1| AsyncJob.cc(131) callEnd: Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:44851 remote=127.0.0.1:1344 FD 18 flags=1, data=0x4a7f0550, size=114, buf=0x4a5d8000) ends job [FD 18;Rw(5)/rp job532500]
2013/05/15 09:34:21.222 kid1| ModXact.cc(1236) swanSong: swan sings [FD 18;Rw(5)/rp job532500]
2013/05/15 09:34:21.222 kid1| AsyncCall.cc(48) cancel: will not call Adaptation::Icap::Xaction::noteCommClosed [call10111247] because comm_remove_close_handler
2013/05/15 09:34:21.222 kid1| Xaction.cc(74) disableRetries: Adaptation::Icap::ModXact still cannot be retried [FD 18;/RwrpS job532500]
2013/05/15 09:34:21.222 kid1| ServiceRep.cc(126) putConnection: pushing pconn [FD 18;/RwrpS job532500]
2013/05/15 09:34:21.222 kid1| Initiate.cc(58) swanSong: swan sings [/RwrpS job532500]
2013/05/15 09:34:21.222 kid1| Initiate.cc(65) swanSong: swan sang [/RwrpS job532500]
2013/05/15 09:34:21.222 kid1| Xaction.cc(60) ~Xaction: Adaptation::Icap::ModXact destructed, this=0x4a7f0550 [icapxjob532500]
2013/05/15 09:34:21.222 kid1| AsyncJob.cc(34) ~AsyncJob: AsyncJob destructed, this=0x4a7f0654 type=Adaptation::Icap::ModXact [job532500]
2013/05/15 09:34:21.222 kid1| AsyncCallQueue.cc(53) fireNext: leaving Adaptation::Icap::Xaction::noteCommRead(local=127.0.0.1:44851 remote=127.0.0.1:1344 FD 18 flags=1, data=0x4a7f0550, size=114, buf=0x4a5d8000)
