[squid-users] Problem with Single Sign-On & NTLM

Hi,

following some howtos/tutorials on the net I managed to get SSO with
NTLM to work ... anyway, there are some significant delay during
authentication ...
I see the two failed 407 requests, then there's some 5-10 second delay
before the successful requests follow.

I've did some strace on the processes and found that the ntlm helper
seems to be causing the delay, specifically the one with the
squid-2.5-ntlmssp
helper protocol. Here's an excerpt from the strace run:

7289 14:14:15 _llseek(2, 0, [809868], SEEK_CUR) = 0
7289 14:14:15 write(2, "NTLMSSP Sign/Seal - Initialising"..., 45) = 45
7289 14:14:15 munmap(0xb775d000, 4096) = 0
7289 14:14:15 fstat64(2, {st_mode=S_IFREG|0640, st_size=809913, ...}) = 0
7289 14:14:15 mmap2(NULL, 4096, PROT_READ|PROT_WRITE,
MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb775d000
7289 14:14:15 _llseek(2, 0, [809913], SEEK_CUR) = 0
7289 14:14:15 write(2, "Got NTLMSSP neg_flags=0xa2088205"..., 33) = 33
7289 14:14:15 munmap(0xb775d000, 4096) = 0
7289 14:14:15 write(1, "AF administrator\n", 17) = 17
7289 14:14:15 read(0, "YR TlRMTVNTUAABAAAAB4IIogAAAAAAA"..., 4096) = 60
7289 14:14:24 uname({sys="Linux", node="BSSVR03", ...}) = 0
7289 14:14:24 socket(PF_NETLINK, SOCK_RAW, 0) = 5

The system call that delays the processing above is actually the
"read(0," call at 14:14:15, which _starts_ at :15, but doesn't finish
until :24 ... I've combined tracing both the Squid process and the auth
helper, but can't discern any routing that in itself would cause the
delay (see below).

I also noticed a post on the Net that talked about M$ deprecating NTLM
(now they do?) in favor of Kerberos, and that Squid 3.2 would have the
direct Kerberos auth available. Does this mean I can use 3.2 with direct
Kerberos for SSO instead of this POS NTLM auth?

Thanks, Garry

----------strace of squid3 (7231) and ntlm_auth helper
(7289)------------------------->

7289 14:29:08 write(1, "AF administrator\n", 17) = 17
7289 14:29:08 read(0, <unfinished ...>
7231 14:29:08 <... gettimeofday resumed> {1339590548, 337498}, NULL) = 0
7231 14:29:08 epoll_ctl(4, EPOLL_CTL_MOD, 8,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=8, u64=12532559950905352}}) = 0
7231 14:29:08 gettimeofday({1339590548, 342113}, NULL) = 0
7231 14:29:08 epoll_wait(4, {{EPOLLIN, {u32=8,
u64=12532559950905352}}}, 65536, 477) = 1
7231 14:29:08 gettimeofday({1339590548, 342521}, NULL) = 0
7231 14:29:08 read(8, "AF administrator\n", 8191) = 17
7231 14:29:08 gettimeofday({1339590548, 343014}, NULL) = 0
7231 14:29:08 socket(PF_INET6, SOCK_STREAM, IPPROTO_TCP) = 42
7231 14:29:08 setsockopt(42, SOL_IPV6, IPV6_V6ONLY, [0], 4) = 0
7231 14:29:08 fcntl64(42, F_GETFD) = 0
7231 14:29:08 fcntl64(42, F_SETFD, FD_CLOEXEC) = 0
7231 14:29:08 fcntl64(42, F_GETFL) = 0x2 (flags O_RDWR)
7231 14:29:08 fcntl64(42, F_SETFL, O_RDWR|O_NONBLOCK) = 0
7231 14:29:08 setsockopt(42, SOL_TCP, TCP_NODELAY, [1], 4) = 0
7231 14:29:08 getsockname(42, {sa_family=AF_INET6, sin6_port=htons(0),
inet_pton(AF_INET6, "::", &sin6_addr), sin6_flowinfo=0,
sin6_scope_id=0}, [28]) = 0
7231 14:29:08 epoll_wait(4, {{EPOLLIN, {u32=27,
u64=12532559950905371}}}, 65536, 476) = 1
7231 14:29:08 gettimeofday({1339590548, 664719}, NULL) = 0
7231 14:29:08 read(27,
"\25\3\1\0\26\343\277\t\7\177n\355\211\220[\212aE\3\340\310\230.8\7\252\364",
65535) = 27
7231 14:29:08 gettimeofday({1339590548, 665169}, NULL) = 0
7231 14:29:08 epoll_ctl(4, EPOLL_CTL_MOD, 25,
{EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=25, u64=25}}) = 0
7231 14:29:08 epoll_wait(4, {{EPOLLIN, {u32=27,
u64=12532559950905371}}, {EPOLLOUT, {u32=25, u64=25}}}, 65536, 154) = 2
7231 14:29:08 gettimeofday({1339590548, 665811}, NULL) = 0
7231 14:29:08 epoll_ctl(4, EPOLL_CTL_DEL, 27, {0, {u32=27,
u64=12532559950905371}}) = 0
7231 14:29:08 write(25,
"\25\3\1\0\26\343\277\t\7\177n\355\211\220[\212aE\3\340\310\230.8\7\252\364",
27) = 27
7231 14:29:08 gettimeofday({1339590548, 667005}, NULL) = 0
7231 14:29:08 epoll_ctl(4, EPOLL_CTL_ADD, 27,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=27, u64=27}}) = 0
7231 14:29:08 epoll_wait(4, {{EPOLLOUT, {u32=25, u64=25}}, {EPOLLIN,
{u32=27, u64=27}}}, 65536, 152) = 2
7231 14:29:08 gettimeofday({1339590548, 667681}, NULL) = 0
7231 14:29:08 epoll_ctl(4, EPOLL_CTL_MOD, 25,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=25, u64=12532559950905369}}) = 0
7231 14:29:08 read(27, "", 65535) = 0
7231 14:29:08 gettimeofday({1339590548, 668253}, NULL) = 0
7231 14:29:08 read(27, "", 65535) = 0
7231 14:29:08 read(25, 0xbfdf18ed, 65535) = -1 EAGAIN (Resource
temporarily unavailable)
7231 14:29:08 epoll_ctl(4, EPOLL_CTL_DEL, 27, {0, {u32=27, u64=27}}) = 0
7231 14:29:08 close(27) = 0
7231 14:29:08 write(5, "1339590548.668 20394 10.40.1.25"..., 113) = 113
7231 14:29:08 epoll_ctl(4, EPOLL_CTL_DEL, 25, {0, {u32=25,
u64=16371771087257625}}) = 0
7231 14:29:08 close(25) = 0
7231 14:29:08 epoll_wait(4, {}, 65536, 151) = 0
7231 14:29:08 gettimeofday({1339590548, 823082}, NULL) = 0
7231 14:29:08 gettimeofday({1339590548, 823352}, NULL) = 0
7231 14:29:08 gettimeofday({1339590548, 823352}, NULL) = 0
7231 14:29:08 epoll_wait(4, {}, 65536, 324) = 0
7231 14:29:09 gettimeofday({1339590549, 149170}, NULL) = 0
7231 14:29:09 gettimeofday({1339590549, 149392}, NULL) = 0
7231 14:29:09 epoll_wait(4, {}, 65536, 673) = 0
7231 14:29:09 gettimeofday({1339590549, 824896}, NULL) = 0
7231 14:29:09 gettimeofday({1339590549, 825120}, NULL) = 0
7231 14:29:09 epoll_wait(4, {}, 65536, 324) = 0
7231 14:29:10 gettimeofday({1339590550, 151083}, NULL) = 0
7231 14:29:10 gettimeofday({1339590550, 151341}, NULL) = 0
7231 14:29:10 epoll_wait(4, {}, 65536, 673) = 0
7231 14:29:10 gettimeofday({1339590550, 826905}, NULL) = 0
7231 14:29:10 gettimeofday({1339590550, 827216}, NULL) = 0
7231 14:29:10 sendto(7,
"\327\342\1\0\0\1\0\0\0\0\0\0\3www\7antifan\2de\0\0\34\0\1", 32, 0,
{sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("10.40.1.12")}, 16) = 32
7231 14:29:10 epoll_wait(4, {}, 65536, 324) = 0
7231 14:29:11 gettimeofday({1339590551, 154941}, NULL) = 0
7231 14:29:11 gettimeofday({1339590551, 155171}, NULL) = 0
7231 14:29:11 epoll_wait(4, {}, 65536, 672) = 0
7231 14:29:11 gettimeofday({1339590551, 830189}, NULL) = 0
7231 14:29:11 gettimeofday({1339590551, 830423}, NULL) = 0
7231 14:29:11 epoll_wait(4, {}, 65536, 62) = 0
7231 14:29:11 gettimeofday({1339590551, 893171}, NULL) = 0
7231 14:29:11 gettimeofday({1339590551, 893391}, NULL) = 0
7231 14:29:11 epoll_wait(4, {}, 65536, 261) = 0
7231 14:29:12 gettimeofday({1339590552, 156806}, NULL) = 0
7231 14:29:12 gettimeofday({1339590552, 157023}, NULL) = 0
7231 14:29:12 epoll_wait(4, {{EPOLLIN, {u32=32,
u64=12532559950905376}}}, 65536, 673) = 1
7231 14:29:12 gettimeofday({1339590552, 684278}, NULL) = 0
7231 14:29:12 read(32, "\25\3\1\0
\367)\1\217OH\320\\|\0\211u\210\22\264\360\343\21\357\270WJ\362Y\353\366y"...,
65535) = 37
7231 14:29:12 gettimeofday({1339590552, 684730}, NULL) = 0
7231 14:29:12 epoll_ctl(4, EPOLL_CTL_MOD, 30,
{EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=30, u64=30}}) = 0
7231 14:29:12 epoll_wait(4, {{EPOLLIN, {u32=32,
u64=12532559950905376}}, {EPOLLOUT, {u32=30, u64=30}}}, 65536, 145) = 2
7231 14:29:12 gettimeofday({1339590552, 685370}, NULL) = 0
7231 14:29:12 epoll_ctl(4, EPOLL_CTL_DEL, 32, {0, {u32=32,
u64=12532559950905376}}) = 0
7231 14:29:12 write(30, "\25\3\1\0
\367)\1\217OH\320\\|\0\211u\210\22\264\360\343\21\357\270WJ\362Y\353\366y"...,
37) = 37
7231 14:29:12 gettimeofday({1339590552, 686337}, NULL) = 0
7231 14:29:12 epoll_ctl(4, EPOLL_CTL_ADD, 32,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=32, u64=32}}) = 0
7231 14:29:12 epoll_wait(4, {{EPOLLOUT, {u32=30, u64=30}}, {EPOLLIN,
{u32=32, u64=32}}}, 65536, 144) = 2
7231 14:29:12 gettimeofday({1339590552, 686967}, NULL) = 0
7231 14:29:12 epoll_ctl(4, EPOLL_CTL_MOD, 30,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=30, u64=12532559950905374}}) = 0
7231 14:29:12 read(32, "", 65535) = 0
7231 14:29:12 epoll_ctl(4, EPOLL_CTL_MOD, 30,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=30, u64=12532559950905374}}) = 0
7231 14:29:12 read(32, "", 65535) = 0
7231 14:29:12 gettimeofday({1339590552, 687567}, NULL) = 0
7231 14:29:12 read(32, "", 65535) = 0
7231 14:29:12 read(30, 0xbfdf18ed, 65535) = -1 EAGAIN (Resource
temporarily unavailable)
7231 14:29:12 brk(0x20fc9000) = 0x20fc9000
7231 14:29:12 brk(0x20fa9000) = 0x20fa9000
7231 14:29:12 epoll_ctl(4, EPOLL_CTL_DEL, 32, {0, {u32=32, u64=32}}) = 0
7231 14:29:12 close(32) = 0
7231 14:29:12 write(5, "1339590552.687 15472 10.40.1.25"..., 122) = 122
7231 14:29:12 epoll_ctl(4, EPOLL_CTL_DEL, 30, {0, {u32=30,
u64=16371771087257630}}) = 0
7231 14:29:12 close(30) = 0
7231 14:29:12 epoll_wait(4, {}, 65536, 142) = 0
7231 14:29:12 gettimeofday({1339590552, 832771}, NULL) = 0
7231 14:29:12 gettimeofday({1339590552, 832999}, NULL) = 0
7231 14:29:12 epoll_wait(4, {}, 65536, 324) = 0
7231 14:29:13 gettimeofday({1339590553, 158730}, NULL) = 0
7231 14:29:13 gettimeofday({1339590553, 158955}, NULL) = 0
7231 14:29:13 epoll_wait(4, {}, 65536, 674) = 0
7231 14:29:13 gettimeofday({1339590553, 834534}, NULL) = 0
7231 14:29:13 gettimeofday({1339590553, 834756}, NULL) = 0
7231 14:29:13 epoll_wait(4, {{EPOLLIN, {u32=7,
u64=38984572037234695}}}, 65536, 324) = 1
7231 14:29:14 gettimeofday({1339590554, 46919}, NULL) = 0
7231 14:29:14 recvfrom(7,
"\327\342\201\200\0\1\0\1\0\0\0\0\3www\7antifan\2de\0\0\34\0\1"...,
16384, 0, {sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("10.40.1.11")}, [16]) = 46
7231 14:29:14 sendto(7,
"\230\323\1\0\0\1\0\0\0\0\0\0\3www\7antifan\2de\0\0\1\0\1", 32, 0,
{sa_family=AF_INET, sin_port=htons(53),
sin_addr=inet_addr("10.40.1.11")}, 16) = 32
7231 14:29:14 recvfrom(7, 0x45af80, 16384, 0, 0x20f24490, 0x20d9db18) =
-1 EAGAIN (Resource temporarily unavailable)
7231 14:29:14 gettimeofday({1339590554, 48507}, NULL) = 0
7231 14:29:14 epoll_wait(4, {}, 65536, 110) = 0
7231 14:29:14 gettimeofday({1339590554, 160587}, NULL) = 0
7231 14:29:14 gettimeofday({1339590554, 160799}, NULL) = 0
7231 14:29:14 epoll_wait(4, {}, 65536, 132) = 0
7231 14:29:14 gettimeofday({1339590554, 295383}, NULL) = 0
7231 14:29:14 gettimeofday({1339590554, 295599}, NULL) = 0
7231 14:29:14 getrusage(RUSAGE_SELF, {ru_utime={0, 184011},
ru_stime={4, 780298}, ...}) = 0
7231 14:29:14 epoll_wait(4, {{EPOLLIN, {u32=29,
u64=13446202573979677}}}, 65536, 539) = 1
7231 14:29:14 gettimeofday({1339590554, 777295}, NULL) = 0
7231 14:29:14 accept(29, {sa_family=AF_INET6, sin6_port=htons(40214),
inet_pton(AF_INET6, "::ffff:10.40.1.254", &sin6_addr), sin6_flowinfo=0,
sin6_scope_id=0}, [28]) = 25
7231 14:29:14 getsockname(25, {sa_family=AF_INET6,
sin6_port=htons(8080), inet_pton(AF_INET6, "::ffff:10.40.1.42",
&sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
7231 14:29:14 fcntl64(25, F_GETFD) = 0
7231 14:29:14 fcntl64(25, F_SETFD, FD_CLOEXEC) = 0
7231 14:29:14 fcntl64(25, F_GETFL) = 0x2 (flags O_RDWR)
7231 14:29:14 fcntl64(25, F_SETFL, O_RDWR|O_NONBLOCK) = 0
7231 14:29:14 gettimeofday({1339590554, 779842}, NULL) = 0
7231 14:29:14 accept(29, 0x20f0d910, [28]) = -1 EAGAIN (Resource
temporarily unavailable)
7231 14:29:14 epoll_ctl(4, EPOLL_CTL_ADD, 25,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=25, u64=25}}) = 0
7231 14:29:14 epoll_wait(4, {}, 65536, 54) = 0
7231 14:29:14 gettimeofday({1339590554, 836364}, NULL) = 0
7231 14:29:14 gettimeofday({1339590554, 836589}, NULL) = 0
7231 14:29:14 epoll_wait(4, {{EPOLLIN, {u32=25, u64=25}}}, 65536, 324) = 1
7231 14:29:14 gettimeofday({1339590554, 854376}, NULL) = 0
7231 14:29:14 read(25, "CONNECT api.twitter.com:443 HTTP"..., 4095) = 179
7231 14:29:14 gettimeofday({1339590554, 854801}, NULL) = 0
7231 14:29:14 setsockopt(25, SOL_IP, IP_TOS, [0], 4) = 0
7231 14:29:14 epoll_ctl(4, EPOLL_CTL_MOD, 25,
{EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=25, u64=25}}) = 0
7231 14:29:14 epoll_wait(4, {{EPOLLOUT, {u32=25, u64=25}}}, 65536, 305) = 1
7231 14:29:14 gettimeofday({1339590554, 862590}, NULL) = 0
7231 14:29:14 write(25, "HTTP/1.0 407 Proxy Authenticatio"..., 3723) = 3723
7231 14:29:14 gettimeofday({1339590554, 868053}, NULL) = 0
7231 14:29:14 read(25, 0xbfdf194d, 65535) = -1 EAGAIN (Resource
temporarily unavailable)
7231 14:29:14 write(5, "1339590554.868 13 10.40.1.25"..., 101) = 101
7231 14:29:14 epoll_ctl(4, EPOLL_CTL_MOD, 25,
{EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=25, u64=9187888528883737}}) = 0
7231 14:29:14 epoll_ctl(4, EPOLL_CTL_DEL, 25, {0, {u32=25,
u64=9187888528883737}}) = 0
7231 14:29:14 close(25) = 0
7231 14:29:14 epoll_wait(4, {{EPOLLIN, {u32=29,
u64=13446202573979677}}}, 65536, 292) = 1
7231 14:29:15 gettimeofday({1339590555, 99535}, NULL) = 0
7231 14:29:15 accept(29, {sa_family=AF_INET6, sin6_port=htons(40215),
inet_pton(AF_INET6, "::ffff:10.40.1.254", &sin6_addr), sin6_flowinfo=0,
sin6_scope_id=0}, [28]) = 25
7231 14:29:15 getsockname(25, {sa_family=AF_INET6,
sin6_port=htons(8080), inet_pton(AF_INET6, "::ffff:10.40.1.42",
&sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, [28]) = 0
7231 14:29:15 fcntl64(25, F_GETFD) = 0
7231 14:29:15 fcntl64(25, F_SETFD, FD_CLOEXEC) = 0
7231 14:29:15 fcntl64(25, F_GETFL) = 0x2 (flags O_RDWR)
7231 14:29:15 fcntl64(25, F_SETFL, O_RDWR|O_NONBLOCK) = 0
7231 14:29:15 gettimeofday({1339590555, 101080}, NULL) = 0
7231 14:29:15 accept(29, 0x20f0d910, [28]) = -1 EAGAIN (Resource
temporarily unavailable)
7231 14:29:15 epoll_ctl(4, EPOLL_CTL_ADD, 25,
{EPOLLIN|EPOLLERR|EPOLLHUP, {u32=25, u64=25}}) = 0
7231 14:29:15 epoll_wait(4, {{EPOLLIN, {u32=25, u64=25}}}, 65536, 59) = 1
7231 14:29:15 gettimeofday({1339590555, 160195}, NULL) = 0
7231 14:29:15 read(25, "CONNECT api.twitter.com:443 HTTP"..., 4095) = 263
7231 14:29:15 gettimeofday({1339590555, 160759}, NULL) = 0
7231 14:29:15 epoll_ctl(4, EPOLL_CTL_MOD, 8,
{EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=8, u64=8}}) = 0
7231 14:29:15 epoll_wait(4, {{EPOLLOUT, {u32=8, u64=8}}}, 65536, 0) = 1
7231 14:29:15 gettimeofday({1339590555, 161520}, NULL) = 0
7231 14:29:15 write(8, "YR TlRMTVNTUAABAAAAB4IIogAAAAAAA"..., 60
<unfinished ...>
7289 14:29:15 <... read resumed> "YR TlRMTVNTUAABAAAAB4IIogAAAAAAA"...,
4096) = 60
7289 14:29:15 uname({sys="Linux", node="BSSVR03", ...}) = 0
Received on Wed Jun 13 2012 - 12:49:21 MDT