Search squid archive

Squid 3.3.4 icap request issue

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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)






[Index of Archives]     [Linux Audio Users]     [Samba]     [Big List of Linux Books]     [Linux USB]     [Yosemite News]

  Powered by Linux