[Samba] mod_ntlm_winbind / Apache2

[Kevin Shanahan]

On Wed, 2006-08-30 at 00:57 +0930, Kevin Shanahan wrote:
> On Tue, 2006-08-29 at 12:09 -0300, Felipe Augusto van de Wiel wrote:
> > 	That's the reason of my question. BH is really bad. The
> > helper probably is missing something. Try to strace the command
> > and see what files it is trying to open. I don't know a easy way
> > to test it (didn't had big problems with NTLM auth, and there is
> > quite a while that I did not setup it again).
> 
> I think the "file not found" message is coming from mod_ntlm_winbind, so
> I'd need to strace apache for that.

Here is the interesting stuff:

3039  read(12, "GET /auth-test HTTP/1.1\r\nAccept: image/gif, image/x-xbitmap, image/jpeg, image/pjpeg, application/x-shockwave-flash, application/vnd.ms-excel, application/vnd.ms-powerpoint, application/msword, */*\r\nAccept-Language: en-au\r\nAccept-Encoding: gzip, deflate\r\nUser-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1)\r\nHost: intranet.ucwb.org.au\r\nConnection: Keep-Alive\r\nAuthorization: Negotiate TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAFASgKAAAADw==\r\n\r\n", 8000) = 461
3039  gettimeofday({1156866947, 939362}, NULL) = 0
3039  stat64("/var/www/auth-test", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
3039  open("/var/www/auth-test/.htaccess", O_RDONLY) = -1 ENOENT (No such file or directory)
3039  pipe([14, 15])                    = 0
3039  pipe([16, 17])                    = 0
3039  access("/usr/bin/ntlm_auth", R_OK|X_OK) = 0
3039  clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7a2f0c8) = 3050
3039  close(14)                         = 0
3039  close(17)                         = 0
3039  gettimeofday({1156866947, 940817}, NULL) = 0
3039  write(7, "[Wed Aug 30 01:25:47 2006] [debug] mod_ntlm_winbind.c(529): [client 192.168.0.53] Launched ntlm_helper, pid 3050\n", 113) = 113
3039  gettimeofday({1156866947, 940972}, NULL) = 0
3039  write(7, "[Wed Aug 30 01:25:47 2006] [debug] mod_ntlm_winbind.c(699): [client 192.168.0.53] creating auth user\n", 101) = 101
3039  write(15, "YR TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAFASgKAAAADw==\n", 60) = 60
3039  gettimeofday({1156866947, 941175}, NULL) = 0
3039  write(7, "[Wed Aug 30 01:25:47 2006] [debug] mod_ntlm_winbind.c(750): [client 192.168.0.53] parsing reply from helper to YR TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAFASgKAAAADw==\\n\n", 173) = 173
3039  read(16, "B", 1)                  = 1
3039  read(16, "H", 1)                  = 1
3039  read(16, "\n", 1)                 = 1
3039  gettimeofday({1156866947, 988012}, NULL) = 0
3039  write(7, "[Wed Aug 30 01:25:47 2006] [debug] mod_ntlm_winbind.c(788): [client 192.168.0.53] got response: BH\n", 99) = 99
3039  gettimeofday({1156866947, 988131}, NULL) = 0
3039  write(7, "[Wed Aug 30 01:25:47 2006] [error] [client 192.168.0.53] (2)No such file or directory: failed to parse response from helper\n", 124) = 124
3039  close(16)                         = 0
3039  close(15)                         = 0

And ntlm_auth is now a zombie:

# ps ax | grep ntlm
 3050 ?        Z      0:00 [ntlm_auth] <defunct>


Okay, I did another strace with -f to see what ntlm_auth is doing:
- pid 3724 is ntlm_auth
- pid 3707 is the apache process waiting for the response

3724  open("/usr/share/samba/valid.dat", O_RDONLY|O_LARGEFILE) = 3
3724  mmap2(NULL, 65536, PROT_READ, MAP_SHARED, 3, 0) = 0xb7b54000
3724  close(3)                          = 0
3724  fstat64(0, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
3724  mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f1d000
3724  read(0, "YR TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAFASgKAAAAD2==\n", 4096) = 60
3724  time(NULL)                        = 1156868276
3724  geteuid32()                       = 33
3724  write(2, "[2006/08/30 01:47:56, 1] utils/ntlm_auth.c:manage_gss_spnego_request(859)\n", 74) = 74
3724  write(1, "BH\n", 3 <unfinished ...>
3707  <... read resumed> "B", 1)        = 1
3707  read(16, "H", 1)                  = 1
3707  read(16, "\n", 1)                 = 1

So, is there something wrong with the YR request or is ntlm_auth unhappy
with what it found in valid.dat? I can't really see anything else...

Regards,
Kevin.