Red Hat Bugzilla – Bug 878564
IPA trust cannot always lookup AD users with wbinfo
Last modified: 2013-02-21 03:46:18 EST
Description of problem: Winbind appears to have a problem looking up users occasionally or for some specific environments. [root@cypher log]# wbinfo -u ADLAB\administrator ADLAB\guest ADLAB\krbtgt ADLAB\fuser ADLAB\steeve ADLAB\tuser1 ADLAB\tuser2 ADLAB\nuser1 ADLAB\nuser2 ADLAB\tuser3 ADLAB\testrelm$ ADLAB\ipa1$ ADLAB\ipa3$ ADLAB\ipa4$ ADLAB\aduser1 [root@cypher log]# wbinfo -n "ADLAB\ipa1$" S-1-5-21-3655990580-1375374850-1633065477-1169 SID_USER (1) [root@cypher log]# wbinfo -n "ADLAB\tuser1" failed to call wbcLookupName: WBC_ERR_DOMAIN_NOT_FOUND Could not lookup name ADLAB\tuser1 [root@cypher log]# wbinfo -n "ADLAB\tuser3" S-1-5-21-3655990580-1375374850-1633065477-1157 SID_USER (1) [root@cypher log]# wbinfo -n "ADLAB\tuser2" failed to call wbcLookupName: WBC_ERR_DOMAIN_NOT_FOUND Could not lookup name ADLAB\tuser2 [root@cypher log]# wbinfo -n "ADLAB\tuser1" failed to call wbcLookupName: WBC_ERR_DOMAIN_NOT_FOUND Could not lookup name ADLAB\tuser1 When this happens, I see something like this in /var/log/samba/log.winbindd: [2012/11/18 19:51:08.284832, 10, pid=5530, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:650(process_request) process_request: Handling async request 5548:LOOKUPNAME [2012/11/18 19:51:08.284906, 3, pid=5530, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_lookupname.c:69(winbindd_lookupname_send) lookupname ADLAB\tuser1 [2012/11/18 19:51:08.284999, 1, pid=5530, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:282(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName in: struct wbint_LookupName domain : * domain : 'ADLAB' name : * name : 'TUSER1' flags : 0x00000000 (0) [2012/11/18 19:51:08.285421, 1, pid=5530, effective(0, 0), real(0, 0)] ../librpc/ndr/ndr.c:282(ndr_print_function_debug) wbint_LookupName: struct wbint_LookupName out: struct wbint_LookupName type : * type : SID_NAME_USE_NONE (0) sid : * sid : S-0-0 result : NT_STATUS_ACCESS_DENIED [2012/11/18 19:51:08.285666, 5, pid=5530, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_lookupname.c:104(winbindd_lookupname_recv) Could not convert sid S-0-0: NT_STATUS_ACCESS_DENIED [2012/11/18 19:51:08.285732, 10, pid=5530, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd.c:712(wb_request_done) wb_request_done[5548:LOOKUPNAME]: NT_STATUS_ACCESS_DENIED Version-Release number of selected component (if applicable): How reproducible: Unknown Steps to Reproduce: 1. Setup IPA Master 2. Setup AD Server and create some users 3. ipa-adtrust-install 4. ipa trust-add <addomain> --admin Administrator --password 5. wbinfo -u 6. wbinfo -n "<ADNETBIOSNAME>\<aduser>" Actual results: Fails with errors similar to above Expected results: Returns user SID Additional info:
So, since I was not able to reproduce this on a consistent basis, is there a better way I could reproduce/verify this than using wbinfo?
Rebooting the AD always triggered the issue for me.
Ok, I was able to reproduce this by rebooting AD AND waiting: [root@rhel6-1 yum.repos.d]# rpm -qa samba4 samba4-4.0.0-44.el6.rc4.x86_64 [root@rhel6-1 yum.repos.d]# wbinfo -n "ADTESTDOM\$RANDOM" failed to call wbcLookupName: WBC_ERR_DOMAIN_NOT_FOUND Could not lookup name ADTESTDOM$RANDOM [root@rhel6-1 yum.repos.d]# wbinfo -n "ADTESTDOM\testuser2" failed to call wbcLookupName: WBC_ERR_DOMAIN_NOT_FOUND Could not lookup name ADTESTDOM\testuser2 [root@rhel6-1 yum.repos.d]# wbinfo -n "ADTESTDOM\testuser2" failed to call wbcLookupName: WBC_ERR_DOMAIN_NOT_FOUND Could not lookup name ADTESTDOM\testuser2 On fixed version after AD reboot: [root@rhel6-2 ~]# rpm -q samba4-client samba4-client-4.0.0-48.el6.rc4.x86_64 [root@rhel6-2 ~]# wbinfo -n "ADTESTDOM\$RANDOM" failed to call wbcLookupName: WBC_ERR_DOMAIN_NOT_FOUND Could not lookup name ADTESTDOM$RANDOM [root@rhel6-2 ~]# wbinfo -n "ADTESTDOM\testuser2" S-1-5-21-1246088475-3077293710-2580964704-1133 SID_USER (1) [root@rhel6-2 ~]# sleep 900 ; wbinfo -n "ADTESTDOM\testuser2" S-1-5-21-1246088475-3077293710-2580964704-1133 SID_USER (1) Is there also something in the log I can search for?
I think it is ok to just see that wbinfo is working again. In the logs (with debug level 10 or higher) you should only see messages from cm_connect_lsa_tcp() but no from cm_connect_lsa(). In in old version if cm_connect_lsa_tcp() failed due to some connection issues cm_connect_lsa() was directly used as a fallback on the new connection. With the patches cm_connect_lsa_tcp() is tried again if the connection is restablished and so you shouldn't see any message from cm_connect_lsa().
Sorry, please look for messages from cm_prepare_connection() in the logs instead of cm_connect_lsa().
Is it possible that I wouldn't see it for every failure? I'm just trying to finish [root@rhel6-1 samba]# wbinfo -n "ADTESTDOM\adtestuser1" failed to call wbcLookupName: WBC_ERR_DOMAIN_NOT_FOUND Could not lookup name ADTESTDOM\adtestuser1 [root@rhel6-1 samba]# date Mon Dec 10 20:28:33 EST 2012 [root@rhel6-1 samba]# grep cm_prepare_connection log.wb-ADTESTDOM <snip/> [2012/12/10 20:02:25.271601, 10, pid=18169, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:965(cm_prepare_connection) cm_prepare_connection: falling back to anonymous connection for DC W2K8R2-1 [2012/12/10 20:02:25.279598, 5, pid=18169, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:969(cm_prepare_connection) Testing again I do see it: [2012/12/10 21:21:56.670091, 10, pid=18169, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:806(cm_prepare_connection) cm_prepare_connection: connecting to DC w2k8r2-1.adtestdom.com for domain ADTESTDOM [2012/12/10 21:21:56.671134, 3, pid=18169, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:597(cm_get_ipc_userpass) cm_get_ipc_userpass: No auth-user defined [2012/12/10 21:21:56.671200, 10, pid=18169, effective(0, 0), real(0, 0), class=winbind] ../source3/winbindd/winbindd_cm.c:965(cm_prepare_connection) cm_prepare_connection: falling back to anonymous connection for DC w2k8r2-1.adtestdom.com
As long as 'ADTESTDOM\adtestuser1' really exists on AD, wbinfo must never fail to lookup that user.
I mean are there some cases where I wouldn't see the cm_prepare_connection messages when I do see failure to lookup a user that does exist? That's what I saw at first above. Sorry I didn't make that clear but, the first log entries I listed happened before the failed lookup I listed. Thanks
Verified. Version :: samba4-4.0.0-48.el6.rc4.x86_64 Manual Test Results :: I've run wbinfo -n commands many times and so far I have seen no errors with the fixed version. As far as I am able to tell right now, this is verified. [root@rhel6-2 ~]# kinit admin Password for admin@TESTRELM2.COM: [root@rhel6-2 ~]# wbinfo -n "ADTESTDOM\adtestuser1" S-1-5-21-1246088475-3077293710-2580964704-1136 SID_USER (1) [root@rhel6-2 ~]# grep cm_prepare /var/log/samba/log.wb-ADTESTDOM [root@rhel6-2 ~]# wbinfo -n "ADTESTDOM\adtestuser1" S-1-5-21-1246088475-3077293710-2580964704-1136 SID_USER (1) [root@rhel6-2 ~]# wbinfo -n "ADTESTDOM\adtestuser2" S-1-5-21-1246088475-3077293710-2580964704-1138 SID_USER (1) [root@rhel6-2 ~]# for u in $(wbinfo -u); do echo "########### $u" ; wbinfo -n "$u"; done ########### ADTESTDOM\administrator S-1-5-21-1246088475-3077293710-2580964704-500 SID_USER (1) ########### ADTESTDOM\guest S-1-5-21-1246088475-3077293710-2580964704-501 SID_USER (1) ########### ADTESTDOM\krbtgt S-1-5-21-1246088475-3077293710-2580964704-502 SID_USER (1) ########### ADTESTDOM\abc S-1-5-21-1246088475-3077293710-2580964704-1105 SID_USER (1) ########### ADTESTDOM\anothertest S-1-5-21-1246088475-3077293710-2580964704-1119 SID_USER (1) ########### ADTESTDOM\testuser1 S-1-5-21-1246088475-3077293710-2580964704-1127 SID_USER (1) ########### ADTESTDOM\testuser2 S-1-5-21-1246088475-3077293710-2580964704-1133 SID_USER (1) ########### ADTESTDOM\adtestuser1 S-1-5-21-1246088475-3077293710-2580964704-1136 SID_USER (1) ########### ADTESTDOM\adtestuser2 S-1-5-21-1246088475-3077293710-2580964704-1138 SID_USER (1) ########### ADTESTDOM\adtestuser3 S-1-5-21-1246088475-3077293710-2580964704-1139 SID_USER (1) ########### ADTESTDOM\adtestuser4 S-1-5-21-1246088475-3077293710-2580964704-1140 SID_USER (1) ########### ADTESTDOM\adtestuser5 S-1-5-21-1246088475-3077293710-2580964704-1142 SID_USER (1) ########### ADTESTDOM\adtestuser10 S-1-5-21-1246088475-3077293710-2580964704-1148 SID_USER (1) ########### ADTESTDOM\adtestuser200 S-1-5-21-1246088475-3077293710-2580964704-1153 SID_USER (1) ########### ADTESTDOM\testrelm$ S-1-5-21-1246088475-3077293710-2580964704-1166 SID_USER (1) ########### ADTESTDOM\testrelm1$ S-1-5-21-1246088475-3077293710-2580964704-1167 SID_USER (1) ########### ADTESTDOM\testrelm2$ S-1-5-21-1246088475-3077293710-2580964704-1169 SID_USER (1) ########### ADTESTDOM\testuser3 S-1-5-21-1246088475-3077293710-2580964704-1170 SID_USER (1) ########### ADTESTDOM\testuser4 S-1-5-21-1246088475-3077293710-2580964704-1171 SID_USER (1)
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. http://rhn.redhat.com/errata/RHSA-2013-0506.html