Added in bugtrack http://bugs.squid-cache.org/show_bug.cgi?id=4657 -----Message d'origine----- De : squid-users [mailto:squid-users-bounces@xxxxxxxxxxxxxxxxxxxxx] De la part de David Touzeau Envoyé : jeudi 5 janvier 2017 17:10 À : squid-users@xxxxxxxxxxxxxxxxxxxxx Objet : [3.5x]: identd lookup made before proxy_protocol checking and failed [help] Hi, We need to use ident daemon in order to authenticate users. Squid works fine when computers are directly connected to the proxy. We have added HaProxy * * * Load-balancer * * * using *proxy_protocol* between users and 2 Squid proxies With the load balancer, squid want to query identd port directly on the load balancer but not on the client source IP address. If you see this piece of logs, you can see that the source client address is correctly understood by Squid but * * after * * the ident verification. How can i fix this behaviour ? Best regards, Browser: 192.168.1.50 Load balancer: 192.168.1.60 Squid: 192.168.1.61 2017/01/05 16:55:19.290 kid1| 5,5| AsyncCall.cc(93) ScheduleCall: TcpAcceptor.cc(317) will call httpAccept(local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1, MXID_244) [call229910] 2017/01/05 16:55:19.290 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 29, type=1, handler=1, client_data=0x18cb298, timeout=0 2017/01/05 16:55:19.290 kid1| 5,5| AsyncCallQueue.cc(55) fireNext: entering httpAccept(local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1, MXID_244) 2017/01/05 16:55:19.290 kid1| 5,5| AsyncCall.cc(38) make: make call httpAccept [call229910] 2017/01/05 16:55:19.290 kid1| 33,4| client_side.cc(3705) httpAccept: local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1: accepted 2017/01/05 16:55:19.290 kid1| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x1eae810 type=Http::Server [job1085] 2017/01/05 16:55:19.290 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x1ab7850 [call229911] 2017/01/05 16:55:19.290 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: AsyncJob.cc(26) will call AsyncJob::start() [call229911] 2017/01/05 16:55:19.290 kid1| 5,5| AsyncCallQueue.cc(57) fireNext: leaving httpAccept(local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1, MXID_244) 2017/01/05 16:55:19.290 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering AsyncJob::start() 2017/01/05 16:55:19.290 kid1| 93,5| AsyncCall.cc(38) make: make call AsyncJob::start [call229911] 2017/01/05 16:55:19.290 kid1| 93,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job1085] 2017/01/05 16:55:19.290 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::connStateClosed constructed, this=0x1e5a750 [call229912] 2017/01/05 16:55:19.290 kid1| 5,5| comm.cc(994) comm_add_close_handler: comm_add_close_handler: FD 12, AsyncCall=0x1e5a750*1 2017/01/05 16:55:19.290 kid1| 28,3| Checklist.cc(70) preCheck: 0x7ffed50496a0 checking fast rules 2017/01/05 16:55:19.290 kid1| 28,5| Checklist.cc(346) fastCheck: aclCheckFast: list: 0x18d4128 2017/01/05 16:55:19.290 kid1| 28,5| Acl.cc(138) matches: checking ident_lookup_access 2017/01/05 16:55:19.290 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/0' is not banned 2017/01/05 16:55:19.290 kid1| 28,5| Acl.cc(138) matches: checking ident_lookup_access#1 2017/01/05 16:55:19.290 kid1| 28,5| Acl.cc(138) matches: checking ident_aware_hosts 2017/01/05 16:55:19.290 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '192.168.1.61:54798' found 2017/01/05 16:55:19.290 kid1| 28,3| Acl.cc(158) matches: checked: ident_aware_hosts = 1 2017/01/05 16:55:19.290 kid1| 28,3| Acl.cc(158) matches: checked: ident_lookup_access#1 = 1 2017/01/05 16:55:19.290 kid1| 28,3| Acl.cc(158) matches: checked: ident_lookup_access = 1 2017/01/05 16:55:19.290 kid1| 28,3| Checklist.cc(63) markFinished: 0x7ffed50496a0 answer ALLOWED for match 2017/01/05 16:55:19.290 kid1| 30,3| AsyncCall.cc(26) AsyncCall: The AsyncCall Ident::ConnectDone constructed, this=0x18c9f10 [call229913] 2017/01/05 16:55:19.290 kid1| 93,5| AsyncJob.cc(34) AsyncJob: AsyncJob constructed, this=0x1ea4838 type=Comm::ConnOpener [job1086] 2017/01/05 16:55:19.290 kid1| 93,5| AsyncCall.cc(26) AsyncCall: The AsyncCall AsyncJob::start constructed, this=0x18cd970 [call229914] 2017/01/05 16:55:19.290 kid1| 93,5| AsyncCall.cc(93) ScheduleCall: AsyncJob.cc(26) will call AsyncJob::start() [call229914] 2017/01/05 16:55:19.290 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffed50496a0 2017/01/05 16:55:19.290 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffed50496a0 2017/01/05 16:55:19.290 kid1| 28,3| Checklist.cc(70) preCheck: 0x7ffed5049430 checking fast rules 2017/01/05 16:55:19.290 kid1| 28,5| Checklist.cc(346) fastCheck: aclCheckFast: list: 0x18dd488 2017/01/05 16:55:19.290 kid1| 28,5| Acl.cc(138) matches: checking proxy_protocol_access 2017/01/05 16:55:19.290 kid1| 28,5| Checklist.cc(400) bannedAction: Action 'ALLOWED/0' is not banned 2017/01/05 16:55:19.290 kid1| 28,5| Acl.cc(138) matches: checking proxy_protocol_access#1 2017/01/05 16:55:19.290 kid1| 28,5| Acl.cc(138) matches: checking all 2017/01/05 16:55:19.290 kid1| 28,3| Ip.cc(539) match: aclIpMatchIp: '192.168.1.61:54798' found 2017/01/05 16:55:19.290 kid1| 28,3| Acl.cc(158) matches: checked: all = 1 2017/01/05 16:55:19.290 kid1| 28,3| Acl.cc(158) matches: checked: proxy_protocol_access#1 = 1 2017/01/05 16:55:19.290 kid1| 28,3| Acl.cc(158) matches: checked: proxy_protocol_access = 1 2017/01/05 16:55:19.290 kid1| 28,3| Checklist.cc(63) markFinished: 0x7ffed5049430 answer ALLOWED for match 2017/01/05 16:55:19.290 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffed5049430 2017/01/05 16:55:19.290 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffed5049430 2017/01/05 16:55:19.290 kid1| 28,4| FilledChecklist.cc(66) ~ACLFilledChecklist: ACLFilledChecklist destroyed 0x7ffed5049860 2017/01/05 16:55:19.290 kid1| 28,4| Checklist.cc(197) ~ACLChecklist: ACLChecklist::~ACLChecklist: destroyed 0x7ffed5049860 2017/01/05 16:55:19.290 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall Http::Server::requestTimeout constructed, this=0x19524c0 [call229915] 2017/01/05 16:55:19.290 kid1| 5,3| comm.cc(553) commSetConnTimeout: local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1 timeout 300 2017/01/05 16:55:19.290 kid1| 33,4| client_side.cc(231) readSomeData: local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1: reading request... 2017/01/05 16:55:19.291 kid1| 33,5| AsyncCall.cc(26) AsyncCall: The AsyncCall ConnStateData::clientReadRequest constructed, this=0x1f4cc10 [call229916] 2017/01/05 16:55:19.291 kid1| 5,5| Read.cc(58) comm_read_base: comm_read, queueing read for local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1; asynCall 0x1f4cc10*1 2017/01/05 16:55:19.291 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 12, type=1, handler=1, client_data=0x7fe9e8ff0678, timeout=0 2017/01/05 16:55:19.291 kid1| 93,5| AsyncJob.cc(152) callEnd: Http::Server status out: [ job1085] 2017/01/05 16:55:19.291 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving AsyncJob::start() 2017/01/05 16:55:19.291 kid1| 93,5| AsyncCallQueue.cc(55) fireNext: entering AsyncJob::start() 2017/01/05 16:55:19.291 kid1| 93,5| AsyncCall.cc(38) make: make call AsyncJob::start [call229914] 2017/01/05 16:55:19.291 kid1| 93,5| AsyncJob.cc(123) callStart: Comm::ConnOpener status in: [ job1086] 2017/01/05 16:55:19.291 kid1| 50,3| comm.cc(347) comm_openex: comm_openex: Attempt open socket for: 192.168.1.62 2017/01/05 16:55:19.291 kid1| 50,3| comm.cc(388) comm_openex: comm_openex: Opened socket local=192.168.1.62 remote=[::] FD 13 flags=1 : family=2, type=1, protocol=6 2017/01/05 16:55:19.291 kid1| 5,5| comm.cc(420) comm_init_opened: local=192.168.1.62 remote=[::] FD 13 flags=1 is a new socket 2017/01/05 16:55:19.291 kid1| 51,3| fd.cc(198) fd_open: fd_open() FD 13 2017/01/05 16:55:19.291 kid1| 50,6| comm.cc(209) commBind: commBind: bind socket FD 13 to 192.168.1.62 2017/01/05 16:55:19.291 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall Comm::ConnOpener::earlyAbort constructed, this=0x1fa6ea0 [call229917] 2017/01/05 16:55:19.291 kid1| 5,5| comm.cc(994) comm_add_close_handler: comm_add_close_handler: FD 13, AsyncCall=0x1fa6ea0*1 2017/01/05 16:55:19.291 kid1| 5,4| AsyncCall.cc(26) AsyncCall: The AsyncCall Comm::ConnOpener::timeout constructed, this=0x1fe7e90 [call229918] * * * * Squid try to connect to the Load-Balancer on 113 port instead 192.168.1.50 * * * * 2017/01/05 16:55:19.291 kid1| 5,3| ConnOpener.cc(289) createFd: local=192.168.1.62 remote=192.168.1.61:113 flags=1 will timeout in 3 2017/01/05 16:55:19.291 kid1| 5,5| comm.cc(644) comm_connect_addr: sock=13, addrinfo( flags=4, family=2, socktype=1, protocol=6, &addr=0x1f788e0, addrlen=16 ) 2017/01/05 16:55:19.291 kid1| 5,5| ConnOpener.cc(343) doConnect: local=192.168.1.62 remote=192.168.1.61:113 flags=1: Comm::INPROGRESS 2017/01/05 16:55:19.291 kid1| 5,5| ModEpoll.cc(116) SetSelect: FD 13, type=2, handler=1, client_data=0x1f788e0, timeout=0 2017/01/05 16:55:19.291 kid1| 93,5| AsyncJob.cc(152) callEnd: Comm::ConnOpener status out: [ job1086] 2017/01/05 16:55:19.291 kid1| 93,5| AsyncCallQueue.cc(57) fireNext: leaving AsyncJob::start() 2017/01/05 16:55:19.291 kid1| 5,3| IoCallback.cc(116) finish: called for local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1 (0, 0) 2017/01/05 16:55:19.291 kid1| 33,5| AsyncCall.cc(93) ScheduleCall: IoCallback.cc(135) will call ConnStateData::clientReadRequest(local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1, data=0x1eae648) [call229916] 2017/01/05 16:55:19.291 kid1| 33,5| AsyncCallQueue.cc(55) fireNext: entering ConnStateData::clientReadRequest(local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1, data=0x1eae648) 2017/01/05 16:55:19.291 kid1| 33,5| AsyncCall.cc(38) make: make call ConnStateData::clientReadRequest [call229916] 2017/01/05 16:55:19.291 kid1| 33,5| AsyncJob.cc(123) callStart: Http::Server status in: [ job1085] 2017/01/05 16:55:19.291 kid1| 33,5| client_side.cc(3283) clientReadRequest: local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(193) rawSpace: reserving 16382 for SBuf18795 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(935) reAlloc: SBuf18795 new store capacity: 16384 2017/01/05 16:55:19.291 kid1| 5,3| Read.cc(91) ReadNow: local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1, size 16382, retval 409, errno 0 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(242) append: from c-string to id SBuf18795 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(193) rawSpace: reserving 409 for SBuf18795 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(200) rawSpace: SBuf18795 not growing 2017/01/05 16:55:19.291 kid1| 33,5| client_side.cc(3232) clientParseRequests: local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1: attempting to parse 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(802) findFirstNotOf: first not of characterset non-LF in id SBuf18808 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(139) assign: assigning SBuf18807 from SBuf18809 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(139) assign: assigning SBuf18795 from SBuf18803 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(139) assign: assigning SBuf18803 from SBuf18807 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(802) findFirstNotOf: first not of characterset IP Address in id SBuf18818 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(139) assign: assigning SBuf18816 from SBuf18819 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(802) findFirstNotOf: first not of characterset IP Address in id SBuf18821 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(139) assign: assigning SBuf18817 from SBuf18822 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(193) rawSpace: reserving 1 for SBuf18816 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(935) reAlloc: SBuf18816 new store capacity: 40 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(193) rawSpace: reserving 1 for SBuf18817 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(935) reAlloc: SBuf18817 new store capacity: 40 * * * * Proxy protocol checking, OK squid get the client source IP address but ACL failed the ident checking was failed before * * * * 2017/01/05 16:55:19.291 kid1| 33,5| client_side.cc(3105) parseProxy1p0: PROXY/1.0 protocol on connection local=192.168.1.62:8080 remote=192.168.1.61:54798 FD 12 flags=1 2017/01/05 16:55:19.291 kid1| 33,5| client_side.cc(3110) parseProxy1p0: PROXY/1.0 upgrade: local=192.168.1.61:8080 remote=192.168.1.50:59019 FD 12 flags=1 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(193) rawSpace: reserving 1 for SBuf18795 2017/01/05 16:55:19.291 kid1| 24,7| SBuf.cc(200) rawSpace: SBuf18795 not growing 2017/01/05 16:55:19.291 kid1| 74,5| HttpParser.cc(37) reset: Request buffer is GET http://www.squid-cache.org/Images/img4.jpg HTTP/1.1 _______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users _______________________________________________ squid-users mailing list squid-users@xxxxxxxxxxxxxxxxxxxxx http://lists.squid-cache.org/listinfo/squid-users
