[Freeipa-users] Kerberos hanging approx. once a day

Thu Jul 23 16:28:39 UTC 2015

On 07/22/2015 11:47 PM, Torsten Harenberg wrote:
> Good morning,
>
> Am 22.07.15 um 19:25 schrieb Rich Megginson:
>> On 07/22/2015 11:03 AM, Torsten Harenberg wrote:
>>> Dear Rich,
>>>
>>> Am 22.07.2015 um 17:03 schrieb Rich Megginson:
>>>> It might be helpful to do a # debuginfo-install 389-ds-base ipa-server
>>>> slapi-nis
>>>> and follow the directions at
>>>> http://www.port389.org/docs/389ds/FAQ/faq.html#debugging-hangs
>>>> to get a full stack trace
>>> thanks for the hint. Did that. But assume I need to wait until it hangs
>>> again, right?
>> Right.
> problem happend again, this time with slightly different symtoms:
>
>
> [root at wn108 ~]# id atlasprd020
> id: atlasprd020: No such user
>
>
> after restarting dirserv:
>
>
> [root at wn108 ~]# id atlasprd020
> uid=18970(atlasprd020) gid=1407(atlasprd) groups=1407(atlasprd)
> [root at wn108 ~]#
>
> So of course the whole site was down.
>
> the dirserv log file has not much:
>
> [22/Jul/2015:11:03:35 +0200] - Skipping CoS Definition cn=Password
> Policy,cn=accounts,dc=pleiades,dc=uni-wuppertal,dc=de--no CoS Templates
> found, which should be add
> ed before the CoS Definition.
> [22/Jul/2015:11:03:38 +0200] NSMMReplicationPlugin -
> replica_check_for_data_reload: Warning: disordely shutdown for replica
> dc=pleiades,dc=uni-wuppertal,dc=de. Check
>   if DB RUV needs to be updated
> [22/Jul/2015:11:03:38 +0200] NSMMReplicationPlugin - Force update of
> database RUV (from CL RUV) ->  55af7af3000e00040000
> [22/Jul/2015:11:03:39 +0200] set_krb5_creds - Could not get initial
> credentials for principal
> [ldap/ipa.pleiades.uni-wuppertal.de at PLEIADES.UNI-WUPPERTAL.DE] in keyta
> b [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for
> requested realm)
> [22/Jul/2015:11:03:39 +0200] - Skipping CoS Definition cn=Password
> Policy,cn=accounts,dc=pleiades,dc=uni-wuppertal,dc=de--no CoS Templates
> found, which should be add
> ed before the CoS Definition.
> [22/Jul/2015:11:03:39 +0200] slapd_ldap_sasl_interactive_bind - Error:
> could not perform interactive bind for id [] mech [GSSAPI]: LDAP error
> -2 (Local error) (SASL(
> -1): generic failure: GSSAPI Error: Unspecified GSS failure.  Minor code
> may provide more information (No Kerberos credentials available)) errno
> 0 (Success)
> [22/Jul/2015:11:03:39 +0200] slapi_ldap_bind - Error: could not perform
> interactive bind for id [] authentication mechanism [GSSAPI]: error -2
> (Local error)
> [22/Jul/2015:11:03:39 +0200] NSMMReplicationPlugin -
> agmt="cn=meToipa2.pleiades.uni-wuppertal.de" (ipa2:389): Replication
> bind with GSSAPI auth failed: LDAP error -2
>   (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified GSS
> failure.  Minor code may provide more information (No Kerberos
> credentials available))
> [22/Jul/2015:11:03:39 +0200] - slapd started.  Listening on All
> Interfaces port 389 for LDAP requests
> [22/Jul/2015:11:03:39 +0200] - Listening on All Interfaces port 636 for
> LDAPS requests
> [22/Jul/2015:11:03:39 +0200] - Listening on
> /var/run/slapd-PLEIADES-UNI-WUPPERTAL-DE.socket for LDAPI requests
> [22/Jul/2015:11:03:43 +0200] NSMMReplicationPlugin -
> agmt="cn=meToipa2.pleiades.uni-wuppertal.de" (ipa2:389): Replication
> bind with GSSAPI auth resumed
> [22/Jul/2015:15:15:41 +0200] find_sid_for_ldap_entry - [file
> ipa_sidgen_common.c, line 522]: Cannot convert Posix ID [51351] into an
> unused SID.
> [22/Jul/2015:15:15:41 +0200] ipa_sidgen_add_post_op - [file
> ipa_sidgen.c, line 149]: Cannot add SID to new entry.
> [23/Jul/2015:07:33:05 +0200] - slapd shutting down - signaling operation
> threads - op stack size 48 max work q size 22 max work q stack size 22
> [23/Jul/2015:07:33:05 +0200] - slapd shutting down - waiting for 1
> thread to terminate
> [23/Jul/2015:07:33:05 +0200] - slapd shutting down - closing down
> internal subsystems and plugins
> [23/Jul/2015:07:33:05 +0200] NSMMReplicationPlugin -
> agmt="cn=meToipa2.pleiades.uni-wuppertal.de" (ipa2:389): Warning:
> Attempting to release replica, but unable to r
> eceive endReplication extended operation response from the replica.
> Error -5 (Timed out)
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - timeout registering with
> portmap service
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - timeout registering with
> portmap service
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - timeout registering with
> portmap service
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - timeout registering with
> portmap service
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - timeout registering with
> portmap service
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - error sending request to
> portmap or rpcbind on 9: Connection refused
> [23/Jul/2015:07:33:06 +0200] nis-plugin - timeout registering with
> portmap service
> [23/Jul/2015:07:33:06 +0200] - Waiting for 4 database threads to stop
> [23/Jul/2015:07:33:06 +0200] - All database threads now stopped
> [23/Jul/2015:07:33:06 +0200] - slapd shutting down - freed 22 work q
> stack objects - freed 49 op stack objects
> [23/Jul/2015:07:33:06 +0200] - slapd stopped.
> [23/Jul/2015:07:33:08 +0200] nis-plugin - error connecting rpcbind
> client socket to the service
> [23/Jul/2015:07:33:08 +0200] SSL Initialization - Configured SSL version
> range: min: TLS1.0, max: TLS1.2
> [23/Jul/2015:07:33:08 +0200] - SSL alert: Configured NSS Ciphers
>
> [...]
>
>
> [23/Jul/2015:07:33:12 +0200] set_krb5_creds - Could not get initial
> credentials for principal [ldap/ipa@] in keytab
> [FILE:/etc/dirsrv/ds.keytab]: -1765328203 (Key table entry not found)
> [23/Jul/2015:07:33:12 +0200] slapd_ldap_sasl_interactive_bind - Error:
> could not perform interactive bind for id [] mech [GSSAPI]: LDAP error
> -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified
> GSS failure.  Minor code may provide more information (No Kerberos
> credentials available)) errno 0 (Success)
> [23/Jul/2015:07:33:12 +0200] slapi_ldap_bind - Error: could not perform
> interactive bind for id [] authentication mechanism [GSSAPI]: error -2
> (Local error)
> [23/Jul/2015:07:33:12 +0200] NSMMReplicationPlugin -
> agmt="cn=meToipa2.pleiades.uni-wuppertal.de" (ipa2:389): Replication
> bind with GSSAPI auth failed: LDAP error -2 (Local error) (SASL(-1):
> generic failure: GSSAPI Error: Unspecified GSS failure.  Minor code may
> provide more information (No Kerberos credentials available))
> [23/Jul/2015:07:33:12 +0200] - slapd started.  Listening on All
> Interfaces port 389 for LDAP requests
> [23/Jul/2015:07:33:12 +0200] - Listening on All Interfaces port 636 for
> LDAPS requests
> [23/Jul/2015:07:33:12 +0200] - Listening on
> /var/run/slapd-PLEIADES-UNI-WUPPERTAL-DE.socket for LDAPI requests
> [23/Jul/2015:07:33:15 +0200] set_krb5_creds - Could not get initial
> credentials for principal [ldap/ipa@] in keytab
> [FILE:/etc/dirsrv/ds.keytab]: -1765328203 (Key table entry not found)
> [23/Jul/2015:07:33:15 +0200] slapd_ldap_sasl_interactive_bind - Error:
> could not perform interactive bind for id [] mech [GSSAPI]: LDAP error
> -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified
> GSS failure.  Minor code may provide more information (No Kerberos
> credentials available)) errno 0 (Success)
> [23/Jul/2015:07:33:15 +0200] slapi_ldap_bind - Error: could not perform
> interactive bind for id [] authentication mechanism [GSSAPI]: error -2
> (Local error)
> [23/Jul/2015:07:33:21 +0200] set_krb5_creds - Could not get initial
> credentials for principal [ldap/ipa@] in keytab
> [FILE:/etc/dirsrv/ds.keytab]: -1765328203 (Key table entry not found)
> [23/Jul/2015:07:33:21 +0200] slapd_ldap_sasl_interactive_bind - Error:
> could not perform interactive bind for id [] mech [GSSAPI]: LDAP error
> -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified
> GSS failure.  Minor code may provide more information (No Kerberos
> credentials available)) errno 0 (Success)
> [23/Jul/2015:07:33:21 +0200] slapi_ldap_bind - Error: could not perform
> interactive bind for id [] authentication mechanism [GSSAPI]: error -2
> (Local error)
> [23/Jul/2015:07:33:33 +0200] set_krb5_creds - Could not get initial
> credentials for principal [ldap/ipa@] in keytab
> [FILE:/etc/dirsrv/ds.keytab]: -1765328203 (Key table entry not found)
> [23/Jul/2015:07:33:33 +0200] slapd_ldap_sasl_interactive_bind - Error:
> could not perform interactive bind for id [] mech [GSSAPI]: LDAP error
> -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified
> GSS failure.  Minor code may provide more information (No Kerberos
> credentials available)) errno 0 (Success)
> [23/Jul/2015:07:33:33 +0200] slapi_ldap_bind - Error: could not perform
> interactive bind for id [] authentication mechanism [GSSAPI]: error -2
> (Local error)
> [23/Jul/2015:07:33:57 +0200] set_krb5_creds - Could not get initial
> credentials for principal [ldap/ipa@] in keytab
> [FILE:/etc/dirsrv/ds.keytab]: -1765328203 (Key table entry not found)
> [23/Jul/2015:07:33:57 +0200] slapd_ldap_sasl_interactive_bind - Error:
> could not perform interactive bind for id [] mech [GSSAPI]: LDAP error
> -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified
> GSS failure.  Minor code may provide more information (No Kerberos
> credentials available)) errno 0 (Success)
> [23/Jul/2015:07:33:57 +0200] slapi_ldap_bind - Error: could not perform
> interactive bind for id [] authentication mechanism [GSSAPI]: error -2
> (Local error)
> [23/Jul/2015:07:34:45 +0200] set_krb5_creds - Could not get initial
> credentials for principal [ldap/ipa@] in keytab
> [FILE:/etc/dirsrv/ds.keytab]: -1765328203 (Key table entry not found)
> [23/Jul/2015:07:34:45 +0200] slapd_ldap_sasl_interactive_bind - Error:
> could not perform interactive bind for id [] mech [GSSAPI]: LDAP error
> -2 (Local error) (SASL(-1): generic failure: GSSAPI Error: Unspecified
> GSS failure.  Minor code may provide more information (No Kerberos
> credentials available)) errno 0 (Success)
> [23/Jul/2015:07:34:45 +0200] slapi_ldap_bind - Error: could not perform
> interactive bind for id [] authentication mechanism [GSSAPI]: error -2
> (Local error)
>
> attached is the strace of slapd as instructed earlier.

Thanks.  This was taken during slapd unresponsive?  The server does not 
appear to be under a load at all.  It is almost completely idle except 
for a thread sending replication updates.

I think we need a better test for slapd being unresponsive, so we can 
narrow the problem down to slapd or something else.  When the directory 
server appears to be hung, try this:

# ldapsearch -xLLL -D "cn=directory manager" -W -s base -b 
"dc=uni-wuppertal,dc=de"

This search should return immediately.  If it hangs, then the problem is 
in slapd, and get a stack trace as before.

>
> I am really a bit lost. Even though we have deployed two IPA servers,
> the whole site is down about twice a day with authentication problems.
>
> Hope anybody can help.
>
> Best regards,
>
>    Torsten
>
>
>
>
>
>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20150723/27c877f9/attachment.htm>