Created attachment 65 [details]
core dump

This is the core created by:

touch /tmp/test
chgrp 10001 /tmp/test
ls -l /tmp/test

I installed gdb and grabbed a backtrace in case that helps. The 3 backtraces 
below are from 3 different incidents, 1 caused by the 'ls -l' described early; 
and the other 2 by 'getent group'. They all look the same.

(gdb) bt
#0  0xff01eda0 in _libc_kill () from /usr/lib/libc.so.1
#1  0xfefb5c68 in abort () from /usr/lib/libc.so.1
#2  0xfefb5f08 in _assert () from /usr/lib/libc.so.1
#3  0xff096f90 in ldap_get_values (ld=0x28a1f8, entry=0x0,
    target=0x161b98 "userPrincipalName") at getvalues.c:63
#4  0x00118dd0 in ads_pull_string ()
#5  0x00119240 in ads_pull_username ()
#6  0x00046bc0 in get_ldap_sequence_number ()
#7  0x00048010 in get_ldap_sequence_number ()
#8  0x0003e5fc in centry_start ()
#9  0x000366e0 in winbindd_list_users ()
#10 0x0003835c in winbindd_getgrent ()
#11 0x000336ac in unbecome_root ()
#12 0x000339b4 in winbind_process_packet ()
#13 0x000342c8 in winbind_client_read ()
#14 0x00034914 in main ()


(gdb) bt
#0  0xff01eda0 in _libc_kill () from /usr/lib/libc.so.1
#1  0xfefb5c68 in abort () from /usr/lib/libc.so.1
#2  0xfefb5f08 in _assert () from /usr/lib/libc.so.1
#3  0xff096f90 in ldap_get_values (ld=0x214f20, entry=0x0,
    target=0x161b98 "userPrincipalName") at getvalues.c:63
#4  0x00118dd0 in ads_pull_string ()
#5  0x00119240 in ads_pull_username ()
#6  0x00046bc0 in get_ldap_sequence_number ()
#7  0x00048010 in get_ldap_sequence_number ()
#8  0x0003e5fc in centry_start ()
#9  0x000366e0 in winbindd_list_users ()
#10 0x0003763c in winbindd_getgrgid ()
#11 0x000336ac in unbecome_root ()
#12 0x000339b4 in winbind_process_packet ()
#13 0x000342c8 in winbind_client_read ()
#14 0x00034914 in main ()

(gdb) bt
#0  0xff01eda0 in _libc_kill () from /usr/lib/libc.so.1
#1  0xfefb5c68 in abort () from /usr/lib/libc.so.1
#2  0xfefb5f08 in _assert () from /usr/lib/libc.so.1
#3  0xff096f90 in ldap_get_values (ld=0x26b208, entry=0x0,
    target=0x161b98 "userPrincipalName") at getvalues.c:63
#4  0x00118dd0 in ads_pull_string ()
#5  0x00119240 in ads_pull_username ()
#6  0x00046bc0 in get_ldap_sequence_number ()
#7  0x00048010 in get_ldap_sequence_number ()
#8  0x0003e5fc in centry_start ()
#9  0x000366e0 in winbindd_list_users ()
#10 0x0003763c in winbindd_getgrgid ()
#11 0x000336ac in unbecome_root ()
#12 0x000339b4 in winbind_process_packet ()
#13 0x000342c8 in winbind_client_read ()
#14 0x00034914 in main ()

Created attachment 67 [details]
log.winbind at debug level 10.

This is 'winbindd -d10' output to log.winbindd. The log only contains the
events from starting of winbindd, immediately followed by 'getent group', which
causes winbindd to core.

Created attachment 69 [details]
Backtrace of a non-stripped winbindd - more detail than other backtraces

The previous backtrace from gdb was created with a "stripped" version of
winbind. I've recreated the problem with a non stripped version so you can see
more detail.

Created attachment 70 [details]
Check return code of ads_search_retry()

Here's a patch that could fix the problem.  From the full backtrace (thanks -
very helpful!) it seems that the ads_search_retry() is returning OK but with an
NULL result.

Jerry, can you take a look and see if this makes sense?

That fixed my particular problem.

Side note, that same check occurs after ads_search_retry() in several other 
places within that same file (winbindd_ads.c). Could there be other similar 
problems that just haven't been triggered in my environment?

Line#   TEXT
126:    if (!ADS_ERR_OK(rc)) {
227:    if (!ADS_ERR_OK(rc)) {
439:    if (!ADS_ERR_OK(rc)) {
514:    if (!ADS_ERR_OK(rc)) {
612:    if (!ADS_ERR_OK(rc)) {
627:    if (!ADS_ERR_OK(rc)) {
715:    if (!ADS_ERR_OK(rc)) {
788:    if (!ADS_ERR_OK(rc)) {
841:    if (!ADS_ERR_OK(rc)) {

Thanks for the quick response!

Something still doesn't work quite right (or at least not the way I'd expect), 
but maybe this is a different bug?

This user is in 6 AD groups.
bash-2.05# wbinfo -r SNB.CA:xbking
10013
10048
10027
10023
10009
10005

bash-2.05# for gid in `wbinfo -r SNB.CA:xbking` ; do
> wbinfo -s `wbinfo -G $gid`
> done
SNB:Domain Users 2
Could not lookup sid S-1-5-32-545
SNB:MVIRP-G 2
SNB:SNB-Admin-G 2
SNB:SNB-EDUC-STUDENTFS-DATA-G 2
SNB:SNB-EDUC-STUDENTFS-DATA-TEST-G 2

Now I have a share defined as:


[public]
   comment = Public Stuff
   path = /home/samba
   public = yes
   writable = yes
   printable = no
   valid users = @SNB.CA:SNB-EDUC-STUDENTFS-DATA-TEST-G

It will not let the user SNB.CA:xbking connect. It doesn't appear to check for 
group permission at all?!?

=======
bash-2.05# /usr/local/samba/bin/smbd -id 3 -s/usr/local/samba/lib/smb.conf
get_current_groups: user is in 11 groups: 1, 0, 2, 3, 4, 5, 6, 7, 8, 9, 12
smbd version 3.0.0beta3 started.
Copyright Andrew Tridgell and the Samba Team 1992-2003
uid=0 gid=0 euid=0 egid=0
lp_load: refreshing parameters
Initialising global parameters
params.c:pm_process() - Processing configuration 
file "/usr/local/samba/lib/smb.conf"
Processing section "[global]"
Processing section "[homes]"
Processing section "[public]"
Processing section "[certmu]"
Processing section "[inuse]"
Processing section "[spad]"
Processing section "[PlanetPATSData]"
adding IPC service
adding IPC service
Failed to load /usr/local/samba/lib/valid.dat - No such file or directory
creating default valid table
added interface ip=10.7.7.5 bcast=10.7.7.255 nmask=255.255.255.0
added interface ip=142.139.95.8 bcast=142.139.95.255 nmask=255.255.252.0
loaded services
Registered MSG_REQ_POOL_USAGE
Registered MSG_REQ_DMALLOC_MARK and LOG_CHANGED
waiting for a connection
open_oplock_ipc: opening loopback UDP socket.
open_oplock ipc: pid = 1187, global_oplock_port = 41572
Transaction 0 of length 183
switch message SMBnegprot (pid 1187)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
Requested protocol [PC NETWORK PROGRAM 1.0]
Requested protocol [MICROSOFT NETWORKS 1.03]
Requested protocol [MICROSOFT NETWORKS 3.0]
Requested protocol [LANMAN1.0]
Requested protocol [LM1.2X002]
Requested protocol [DOS LANMAN2.1]
Requested protocol [Samba]
using SPNEGO
Selected protocol NT LANMAN 1.0
Transaction 1 of length 1414
switch message SMBsesssetupX (pid 1187)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
wct=12 flg2=0xc801
Doing spnego session setup
NativeOS=[Unix] NativeLanMan=[Samba]
Got OID 1 2 840 48018 1 2 2
Got OID 1 3 6 1 4 1 311 2 2 10
Got secblob of size 1273
Ticket name is [xbking@SNB.CA]
push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
push_conn_ctx(0) : conn_ctx_stack_ndx = 0
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
fetch sid from gid cache 10013 -> S-1-5-21-1416833156-1238969774-10498456-513
User name: SNB.CA:xbking        Real name: Brian King (SNB/xwave)
UNIX uid 10010 is UNIX user SNB.CA:xbking, and will be vuid 100
Adding/updating homes service for user 'SNB.CA:xbking' using home 
directory: '/export/home/SNB.CA/xbking'
adding home's share [xbking] for user 'SNB.CA:xbking' 
at '/export/home/SNB.CA/xbking'
Transaction 2 of length 100
switch message SMBtconX (pid 1187)
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
user 'SNB.CA:xbking' (from session setup) not permitted to access this share 
(public)
error string = Bad file number
error packet at smbd/reply.c(268) cmd=117 (SMBtconX) NT_STATUS_ACCESS_DENIED
Transaction 3 of length 45
switch message SMBclose (pid 1187)
error packet at smbd/process.c(719) cmd=4 (SMBclose) 
NT_STATUS_NETWORK_NAME_DELETED
end of file from client
setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
Closing connections
Yielding connection to
Server exit (normal exit)

===
I expected groups to work this way because users do work this way.

   valid users = @SNB.CA:xbking

Does work for access.

====
This might be related. The "groups" command does not pick up all the AD users 
groups:

bash-2.05# groups SNB.CA:xbking
SNB:Domain Users

Correction to the last comment.

   valid users = SNB.CA:xbking

works for access to the share. xbking is a user, not a group.

The groups command not picking up all the groups is probably causing the access
check to fail.  Would you be able to post:

  - smbd debug level 10 (instead of level 3) from comment 8
  - winbindd debug level 10 when doing the groups command that doesn't return
the full group membership

Thanks!

Jerry dude, what do you think about applying the NULL check patch to the result
of all searches in winbindd_ads.c?

Created attachment 77 [details]
"smbd -id 10" from comment 8

I am probably reading the output in the attachment wrong, but does the line:

NT user token of user S-1-5-21-1298324328-75492828-1082003079-21020

mean that the sid of SNB.CA:xbking should be that sid? SNB.CA:xbking is:

bash-2.05# wbinfo -n SNB.CA:xbking
S-1-5-21-1416833156-1238969774-10498456-5909 1

Created attachment 78 [details]
"winbind -d10" : "groups SNB.CA:xbking" returns 1 of 6 groups (see comment 8)

I think that checking the return codes is about the bext 
ew can do.  Looking at the backtrace, i wonder if a user 
has not been deleted from the directory ut not removed from a group.
However, whenever I remove a user, the group membership is cleaned
up as well.

Are you working off the latest SAMBA_3_0 cvs code ?  I fixed a problem 
with secondary groups last week.

No, working off of the 3.0b3 code, plus the patch attached to this bug. Should 
I be switching?

If you wouldn't mind testing the latest CVS for the issing 
supplementary groups problem that would be good.

I haven't used the CVS before, so I could have done this wrong, but I think I 
downloaded the latest source, and now nothing seems to be working.
- I can't connect with "smbclient -k" like I used to be able to.
- "wbinfo -g" doesn't return anything
- getent passwd shows the local users and hangs
- Stopping samba, winbindd could not be killed without 'kill -9'
- "ls -l" on a file owned by group 10001 no longer shows the AD group, but 
doesn't kill winbindd or hang like it did with 3.0b3

smbclient can still be used to connect to windows based shares. So the network, 
kerberos, and authentication are still working from the client side.

This is what I am seeing in the log.winbindd (no debug - I'll send debug 
attachment in a while):

  winbindd version 3.0.0rc1 started.
  Copyright The Samba Team 2000-2003
[2003/08/15 14:57:27, 0] nsswitch/winbindd.c:process_loop(722)
  process_loop: Invalid request size from pid 22428: 1312 bytes sent, should be 
1568
[2003/08/15 14:57:35, 0] nsswitch/winbindd.c:process_loop(722)
  process_loop: Invalid request size from pid 22428: 1312 bytes sent, should be 
1568


==
That PID corresponds to:
bash-2.05# ps -fp 22428
     UID   PID  PPID  C    STIME TTY      TIME CMD
    root 22428     1  0   Aug 08 ?        0:22 /usr/sbin/nscd

===

Interesting... instead of stopping the processes this time, I tried to change 
the debug level on the fly with smbcontrol.

I had a "wbinfo -g" running and appearing hung.
Within a second or so of sending "./smbcontrol winbindd debug 10", the wbinfo -
g returned with a LONG list of groups.

Where I used to only get groups in my "container" (SNB.CA), I now suddenly get 
groups belonging to what I believe is the PARENT container for SNB.CA (GNB.CA), 
and also groups belonging to "MYGROUP" which I believe is a child of the SNB.CA 
container that my server is registered in.

I believe the "hang" might have just been a long delay because of the vast 
increase in the number of objects needing to be returned. Used to be ~370 
groups, now there are ~7100 groups. Users grew from __ to ~8000 a while ago, to 
~18000 at last try (based on "wbinfo -u|wc -l").

I'll do a little more experimenting and report back. If there is anything you'd 
like me to try/change/check, let me know.

Created attachment 80 [details]
winbind coredump while doing "groups SNB.CA:xbking"

Tried:
bash-2.05# groups SNB.CA:xbking
SNB.CA:xbking : SNB:Domain Users

While groups was running,after ~30 seconds in another window I did:
./smbcontrol winbindd debug 10

It returned my groups (well 1 anyway), but winbind cored.

Created attachment 81 [details]
log.winbind associated with previous core/back trace

More info. I started "winbind -g" and it's been running 10 minutes now. This 
time winbindd was running at debug level 10 from the start and I can see the 
cause of the delays.

It's trying to contact every AD server listed in the "trusted" group for our AD 
domain/realm. Many of them are firewalled so that my UNIX Samba server can't 
reach them. It's taking ~225 seconds per IP address to timeout:

...
 remove_duplicate_addrs2: looking for duplicate address/port pairs
[2003/08/15 15:42:20, 5] libsmb/namecache.c:namecache_store(131)
  namecache_store: storing 11 addresses for nbed.nb.ca#1c: 
142.139.201.68:389,204.81.12.61:389,204.81.8.128:389,204.81.12.87:389,204.82.79.
51:389,204.82.78.122:389,204.82.79.54:389,204.82.78.249:389,204.81.189.104:389,2
04.81.0.121:389,204.81.0.215:389
[2003/08/15 15:42:20, 10] lib/gencache.c:gencache_set(126)
  Adding cache entry with key = NBT/NBED.NB.CA#1C; value = 
142.139.201.68:389,204.81.12.61:389,204.81.8.128:389,204.81.12.87:389,204.82.79.
51:389,204.82.78.122:389,204.82.79.54:389,204.82.78.249:389,204.81.189.104:389,2
04.81.0.121:389,204.81.0.215:389 and timeout                    = Fri Aug 15 
15:53:20 2003
   (660 seconds ahead)
[2003/08/15 15:42:20, 10] libsmb/namequery.c:internal_resolve_name(1099)
  internal_resolve_name: returning 11 addresses: 142.139.201.68:389 
204.81.12.61:389 204.81.8.128:389 204.81.12.87:389 204.82.79.51:389 
204.82.78.122:389 204.82.79.54:389 204.82.78.249:389 204.81.189.104:389 
204.81.0.121:389 204.81.0.215:389
[2003/08/15 15:42:20, 5] libads/ldap.c:ads_try_connect(56)
  ads_try_connect: trying ldap server '142.139.201.68' port 389
[2003/08/15 15:46:05, 10] libsmb/conncache.c:add_failed_connection_entry(132)
  add_failed_connection_entry: added domain nbed.nb.ca (142.139.201.68) to 
failed conn cache
[2003/08/15 15:46:05, 5] libads/ldap.c:ads_try_connect(56)
  ads_try_connect: trying ldap server '204.81.12.61' port 389
[2003/08/15 15:46:05, 10] libsmb/conncache.c:add_failed_connection_entry(132)
  add_failed_connection_entry: added domain nbed.nb.ca (204.81.12.61) to failed 
conn cache
[2003/08/15 15:46:05, 5] libads/ldap.c:ads_try_connect(56)
  ads_try_connect: trying ldap server '204.81.8.128' port 389
[2003/08/15 15:46:05, 10] libsmb/conncache.c:add_failed_connection_entry(132)
  add_failed_connection_entry: added domain nbed.nb.ca (204.81.8.128) to failed 
conn cache
[2003/08/15 15:46:05, 5] libads/ldap.c:ads_try_connect(56)
  ads_try_connect: trying ldap server '204.81.12.87' port 389

[2003/08/15 15:49:49, 10] libsmb/conncache.c:add_failed_connection_entry(132)
  add_failed_connection_entry: added domain nbed.nb.ca (204.81.12.87) to failed 
conn cache
[2003/08/15 15:49:49, 5] libads/ldap.c:ads_try_connect(56)
  ads_try_connect: trying ldap server '204.82.79.51' port 389
[2003/08/15 15:53:34, 10] libsmb/conncache.c:add_failed_connection_entry(132)
  add_failed_connection_entry: added domain nbed.nb.ca (204.82.79.51) to failed 
conn cache
[2003/08/15 15:53:34, 5] libads/ldap.c:ads_try_connect(56)
  ads_try_connect: trying ldap server '204.82.78.122' port 389
....

These other trusts were set up so that people in our domain could use resources 
in the other domains, but not the reverse. As such, we can't contact most of 
the other AD servers. I'm guessing there must be a config option that I missed 
to limit me to only my container, and  not look at the trusts?

The core dump is probably still an issue for you though since smbcontrol run at 
certain times seems to be able to take out winbindd.

The invalid request size message means that you either haven't installed a new
version of libnss_winbind.so, or there is a running process that has a mmapped()
copy of the old library.  The process will need to be restarted.

Did you apply the patch from comment 5 to the new source tree?  We haven't
committed this patch to CVS yet.

OK, I found the parameter "allow trusted domains = no" and it has stopped the 
extra long delays from AD servers that are unreachable.

The new CVS code plus the patch above (wasn't applied in CVS), does not fix my 
original problem either.

"getent group" does seem to return some of the proper entries, but they don't 
agree with the groups command, or the wbinfo -r command:


bash-2.05# for gid in `wbinfo -r SNB.CA\\\\xnoel` ; do wbinfo -s `wbinfo -G 
$gid` ; done
SNB\Domain Users 2
Could not lookup sid S-1-5-32-544
Could not lookup sid S-1-5-32-545
Could not lookup sid S-1-5-32-550
SNB\SMSRemoteControlServers 2
SNB\Domain Admins 2

bash-2.05# groups SNB.CA\\xnoel
SNB:Domain Users

bash-2.05# getent group | grep xnoel
SNB\Domain 
Admins:x:10001:SNB\xbert,SNB\xnoel,SNB\SMSService,SNB\sms,SNB\Admin,SNB\arcserve
,SNB\oper
SNB\SMSRemoteControlServers:x:10340:SNB\xbert,SNB\xnoel



* I restarted nscd and that got rid of the invalid request size problem

Created attachment 82 [details]
winbind -d10 for comment 25

It looks like winbind is rotating the log file and I may not have captured
everything here. If you need more I'll try that again. I do see a "Bad search
filter" message in there several times, that might be related? Also a confusing
message "ads reopen failed after error Success" sounds like it thinks "Success"
is a bad thing?!?

Good news...
The original functionality I was looking for (the ability to use AD groups on 
the "valid users" line in smb.conf) is actually working now. The "groups" 
command still doesn't return what I'd expect, but it has no apparent affect on 
functionality.

The errors in comment 26 , attachment 82 [details] , "bad search filter" seem to just be 
a matter of escaping the brackets. e.g.

---- log.winbindd (-d10) -----
[2003/08/18 09:58:09, 3] libads/ldap.c:ads_do_paged_search(451)
  ldap_search_ext_s((distinguishedName=CN=Stairs\, George (SNB),OU=SNB UsersG,DC
=snb,DC=ca)) -> Bad search filter
[2003/08/18 09:58:09, 3] libads/ldap_utils.c:ads_do_search_retry(60)
  Reopening ads connection to realm 'SNB.CA' after error Bad search filter
------------------------

If I escape the brackets around "SNB", it returns the record it should have.
bash# net ads search '(distinguishedName=CN=Stairs\\, George \(SNB\),OU=SNB 
UsersG,DC=snb,DC=ca)'

* Note, the double backslash before the comma is just because I was executing 
in a shell, it shouldn't normally be necessary

===

This also works now:

bash-2.05# touch /tmp/test
bash-2.05# chown SNB\\xbking:SNB\\Domain\ Users /tmp/test
bash-2.05# ls -l /tmp/test
-rw-r--r--    1 SNB\xbking SNB\Domain Users        0 Aug  8 15:57 /tmp/test

====
The only outstanding problems would be:

- the ldapsearch error in the winbind log that doesn't cause any noticable 
problems YET
- the winbind dumping core with "allow trusted domains = Yes"; and sending 
multiple "smbcontrol winbindd debug 10" messages during a long running "groups 
<ADUser>". (shouldn't have any major impacts)

Would it be easier for you to track if we close this bug report and I open two 
others for those two items?
===
Thanks for all your quick responses and the patch!

It would be better to open 2 new bugs:

  * ldapsearch errors
  * core dump when "allow trusted domains = yes"

The smbcontrol behavior is expected since Samba
daemons handle messages (and signal processing) in 
band.  winbindd won't do anything about the message 
from smbcontrol until it gets done with the current 
operation.  

I'm marking this issue as fixed.  Please open up 
new bugs for the above issues.  And thanks for you 
help in tracking down these problems.

Just a reminder, this patch does not seem to have made it into the CVS codebase 
yet (see comment 34). I thought it might have gotten overlooked since the issue 
was marked resolved.

===
A diff between my winbindd_adc.c, and one I just downloaded from CVS.

bash-2.05# diff -u winbindd_ads.c winbindd_ads.c.bk
--- winbindd_ads.c      Thu Aug 28 15:28:01 2003
+++ winbindd_ads.c.bk   Fri Aug 15 09:54:29 2003
@@ -378,7 +378,7 @@
        SAFE_FREE(ldap_exp);
        SAFE_FREE(escaped_dn);

-       if (!ADS_ERR_OK(rc)) {
+       if (!ADS_ERR_OK(rc) || !res) {
                goto failed;
        }

Checked in.

Has anyone opened bugs for the side-issues discovered when fixing this one?

I opened a bug for the ldapsearch problem (bug 316)

I didn't open one for the 'allow trusted domains = yes'. winbindd probably 
shouldn't have dumped core, but at least part of the problem was the 
environment. We have 1 way trusted and firewalls don't allow communication the 
other way, so I _think_ this is an abnormal situation. I found I needed 'allow 
trusted domains = no' anyway because of the direction of the 1 way trusts.

I don't know if comment 7 has been addressed or not. It doesn't belong as a 
separate bug (I don't think anyway?).

Tim, there were actually several pointer checks
that we thought were needed (code that had been copied 
from one section to another).  Do we still need then?

Extra checks added.

I had a brief look around for places for any extra checks but couldn't find any
in that file.

I am wondering whether we should just fix it inside the search function rather
than doing the extra check thing?

do what you think needs to be done.  We've closed 
this particular bug but if you think we need more done, 
open a new one.

originally reported against 3.0.0beta3.  CLeaning out 
non-production release versions.

sorry for the same, cleaning up the database to prevent unecessary reopens of bugs.

database cleanup