[Samba] "Could not convert SID" error - different results for the same AD query

Tue Apr 15 15:29:34 MDT 2014

I have a situation where users sometimes can't access shares on samba
servers, and sometimes (a minute later) can. 

This is Samba 3.6.3 on Ubuntu 12.04, using Winbind against a Windows 2008 AD
server.

Comparing the success and failure debug logs I managed to capture, I see
this difference:

This line is present in the log of the failed attempt, but not the
successful attempt:
[2014/03/21 15:38:46.920046, 10] auth/auth_util.c:505(create_local_token)
Could not convert SID S-1-5-21-3579304287-3829738268-3886208222-513 to gid,
ignoring it

My suspicion is that the AD server isn't responding when queried for
information about this SID, or else winbind isn't doing something correctly.
Given that winbind sometimes has wildly differing response times when
queried for information (anywhere from ~0 seconds to 15 seconds), and this
bears a similar feel to a network timeout, it's possible that the AD server
sometimes isn't responding quickly enough. Or, the AD server could simply be
returning incomplete information.

Does anyone have a suggestion for how to track things down further? I really
don't know much about winbind or AD or even SIDs in general.

Is there much chance that this is a winbind problem, or is it more likely an
AD problem?

Given that I'm not going to be able to replace the AD server, might sssd
work better for querying the AD server?

More details:

Note the different number of SIDs in this successful attempt (12) vs. the
unsuccessful attempt (11):

Successful login:
[2014/03/21 15:40:40.262408, 10]
../libcli/security/security_token.c:63(security_token_debug)
Security token SIDs (12):
SID[ 0]: S-1-5-21-3579304287-3829738268-3886208222-1188
SID[ 1]: S-1-5-21-3579304287-3829738268-3886208222-513
SID[ 2]: S-1-1-0
SID[ 3]: S-1-5-2
SID[ 4]: S-1-5-11
SID[ 5]: S-1-5-32-545
SID[ 6]: S-1-22-1-645
SID[ 7]: S-1-22-2-602
SID[ 8]: S-1-22-2-605
SID[ 9]: S-1-22-2-606
SID[ 10]: S-1-22-2-608
SID[ 11]: S-1-22-2-1222
Privileges (0x 0):
Rights (0x 0):

Unsuccessful login:
[2014/03/21 15:38:46.920111, 10]
../libcli/security/security_token.c:63(security_token_debug)
Security token SIDs (11):
SID[ 0]: S-1-5-21-3579304287-3829738268-3886208222-1188
SID[ 1]: S-1-5-21-3579304287-3829738268-3886208222-513
SID[ 2]: S-1-1-0
SID[ 3]: S-1-5-2
SID[ 4]: S-1-5-11
SID[ 5]: S-1-5-32-545
SID[ 6]: S-1-22-1-645
SID[ 7]: S-1-22-2-605
SID[ 8]: S-1-22-2-606
SID[ 9]: S-1-22-2-608
SID[ 10]: S-1-22-2-1222
Privileges (0x 0):
Rights (0x 0):

The difference is SID S-1-22-2-602. SID
S-1-5-21-3579304287-3829738268-3886208222-513 decodes to GID 602, so I'm
guessing that SID S-1-22-2-602 is somehow a result of that.

Note the different number of supplementary groups in this successful attempt
(5) vs. the unsuccessful attempt (4):

[2014/03/21 15:40:40.262667, 10]
auth/token_util.c:527(debug_unix_user_token)
UNIX token of user 645
Primary group is 602 and contains 5 supplementary groups
Group[ 0]: 602
Group[ 1]: 605
Group[ 2]: 606
Group[ 3]: 608
Group[ 4]: 1222

[2014/03/21 15:38:46.920432, 10]
auth/token_util.c:527(debug_unix_user_token)
UNIX token of user 645
Primary group is 602 and contains 4 supplementary groups
Group[ 0]: 605
Group[ 1]: 606
Group[ 2]: 608
Group[ 3]: 1222

Much further down the line we see:
success:
[2014/03/21 15:40:40.283134, 10] smbd/share_access.c:241(user_ok_token)
user_ok_token: share cadshare is ok for unix user EXAMPLEAD\nagios

failure:
[2014/03/21 15:38:46.972158, 10] smbd/share_access.c:219(user_ok_token)
User EXAMPLEAD\nagios not in 'valid users'

SID S-1-5-21-3579304287-3829738268-3886208222-513 is GID 602, the 'domain
users' group. So in one case the user was part of that group, in another
case it wasn't.

-- 
Carl Soderstrom
Systems Administrator
Real-Time Enterprises
www.real-time.com