Bug 9465 - Unable to setup messaging listener for '/usr/local/samba/private/smbd.tmp/msg/msg.17364.2':NT_STATUS_ACCESS_DENIED
Unable to setup messaging listener for '/usr/local/samba/private/smbd.tmp/msg...
Status: RESOLVED FIXED
Product: Samba 4.0
Classification: Unclassified
Component: DCE-RPCs and pipes
4.0.0rc5
x64 Linux
: P5 normal
: ---
Assigned To: Karolin Seeger
Samba QA Contact
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2012-12-05 09:34 UTC by Marc Muehlfeld
Modified: 2013-05-29 09:46 UTC (History)
2 users (show)

See Also:


Attachments
Patch for master to become root and fix this issue (2.16 KB, patch)
2013-05-02 05:37 UTC, Andrew Bartlett
no flags Details
improved patch (2.67 KB, patch)
2013-05-12 06:45 UTC, Andrew Bartlett
no flags Details
patches cherry-picked from master (2.78 KB, patch)
2013-05-21 22:38 UTC, Andrew Bartlett
metze: review+
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Marc Muehlfeld 2012-12-05 09:34:46 UTC
In /var/log/messages on my samba4 DC, the followinig error block is appearing about 4-6 times per day (not on fixed times).

Dec  4 16:25:35 exon smbd[17364]: [2012/12/04 16:25:35.179534,  0, pid=17364] ../source4/lib/messaging/messaging.c:633(imessaging_init)
Dec  4 16:25:35 exon smbd[17364]:   Unable to setup messaging listener for '/usr/local/samba/private/smbd.tmp/msg/msg.17364.2':NT_STATUS_ACCESS_DENIED
Dec  4 16:25:35 exon smbd[17364]: [2012/12/04 16:25:35.179783,  0, pid=17364] ../source3/rpc_server/dcesrv_auth_generic.c:40(auth_generic_server_authtype_start)
Dec  4 16:25:35 exon smbd[17364]: ../source3/rpc_server/dcesrv_auth_generic.c:40: auth_generic_prepare failed: NT_STATUS_INVALID_SERVER_STATE
Dec  4 16:25:35 exon smbd[17364]: [2012/12/04 16:25:35.179886,  0, pid=17364] ../source3/rpc_server/srv_pipe.c:553(pipe_auth_generic_bind)
Dec  4 16:25:35 exon smbd[17364]:   ../source3/rpc_server/srv_pipe.c:553: auth_generic_server_authtype_start failed: NT_STATUS_INVALID_SERVER_STATE




When I search the samba machine logs for the same time I found the following:

[2012/12/04 16:25:35.179534,  0, pid=17364] ../source4/lib/messaging/messaging.c:633(imessaging_init)
  Unable to setup messaging listener for '/usr/local/samba/private/smbd.tmp/msg/msg.17364.2':NT_STATUS_ACCESS_DENIED
[2012/12/04 16:25:35.179710,  1, pid=17364] ../source3/auth/auth_samba4.c:147(prepare_gensec)
  imessaging_init failed
[2012/12/04 16:25:35.179783,  0, pid=17364] ../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
[2012/12/04 16:25:35.179886,  0, pid=17364] ../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
[2012/12/04 16:25:47.341458,  1, pid=17381] ../source3/smbd/service.c:891(make_connection_snum)
  192.168.29.3 (ipv4:192.168.29.3:1839) connect to service sysvol initially as user MUC\bheye (uid=2373, gid=513) (pid 17381)
[2012/12/04 16:25:47.584462,  1, pid=17382] ../source3/smbd/service.c:891(make_connection_snum)
  192.168.29.3 (ipv4:192.168.29.3:1841) connect to service sysvol initially as user MUC\amplicon$ (uid=2123, gid=515) (pid 17382)
[2012/12/04 16:25:48.564619,  1, pid=17384] ../source3/smbd/service.c:891(make_connection_snum)
  192.168.29.3 (ipv4:192.168.29.3:1843) connect to service netlogon initially as user MUC\bheye (uid=2373, gid=513) (pid 17384)
[2012/12/04 16:25:48.850855,  1, pid=17386] ../source3/smbd/service.c:891(make_connection_snum)
  192.168.29.3 (ipv4:192.168.29.3:1861) connect to service netlogon initially as user MUC\amplicon$ (uid=2123, gid=515) (pid 17386)



If you could tell me at what log level I should log for further information, I can do that. I only can't let the DC stay on log level 10 the whole day, because this message appears irregular and it would flood the logs.
Comment 1 Marc Muehlfeld 2012-12-05 09:36:10 UTC
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
Comment 2 Marc Muehlfeld 2012-12-05 10:12:15 UTC
> 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.
Comment 3 tbskyd 2013-04-05 06:33:05 UTC
(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
Comment 4 Simon Thorley 2013-04-26 12:01:27 UTC
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
Comment 5 Simon Thorley 2013-04-26 12:26:21 UTC
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.
Comment 6 Simon Thorley 2013-04-26 13:16:38 UTC
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.
Comment 7 Simon Thorley 2013-04-30 11:53:34 UTC
Ok, after i chmod 777 the profiles directory it works fine.  The homedrives though is 755 and that also works fine.
Comment 8 Simon Thorley 2013-05-01 08:29:32 UTC
Actually no,  it has stopped working again.  Even on 777.
Comment 9 Andrew Bartlett 2013-05-02 05:37:17 UTC
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,
Comment 10 Marc Muehlfeld 2013-05-06 20:15:23 UTC
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)
Comment 11 Marc Muehlfeld 2013-05-06 20:21:40 UTC
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
Comment 12 Andrew Bartlett 2013-05-12 06:45:17 UTC
Created attachment 8879 [details]
improved patch

Can you try this patch?

Thanks,
Comment 13 Marc Muehlfeld 2013-05-12 10:13:11 UTC
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 :-))?
Comment 14 Andrew Bartlett 2013-05-12 10:21:39 UTC
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).
Comment 15 Marc Muehlfeld 2013-05-12 15:01:08 UTC
I put the patch now on my production site. I'll give feedback tomorrow.
Comment 16 Marc Muehlfeld 2013-05-13 09:56:20 UTC
Looks good. Your patch is 15h in production now and the error didn't appeared any more in that time.

Thanks.
Comment 17 Marc Muehlfeld 2013-05-21 19:38:28 UTC
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?
Comment 18 Andrew Bartlett 2013-05-21 22:38:20 UTC
Created attachment 8908 [details]
patches cherry-picked from master
Comment 19 Stefan Metzmacher 2013-05-22 06:44:57 UTC
Comment on attachment 8908 [details]
patches cherry-picked from master

Looks good
Comment 20 Karolin Seeger 2013-05-27 11:56:17 UTC
Pushed to autobuild-v4-0-test.
Comment 21 Karolin Seeger 2013-05-29 09:46:07 UTC
Pushed to v4-0-test.
Closing out bug report.

Thanks!