Package: nslcd Version: 0.9.10-2 Severity: normal
-- System Information: Debian Release: 10.3 APT prefers stable APT policy: (500, 'stable') Architecture: i386 (i686) Kernel: Linux 4.19.0-8-686 (SMP w/1 CPU core) Locale: LANG=C, LC_CTYPE=C.UTF-8 (charmap=UTF-8), LANGUAGE=C (charmap=UTF-8) Shell: /bin/sh linked to /usr/bin/dash Init: systemd (via /run/systemd/system) LSM: AppArmor: enabled Versions of packages nslcd depends on: ii adduser 3.118 ii ca-certificates 20190110 ii debconf [debconf-2.0] 1.5.71 ii libc6 2.28-10 ii libgssapi-krb5-2 1.17-3 ii libldap-2.4-2 2.4.47+dfsg-3+deb10u1 ii lsb-base 10.2019051400 Versions of packages nslcd recommends: ii bind9-host [host] 1:9.11.5.P4+dfsg-5.1 ii ldap-utils 2.4.47+dfsg-3+deb10u1 ii libnss-ldapd [libnss-ldap] 0.9.10-2 pn libpam-ldapd | libpam-ldap | libpam-krb5 | libpam-he <none> pn nscd <none> pn nslcd-utils <none> Versions of packages nslcd suggests: ii kstart 4.2-2 -- debconf information excluded On first login after boot up on the linux console with a local user I have to wait one minute to get a shell prompt. After first login I can logoff and login as usual without delay. The account is a local unix account with entries in /etc/passwd and /etc/group and does not has a posixAccount on the ldap directory. Authorization against the ldap server is done with SASL Proxy Authorization. The bug is only seen when quering for the group account. This can simply verified with removing the 'ldap' postfix at the line group: files ldap in /etc/nsswitch.conf. Without 'ldap' on that line I can first login after boot up without delay. If I use ssh or a serial console (on a virtual machine) then there is no problem. In these cases LOGIN isn't involved so it seems only to be a problem in conjunction with LOGIN. As shown in the debug log below the dbus-daemon is timing out the attempt of nslcd to connect to the ldap server. These are the important lines: Feb 15 15:52:45 kawa dbus-daemon[345]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 60015ms) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> failed to bind to LDAP server ldap://kdc-master.home.hoeft-online.de: Can't contact LDAP server: Invalid argument I have verified with tcpdump that nslcd does not output any ip packages to the ldap server. It just do nothing on the network at this time. The immediate next attempt of nslcd to connect to the ldap server succeded. Here are the configuration files -------------------------------- # /etc/nslcd.conf # nslcd configuration file. See nslcd.conf(5) # for details. # The user and group nslcd should run as. uid nslcd gid nslcd # Logging options, default is info log syslog debug # The location at which the LDAP server(s) should be reachable. uri ldap://kdc-master.home.hoeft-online.de # The search base that will be used for all queries. base ou=home,dc=hoeft-online,dc=de # The LDAP protocol version to use. #ldap_version 3 # The DN to bind with for normal lookups. binddn uid=anyuser,ou=people,ou=home,dc=hoeft-online,dc=de # The DN used for password modifications by root. #rootpwmoddn cn=admin,dc=example,dc=com # SSL options #ssl off #tls_reqcert never tls_cacertfile /etc/ssl/certs/ca-certificates.crt # SASL options sasl_mech GSSAPI krb5_ccname /run/nslcd/nslcd.tkt # The search scope. #scope sub # /etc/nsswitch.conf passwd: files ldap group: files ldap shadow: files gshadow: files hosts: files resolve [!UNAVAIL=return] dns networks: files protocols: db files services: db files ethers: db files rpc: db files netgroup: nis Debug log from the systemd journal ---------------------------------- Feb 15 15:20:16 kawa systemd[1]: Started Wait for Network to be Configured. Feb 15 15:20:16 kawa systemd[1]: Reached target Network is Online. Feb 15 15:20:16 kawa systemd[1]: Starting LSB: LDAP connection daemon... Feb 15 15:20:16 kawa systemd-timesyncd[260]: Synchronized to time server for the first time 178.63.9.212:123 (2.debian.pool.ntp.org). Feb 15 15:20:19 kawa nslcd[373]: Starting Keep alive Kerberos ticket: k5start. Feb 15 15:20:19 kawa sshd[384]: Server listening on 0.0.0.0 port 22. Feb 15 15:20:19 kawa sshd[384]: Server listening on :: port 22. Feb 15 15:20:19 kawa systemd[1]: Started OpenBSD Secure Shell server. Feb 15 15:20:20 kawa lvm[234]: Monitoring snapshot vg1-deb10.2_recommended+ssh+resolve_no_krb5.lv. Feb 15 15:20:20 kawa systemd[1]: Started LVM2 poll daemon. Feb 15 15:20:21 kawa lvm[342]: Background polling started for 1 logical volume(s) in volume group "vg1" Feb 15 15:20:24 kawa lvm[342]: 5 logical volume(s) in volume group "vg1" now active Feb 15 15:20:24 kawa systemd[1]: Started LVM event activation on device 8:1. Feb 15 15:20:24 kawa lvm[341]: Background polling started for 1 logical volume(s) in volume group "vg1" Feb 15 15:20:24 kawa lvm[341]: 5 logical volume(s) in volume group "vg1" now active Feb 15 15:20:24 kawa nslcd[403]: version 0.9.10 starting Feb 15 15:20:24 kawa nslcd[403]: DEBUG: initgroups("nslcd",112) done Feb 15 15:20:24 kawa nslcd[403]: DEBUG: setgid(112) done Feb 15 15:20:24 kawa nslcd[403]: DEBUG: setuid(106) done Feb 15 15:20:24 kawa nslcd[403]: DEBUG: unlink() of /var/run/nslcd/socket failed (ignored): No such file or directory Feb 15 15:20:24 kawa systemd[1]: Started LSB: LDAP connection daemon. Feb 15 15:20:24 kawa nslcd[373]: Starting LDAP connection daemon: nslcd. Feb 15 15:20:24 kawa nslcd[403]: accepting connections Feb 15 15:20:24 kawa systemd[1]: Started Regular background program processing daemon. Feb 15 15:20:24 kawa systemd[1]: Reached target Multi-User System. Feb 15 15:20:24 kawa systemd[1]: Reached target Graphical Interface. Feb 15 15:20:24 kawa systemd[1]: Starting Update UTMP about System Runlevel Changes... Feb 15 15:20:24 kawa systemd[1]: Started LVM event activation on device 8:2. Feb 15 15:20:24 kawa systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Feb 15 15:20:24 kawa systemd[1]: Started Update UTMP about System Runlevel Changes. Feb 15 15:20:24 kawa systemd[1]: Startup finished in 1min 4.693s (kernel) + 48.837s (userspace) = 1min 53.530s. Feb 15 15:20:24 kawa cron[409]: (CRON) INFO (pidfile fd = 3) Feb 15 15:20:24 kawa cron[409]: (CRON) INFO (Running @reboot jobs) Feb 15 15:33:40 kawa systemd[1]: Starting Cleanup of Temporary Directories... Feb 15 15:33:43 kawa systemd[1]: systemd-tmpfiles-clean.service: Succeeded. Feb 15 15:33:43 kawa systemd[1]: Started Cleanup of Temporary Directories. Feb 15 15:36:36 kawa lvm[234]: No longer monitoring snapshot vg1-deb10_ssh+resolve_no_krb5.lv. Feb 15 15:36:36 kawa lvm[234]: Monitoring snapshot vg1-deb10_ssh+resolve_no_krb5.lv. Feb 15 15:36:37 kawa lvmpolld[391]: W: LVPOLL: PID 398: STDERR: ' WARNING: This metadata update is NOT backed up.' Feb 15 15:37:37 kawa systemd[1]: lvm2-lvmpolld.service: Succeeded. Feb 15 15:51:45 kawa login[362]: pam_unix(login:session): session opened for user local by LOGIN(uid=0) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] DEBUG: connection from pid=362 uid=0 gid=65533 Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: myldap_search(base="ou=home,dc=hoeft-online,dc=de", filter="(&(objectClass=posixAccount)(uid=local))") Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_initialize(ldap://kdc-master.home.hoeft-online.de) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_rebind_proc() Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_PROTOCOL_VERSION,3) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_DEREF,0) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_TIMELIMIT,0) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_TIMEOUT,0) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_NETWORK_TIMEOUT,0) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_REFERRALS,LDAP_OPT_ON) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_RESTART,LDAP_OPT_ON) Feb 15 15:51:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_sasl_interactive_bind_s("uid=anyuser,ou=people,ou=home,dc=hoeft-online,dc=de","GSSAPI") (uri="ldap://kdc-master.home.hoeft-online.de";) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] DEBUG: connection from pid=345 uid=104 gid=110 Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: myldap_search(base="ou=home,dc=hoeft-online,dc=de", filter="(&(objectClass=posixAccount)(uid=nslcd))") Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_initialize(ldap://kdc-master.home.hoeft-online.de) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_set_rebind_proc() Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_set_option(LDAP_OPT_PROTOCOL_VERSION,3) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_set_option(LDAP_OPT_DEREF,0) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_set_option(LDAP_OPT_TIMELIMIT,0) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_set_option(LDAP_OPT_TIMEOUT,0) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_set_option(LDAP_OPT_NETWORK_TIMEOUT,0) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_set_option(LDAP_OPT_REFERRALS,LDAP_OPT_ON) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_set_option(LDAP_OPT_RESTART,LDAP_OPT_ON) Feb 15 15:51:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_sasl_interactive_bind_s("uid=anyuser,ou=people,ou=home,dc=hoeft-online,dc=de","GSSAPI") (uri="ldap://kdc-master.home.hoeft-online.de";) Feb 15 15:52:45 kawa dbus-daemon[345]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 60015ms) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> failed to bind to LDAP server ldap://kdc-master.home.hoeft-online.de: Can't contact LDAP server: Invalid argument Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_unbind() Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> no available LDAP server found: Can't contact LDAP server: Invalid argument Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: myldap_search(base="ou=home,dc=hoeft-online,dc=de", filter="(&(objectClass=posixGroup)(memberUid=local))") Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_initialize(ldap://kdc-master.home.hoeft-online.de) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_rebind_proc() Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_PROTOCOL_VERSION,3) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_DEREF,0) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_TIMELIMIT,0) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_TIMEOUT,0) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_NETWORK_TIMEOUT,0) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_REFERRALS,LDAP_OPT_ON) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_set_option(LDAP_OPT_RESTART,LDAP_OPT_ON) Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_sasl_interactive_bind_s("uid=anyuser,ou=people,ou=home,dc=hoeft-online,dc=de","GSSAPI") (uri="ldap://kdc-master.home.hoeft-online.de";) Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 1 Feb 15 15:52:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: do_sasl_interact(): were asked for sasl_authzid but we don't have any Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 1 Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 1 Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: do_sasl_interact(): were asked for sasl_authzid but we don't have any Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 1 Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 1 Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: do_sasl_interact(): were asked for sasl_authzid but we don't have any Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 1 Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 1 Feb 15 15:52:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: do_sasl_interact(): were asked for sasl_authzid but we don't have any Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 1 Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 2 Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> connected to LDAP server ldap://kdc-master.home.hoeft-online.de Feb 15 15:52:45 kawa nslcd[403]: GSSAPI client step 2 Feb 15 15:52:45 kawa nslcd[403]: [8b4567] <group/member="local"> DEBUG: ldap_result(): end of results (0 total) Feb 15 15:52:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_result(): end of results (0 total) Feb 15 15:52:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: myldap_search(base="ou=home,dc=hoeft-online,dc=de", filter="(&(objectClass=posixGroup)(memberUid=nslcd))") Feb 15 15:52:45 kawa nslcd[403]: [7b23c6] <group/member="nslcd"> DEBUG: ldap_result(): end of results (0 total)
