Bug 7038 - Samba "force user = xxx" results in faulty primary GID
Summary: Samba "force user = xxx" results in faulty primary GID
Status: NEW
Alias: None
Product: Samba 3.5
Classification: Unclassified
Component: User & Group Accounts (show other bugs)
Version: 3.5.4
Hardware: x64 All
: P3 normal
Target Milestone: ---
Assignee: Samba Bugzilla Account
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-01-13 08:34 UTC by Christian Svensson
Modified: 2010-08-06 17:02 UTC (History)
1 user (show)

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Christian Svensson 2010-01-13 08:34:28 UTC 
Background:
We are using Windows Server 2003 as Active Directory server. Our domain is named TELLUS.NDC

User test has only one domain group membership called ftpacc_gr - it is it's primary obviously.

When we mount [srv-no-force] as the user test the connection is established:
  __ffff_192.168.117.90 (::ffff:192.168.117.90) connect to service srv-no-force initially as user TELLUS\test (uid=708314366, gid=708314365) (pid 3928)

# getent group | grep 708314365
TELLUS\ftpacc_gr:x:708314365:

That is all fine and ACLs and everything is working like a charm.

We need to have another share that will force a certain user for administrative purposes. We call that one [srv-as-ftp] which will use TELLUS\test as its forced user.

Mounting this results in:
  __ffff_192.168.117.90 (::ffff:192.168.117.90) connect to service srv-as-ftp initially as user TELLUS\test (uid=708314366, gid=708313601) (pid 3928)

# getent group | grep 708313601
TELLUS\domain users:x:708313601:TELLUS\ftpacc,TELLUS\wsr-w35

Note: The TELLUS\test user is not a member of Domain Users
I have explicitly deleted that default membership for this test, same result if it is member of it but has another group as primary)

I find this exceptionally weird. This has the effect that I can access resources using [srv-no-force] but not using [srv-as-ftp] - while both are logged in as test.

man smb.conf says:
 In Samba 2.0.5 and above this parameter also causes the primary group of the  forced user to be used as the primary group for all file activity.

This seems to either not apply or primary GID is not correctly looked up.

We are using Samba 3.4.3 from Debian Lenny Backports  - I can not find anything related in 3.4.4 release notes.

Configuration file:
[global]
   realm = TELLUS.NDC
   workgroup = TELLUS
   server string = ndc-fs1 - File Server 09
   security = ADS

   # Winbindd start
   idmap backend = hash

   idmap uid = 1000-50000000
   idmap gid = 1000-50000000

   winbind enum users = yes
   winbind enum groups = yes
   # Winbindd end


   admin users = root TELLUS\cgm TELLUS\Administrator

   map acl inherit = yes
   nt acl support = yes

   log level = 3 passdb:5 auth:10 winbind:2

   log file = /var/log/samba/log.%m
   max log size = 50
   password server = 192.168.117.250

   oplocks = no
   level2 oplocks = no

   interfaces = eth0 lo
   local master = no
   os level = 33
   domain master = no

   wins support = yes
   wins server = 192.168.117.250

   dns proxy = no
   name resolve order = wins hosts lmhosts bcast

   unix charset = UTF-8
   display charset = UTF-8

    getwd cache = yes
    socket options = TCP_NODELAY SO_KEEPALIVE IPTOS_LOWDELAY SO_SNDBUF=65535 SO_RCVBUF=65535

    keep alive = 600

    dead time = 30
    max xmit =  32768
    max mux = 20000


   # Disable printing
   load printers = no
   printing = bsd
   printcap name = /dev/null
   disable spoolss = yes

[srv-no-force]
   comment = Administration point
   path = /srv
   locking = no
   writable = yes
   inherit acls = yes
   inherit permissions = yes

[srv-as-ftp]
   comment = Administration point forced to ftpacc
   path = /srv
   locking = no
   writable = yes
   force user = TELLUS\test
   inherit acls = yes
   inherit permissions = yes

Output of remote mount:
# mount //192.168.117.222/srv-as-ftp /mnt/ftp -o username=test,password=######,domain=tellus
[2010/01/13 15:00:52,  3] smbd/process.c:1459(process_smb)
  Transaction 45 of length 112 (0 toread)
[2010/01/13 15:00:52,  3] smbd/process.c:1273(switch_message)
  switch message SMBtconX (pid 3928) conn 0x0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-695124914-1523397741-1367410937-1278]
[2010/01/13 15:00:52,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-21-695124914-1523397741-1367410937-513]
[2010/01/13 15:00:52,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-2]
[2010/01/13 15:00:52,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-11]
[2010/01/13 15:00:52,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-22-2-708313601]
[2010/01/13 15:00:52,  3] lib/privileges.c:63(get_privileges)
  get_privileges: No privileges assigned to SID [S-1-5-32-545]
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52, 10] auth/auth_util.c:750(create_local_token)
  Could not convert SID S-1-1-0 to gid, ignoring it
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52, 10] auth/auth_util.c:750(create_local_token)
  Could not convert SID S-1-5-2 to gid, ignoring it
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52, 10] auth/auth_util.c:750(create_local_token)
  Could not convert SID S-1-5-11 to gid, ignoring it
[2010/01/13 15:00:52, 10] auth/token_util.c:528(debug_nt_user_token)
  NT user token of user S-1-5-21-695124914-1523397741-1367410937-1278
  contains 9 SIDs
  SID[  0]: S-1-5-21-695124914-1523397741-1367410937-1278
  SID[  1]: S-1-5-21-695124914-1523397741-1367410937-513
  SID[  2]: S-1-1-0
  SID[  3]: S-1-5-2
  SID[  4]: S-1-5-11
  SID[  5]: S-1-22-2-708313601
  SID[  6]: S-1-5-32-545
  SID[  7]: S-1-22-1-708314366
  SID[  8]: S-1-22-2-1005
  SE_PRIV  0x0 0x0 0x0 0x0
[2010/01/13 15:00:52, 10] auth/token_util.c:548(debug_unix_user_token)
  UNIX token of user 708314366
  Primary group is 708313601 and contains 2 supplementary groups
  Group[  0]: 708313601
  Group[  1]: 1005
[2010/01/13 15:00:52,  3] smbd/service.c:753(make_connection_snum)
  Forced user TELLUS\test
[2010/01/13 15:00:52,  3] smbd/service.c:807(make_connection_snum)
  Connect path is '/srv' for service [srv-as-ftp]
[2010/01/13 15:00:52,  3] smbd/vfs.c:95(vfs_init_default)
  Initialising default vfs hooks
[2010/01/13 15:00:52,  3] smbd/vfs.c:129(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2010/01/13 15:00:52,  3] lib/util_sid.c:228(string_to_sid)
  string_to_sid: Sid root does not start with 'S-'.
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] lib/util_sid.c:228(string_to_sid)
  string_to_sid: Sid TELLUS\cgm does not start with 'S-'.
[2010/01/13 15:00:52,  3] lib/util_sid.c:228(string_to_sid)
  string_to_sid: Sid TELLUS\Administrator does not start with 'S-'.
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (708314366, 708313601) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  1] smbd/service.c:1047(make_connection_snum)
  __ffff_192.168.117.90 (::ffff:192.168.117.90) connect to service srv-as-ftp initially as user TELLUS\test (uid=708314366, gid=708313601) (pid 3928)
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/reply.c:754(reply_tcon_and_X)
  tconX service=srv-as-ftp
[2010/01/13 15:00:52,  3] smbd/process.c:1459(process_smb)
  Transaction 46 of length 72 (0 toread)
[2010/01/13 15:00:52,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d6e70
[2010/01/13 15:00:52,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (708314366, 708313601) - sec_ctx_stack_ndx = 0
[2010/01/13 15:00:52,  3] smbd/trans2.c:2599(call_trans2qfsinfo)
  call_trans2qfsinfo: level = 260
[2010/01/13 15:00:52,  3] smbd/process.c:1459(process_smb)
  Transaction 47 of length 72 (0 toread)
[2010/01/13 15:00:52,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d6e70
[2010/01/13 15:00:52,  3] smbd/trans2.c:2599(call_trans2qfsinfo)
  call_trans2qfsinfo: level = 261
[2010/01/13 15:00:52,  3] smbd/process.c:1459(process_smb)
  Transaction 48 of length 72 (0 toread)
[2010/01/13 15:00:52,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d6e70
[2010/01/13 15:00:52,  3] smbd/trans2.c:2599(call_trans2qfsinfo)
  call_trans2qfsinfo: level = 512
[2010/01/13 15:00:52,  3] smbd/process.c:1459(process_smb)
  Transaction 49 of length 86 (0 toread)
[2010/01/13 15:00:52,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d6e70
[2010/01/13 15:00:52,  3] smbd/process.c:1459(process_smb)
  Transaction 50 of length 78 (0 toread)
[2010/01/13 15:00:52,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d6e70
[2010/01/13 15:00:52,  3] smbd/trans2.c:3955(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: TRANSACT2_QPATHINFO: level = 512
[2010/01/13 15:00:52,  3] smbd/trans2.c:4069(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo . (fnum = -1) level=512 call=5 total_data=0
[2010/01/13 15:01:20,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0


Output of remote mount:
# mount //192.168.117.222/srv-no-force /mnt/no-force/ -o username=test,password=########,domain=tellus

[2010/01/13 15:03:23,  3] smbd/process.c:1459(process_smb)
  Transaction 73 of length 116 (0 toread)
[2010/01/13 15:03:23,  3] smbd/process.c:1273(switch_message)
  switch message SMBtconX (pid 3928) conn 0x0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/service.c:807(make_connection_snum)
  Connect path is '/srv' for service [srv-no-force]
[2010/01/13 15:03:23,  3] smbd/vfs.c:95(vfs_init_default)
  Initialising default vfs hooks
[2010/01/13 15:03:23,  3] smbd/vfs.c:129(vfs_init_custom)
  Initialising custom vfs hooks from [/[Default VFS]/]
[2010/01/13 15:03:23,  3] lib/util_sid.c:228(string_to_sid)
  string_to_sid: Sid root does not start with 'S-'.
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/01/13 15:03:23,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/01/13 15:03:23,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 2
[2010/01/13 15:03:23,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 2
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] lib/util_sid.c:228(string_to_sid)
  string_to_sid: Sid TELLUS\cgm does not start with 'S-'.
[2010/01/13 15:03:23,  3] lib/util_sid.c:228(string_to_sid)
  string_to_sid: Sid TELLUS\Administrator does not start with 'S-'.
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:210(push_sec_ctx)
  push_sec_ctx(0, 0) : sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/uid.c:428(push_conn_ctx)
  push_conn_ctx(0) : conn_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 1
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:418(pop_sec_ctx)
  pop_sec_ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (708314366, 708314365) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  1] smbd/service.c:1047(make_connection_snum)
  __ffff_192.168.117.90 (::ffff:192.168.117.90) connect to service srv-no-force initially as user TELLUS\test (uid=708314366, gid=708314365) (pid 3928)
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (0, 0) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/reply.c:754(reply_tcon_and_X)
  tconX service=srv-no-force
[2010/01/13 15:03:23,  3] smbd/process.c:1459(process_smb)
  Transaction 74 of length 72 (0 toread)
[2010/01/13 15:03:23,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d3cc0
[2010/01/13 15:03:23,  3] smbd/sec_ctx.c:310(set_sec_ctx)
  setting sec ctx (708314366, 708314365) - sec_ctx_stack_ndx = 0
[2010/01/13 15:03:23,  3] smbd/trans2.c:2599(call_trans2qfsinfo)
  call_trans2qfsinfo: level = 260
[2010/01/13 15:03:23,  3] smbd/process.c:1459(process_smb)
  Transaction 75 of length 72 (0 toread)
[2010/01/13 15:03:23,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d3cc0
[2010/01/13 15:03:23,  3] smbd/trans2.c:2599(call_trans2qfsinfo)
  call_trans2qfsinfo: level = 261
[2010/01/13 15:03:23,  3] smbd/process.c:1459(process_smb)
  Transaction 76 of length 72 (0 toread)
[2010/01/13 15:03:23,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d3cc0
[2010/01/13 15:03:23,  3] smbd/trans2.c:2599(call_trans2qfsinfo)
  call_trans2qfsinfo: level = 512
[2010/01/13 15:03:23,  3] smbd/process.c:1459(process_smb)
  Transaction 77 of length 86 (0 toread)
[2010/01/13 15:03:23,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d3cc0
[2010/01/13 15:03:23,  3] smbd/process.c:1459(process_smb)
  Transaction 78 of length 78 (0 toread)
[2010/01/13 15:03:23,  3] smbd/process.c:1273(switch_message)
  switch message SMBtrans2 (pid 3928) conn 0x16d3cc0
[2010/01/13 15:03:23,  3] smbd/trans2.c:3955(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo: TRANSACT2_QPATHINFO: level = 512
[2010/01/13 15:03:23,  3] smbd/trans2.c:4069(call_trans2qfilepathinfo)
  call_trans2qfilepathinfo . (fnum = -1) level=512 call=5 total_data=0
Comment 1 Volker Lendecke 2010-01-16 10:08:55 UTC 
Assuming that you are running winbind, can you please do the following just for a test:

Shutdown winbind, remove winbindd_cache.tdb and netsamlogon_cache.tdb (not sure where they are located on your distribution). Set debug level 10. Remove /var/log/samba/log.*. Start winbind. Execute "wbinfo -i TELLUS\\test. Upload /var/log/samba/log.*

Thanks,

Volker
Comment 2 Christian Svensson 2010-01-16 11:14:39 UTC 
(In reply to comment #1)
> Assuming that you are running winbind, can you please do the following just for
> a test:
> 
> Shutdown winbind, remove winbindd_cache.tdb and netsamlogon_cache.tdb (not sure
> where they are located on your distribution). Set debug level 10. Remove
> /var/log/samba/log.*. Start winbind. Execute "wbinfo -i TELLUS\\test. Upload
> /var/log/samba/log.*
> 
> Thanks,
> 
> Volker
> 

# /etc/init.d/samba stop
Stopping Samba daemons: nmbd smbd.
# /etc/init.d/winbind stop
Stopping the Winbind daemon: winbind.
# rm /var/cache/samba/winbindd_cache.tdb 
# rm /var/cache/samba/netsamlogon_cache.tdb 
# rm -fr /var/log/samba/*
# /etc/init.d/winbind start
Starting the Winbind daemon: winbind.
# wbinfo -i TELLUS\\test
TELLUS\test:*:708314366:708314365:test:/home/TELLUS/test:/bin/false
# getent group | grep 708314365
TELLUS\ftpacc_gr:x:708314365:

=> File log.wbinfo

[2010/01/16 18:02:41,  2] lib/interface.c:340(add_interface)
  added interface eth0 ip=fe80::2e0:81ff:feb1:4912%eth0 bcast=fe80::ffff:ffff:ffff:ffff%eth0 netmask=ffff:ffff:ffff:ffff::
[2010/01/16 18:02:41,  2] lib/interface.c:340(add_interface)
  added interface eth0 ip=192.168.117.222 bcast=192.168.117.255 netmask=255.255.255.0
[2010/01/16 18:02:41,  2] lib/interface.c:340(add_interface)
  added interface lo ip=::1 bcast=::1 netmask=ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff
[2010/01/16 18:02:41,  2] lib/interface.c:340(add_interface)
  added interface lo ip=127.0.0.1 bcast=127.255.255.255 netmask=255.0.0.0

=> File log.wb-TELLUS

[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:479(set_domain_online_request)
  set_domain_online_request: called for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:508(set_domain_online_request)
  set_domain_online_request: domain TELLUS was globally offline.
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:906(calculate_next_machine_pwd_change)
  machine password still valid until: Tue, 19 Jan 2010 23:05:04 CET
[2010/01/16 18:02:38,  4] winbindd/winbindd_dual.c:1452(fork_domain_child)
  child daemon request 50
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:452(child_process_request)
  child_process_request: request fn INIT_CONNECTION
[2010/01/16 18:02:38,  8] winbindd/winbindd_cm.c:1597(connection_ok)
  connection_ok: Connection to  for domain TELLUS has NULL cli!
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:1430(cm_open_connection)
  cm_open_connection: saf_servername is 'ndc-adx.tellus.ndc' for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:1462(cm_open_connection)
  cm_open_connection: dcname is 'ndc-adx.tellus.ndc' for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:774(cm_prepare_connection)
  cm_prepare_connection: connecting to DC ndc-adx.tellus.ndc for domain TELLUS
[2010/01/16 18:02:38,  5] winbindd/winbindd_cm.c:851(cm_prepare_connection)
  connecting to ndc-adx.tellus.ndc from NDC-FS1 with kerberos principal [NDC-FS1$@TELLUS.NDC] and realm [TELLUS.NDC]
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:939(cli_session_setup_spnego)
  Doing spnego session setup (blob length=107)
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:966(cli_session_setup_spnego)
  got OID=1.2.840.48018.1.2.2
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:966(cli_session_setup_spnego)
  got OID=1.2.840.113554.1.2.2
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:966(cli_session_setup_spnego)
  got OID=1.2.840.113554.1.2.2.3
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:966(cli_session_setup_spnego)
  got OID=1.3.6.1.4.1.311.2.2.10
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:974(cli_session_setup_spnego)
  got principal=ndc-adx$@TELLUS.NDC
[2010/01/16 18:02:38,  2] libsmb/cliconnect.c:738(cli_session_setup_kerberos)
  Doing kerberos session setup
[2010/01/16 18:02:38,  3] libsmb/clikrb5.c:621(ads_cleanup_expired_creds)
  ads_cleanup_expired_creds: Ticket in ccache[MEMORY:cliconnect] expiration Sun, 17 Jan 2010 04:02:38 CET
[2010/01/16 18:02:38,  3] libsmb/clikrb5.c:730(ads_krb5_mk_req)
  ads_krb5_mk_req: server marked as OK to delegate to, building forwardable TGT
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3064(set_global_winbindd_state_online)
  set_global_winbindd_state_online: online requested.
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3067(set_global_winbindd_state_online)
  set_global_winbindd_state_online: rejecting.
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:402(set_domain_online)
  set_domain_online: called for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:1955(set_dc_type_and_flags)
  set_dc_type_and_flags: setting up flags for primary domain
[2010/01/16 18:02:38,  5] winbindd/winbindd_cm.c:1799(set_dc_type_and_flags_connect)
  set_dc_type_and_flags_connect: domain TELLUS
[2010/01/16 18:02:38,  5] winbindd/winbindd_cm.c:1931(set_dc_type_and_flags_connect)
  set_dc_type_and_flags_connect: domain TELLUS is in native mode.
[2010/01/16 18:02:38,  5] winbindd/winbindd_cm.c:1934(set_dc_type_and_flags_connect)
  set_dc_type_and_flags_connect: domain TELLUS is running active directory.
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2627(cache_store_response)
  Storing response for pid 773, len 3496
[2010/01/16 18:02:38,  4] winbindd/winbindd_dual.c:1452(fork_domain_child)
  child daemon request 20
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:452(child_process_request)
  child_process_request: request fn LIST_TRUSTDOM
[2010/01/16 18:02:38,  3] winbindd/winbindd_misc.c:359(winbindd_dual_list_trusted_domains)
  [  767]: list trusted domains
[2010/01/16 18:02:38,  5] winbindd/winbindd_cache.c:178(get_cache)
  get_cache: Setting ADS methods for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:405(fetch_cache_seqnum)
  fetch_cache_seqnum: invalid data size key [SEQNUM/TELLUS]
[2010/01/16 18:02:38,  3] winbindd/winbindd_ads.c:1203(sequence_number)
  ads: fetch sequence_number for TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_ads.c:45(ads_cached_connection)
  ads_cached_connection
[2010/01/16 18:02:38,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:38,  3] libads/ldap.c:621(ads_connect)
  Successfully contacted LDAP server 192.168.117.250
[2010/01/16 18:02:38,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:38,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:38,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:38,  3] libads/ldap.c:621(ads_connect)
  Successfully contacted LDAP server 192.168.117.250
[2010/01/16 18:02:38,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:38,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:38,  3] libads/ldap.c:621(ads_connect)
  Successfully contacted LDAP server 192.168.117.250
[2010/01/16 18:02:38,  3] libads/ldap.c:675(ads_connect)
  Connected to LDAP server ndc-adx.tellus.ndc
[2010/01/16 18:02:38,  3] libads/sasl.c:780(ads_sasl_spnego_bind)
  ads_sasl_spnego_bind: got OID=1.2.840.48018.1.2.2
[2010/01/16 18:02:38,  3] libads/sasl.c:780(ads_sasl_spnego_bind)
  ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2
[2010/01/16 18:02:38,  3] libads/sasl.c:780(ads_sasl_spnego_bind)
  ads_sasl_spnego_bind: got OID=1.2.840.113554.1.2.2.3
[2010/01/16 18:02:38,  3] libads/sasl.c:780(ads_sasl_spnego_bind)
  ads_sasl_spnego_bind: got OID=1.3.6.1.4.1.311.2.2.10
[2010/01/16 18:02:38,  3] libads/sasl.c:789(ads_sasl_spnego_bind)
  ads_sasl_spnego_bind: got server principal name = ndc-adx$@TELLUS.NDC
[2010/01/16 18:02:38,  3] libsmb/clikrb5.c:688(ads_krb5_mk_req)
  ads_krb5_mk_req: krb5_cc_get_principal failed (No credentials cache found)
[2010/01/16 18:02:38,  3] libsmb/clikrb5.c:621(ads_cleanup_expired_creds)
  ads_cleanup_expired_creds: Ticket in ccache[MEMORY:winbind_ccache] expiration Sun, 17 Jan 2010 04:02:38 CET
[2010/01/16 18:02:38,  3] libsmb/clikrb5.c:730(ads_krb5_mk_req)
  ads_krb5_mk_req: server marked as OK to delegate to, building forwardable TGT
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:456(store_cache_seqnum)
  store_cache_seqnum: success [TELLUS][2319015 @ 1263661358]
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:537(refresh_sequence_number)
  refresh_sequence_number: TELLUS seq number is now 2319015
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2310(trusted_domains)
  trusted_domains: [Cached] - doing backend query for info for domain TELLUS
[2010/01/16 18:02:38,  3] winbindd/winbindd_ads.c:1270(trusted_domains)
  ads: trusted_domains
[2010/01/16 18:02:38, 10] winbindd/winbindd_ads.c:1369(trusted_domains)
  trusted_domains(ads):  Searching trusted domain list of TELLUS and storing trust flags for domain tellus.ndc
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:4073(wcache_tdc_add_domain)
  wcache_tdc_add_domain: Adding domain TELLUS (tellus.ndc), SID S-1-5-21-695124914-1523397741-1367410937, flags = 0x1d, attributes = 0x0, type = 0x2
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3796(add_wbdomain_to_tdc_array)
  add_wbdomain_to_tdc_array: Found existing record for TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3882(pack_tdc_domains)
  pack_tdc_domains: Packing 3 trusted domains
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain BUILTIN ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain NDC-FS1 ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain TELLUS (tellus.ndc)
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2627(cache_store_response)
  Storing response for pid 773, len 3555
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2641(cache_store_response)
  Storing extra data: len=59
[2010/01/16 18:02:38,  4] winbindd/winbindd_dual.c:1452(fork_domain_child)
  child daemon request 20
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:452(child_process_request)
  child_process_request: request fn LIST_TRUSTDOM
[2010/01/16 18:02:38,  3] winbindd/winbindd_misc.c:359(winbindd_dual_list_trusted_domains)
  [  767]: list trusted domains
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:492(refresh_sequence_number)
  refresh_sequence_number: TELLUS time ok
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:537(refresh_sequence_number)
  refresh_sequence_number: TELLUS seq number is now 2319015
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2310(trusted_domains)
  trusted_domains: [Cached] - doing backend query for info for domain TELLUS
[2010/01/16 18:02:38,  3] winbindd/winbindd_ads.c:1270(trusted_domains)
  ads: trusted_domains
[2010/01/16 18:02:38, 10] winbindd/winbindd_ads.c:1369(trusted_domains)
  trusted_domains(ads):  Searching trusted domain list of TELLUS and storing trust flags for domain tellus.ndc
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:4073(wcache_tdc_add_domain)
  wcache_tdc_add_domain: Adding domain TELLUS (tellus.ndc), SID S-1-5-21-695124914-1523397741-1367410937, flags = 0x1d, attributes = 0x0, type = 0x2
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3796(add_wbdomain_to_tdc_array)
  add_wbdomain_to_tdc_array: Found existing record for TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3882(pack_tdc_domains)
  pack_tdc_domains: Packing 3 trusted domains
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain BUILTIN ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain NDC-FS1 ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain TELLUS (tellus.ndc)
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2627(cache_store_response)
  Storing response for pid 773, len 3555
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2641(cache_store_response)
  Storing extra data: len=59
[2010/01/16 18:02:41,  4] winbindd/winbindd_dual.c:1452(fork_domain_child)
  child daemon request 22
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:452(child_process_request)
  child_process_request: request fn LOOKUPNAME
[2010/01/16 18:02:41,  3] winbindd/winbindd_async.c:442(winbindd_dual_lookupname)
  [  767]: lookupname TELLUS\test
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:492(refresh_sequence_number)
  refresh_sequence_number: TELLUS time ok
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:537(refresh_sequence_number)
  refresh_sequence_number: TELLUS seq number is now 2319015
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:1653(name_to_sid)
  name_to_sid: [Cached] - doing backend query for name for domain TELLUS
[2010/01/16 18:02:41,  3] winbindd/winbindd_rpc.c:295(msrpc_name_to_sid)
  rpc: name_to_sid name=TELLUS\test
[2010/01/16 18:02:41,  3] winbindd/winbindd_rpc.c:309(msrpc_name_to_sid)
  name_to_sid [rpc] TELLUS\test for domain TELLUS
[2010/01/16 18:02:41, 10] winbindd/winbindd_cm.c:2192(cm_connect_lsa_tcp)
  cm_connect_lsa_tcp
[2010/01/16 18:02:41,  3] lib/util_sock.c:1033(open_socket_out_send)
  Connecting to 192.168.117.250 at port 135
[2010/01/16 18:02:41,  3] lib/util_sock.c:1033(open_socket_out_send)
  Connecting to 192.168.117.250 at port 1026
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:492(refresh_sequence_number)
  refresh_sequence_number: TELLUS time ok
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:537(refresh_sequence_number)
  refresh_sequence_number: TELLUS seq number is now 2319015
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:869(wcache_save_name_to_sid)
  wcache_save_name_to_sid: TELLUS\TEST -> S-1-5-21-695124914-1523397741-1367410937-1278 (NT_STATUS_OK)
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:891(wcache_save_sid_to_name)
  wcache_save_sid_to_name: S-1-5-21-695124914-1523397741-1367410937-1278 -> test (NT_STATUS_OK)
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:2627(cache_store_response)
  Storing response for pid 773, len 3496
[2010/01/16 18:02:41,  4] winbindd/winbindd_dual.c:1452(fork_domain_child)
  child daemon request 59
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:452(child_process_request)
  child_process_request: request fn DUAL_USERINFO
[2010/01/16 18:02:41,  3] winbindd/winbindd_user.c:166(winbindd_dual_userinfo)
  [  767]: lookupsid S-1-5-21-695124914-1523397741-1367410937-1278
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:492(refresh_sequence_number)
  refresh_sequence_number: TELLUS time ok
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:537(refresh_sequence_number)
  refresh_sequence_number: TELLUS seq number is now 2319015
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:1956(query_user)
  query_user: [Cached] - doing backend query for info for domain TELLUS
[2010/01/16 18:02:41,  3] winbindd/winbindd_ads.c:467(query_user)
  ads: query_user
[2010/01/16 18:02:41, 10] winbindd/winbindd_ads.c:45(ads_cached_connection)
  ads_cached_connection
[2010/01/16 18:02:41,  7] winbindd/winbindd_ads.c:58(ads_cached_connection)
  Current tickets expire in 35997 seconds (at 1263697358, time is now 1263661361)
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:492(refresh_sequence_number)
  refresh_sequence_number: TELLUS time ok
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:537(refresh_sequence_number)
  refresh_sequence_number: TELLUS seq number is now 2319015
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:4233(nss_get_info_cached)
  nss_get_info returned NT_STATUS_OK
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:4236(nss_get_info_cached)
  result:
  	homedir = '/home/%D/%U'
  	shell = '/bin/false'
  	gecos = '(null)'
  	gid = '4294967295'
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:4190(wcache_save_user_pwinfo)
  wcache_save_user_pwinfo: S-1-5-21-695124914-1523397741-1367410937-1278
[2010/01/16 18:02:41,  3] winbindd/winbindd_ads.c:569(query_user)
  ads query_user gave test
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:492(refresh_sequence_number)
  refresh_sequence_number: TELLUS time ok
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:537(refresh_sequence_number)
  refresh_sequence_number: TELLUS seq number is now 2319015
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:917(wcache_save_user)
  wcache_save_user: S-1-5-21-695124914-1523397741-1367410937-1278 (acct_name test)
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:2627(cache_store_response)
  Storing response for pid 773, len 3496

=> File log.winbindd

[2010/01/16 18:02:38,  0] winbindd/winbindd.c:1252(main)
  winbindd version 3.4.3 started.
  Copyright Andrew Tridgell and the Samba Team 1992-2009
[2010/01/16 18:02:38,  2] lib/tallocmsg.c:106(register_msg_pool_usage)
  Registered MSG_REQ_POOL_USAGE
[2010/01/16 18:02:38,  2] lib/dmallocmsg.c:77(register_dmalloc_msgs)
  Registered MSG_REQ_DMALLOC_MARK and LOG_CHANGED
[2010/01/16 18:02:38,  3] param/loadparm.c:9024(lp_load_ex)
  lp_load_ex: refreshing parameters
Initialising global parameters
[2010/01/16 18:02:38,  3] ../lib/util/params.c:550(pm_process)
  params.c:pm_process() - Processing configuration file "/etc/samba/smb.conf"
[2010/01/16 18:02:38,  3] param/loadparm.c:7711(do_section)
  Processing section "[global]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[srv-no-force]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[srv-as-ftp]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[ihotell]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[ihotell-bak]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[ihotell-admin]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[ihotell-w37]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[cts-mail]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[appsrv]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[ftp-share]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[install]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-acc]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-acc]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-bak]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-bak]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-jed]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-jed]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-md1]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-md1]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-md2]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-md2]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-md3]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-md3]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-md4]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-md4]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-pdc]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-pdc]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-rex]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-rex]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-rlx]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-rlx]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-rlz]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-rlz]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-w31]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-w31]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-w32]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-w32]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-w36]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-w36]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[data-w37]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[prg-w37]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[home-data]"
[2010/01/16 18:02:38,  2] param/loadparm.c:7728(do_section)
  Processing section "[home-prg]"
[2010/01/16 18:02:38,  3] param/loadparm.c:6182(lp_add_ipc)
  adding IPC service
[2010/01/16 18:02:38,  2] lib/interface.c:340(add_interface)
  added interface eth0 ip=fe80::2e0:81ff:feb1:4912%eth0 bcast=fe80::ffff:ffff:ffff:ffff%eth0 netmask=ffff:ffff:ffff:ffff::
[2010/01/16 18:02:38,  2] lib/interface.c:340(add_interface)
  added interface eth0 ip=192.168.117.222 bcast=192.168.117.255 netmask=255.255.255.0
[2010/01/16 18:02:38,  2] lib/interface.c:340(add_interface)
  added interface lo ip=::1 bcast=::1 netmask=ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff
[2010/01/16 18:02:38,  2] lib/interface.c:340(add_interface)
  added interface lo ip=127.0.0.1 bcast=127.255.255.255 netmask=255.0.0.0
[2010/01/16 18:02:38,  2] lib/interface.c:340(add_interface)
  added interface eth0 ip=fe80::2e0:81ff:feb1:4912%eth0 bcast=fe80::ffff:ffff:ffff:ffff%eth0 netmask=ffff:ffff:ffff:ffff::
[2010/01/16 18:02:38,  2] lib/interface.c:340(add_interface)
  added interface eth0 ip=192.168.117.222 bcast=192.168.117.255 netmask=255.255.255.0
[2010/01/16 18:02:38,  2] lib/interface.c:340(add_interface)
  added interface lo ip=::1 bcast=::1 netmask=ffff:ffff:ffff:ffff:ffff:ffff:ffff:ffff
[2010/01/16 18:02:38,  2] lib/interface.c:340(add_interface)
  added interface lo ip=127.0.0.1 bcast=127.255.255.255 netmask=255.0.0.0
[2010/01/16 18:02:38,  0] winbindd/winbindd_cache.c:2578(initialize_winbindd_cache)
  initialize_winbindd_cache: clearing cache and re-creating with version number 1
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:4073(wcache_tdc_add_domain)
  wcache_tdc_add_domain: Adding domain BUILTIN (), SID S-1-5-32, flags = 0x0, attributes = 0x0, type = 0x0
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3882(pack_tdc_domains)
  pack_tdc_domains: Packing 1 trusted domains
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain BUILTIN ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_util.c:212(add_trusted_domain)
  idmap config BUILTIN : range = not defined
[2010/01/16 18:02:38,  2] winbindd/winbindd_util.c:235(add_trusted_domain)
  Added domain BUILTIN  S-1-5-32
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:4073(wcache_tdc_add_domain)
  wcache_tdc_add_domain: Adding domain NDC-FS1 (), SID S-1-5-21-399855623-637440385-3424171433, flags = 0x0, attributes = 0x0, type = 0x0
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3882(pack_tdc_domains)
  pack_tdc_domains: Packing 2 trusted domains
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain BUILTIN ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain NDC-FS1 ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_util.c:212(add_trusted_domain)
  idmap config NDC-FS1 : range = not defined
[2010/01/16 18:02:38,  2] winbindd/winbindd_util.c:235(add_trusted_domain)
  Added domain NDC-FS1  S-1-5-21-399855623-637440385-3424171433
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:4073(wcache_tdc_add_domain)
  wcache_tdc_add_domain: Adding domain TELLUS (TELLUS.NDC), SID S-1-5-21-695124914-1523397741-1367410937, flags = 0x0, attributes = 0x0, type = 0x0
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3882(pack_tdc_domains)
  pack_tdc_domains: Packing 3 trusted domains
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain BUILTIN ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain NDC-FS1 ()
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3901(pack_tdc_domains)
  pack_tdc_domains: Packing domain TELLUS (TELLUS.NDC)
[2010/01/16 18:02:38, 10] winbindd/winbindd_util.c:212(add_trusted_domain)
  idmap config TELLUS : range = not defined
[2010/01/16 18:02:38,  2] winbindd/winbindd_util.c:235(add_trusted_domain)
  Added domain TELLUS TELLUS.NDC S-1-5-21-695124914-1523397741-1367410937
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:479(set_domain_online_request)
  set_domain_online_request: called for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:508(set_domain_online_request)
  set_domain_online_request: domain TELLUS was globally offline.
[2010/01/16 18:02:38, 10] winbindd/winbindd_util.c:1302(open_winbindd_socket)
  open_winbindd_socket: opened socket fd 15
[2010/01/16 18:02:38, 10] winbindd/winbindd_util.c:1314(open_winbindd_priv_socket)
  open_winbindd_priv_socket: opened socket fd 16
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:125(async_request)
  Sending request to child pid 0 (domain=TELLUS)
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:1249(fork_domain_child)
  fork_domain_child called for domain 'TELLUS'
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:1283(fork_domain_child)
  Child process 773
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2667(cache_retrieve_response)
  Retrieving response for pid 773
[2010/01/16 18:02:38,  5] winbindd/winbindd_util.c:672(init_child_recv)
  Received child initialization response for domain TELLUS
[2010/01/16 18:02:38,  8] winbindd/winbindd_cm.c:1597(connection_ok)
  connection_ok: Connection to  for domain TELLUS has NULL cli!
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:1430(cm_open_connection)
  cm_open_connection: saf_servername is 'ndc-adx.tellus.ndc' for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:1462(cm_open_connection)
  cm_open_connection: dcname is 'ndc-adx.tellus.ndc' for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:774(cm_prepare_connection)
  cm_prepare_connection: connecting to DC ndc-adx.tellus.ndc for domain TELLUS
[2010/01/16 18:02:38,  5] winbindd/winbindd_cm.c:851(cm_prepare_connection)
  connecting to ndc-adx.tellus.ndc from NDC-FS1 with kerberos principal [NDC-FS1$@TELLUS.NDC] and realm [tellus.ndc]
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:939(cli_session_setup_spnego)
  Doing spnego session setup (blob length=107)
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:966(cli_session_setup_spnego)
  got OID=1.2.840.48018.1.2.2
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:966(cli_session_setup_spnego)
  got OID=1.2.840.113554.1.2.2
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:966(cli_session_setup_spnego)
  got OID=1.2.840.113554.1.2.2.3
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:966(cli_session_setup_spnego)
  got OID=1.3.6.1.4.1.311.2.2.10
[2010/01/16 18:02:38,  3] libsmb/cliconnect.c:974(cli_session_setup_spnego)
  got principal=ndc-adx$@TELLUS.NDC
[2010/01/16 18:02:38,  2] libsmb/cliconnect.c:738(cli_session_setup_kerberos)
  Doing kerberos session setup
[2010/01/16 18:02:38,  3] libsmb/clikrb5.c:621(ads_cleanup_expired_creds)
  ads_cleanup_expired_creds: Ticket in ccache[MEMORY:cliconnect] expiration Sun, 17 Jan 2010 04:02:38 CET
[2010/01/16 18:02:38,  3] libsmb/clikrb5.c:730(ads_krb5_mk_req)
  ads_krb5_mk_req: server marked as OK to delegate to, building forwardable TGT
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3064(set_global_winbindd_state_online)
  set_global_winbindd_state_online: online requested.
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:3067(set_global_winbindd_state_online)
  set_global_winbindd_state_online: rejecting.
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:402(set_domain_online)
  set_domain_online: called for domain TELLUS
[2010/01/16 18:02:38, 10] winbindd/winbindd_cm.c:1955(set_dc_type_and_flags)
  set_dc_type_and_flags: setting up flags for primary domain
[2010/01/16 18:02:38,  5] winbindd/winbindd_cm.c:1799(set_dc_type_and_flags_connect)
  set_dc_type_and_flags_connect: domain TELLUS
[2010/01/16 18:02:38,  5] winbindd/winbindd_cm.c:1931(set_dc_type_and_flags_connect)
  set_dc_type_and_flags_connect: domain TELLUS is in native mode.
[2010/01/16 18:02:38,  5] winbindd/winbindd_cm.c:1934(set_dc_type_and_flags_connect)
  set_dc_type_and_flags_connect: domain TELLUS is running active directory.
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:125(async_request)
  Sending request to child pid 773 (domain=TELLUS)
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2667(cache_retrieve_response)
  Retrieving response for pid 773
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2689(cache_retrieve_response)
  Retrieving extra data length=59
[2010/01/16 18:02:38, 10] winbindd/winbindd_util.c:454(rescan_forest_root_trusts)
  rescan_forest_root_trusts: Following trust path for domain tree root TELLUS (tellus.ndc)
[2010/01/16 18:02:38, 10] winbindd/winbindd_dual.c:125(async_request)
  Sending request to child pid 773 (domain=TELLUS)
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2667(cache_retrieve_response)
  Retrieving response for pid 773
[2010/01/16 18:02:38, 10] winbindd/winbindd_cache.c:2689(cache_retrieve_response)
  Retrieving extra data length=59
[2010/01/16 18:02:41,  6] winbindd/winbindd.c:834(new_connection)
  accepted socket 21
[2010/01/16 18:02:41, 10] winbindd/winbindd.c:537(process_request)
  process_request: request fn INTERFACE_VERSION
[2010/01/16 18:02:41,  3] winbindd/winbindd_misc.c:754(winbindd_interface_version)
  [  774]: request interface version
[2010/01/16 18:02:41, 10] winbindd/winbindd.c:537(process_request)
  process_request: request fn WINBINDD_PRIV_PIPE_DIR
[2010/01/16 18:02:41,  3] winbindd/winbindd_misc.c:787(winbindd_priv_pipe_dir)
  [  774]: request location of privileged pipe
[2010/01/16 18:02:41,  6] winbindd/winbindd.c:834(new_connection)
  accepted socket 22
[2010/01/16 18:02:41, 10] winbindd/winbindd.c:537(process_request)
  process_request: request fn GETPWNAM
[2010/01/16 18:02:41,  3] winbindd/winbindd_user.c:438(winbindd_getpwnam)
  [  774]: getpwnam TELLUS\test
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:125(async_request)
  Sending request to child pid 773 (domain=TELLUS)
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:2667(cache_retrieve_response)
  Retrieving response for pid 773
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:125(async_request)
  Sending request to child pid 773 (domain=TELLUS)
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:2667(cache_retrieve_response)
  Retrieving response for pid 773
[2010/01/16 18:02:41, 10] winbindd/winbindd_idmap.c:269(winbindd_sid2uid_async)
  winbindd_sid2uid_async found domain TELLUS, have_idmap_config = 0
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:125(async_request)
  Sending request to child pid 0 (domain='')
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:1251(fork_domain_child)
  fork_domain_child called without domain.
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:1283(fork_domain_child)
  Child process 775
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:2667(cache_retrieve_response)
  Retrieving response for pid 775
[2010/01/16 18:02:41,  7] winbindd/winbindd_idmap.c:351(winbindd_sid2gid_async)
  winbindd_sid2gid_async: Resolving S-1-5-21-695124914-1523397741-1367410937-1277 to a gid
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:125(async_request)
  Sending request to child pid 775 (domain='')
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:2667(cache_retrieve_response)
  Retrieving response for pid 775

=> File log.winbindd-dc-connect

[2010/01/16 18:02:46,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:46,  3] libads/ldap.c:621(ads_connect)
  Successfully contacted LDAP server 192.168.117.250
[2010/01/16 18:02:46,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:46,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:46,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"
[2010/01/16 18:02:46,  3] libsmb/namequery.c:1972(get_dc_list)
  get_dc_list: preferred server list: "ndc-adx.tellus.ndc, 192.168.117.250"

=> File log.winbindd-idmap

[2010/01/16 18:02:41, 10] winbindd/winbindd_cm.c:479(set_domain_online_request)
  set_domain_online_request: called for domain TELLUS
[2010/01/16 18:02:41, 10] winbindd/winbindd_cm.c:508(set_domain_online_request)
  set_domain_online_request: domain TELLUS was globally offline.
[2010/01/16 18:02:41,  4] winbindd/winbindd_dual.c:1452(fork_domain_child)
  child daemon request 51
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:452(child_process_request)
  child_process_request: request fn DUAL_SID2UID
[2010/01/16 18:02:41,  3] winbindd/winbindd_idmap.c:293(winbindd_dual_sid2uid)
  [  767]: sid to uid S-1-5-21-695124914-1523397741-1367410937-1278
[2010/01/16 18:02:41, 10] winbindd/winbindd_idmap.c:306(winbindd_dual_sid2uid)
  winbindd_dual_sid2uid: 0x00000000 - S-1-5-21-695124914-1523397741-1367410937-1278 - 708314366
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:2627(cache_store_response)
  Storing response for pid 775, len 3496
[2010/01/16 18:02:41,  4] winbindd/winbindd_dual.c:1452(fork_domain_child)
  child daemon request 52
[2010/01/16 18:02:41, 10] winbindd/winbindd_dual.c:452(child_process_request)
  child_process_request: request fn DUAL_SID2GID
[2010/01/16 18:02:41,  3] winbindd/winbindd_idmap.c:364(winbindd_dual_sid2gid)
  [  767]: sid to gid S-1-5-21-695124914-1523397741-1367410937-1277
[2010/01/16 18:02:41, 10] winbindd/winbindd_idmap.c:379(winbindd_dual_sid2gid)
  winbindd_dual_sid2gid: 0x00000000 - S-1-5-21-695124914-1523397741-1367410937-1277 - 708314365
[2010/01/16 18:02:41, 10] winbindd/winbindd_cache.c:2627(cache_store_response)
  Storing response for pid 775, len 3496
[2010/01/16 18:02:46, 10] winbindd/winbindd_cm.c:279(check_domain_online_handler)
  check_domain_online_handler: called for domain TELLUS (online = True)
[2010/01/16 18:02:46,  5] winbindd/winbindd_cm.c:136(msg_try_to_go_online)
  msg_try_to_go_online: received for domain TELLUS.
[2010/01/16 18:02:46,  5] winbindd/winbindd_cm.c:148(msg_try_to_go_online)
  msg_try_to_go_online: domain TELLUS already online.
Comment 3 Christian Svensson 2010-07-02 15:36:48 UTC 
Bug is still present in 3.5.4
Comment 4 Scott K Logan 2010-08-06 17:02:45 UTC 
I'm confirming a similar problem in 3.5.4-62.fc13

I joined to AD domain, but IDMAP (rid) doesn't change ANY of the UIDs or GIDs at all. I checked the log.winbindd-idmap against that of a working installation of 3.4.7-0.50.fc11 and the only difference was this:

[2010/08/06 16:55:24.236331,  3] winbindd/winbindd_cm.c:1633(connection_ok)
  connection_ok: Connection to  for domain DOMAINNAME is not connected

Note the lack of DC name in this entry and yours. "Connection to  for..."

Like I said, this is the only difference I see in Debug 3.

Is IDMAP broken?