[Samba] winbind error after startup on Samba member server

Thu Jun 13 15:21:49 UTC 2024

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