[Samba] SID_TO_UID not working

[Victor Mataré]

Hello everyone,

I use winbind against a Samba DC for nsswich, and on one client it works 
perfectly (Samba 3.5.15 on all systems). On another client, everything works 
except SID_TO_UID (i.e. wbinfo -i, -S ... which breaks directory listings, 
too). I've now tried to narrow down the problem in a level 10 log, but I need 
some help interpreting. In log.winbindd, I see the following when running 
wbinfo -S S-1-5-21-555555555-5555555555-5555555555-3032 (SID changed):

===========================================================
[2012/12/06 17:43:12.841393,  3] 
winbindd/winbindd_sid_to_uid.c:47(winbindd_sid_to_uid_send)
  sid to uid S-1-5-21-555555555-5555555555-5555555555-3032
[2012/12/06 17:43:12.841517, 10] lib/gencache.c:334(gencache_get_data_blob)
  Cache entry with key = 
IDMAP/SID2UID/S-1-5-21-555555555-5555555555-5555555555-3032 couldn't be found
[2012/12/06 17:43:12.841564, 10] 
winbindd/winbindd_util.c:843(find_lookup_domain_from_sid)
  find_lookup_domain_from_sid(S-1-5-21-555555555-5555555555-5555555555-3032)
[2012/12/06 17:43:12.841605, 10] 
winbindd/winbindd_util.c:853(find_lookup_domain_from_sid)
  calling find_our_domain
[2012/12/06 17:43:12.841679, 10] 
winbindd/winbindd_cache.c:4805(wcache_fetch_ndr)
  Entry has timed out
[2012/12/06 17:43:12.852143,  5] 
winbindd/winbindd_sid_to_uid.c:90(winbindd_sid_to_uid_recv)
  Could not convert sid S-1-5-21-555555555-5555555555-5555555555-3032: 
NT_STATUS_NONE_MAPPED
[2012/12/06 17:43:12.852201, 10] winbindd/winbindd.c:655(wb_request_done)
  wb_request_done[10630:SID_TO_UID]: NT_STATUS_NONE_MAPPED
===========================================================

wbinfo -S then yields:
Could not convert sid S-1-5-21-555555555-5555555555-5555555555-3032 to uid

Now I'm not sure what "Entry has timed out" means. This occurs even when I do 
"net cache flush" before. In the meantime, /var/log/samba/log.wb-SGI looks 
like the request is correctly answered by the server. The request comes in:

===========================================================
[2012/12/06 17:43:12.841812, 10] 
winbindd/winbindd_dual.c:62(child_read_request)
  Need to read 28 extra bytes
[2012/12/06 17:43:12.841921,  4] 
winbindd/winbindd_dual.c:1528(fork_domain_child)
  child daemon request 63
[2012/12/06 17:43:12.841956, 10] 
winbindd/winbindd_dual.c:485(child_process_request)
  child_process_request: request fn NDRCMD
[2012/12/06 17:43:12.841986, 10] 
winbindd/winbindd_dual_ndr.c:263(winbindd_dual_ndrcmd)
  winbindd_dual_ndrcmd: Running command WBINT_LOOKUPSID (SGI)
[2012/12/06 17:43:12.842034,  1] 
../librpc/ndr/ndr.c:251(ndr_print_function_debug)
       wbint_LookupSid: struct wbint_LookupSid
          in: struct wbint_LookupSid
              sid                      : *
                  sid                      : 
S-1-5-21-555555555-5555555555-5555555555-3032
===========================================================

... Then there's a lot of parsing and other noise, until we return with the 
correct answer:

===========================================================
[2012/12/06 17:43:12.850133, 10] 
rpc_client/cli_lsarpc.c:191(rpccli_lsa_lookup_sids_noalloc)
  LSA_LOOKUPSIDS returned 'NT_STATUS_OK', mapped count = 1'
[2012/12/06 17:43:12.850170,  5] 
winbindd/winbindd_rpc.c:373(msrpc_sid_to_name)
  Mapped sid to [SGI]\[matare]
[2012/12/06 17:43:12.850205, 10] 
winbindd/winbindd_cache.c:555(refresh_sequence_number)
  refresh_sequence_number: SGI time ok
[2012/12/06 17:43:12.850234, 10] 
winbindd/winbindd_cache.c:600(refresh_sequence_number)
  refresh_sequence_number: SGI seq number is now 1354812192
[2012/12/06 17:43:12.850375, 10] 
winbindd/winbindd_cache.c:969(wcache_save_sid_to_name)
  wcache_save_sid_to_name: S-1-5-21-555555555-5555555555-5555555555-3032 -> 
matare (NT_STATUS_OK)
[2012/12/06 17:43:12.850410,  1] 
../librpc/ndr/ndr.c:251(ndr_print_function_debug)
       wbint_LookupSid: struct wbint_LookupSid
          out: struct wbint_LookupSid
              type                     : *
                  type                     : SID_NAME_USER (1)
              domain                   : *
                  domain                   : *
                      domain                   : 'SGI'
              name                     : *
                  name                     : *
                      name                     : 'matare'
              result                   : NT_STATUS_OK
===========================================================

Note the times, which show that the mapping is retrieved from the DC by the 
child process before the parent returns NT_STATUS_NONE_MAPPED. I find this 
really confusing and frankly, I'm out of ideas where to look. Please, if you 
have any idea let me know. Maybe I'm looking entirely in the wrong 
direction...

Thanks,
Victor