[Samba] Log errors on domain member

Tue Jan 31 13:33:46 UTC 2023

On 31/01/2023 06:59, Peter Milesson via samba wrote:
> Hi folks,
> 
> The smb.conf and other information after specification of the problems.
> 
> The journal on a AD domain member server is cluttered with permission 
> denied entries of this message pair:
> 
>     Jan 31 07:02:26 konsrvfast smbd[436004]: [2023/01/31
>     07:02:26.083500,  0, effective(11025, 10515), real(11025, 0)]
>     ../../source3/smbd/smb2_service.c:168(chdir_current_service)
> 
>     Jan 31 07:02:26 konsrvfast smbd[436004]:   chdir_current_service:
>     vfs_ChDir(/data/samba/profiles) failed: Permission denied. Current
>     token: uid=11025, gid=10515, 5 groups: 11025 10515 3003 3004 3006
> 
> uid=11025 is a Windows 10 workstation, and gid=10515 is the domain 
> computers object.
> 
> 
> There are also recurring entry blocks of the following type:
> 
>     Jan 30 19:55:39 konsrvfast rpcd_classic[358632]: [2023/01/30
>     19:55:39.802586,  0, effective(11006, 10513), real(11006, 0)]
>     ../../lib/util/debug.c:1264(reopen_one_log)
>     Jan 30 19:55:39 konsrvfast rpcd_classic[358632]:   reopen_one_log:
>     Unable to open new log file '/var/log/samba/log.rpcd_classic':
>     Permission denied
>     Jan 30 19:55:39 konsrvfast rpcd_classic[358632]: [2023/01/30
>     19:55:39.803020,  0, effective(11006, 10513), real(11006, 0)]
>     ../../lib/util/debug.c:1264(reopen_one_log)
>     Jan 30 19:55:39 konsrvfast rpcd_classic[358632]:   reopen_one_log:
>     Unable to open new log file '/var/log/samba/log.rpcd_classic':
>     Permission denied
>     Jan 30 19:55:39 konsrvfast rpcd_classic[358632]: [2023/01/30
>     19:55:39.803056,  0, effective(11006, 10513), real(11006, 0)]
>     ../../lib/util/debug.c:1264(reopen_one_log)
>     Jan 30 19:55:39 konsrvfast rpcd_classic[358632]:   reopen_one_log:
>     Unable to open new log file '/var/log/samba/log.rpcd_classic':
>     Permission denied
>     Jan 30 19:55:55 konsrvfast rpcd_classic[358632]: [2023/01/30
>     19:55:55.231090,  0, effective(11006, 10513), real(11006, 0)]
>     ../../source3/lib/sharesec.c:161(share_info_db_init)
>     Jan 30 19:55:55 konsrvfast rpcd_classic[358632]:   Failed to open
>     share info database /var/lib/samba/share_info.tdb (Permission denied)
>     Jan 30 19:55:59 konsrvfast rpcd_classic[358632]: [2023/01/30
>     19:55:59.715024,  0, effective(11006, 10513), real(11006, 0)]
>     ../../source3/lib/sharesec.c:161(share_info_db_init)
> 
> 
> After scanning the samba logs I found the following:
> 
> */var/log/samba/log.rpcd_classic (those 2 entries occur frequently)*
> 
>     [2023/01/30 15:15:28.729356,  0, effective(11156, 10513),
>     real(11156, 0)] ../../lib/util/debug.c:1264(reopen_one_log)
>     reopen_one_log: Unable to open new log file
>     '/var/log/samba/log.rpcd_classic': Permission denied
> 
>     [2023/01/30 20:09:09.054259,  0, effective(11006, 10513),
>     real(11006, 0)]
>     ../../source3/lib/sharesec.c:161(share_info_db_init)  Failed to open
>     share info database /var/lib/samba/share_info.tdb (Permission denied)
> 
> 
> */var/log/samba/log.samba-dcerpcd (the following block repeats frequently)*
> 
>     [2023/01/30 15:31:55.316639,  1, effective(0, 0), real(0, 0)]
>     ../../source3/rpc_client/cli_pipe.c:3014(rpc_pipe_open_ncalrpc)
>     rpc_pipe_open_ncalrpc: connect(/run/samba/ncalrpc/EPMAPPER) failed:
>     No such file or directory
>     [2023/01/30 15:31:55.341724,  1, effective(0, 0), real(0, 0)]
>     ../../source3/rpc_server/rpc_host.c:1763(rpc_worker_exited)
>     rpc_worker_exited: No worker with PID 328204
>     [2023/01/30 15:34:13,  0] 
> ../../source3/rpc_server/rpc_host.c:2966(main)
> 
> When checking the directory /run/samba/ncalrpc there is really no such 
> file as EPMAPPER, but there exists /run/samba/ncalrpc/np/epmapper
> 
> 
> */var/log/samba/smbd.log (the following entry is spawned thousands of 
> times within a second)*
> 
> [2023/01/30 20:07:59.636915,  1, effective(11006, 10513), real(11006, 
> 0)] ../../source3/auth/token_util.c:1020(create_token_from_sid)
>    getpwuid(1011) failed
> 
> 
> */var/log/samba/winbindd (the entries below frequently occuring)*
> 
> [2023/01/30 23:34:57.527639,  1, effective(0, 0), real(0, 0)] 
> ../../source3/winbindd/winbindd_getpwuid.c:118(winbindd_getpwuid_recv)
>    Could not convert sid S-0-0: NT_STATUS_NO_SUCH_USER
> 
> [2023/01/31 00:17:01.889654,  1, effective(0, 0), real(0, 0)] 
> ../../source3/winbindd/winbindd_getgroups.c:259(winbindd_getgroups_recv)
>    Could not convert sid S-0-0: NT_STATUS_NONE_MAPPED
> 
> (occurs several times per second, hundreds of consecutive entries)
> [2023/01/30 23:30:50.246781,  1, effective(0, 0), real(0, 0)] 
> ../../source3/winbindd/winbindd_getgrgid.c:124(winbindd_getgrgid_recv)
>    Could not convert sid S-0-0: NT_STATUS_NO_SUCH_GROUP
> 
> 
>  From the users point of view everything seems normal, there have been 
> no complaints about inaccessible folders or files, or other permission 
> issues.
> 
> The server is a member of a AD domain, and everything in the domain is 
> managed via the RSAT tools. There are only Windows ACLs, no Posix ACLs. 
> There are only a couple of local linux accounts for server 
> administration, with user names that do not conflict with AD user names. 
> The domain is working, no DNS problems.
> 
> If would be grateful if somebody could point out what's going wrong here.
> 

I don't think anything is going wrong here, it just seems that, lately, 
Samba has got very chatty. You are about the third person to raise this 
'problem', I wonder if it has something to do with all the changes there 
have been lately ???

Perhaps you would like to raise a bug report about this ?

Rowland