samba - Jun 2024 - winbind error after startup on Samba member server

On Thu, 13 Jun 2024 16:26:17 +0200
Peter Milesson via samba <samba at lists.samba.org> wrote:
> Hi folks,
> 
> The last log record from journalctl -xeu winbind directly after
> winbind startup is:
> 
>     Jun 13 12:41:36 datasrv winbindd[582]: gpupdate_cmd_done: gpupdate
>     failed with exit status 1
> 
> For completeness, the log entries for winbind startup is displayed
> below.
> 
> Things seem to work though, but I have never seen it before (I don't 
> like error messages). When I noticed the message I ran a sysvolcheck, 
> but that was OK. After restart of winbind the message sequence was
> the same. There were no messages in the DC, that could be linked to
> the error.
> 
> I would be grateful for a clarification, if the message is important,
> or I just shouldn't care.
> 
> Best regards,
> 
> Peter
> 
> OS: Debian Bookworm with bookworm-backports (updated)
> Forest and domain levels 2016.
> 
> smb.conf below
> 
> [global]
>  ??????? apply group policies = Yes
>  ??????? debug pid = Yes
>  ??????? debug uid = Yes
>  ??????? dedicated keytab file = /etc/krb5.keytab
>  ??????? disable netbios = Yes
>  ??????? disable spoolss = Yes
>  ??????? smb ports = 445
>  ??????? kerberos method = secrets and keytab
>  ??????? printcap name = /dev/null
>  ??????? realm = PRIVATE.TALPS
>  ??????? restrict anonymous = 2
>  ??????? security = ADS
>  ??????? server role = member server
>  ??????? template homedir = /home/%U
>  ??????? template shell = /bin/bash
>  ??????? username map = /etc/samba/user.map
>  ??????? min domain uid = 0
>  ??????? winbind enum groups = Yes
>  ??????? winbind enum users = Yes
>  ??????? winbind expand groups = 4
>  ??????? winbind refresh tickets = Yes
>  ??????? winbind use default domain = Yes
>  ??????? workgroup = PRIVATE
>  ??????? idmap config private : range = 10000-99999
>  ??????? idmap config private : backend = rid
>  ??????? idmap config * : range = 3000-9999
>  ??????? idmap config * : backend = tdb
>  ??????? map acl inherit = Yes
>  ??????? vfs objects = acl_xattr
> 
> (and yes, I sincerely dislike how testparm is messing up smb.conf)
> winbind enum is just during on for testing
> 
> 
> excerpt from journalctl -xeu winbind on the member server
> 
> Jun 13 12:41:35 datasrv samba-dcerpcd[597]:?? samba-dcerpcd version 
> 4.20.1-Debian started.
> Jun 13 12:41:35 datasrv samba-dcerpcd[597]:?? Copyright Andrew
> Tridgell and the Samba Team 1992-2024
> Jun 13 12:41:36 datasrv rpcd_lsad[610]: [2024/06/13 12:41:36.064459,
> 0, pid=610, effective(0, 0), real(0, 0)] 
> source3/rpc_server/rpc_worker.c:1155(rpc_worker_main)
> Jun 13 12:41:36 datasrv rpcd_lsad[610]:?? rpcd_lsad version 
> 4.20.1-Debian started.
> Jun 13 12:41:36 datasrv rpcd_lsad[610]:?? Copyright Andrew Tridgell
> and the Samba Team 1992-2024
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.207955,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate: 
> Traceback (most recent call last):
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208001,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
> File "/usr/sbin/samba-gpupdate", line 135, in <module>
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208019,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:???? 
> apply_gp(lp, creds, store, gp_extensions, username,
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208030,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
> File "/usr/lib/python3/dist-packages/samba/gp/gpclass.py", line
1011,
> in apply_gp Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13
> 12:41:36.208413, 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:???? 
> gpos = get_gpo_list(dc_hostname, creds, lp, username)
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208434,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate: 
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208444,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
> File "/usr/lib/python3/dist-packages/samba/gp/gpclass.py", line
850,
> in get_gpo_list
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208597,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:???? 
> uac, dn = find_samaccount(samdb, username.split('\\')[-1])
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208612,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate: 
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208621,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
> File "/usr/lib/python3/dist-packages/samba/gp/gpclass.py", line
694,
> in find_samaccount
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208633,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:
> res = samdb.search(samdb.get_default_basedn(), ldb.SCOPE_SUBTREE,
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208650,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate: 
> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208660,
> 0, pid=582, effective(0, 0), real(0, 0)] 
> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate: 
> _ldb.LdbError: (1, '00002020: Operation unavailable without
> authentication') Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13
> 12:41:36.230755, 0, pid=582, effective(0, 0), real(0, 0)] 
> source3/winbindd/winbindd_gpupdate.c:182(gpupdate_cmd_done)
> Jun 13 12:41:36 datasrv winbindd[582]:?? gpupdate_cmd_done: gpupdate 
> failed with exit status 1
If you wade through all the log output it tells you the reason that
gpupdate is failing:

(1, '00002020: Operation unavailable without authentication')

Now why it is failing is another question.
Have you recently upgrading Samba and it has started doing this, or was
it working previously on 4.20.1 and is now failing ?

Rowland

On 13.06.2024 17:21, Rowland Penny via samba wrote:
> On Thu, 13 Jun 2024 16:26:17 +0200
> Peter Milesson via samba <samba at lists.samba.org> wrote:
>
>> Hi folks,
>>
>> The last log record from journalctl -xeu winbind directly after
>> winbind startup is:
>>
>>      Jun 13 12:41:36 datasrv winbindd[582]: gpupdate_cmd_done: gpupdate
>>      failed with exit status 1
>>
>> For completeness, the log entries for winbind startup is displayed
>> below.
>>
>> Things seem to work though, but I have never seen it before (I
don't
>> like error messages). When I noticed the message I ran a sysvolcheck,
>> but that was OK. After restart of winbind the message sequence was
>> the same. There were no messages in the DC, that could be linked to
>> the error.
>>
>> I would be grateful for a clarification, if the message is important,
>> or I just shouldn't care.
>>
>> Best regards,
>>
>> Peter
>>
>> OS: Debian Bookworm with bookworm-backports (updated)
>> Forest and domain levels 2016.
>>
>> smb.conf below
>>
>> [global]
>>   ??????? apply group policies = Yes
>>   ??????? debug pid = Yes
>>   ??????? debug uid = Yes
>>   ??????? dedicated keytab file = /etc/krb5.keytab
>>   ??????? disable netbios = Yes
>>   ??????? disable spoolss = Yes
>>   ??????? smb ports = 445
>>   ??????? kerberos method = secrets and keytab
>>   ??????? printcap name = /dev/null
>>   ??????? realm = PRIVATE.TALPS
>>   ??????? restrict anonymous = 2
>>   ??????? security = ADS
>>   ??????? server role = member server
>>   ??????? template homedir = /home/%U
>>   ??????? template shell = /bin/bash
>>   ??????? username map = /etc/samba/user.map
>>   ??????? min domain uid = 0
>>   ??????? winbind enum groups = Yes
>>   ??????? winbind enum users = Yes
>>   ??????? winbind expand groups = 4
>>   ??????? winbind refresh tickets = Yes
>>   ??????? winbind use default domain = Yes
>>   ??????? workgroup = PRIVATE
>>   ??????? idmap config private : range = 10000-99999
>>   ??????? idmap config private : backend = rid
>>   ??????? idmap config * : range = 3000-9999
>>   ??????? idmap config * : backend = tdb
>>   ??????? map acl inherit = Yes
>>   ??????? vfs objects = acl_xattr
>>
>> (and yes, I sincerely dislike how testparm is messing up smb.conf)
>> winbind enum is just during on for testing
>>
>>
>> excerpt from journalctl -xeu winbind on the member server
>>
>> Jun 13 12:41:35 datasrv samba-dcerpcd[597]:?? samba-dcerpcd version
>> 4.20.1-Debian started.
>> Jun 13 12:41:35 datasrv samba-dcerpcd[597]:?? Copyright Andrew
>> Tridgell and the Samba Team 1992-2024
>> Jun 13 12:41:36 datasrv rpcd_lsad[610]: [2024/06/13 12:41:36.064459,
>> 0, pid=610, effective(0, 0), real(0, 0)]
>> source3/rpc_server/rpc_worker.c:1155(rpc_worker_main)
>> Jun 13 12:41:36 datasrv rpcd_lsad[610]:?? rpcd_lsad version
>> 4.20.1-Debian started.
>> Jun 13 12:41:36 datasrv rpcd_lsad[610]:?? Copyright Andrew Tridgell
>> and the Samba Team 1992-2024
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.207955,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
>> Traceback (most recent call last):
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208001,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
>> File "/usr/sbin/samba-gpupdate", line 135, in <module>
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208019,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:
>> apply_gp(lp, creds, store, gp_extensions, username,
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208030,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
>> File "/usr/lib/python3/dist-packages/samba/gp/gpclass.py",
line 1011,
>> in apply_gp Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13
>> 12:41:36.208413, 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:
>> gpos = get_gpo_list(dc_hostname, creds, lp, username)
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208434,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:
>> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208444,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
>> File "/usr/lib/python3/dist-packages/samba/gp/gpclass.py",
line 850,
>> in get_gpo_list
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208597,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:
>> uac, dn = find_samaccount(samdb, username.split('\\')[-1])
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208612,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:
>> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208621,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
>> File "/usr/lib/python3/dist-packages/samba/gp/gpclass.py",
line 694,
>> in find_samaccount
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208633,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:
>> res = samdb.search(samdb.get_default_basedn(), ldb.SCOPE_SUBTREE,
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208650,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]: /usr/sbin/samba-gpupdate:
>> ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>> Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13 12:41:36.208660,
>> 0, pid=582, effective(0, 0), real(0, 0)]
>> lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
>> Jun 13 12:41:36 datasrv winbindd[582]:?? /usr/sbin/samba-gpupdate:
>> _ldb.LdbError: (1, '00002020: Operation unavailable without
>> authentication') Jun 13 12:41:36 datasrv winbindd[582]: [2024/06/13
>> 12:41:36.230755, 0, pid=582, effective(0, 0), real(0, 0)]
>> source3/winbindd/winbindd_gpupdate.c:182(gpupdate_cmd_done)
>> Jun 13 12:41:36 datasrv winbindd[582]:?? gpupdate_cmd_done: gpupdate
>> failed with exit status 1
> If you wade through all the log output it tells you the reason that
> gpupdate is failing:
>
> (1, '00002020: Operation unavailable without authentication')
>
> Now why it is failing is another question.
> Have you recently upgrading Samba and it has started doing this, or was
> it working previously on 4.20.1 and is now failing ?
>
> Rowland
>
Hi Rowland,

It's a completely new installation with the most recent Samba from 
Bookworm backports. I cannot compare with the previous installation, as 
the SSD died, and I had to set it up from scratch.

Yes, I noticed that the failure is due to unavailable authentication, 
but why? And what are the consequences, if any?

I can compare with another member server that started its life as a 
Debian Bullseye with Samba 4.17.x. It has been upgraded to keep up with 
the current status of Debian and Samba. The smb.conf is almost 
identical. But instead, it continues the old nagging (all the way from 
start):

Jun 13 20:25:07 linuxdev winbindd[704]: [2024/06/13 20:25:07.417641,? 0] 
lib/util/util_runcmd.c:355(samba_runcmd_io_handler)
Jun 13 20:25:07 linuxdev winbindd[704]:?? /usr/sbin/samba-gpupdate: ldb: 
Failed to connect to '/var/lib/samba/private/secrets.ldb' with backend 
'tdb': Unable to open tdb '/var/lib/samba/private/secrets.ldb':
No such
file or directory

The two winbindd logs seem to have samba-gpupdate in common, however. 
But why are they different? Both are now 4.20.1, and should behave 
similarly. But it does not seem to have any practical impact. BTW, 
secrets.ldb never existed. There is a secrets.tdb file, however.

I'm not in the position to dig down in the Samba source code, but 
hopefully somebody with a deeper knowledge could explain what's going on.

Best regards,

Peter