[squid-users] [3.5x]: identd lookup made before proxy_protocol checking and failed [help]

Thu Jan 5 16:10:17 UTC 2017

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