Andrews reply to my post on the mailing list:


Am 05.12.2012 00:14, schrieb Andrew Bartlett:
> On Tue, 2012-12-04 at 16:57 +0100, Marc Muehlfeld wrote:
>> I saw in /var/log/messages on my samba4 rc5 DC the following error block
>> appearing about 4-6 times per day (no fixed time) and wonder if it's something
>> I have to worry about or not:
> 
> Based on your very helpful analysis, I think this may be the issue:
> 
> Somewhere in the DCE/RPC server we are missing a
> become_root()/unbecome_root() pair around the calls to gensec.  We
> should fix this, so please file a bug.
> 
> Why this happens only sometimes, and not every time, is a concern.
> 
> However, to further diagnose: after this happens, do you notice if the
> mentioned file actually exists, and if so, does it have a timestamp
> matching these errors, or something different?
> 
> Andrew Bartlett

> However, to further diagnose: after this happens, do you notice if the
> mentioned file actually exists, and if so, does it have a timestamp
> matching these errors, or something different?

The last time I had this error was about 3h ago and the msg.* file from this log entry is not existing.

(In reply to comment #2)
> > However, to further diagnose: after this happens, do you notice if the
> > mentioned file actually exists, and if so, does it have a timestamp
> > matching these errors, or something different?
> 
> The last time I had this error was about 3h ago and the msg.* file from this
> log entry is not existing.

I Installed samba 4.0.4 as AD DC and file server.
I map two shares to windows with group policy.
and everytime my windows 7 logon,I see the same error messages below.
I have full log about it. please mail me if you need it. thanks a lot!

[2013/04/05 14:09:28.609586,  3] ../source3/rpc_server/srv_pipe.c:347(check_bind_req)
  check_bind_req: winreg -> winreg rpc service
[2013/04/05 14:09:28.609664,  5] ../source3/auth/auth.c:476(make_auth_context_subsystem)
  Making default auth method list for server role = 'active directory domain controller'
[2013/04/05 14:09:28.609714,  5] ../source3/auth/auth.c:351(load_auth_module)
  load_auth_module: Attempting to find an auth method to match samba4
[2013/04/05 14:09:28.609764,  5] ../source3/auth/auth.c:376(load_auth_module)
  load_auth_module: auth method samba4 has a valid init
[2013/04/05 14:09:28.609852,  0] ../source4/lib/messaging/messaging.c:633(imessaging_init)
  Unable to setup messaging listener for '/usr/local/samba/private/smbd.tmp/msg/msg.20252.2':NT_STATUS_ACCESS_DENIED
[2013/04/05 14:09:28.609990,  1] ../source3/auth/auth_samba4.c:147(prepare_gensec)
  imessaging_init failed
[2013/04/05 14:09:28.610055,  0] ../source3/rpc_server/dcesrv_auth_generic.c:40(auth_generic_server_authtype_start)
  ../source3/rpc_server/dcesrv_auth_generic.c:40: auth_generic_prepare failed: NT_STATUS_INVALID_SERVER_STATE
[2013/04/05 14:09:28.610197,  0] ../source3/rpc_server/srv_pipe.c:553(pipe_auth_generic_bind)
  ../source3/rpc_server/srv_pipe.c:553: auth_generic_server_authtype_start failed: NT_STATUS_INVALID_SERVER_STATE
[2013/04/05 14:09:28.610895,  4] ../source3/smbd/uid.c:394(change_to_user)
  Skipping user change - already user
[2013/04/05 14:09:28.610957,  6] ../source3/rpc_server/srv_pipe_hnd.c:285(read_from_internal_pipe)
   name: \winreg len: 1024

Hi,

I have a compiled Samba 4.0.5 running as an AD DC.  I am having the same issue accessing a profiles$ share when a user logs on with a roaming profile.  Other shares seem to work fine (home drive, print$, etc). I followed the log.smbd whilst i logged into the Windows 7 ad member machine:

[2013/04/26 12:45:19.502204,  0] ../source4/lib/messaging/messaging.c:633(imessaging_init)
  Unable to setup messaging listener for '/usr/local/samba/private/smbd.tmp/msg/msg.1454.2':NT_STATUS_ACCESS_DENIED
[2013/04/26 12:45:19.503190,  0] ../source3/rpc_server/dcesrv_auth_generic.c:40(auth_generic_server_authtype_start)
  ../source3/rpc_server/dcesrv_auth_generic.c:40: auth_generic_prepare failed: NT_STATUS_INVALID_SERVER_STATE
[2013/04/26 12:45:19.503414,  0] ../source3/rpc_server/srv_pipe.c:553(pipe_auth_generic_bind)
  ../source3/rpc_server/srv_pipe.c:553: auth_generic_server_authtype_start failed: NT_STATUS_INVALID_SERVER_STATE


Here is the windows user profile service event for the logon:

Windows cannot locate the server copy of your roaming profile and is attempting to log you on with your local profile. Changes to the profile will not be copied to the server when you log off. This error may be caused by network problems or insufficient security rights. 

 DETAIL - Access is denied.


The share is a standard share for profiles:

[profiles$]
	path = /home/Profiles
        read only = no

It is the same as my working homedrive share:

[homes$]
        path = /home/HomeDrives
        read only = No

In Addition, i did another test logon and checked to see if the msg file existed about 5 seconds after the error event and the file did not exist.

Additional additional:  I can access profiles$ share fine through the UNC path and read\write to it with no issues.  This only occurs during logon.

It also happens if i manually create the profile folder and duplicate the facls from the home drive from that user.

Ok, after i chmod 777 the profiles directory it works fine.  The homedrives though is 755 and that also works fine.

Actually no,  it has stopped working again.  Even on 777.

Created attachment 8845 [details]
Patch for master to become root and fix this issue

I do apologise for the time it has taken to address this issue, which has been around since we did the s3fs integration, but I didn't get back to addressing.

The attached patch should fix it, ensuring we are root when needed.

Please test and let me know so I can get it into master, and then 4.0.

Thanks,

After applying the patch, recompiling and installing, I saw the following in messages:


May  6 22:08:07 exon smbd[97697]: [2013/05/06 22:08:07.693282,  0, pid=97697] ../source3/rpc_server/srv_pipe.c:604(pipe_auth_generic_verify_final)
May  6 22:08:07 exon smbd[97697]:   ../source3/rpc_server/srv_pipe.c:604: failed to obtain the server info for authenticated user: NT_STATUS_INTERNAL_DB_CORRUPTION
May  6 22:08:07 exon smbd[97697]: [2013/05/06 22:08:07.693334,  0, pid=97697] ../source3/rpc_server/srv_pipe.c:1168(api_pipe_alter_context)
May  6 22:08:07 exon smbd[97697]:   Auth Verify failed (NT_STATUS_ACCESS_DENIED)

This was the output of the samba logs (debug level = 1):

[2013/05/06 22:08:07.693141,  1, pid=97697] ../lib/ldb-samba/ldb_wrap.c:69(ldb_wrap_debug)
  ldb: Unable to open tdb '/usr/local/samba/private/privilege.ldb'
[2013/05/06 22:08:07.693202,  1, pid=97697] ../lib/ldb-samba/ldb_wrap.c:69(ldb_wrap_debug)
  ldb: Failed to connect to '/usr/local/samba/private/privilege.ldb' with backend 'tdb': Unable to open tdb '/usr/local/samba/private/privilege.ldb'
[2013/05/06 22:08:07.693228,  1, pid=97697] ../source4/dsdb/samdb/samdb.c:166(security_token_create)
  Unable to access privileges database
[2013/05/06 22:08:07.693254,  1, pid=97697] ../source3/rpc_server/dcesrv_auth_generic.c:128(auth_generic_server_get_user_info)
  ../source3/rpc_server/dcesrv_auth_generic.c:128: Failed to get authenticated user info: NT_STATUS_INTERNAL_DB_CORRUPTION
[2013/05/06 22:08:07.693282,  0, pid=97697] ../source3/rpc_server/srv_pipe.c:604(pipe_auth_generic_verify_final)
  ../source3/rpc_server/srv_pipe.c:604: failed to obtain the server info for authenticated user: NT_STATUS_INTERNAL_DB_CORRUPTION
[2013/05/06 22:08:07.693334,  0, pid=97697] ../source3/rpc_server/srv_pipe.c:1168(api_pipe_alter_context)
  Auth Verify failed (NT_STATUS_ACCESS_DENIED)




Permissions of that file:
# ls -la /usr/local/samba/private/privilege.ldb 
-rw------- 1 root root 1286144  8. Sep 2012  /usr/local/samba/private/privilege.ldb

Created attachment 8879 [details]
improved patch

Can you try this patch?

Thanks,

Thanks Andrew for the new patch.

On my test environment the error, introduced by the the previous patch, is gone again.

The 'Unable to setup messaging listener...' error I haven't seen yet in my testing setup. But I think this isn't meaningfull, because even in my live environment (ca. 230 workstations), I have this error only a few times per day, and I haven't found a way to force appearing it.

Would it be safe to apply this patch to a live environment (I'm on SambaXP and problems in productions wouldn't be good in that time :-))?

I don't think this is very high risk, given it just becomes and unbecomes root, as long as we always do both (which you should be able to verify by inspection).

I put the patch now on my production site. I'll give feedback tomorrow.

Looks good. Your patch is 15h in production now and the error didn't appeared any more in that time.

Thanks.

The patch was sadly not included in 4.0.6. But it applies fine to the 4.0.6 sources, as well. And the message is then also gone.

Can you please push it for 4.0.7?

Created attachment 8908 [details]
patches cherry-picked from master

Comment on attachment 8908 [details]
patches cherry-picked from master

Looks good

Pushed to autobuild-v4-0-test.

Pushed to v4-0-test.
Closing out bug report.

Thanks!