Bug 316 - ldap search errors in log.winbindd (-d10)
ldap search errors in log.winbindd (-d10)
Status: CLOSED FIXED
Product: Samba 3.0
Classification: Unclassified
Component: winbind
3.0.0preX
All Solaris
: P1 normal
: 3.0.1
Assigned To: Gerald (Jerry) Carter
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2003-08-18 10:46 UTC by Brian King
Modified: 2005-11-14 09:31 UTC (History)
1 user (show)

See Also:


Attachments
log.winbind (-d10, 1000K extract) (998.97 KB, text/plain)
2003-09-08 11:52 UTC, Brian King
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Brian King 2003-08-18 10:46:49 UTC
with winbindd running at debug level 10, I see the following ldap search errors 
when doing "wbinfo -u" or "wbinfo -g". It also shows up when I connect to a 
share.

...
[2003/08/18 14:33:39, 3] libads/ldap.c:ads_do_paged_search(451)
  ldap_search_ext_s((distinguishedName=CN=Thompson\, Pamela (SNB),OU=Tele Servic
esG,OU=SNB UsersG,DC=snb,DC=ca)) -> Bad search filter
[2003/08/18 14:33:39, 3] libads/ldap_utils.c:ads_do_search_retry(60)
  Reopening ads connection to realm 'SNB.CA' after error Bad search filter
[2003/08/18 14:33:39, 6] libads/ldap.c:ads_find_dc(147)
  ads_find_dc: looking for domain 'MYGROUP'
[2003/08/18 14:33:39, 8] libsmb/namequery.c:get_sorted_dc_list(1215)
  get_sorted_dc_list: attempting lookup using [lmhosts wins host bcast]
[2003/08/18 14:33:39, 10] libsmb/namequery.c:internal_resolve_name(989)
  internal_resolve_name: looking up snb-fton-ad1.snb.ca#20
[2003/08/18 14:33:39, 10] lib/gencache.c:gencache_get(263)
  Returning valid cache entry: key = NBT/SNB-FTON-AD1.SNB.CA#20, value = 142.139
.93.41:0, timeout = Mon Aug 18 14:40:21 2003
...


The "cause" appears to be the brackets in our usernames:

bash-2.05# net ads search '(distinguishedName=CN=Fortune\, Jim 
(SNB/xwave),OU=xwave,OU=IT Admin,OU=SNB UsersG,DC=snb,DC=ca)'
search failed: Bad search filter


bash-2.05# net ads search '(distinguishedName=CN=Fortune\\, Jim 
\(SNB/xwave\),OU=xwave,OU=IT Admin,OU=SNB UsersG,DC=snb,DC=ca)'
Got 1 replies

...

Once I excape the brackets (and double escape the comma because I'm working in 
a shell), it seems to return all the correct info.

I have not noticed what the functional effect of this error is.
Comment 1 Brian King 2003-09-08 11:47:24 UTC
I downloaded new CVS code today (2003-09-08) and noticed this error _seems_ to 
be worse. I now see every user repeated 3 times in a row, and eventually the 
user repeats again 3 times in a row (the users "triplet" repeats multiple (more 
than 5) times each). It is not stuck in a loop because it does eventually stop 
(about 15 minutes later with 1017 users), but it seems that an excessive amount 
of work is being done for ldap searches that should not fail. I did a 
single 'getent group', and it took about 2 minutes, but it eventually returned, 
but the ldap errors were written to log.winbindd for approximately 15 minutes 
afterward.

I'm attaching a 100K section of the log.winbindd
Comment 2 Brian King 2003-09-08 11:52:15 UTC
Created attachment 127 [details]
log.winbind (-d10, 1000K extract)

Shows repeated ldap failures, looking like they are due to non-escaped
brackets.
Comment 3 Brian King 2003-09-08 12:15:57 UTC
This may also be of interest. While waiting for "getent group" to return I 
tried to switch to debug level 10 (was at 1) for winbindd by using "smbcontrol 
winbindd debug 10". winbindd dumped core with the following backtrace and full 
backtrace. (also note, within the "smbcontrol --help", winbindd is not 
mentioned as a "destination" but does work (most of the time))

(gdb) bt
#0  0xfef1eda0 in _libc_kill () from /usr/lib/libc.so.1
#1  0xfeeb5c68 in abort () from /usr/lib/libc.so.1
#2  0x00087984 in smb_panic (why=0x13f080 "internal error") at lib/util.c:1421
#3  0x00074a5c in fault_report (sig=11) at lib/fault.c:41
#4  <signal handler called>
#5  0xfeeb3464 in strlen () from /usr/lib/libc.so.1
#6  0xfeed0578 in strdup () from /usr/lib/libc.so.1
#7  0x00123340 in ads_do_search_retry (ads=0x1ed5d0, bind_path=0x0, scope=2, 
expr=0x20129d8 "(distinguishedName=CN=Schurman\\, George (SNB),OU=SNB 
UsersG,DC=snb,DC=ca)", attrs=0xffbfecf0, res=0xffbfecd8) at 
libads/ldap_utils.c:43
#8  0x00123660 in ads_search_retry (ads=0x1ed5d0, res=0xffbfecd8, 
expr=0x20129d8 "(distinguishedName=CN=Schurman\\, George (SNB),OU=SNB 
UsersG,DC=snb,DC=ca)", attrs=0xffbfecf0) at libads/ldap_utils.c:88
#9  0x00047a0c in dn_lookup (ads=0x1ed5d0, mem_ctx=0x1d59b30, 
dn=0x1d87aa8 "CN=Schurman\\, George (SNB),OU=SNB UsersG,DC=snb,DC=ca", 
name=0xffbfed7c, name_type=0xffbfed78, sid=0xffbfed88) at 
nsswitch/winbindd_ads.c:368
#10 0x00048ed4 in lookup_groupmem (domain=0x1d0, mem_ctx=0x1d59b30, 
group_sid=0xffbff390, num_names=0xffbff100, sid_mem=0xffbff0fc, 
names=0xffbff0f8, name_types=0xffbff104) at nsswitch/winbindd_ads.c:749
#11 0x0003ef30 in lookup_groupmem (domain=0x1eb740, mem_ctx=0x1d59b30, 
group_sid=0xffbff390, num_names=0xffbff100, sid_mem=0xffbff0fc, 
names=0xffbff0f8, name_types=0xffbff104) at nsswitch/winbindd_cache.c:1238
#12 0x00036bf4 in fill_grent_mem (domain=0x1eb740, group_sid=0xffbff390, 
group_name_type=SID_NAME_DOM_GRP, num_gr_mem=0x2305e4, gr_mem=0xffbff388, 
gr_mem_len=0xffbff384) at nsswitch/winbindd_group.c:117
#13 0x00038870 in winbindd_getgrent (state=0x1fa740) at 
nsswitch/winbindd_group.c:721
#14 0x00033b94 in process_request (state=0x1fa740) at nsswitch/winbindd.c:306
#15 0x00033e9c in winbind_process_packet (state=0x620) at 
nsswitch/winbindd.c:430
#16 0x000347b0 in process_loop () at nsswitch/winbindd.c:727
#17 0x00034df8 in main (argc=0, argv=0xffbff700) at nsswitch/winbindd.c:929
(gdb) bt full
#0  0xfef1eda0 in _libc_kill () from /usr/lib/libc.so.1
No symbol table info available.
#1  0xfeeb5c68 in abort () from /usr/lib/libc.so.1
No symbol table info available.
#2  0x00087984 in smb_panic (why=0x13f080 "internal error") at lib/util.c:1421
        cmd = 0x2013d40 ""
        result = 33635648
#3  0x00074a5c in fault_report (sig=11) at lib/fault.c:41
        counter = 1
#4  <signal handler called>
No symbol table info available.
#5  0xfeeb3464 in strlen () from /usr/lib/libc.so.1
No symbol table info available.
#6  0xfeed0578 in strdup () from /usr/lib/libc.so.1
No symbol table info available.
#7  0x00123340 in ads_do_search_retry (ads=0x1ed5d0, bind_path=0x0, scope=2, 
expr=0x20129d8 "(distinguishedName=CN=Schurman\\, George (SNB),OU=SNB 
UsersG,DC=snb,DC=ca)", attrs=0xffbfecf0, res=0xffbfecd8) at 
libads/ldap_utils.c:43
        status = {error_type = ADS_ERROR_LDAP, err = {rc = 73, nt_status = {v = 
73}}, minor_status = 0}
        count = 0
        bp = 0x7 <Address 0x7 out of bounds>
#8  0x00123660 in ads_search_retry (ads=0x1ed5d0, res=0xffbfecd8, 
expr=0x20129d8 "(distinguishedName=CN=Schurman\\, George (SNB),OU=SNB 
UsersG,DC=snb,DC=ca)", attrs=0xffbfecf0) at libads/ldap_utils.c:88
No locals.
#9  0x00047a0c in dn_lookup (ads=0x1ed5d0, mem_ctx=0x1d59b30, 
dn=0x1d87aa8 "CN=Schurman\\, George (SNB),OU=SNB UsersG,DC=snb,DC=ca", 
name=0xffbfed7c, name_type=0xffbfed78, sid=0xffbfed88) at 
nsswitch/winbindd_ads.c:368
        ldap_exp = 0x20129d8 "(distinguishedName=CN=Schurman\\, George 
(SNB),OU=SNB UsersG,DC=snb,DC=ca)"
        res = (void *) 0x0
        attrs = {0x132610 "userPrincipalName", 0x132600 "sAMAccountName", 
0x132630 "objectSid", 0x132650 "sAMAccountType", 0x0}
        rc = {error_type = ADS_ERROR_LDAP, err = {rc = 81, nt_status = {v = 
81}}, minor_status = 0}
        atype = 805306368
        escaped_dn = 0x1fac338 "CN=Schurman\\5c, George \\28SNB\\29,OU=SNB 
UsersG,DC=snb,DC=ca"
#10 0x00048ed4 in lookup_groupmem (domain=0x1d0, mem_ctx=0x1d59b30, 
group_sid=0xffbff390, num_names=0xffbff100, sid_mem=0xffbff0fc, 
names=0xffbff0f8, name_types=0xffbff104) at nsswitch/winbindd_ads.c:749
        name_type = 1
        name = 0x1ff2208 "AMMACDOU"
        sid = {sid_rev_num = 1 '\001', num_auths = 5 '\005', id_auth = "\0\0\0\0
\0\005", sub_auths = {21, 1416833156, 1238969774, 10498456, 1816, 0, 0, 0, 0, 
0, 0, 0, 0, 0, 0}}
        rc = {error_type = ADS_ERROR_LDAP, err = {rc = 0, nt_status = {v = 0}}, 
minor_status = 0}
        count = 0
        res = (void *) 0x1d64738
        ads = (ADS_STRUCT *) 0x1ed5d0
        ldap_exp = 0x1c5c0b8 "`Z\006\006+\006\001\005\005\002 P0N 00.\006
\t*\206H\202÷\022\001\002\002\006\t*\206H\206÷\022\001\002\002\006
\n*\206H\206÷\022\001\002\002\003\006\n+\006\001\004\001\2027\002\002\n£\0320
\030 \026\e\024snb-fton-ad1$@SNB.CA"
        status = {v = 30836552}
        sidstr = 0x64 <Address 0x64 out of bounds>
        attrs = {0x132c58 "member", 0x0}
        members = (char **) 0x1d7b750
        i = 464
        num_members = 688
        sid_string = "ÿ¿îð?\\È:", '\0' <repeats 25 
times>, "\036Ö¨ÿ¿îà\001Õ\\\230\0\0\0/\0\036\200\020\0\0ÿ\0ÿ¿îx\0\003Î|969774-
10498456-3908\0\0ö¼\001ÖRP\0\0\0/\001Õ\\\230\0\0\0/\0\0ç\204\0\0\0@\0\0\0\0\0\0
\0@\0\0\0/\0\0\0\f±Tx\e&\001\031\231ÿ¿íh\0\0\0\vÿ¿ó¬\0\0\0\005ÿ¿ó¬\0\0\0
\005ÿ¿îè\0\024\f\0\0\024\020\0\001Ñ\207pÿ¿ñ\004ÿ¿í\210\0\036\200\020\0\036·@\0
\023\vàÿ¿ï\200\0\0\0\001\0#\004àÿ¿ï\b\0\003ð"...
#11 0x0003ef30 in lookup_groupmem (domain=0x1eb740, mem_ctx=0x1d59b30, 
group_sid=0xffbff390, num_names=0xffbff100, sid_mem=0xffbff0fc, 
names=0xffbff0f8, name_types=0xffbff104) at nsswitch/winbindd_cache.c:1238
        cache = (struct winbind_cache *) 0x48c40
        centry = (struct cache_entry *) 0x0
        status = {v = 30776112}
        i = 4290769424
        sid_string = "S-1-5-21-1416833156-1238969774-10498456-3908\0\0\0¤\001
\022\"Ø\0\0\0\005ÿ¿îè\0\024\f\0\0\024\020\0\0\0\0\vÿ¿ñ\004ÿ¿í\210\001\022F \0
\023\vàÿ¿ï\200ÿ¿ñ\0ÿ¿ðüÿ¿ðøÿ¿ð \0\bÆ\234\0\0\0\003\0\0\0\003\0\0\0
\0þÚO\024ÿ¿ðp\0\0\0\023\0\0\0\0\0\0\0\004\0\0\0\0\0\0\0\001ÿ¿ðP\0\t¨8\0\004
\214@\0\0\0\0\001\rJèÿ¿ò\fÿ¿ñ\004ÿ¿ô(\0\0\002iþô\005\230\001\022F \0\036^("...
#12 0x00036bf4 in fill_grent_mem (domain=0x1eb740, group_sid=0xffbff390, 
group_name_type=SID_NAME_DOM_GRP, num_gr_mem=0x2305e4, gr_mem=0xffbff388, 
gr_mem_len=0xffbff384) at nsswitch/winbindd_group.c:117
        sid_mem = (DOM_SID **) 0x1d68748
        num_names = 26
        name_types = (unsigned int *) 0x1d69218
        buf_len = 0
        buf_ndx = 0
        i = 2
        names = (char **) 0x1d73850
        buf = 0x12e800 "error getting user info for user '[%s]\\[%s]'\n"
        result = 0
        mem_ctx = (TALLOC_CTX *) 0x1d59b30
        status = {v = 1239040}
        sid_string = "SNB\\SMS2-Include-G\0\b\0\031,\0\0\031,\0
\001Ñ\003`ÿ¿ñ\004ÿ¿ô(\0\0\002\201þô\005\230ÿ¿ó\fÿ¿ólÿ¿óà\0\036^È\0\0\0\004ÿ¿ô-
ÿ¿ò¨\0\022\207Hÿ¿ò\224\0\aØ`\0\0\0H\0'÷Ðÿ¿ò\230\0\003\200\\", '\0' <repeats 15 
times>, "\016\0\0\0\0þóÀ\0\0\0\0\0\0\0\0\022\0\0\0\0\0\037\233Ð\0'÷Ð\0\031G \0
\036·@\0\0\0\0\0\0\0\001\0\0\0\0\001Ñ\225È\0\036·@\0\0\0\0\0
\037¶hÿ¿óÜÿ¿ó\214ÿ¿óà\0\0\0\005\0\0\017D\001"...
#13 0x00038870 in winbindd_getgrent (state=0x1fa740) at 
nsswitch/winbindd_group.c:721
        member_sid = {sid_rev_num = 1 '\001', num_auths = 5 '\005', id_auth 
= "\0\0\0\0\0\005", sub_auths = {21, 1416833156, 1238969774, 10498456, 3908, 0, 
0, 0, 0, 0, 0, 0, 0, 0, 0}}
        new_gr_mem_list = 0x1eb740 "SNB"
        domain = (struct winbindd_domain *) 0x1eb740
        name_list = (struct acct_info *) 0x27f7d0
        domain_group_name = "SNB\\SMS2-Include-G\0L-M\0TO-M\0\0\0\0\0ÿ¿õ \0
\bóèÿ¿õ \0\bóè\0\030Ð\0\0\024\024", '\0' <repeats 20 times>, "\r\0@\0\0\0\0\0
\020\0@\0\0\0\0\0\021\0@\0\0\0\0\0\023\0@\0@\0\0\0\023\0@", '\0' <repeats 15 
times>, "\002£A\0\0Aè\0\0\0\002\0\0\0\0\0\0\0\001", '\0' <repeats 17 
times>, "\037\233Ð", '\0' <repeats 33 times>, "\036^(\0\0\0\0\0\004\036,\0
\036^È\0\037§5ÿ¿õ8\0\003;\214", '\0' <repeats 12 times>, "þóò¨\177ÿÿÿ\0\0\0"...
        result = 1
        group_gid = 10248
        gr_mem_len = 0
        gr_mem = 0x0
        group_sid = {sid_rev_num = 1 '\001', num_auths = 5 '\005', id_auth = "\0
\0\0\0\0\005", sub_auths = {21, 1416833156, 1238969774, 10498456, 3908, 0, 0, 
0, 0, 0, 0, 0, 0, 0, 0}}
        ent = (struct getent_state *) 0x1f9bd0
        num_groups = 250
        group_list_ndx = 245
        i = 245
        gr_mem_list_len = 639
        new_extra_data = 0x2 <Address 0x2 out of bounds>
        gr_mem_list = 
0x1d10360 "SNB\\SNBBRBTOC02,SNB\\SNBCCMTNC01,SNB\\SNBCMMCHV02,SNB\\SNBCMMCHV01,S
NB\\SNBBMCTNC01,SNB\\SNBCMMCHC01,SNB\\SNBFHMPNC02,SNB\\SNBFHMPNC01,SNB\\SNBFSSTN
C02,SNB\\SNBFSSTNC01,SNB\\SNBFSTJHC03,SNB\\SNBFSTJHC02,SNB\\SNBF"...
#14 0x00033b94 in process_request (state=0x1fa740) at nsswitch/winbindd.c:306
        table = (struct dispatch_table *) 0x17e5b0
#15 0x00033e9c in winbind_process_packet (state=0x620) at 
nsswitch/winbindd.c:430
No locals.
#16 0x000347b0 in process_loop () at nsswitch/winbindd.c:727
        state = (struct winbindd_cli_state *) 0x1fa740
        r_fds = {fds_bits = {524288, 0 <repeats 31 times>}}
        w_fds = {fds_bits = {0 <repeats 32 times>}}
        maxfd = 1583104
        listen_sock = 16
        listen_priv_sock = 17
        selret = 1568
        timeout = {tv_sec = 30, tv_usec = 0}
        r_fds = {fds_bits = {524288, 0 <repeats 31 times>}}
        w_fds = {fds_bits = {0 <repeats 32 times>}}
        timeout = {tv_sec = 30, tv_usec = 0}
#17 0x00034df8 in main (argc=0, argv=0xffbff700) at nsswitch/winbindd.c:929
        logfile = "/usr/local/samba/var/log.winbindd\0\211\204ÿ1ú", '\0' 
<repeats 17 times>, "ÿ¿ù0ÿ1ù$", '\0' <repeats 32 times>, "ÿ3@", '\0' <repeats 
29 times>, "ÿ3ZÌ", '\0' <repeats 20 times>, "ÿ¿ù\220ÿ2\001¬", '\0' <repeats 19 
times>, "\002\0\200\0\0\177ÿÿÿ", '\0' <repeats 44 times>, "ÿ?\201ä\0
\002í\0ÿ<Ê\020ÿ?\206Ìÿ¿ùðÿ<Ê\030ÿ;\002,ÿ;\002,ÿ>@\nÿ;\002,ÿ;\002,\0\0\0
\0ÿ<b\214ÿ?\200Èÿ\n÷\0\0\0\0\030þõ\b0ÿ"...
        interactive = 0
        Fork = 1
        log_stdout = 0
        long_options = {{longName = 0x0, shortName = 0 '\0', argInfo = 4, arg = 
0x193a18, val = 0, descrip = 0x12e348 "Help options:", argDescrip = 0x0}, 
{longName = 0x12e358 "stdout", shortName = 83 'S', argInfo = 7, arg = 0x17e738, 
val = 1, descrip = 0x12e360 "Log to stdout", argDescrip = 0x0}, {longName = 
0x12e370 "foreground", shortName = 70 'F', argInfo = 7, arg = 0x17e734, val = 
0, descrip = 0x12e380 "Daemon in foreground mode", argDescrip = 0x0}, {longName 
= 0x12e3a0 "interactive", shortName = 105 'i', argInfo = 0, arg = 0x0, val = 
105, descrip = 0x12e3b0 "Interactive mode", argDescrip = 0x0}, {longName = 
0x12e3c8 "single-daemon", shortName = 89 'Y', argInfo = 7, arg = 0x17e534, val 
= 0, descrip = 0x12e3d8 "Single daemon mode", argDescrip = 0x0}, {longName = 
0x12e3f0 "no-caching", shortName = 110 'n', argInfo = 7, arg = 0x17e530, val = 
0, descrip = 0x12e400 "Disable caching", argDescrip = 0x0}, {longName = 0x0, 
shortName = 0 '\0', argInfo = 4, arg = 0x184440, val = 0, descrip = 
0x12e410 "Common samba options:", argDescrip = 0x0}, {longName = 0x0, shortName 
= 0 '\0', argInfo = 0, arg = 0x0, val = 0, descrip = 0x0, argDescrip = 0x0}}
        pc = 0x1e5c00
        opt = 16

Comment 4 Gerald (Jerry) Carter 2003-09-10 07:14:53 UTC
Brian, is this head or the 3.0 cvs tree?  I'ma assuming 
its 3.0.  Would you mind updating the versio?  Thanks.
Comment 5 Gerald (Jerry) Carter 2003-09-10 07:17:14 UTC
changing to 3.0 so I don't loose this one.
Comment 6 Brian King 2003-09-10 09:42:55 UTC
You were correct, it was CVS 3.0. I've seen it with rc1-rc3 so I just updated 
the version to rc3.
Comment 7 Guenther Deschner 2003-10-13 15:27:05 UTC
brian, 

most probably the fix for bug #592 resolves the bad search filters you were seeing.
Comment 8 Gerald (Jerry) Carter 2003-10-21 07:39:06 UTC
marking as fixed based on Guenther's comments.  Reopen 
if you find differently.
Comment 9 Gerald (Jerry) Carter 2005-02-07 09:06:27 UTC
originally reported against one of the 3.0.0rc[1-4] releases.
Cleaning up non-production versions.
Comment 10 Gerald (Jerry) Carter 2005-08-24 10:20:14 UTC
sorry for the same, cleaning up the database to prevent unecessary reopens of bugs.
Comment 11 Gerald (Jerry) Carter 2005-11-14 09:31:31 UTC
database cleanup