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

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

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