Bug 878564

Summary: IPA trust cannot always lookup AD users with wbinfo
Product: Red Hat Enterprise Linux 6 Reporter: Scott Poore <spoore>
Component: samba4Assignee: Andreas Schneider <asn>
Status: CLOSED ERRATA QA Contact: Namita Soman <nsoman>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 6.4CC: gdeschner, sbose, syeghiay
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: samba4-4.0.0-48.el6.rc4 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-02-21 08:46:18 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 886216    

Description Scott Poore 2012-11-20 17:02:24 UTC
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:

Comment 6 Scott Poore 2012-12-06 20:07:53 UTC
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?

Comment 9 Sumit Bose 2012-12-07 08:07:14 UTC
Rebooting the AD always triggered the issue for me.

Comment 10 Scott Poore 2012-12-07 22:49:10 UTC
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?

Comment 11 Sumit Bose 2012-12-10 10:15:07 UTC
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().

Comment 12 Sumit Bose 2012-12-10 21:06:51 UTC
Sorry, please look for messages from cm_prepare_connection() in the logs instead of cm_connect_lsa().

Comment 13 Scott Poore 2012-12-11 02:50:02 UTC
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

Comment 14 Guenther Deschner 2012-12-11 08:07:43 UTC
As long as 'ADTESTDOM\adtestuser1' really exists on AD, wbinfo must never fail to lookup that user.

Comment 15 Scott Poore 2012-12-11 14:38:34 UTC
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

Comment 16 Scott Poore 2012-12-11 15:15:59 UTC
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: 

[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)

Comment 17 errata-xmlrpc 2013-02-21 08:46:18 UTC
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