freeipa

#7044 IPA Server Problem after upgrading from Fedora 23-->25
Closed: insufficientinfo Opened by dntosas.

Closed: insufficientinfo
Reopen Issue

Hello World!

I got an installation with FreeIPA server 4.2.4 in Fedora 23 and all worked fine

I decided to upgrade to Fedora 25 via dnf-upgrade-plugin

All the upgrade proc goes smooth and as a result my freeipa* rpm packages also upgraded
(from 4.2.4 to 4.4.4)

Now, the problem is that nothing works now.

Tried the command "ipa-server-upgrade" and the result is:

IPA server upgrade failed: Inspect /var/log/ipaupgrade.log and run command
ipa-server-upgrade manually.
Timeout exceeded
The ipa-server-upgrade command failed. See /var/log/ipaupgrade.log for more information

Tailing the appropriate logs has these results:

  • /var/log/ipaupgrade.log
2017-06-29T14:55:06Z DEBUG duration: 0 seconds
2017-06-29T14:55:06Z DEBUG [10/10]: starting directory server
2017-06-29T14:55:06Z DEBUG Starting external process
2017-06-29T14:55:06Z DEBUG args=/bin/systemctl start dirsrv(a)xxx.service
2017-06-29T14:55:09Z DEBUG Process finished, return code=0
2017-06-29T14:55:09Z DEBUG stdout=
2017-06-29T14:55:09Z DEBUG stderr=
2017-06-29T14:55:09Z DEBUG Starting external process
2017-06-29T14:55:09Z DEBUG args=/bin/systemctl is-active dirsrv(a)xxx.service
2017-06-29T14:55:09Z DEBUG Process finished, return code=0
2017-06-29T14:55:09Z DEBUG stdout=active
2017-06-29T14:55:09Z DEBUG stderr=
2017-06-29T14:55:09Z DEBUG wait_for_open_ports: localhost [389] timeout 300
  • /var/log/dirsrv/.../errors.log
[29/Jun/2017:17:57:21.091850887 +0300] slapi_ldap_bind - Error: could not send startTLS
request: error -1 (Can't contact LDAP server) errno 110 (Connection timed out)
[29/Jun/2017:17:58:18.114145058 +0300] slapi_ldap_bind - Error: could not send startTLS
request: error -1 (Can't contact LDAP server) errno 107 (Transport endpoint is not
connected)
[29/Jun/2017:17:58:42.135719951 +0300] slapi_ldap_bind - Error: could not send startTLS
request: error -1 (Can't contact LDAP server) errno 110 (Connection timed out)
[29/Jun/2017:18:01:30.160763487 +0300] slapi_ldap_bind - Error: could not send startTLS
request: error -1 (Can't contact LDAP server) errno 107 (Transport endpoint is not
connected)
[29/Jun/2017:18:01:54.183552684 +0300] slapi_ldap_bind - Error: could not send startTLS
request: error -1 (Can't contact LDAP server) errno 110 (Connection timed out)
  • /var/log/krb5kdc.log
Jun 29 17:54:08 ipa1.srv.xxx.com krb5kdc[1335](info): AS_REQ (6 etypes {18 17 16 23 25
26}) x.x.x.x: ISSUE: authtime 1498748048, etypes {rep=18 tkt=18 ses=18},
ldap/ipa1.srv.xxx.com(a)SRV.xxx.COM for krbtgt/SRV.xxx.COM(a)SRV.xxx.COM
Jun 29 17:54:08 ipa1.srv.xxx.com krb5kdc[1335](info): closing down fd 4
Jun 29 17:55:08 ipa1.srv.xxx.com krb5kdc[1335](info): AS_REQ (6 etypes {18 17 16 23 25
26}) x.x.x.x: LOOKING_UP_CLIENT: ldap/ipa1.srv.xxx.com(a)SRV.xxx.COM for
krbtgt/SRV.xxx.COM(a)SRV.xxx.COM, Server error
Jun 29 17:55:08 ipa1.srv.xxx.com krb5kdc[1335](info): closing down fd 4
Jun 29 17:55:08 ipa1.srv.xxx.com krb5kdc[1335](info): AS_REQ (6 etypes {18 17 16 23 25
26}) x.x.x.x: LOOKING_UP_CLIENT: ldap/ipa1.srv.xxx.com(a)SRV.xxx.COM for
krbtgt/SRV.xxx.COM(a)SRV.xxx.COM, Server error
Jun 29 17:55:08 ipa1.srv.xxx.com krb5kdc[1335](info): closing down fd 4
Jun 29 17:55:24 ipa1.srv.xxx.com krb5kdc[1335](info): AS_REQ (6 etypes {18 17 16 23 25
26}) x.x.x.x: NEEDED_PREAUTH: ldap/ipa1.srv.xxx.com(a)SRV.xxx.COM for
krbtgt/SRV.xxx.COM(a)SRV.xxx.COM, Additional pre-authentication required
Jun 29 17:55:24 ipa1.srv.xxx.com krb5kdc[1335](info): closing down fd 4
Jun 29 17:55:24 ipa1.srv.xxx.com krb5kdc[1335](info): AS_REQ (6 etypes {18 17 16 23 25
26}) x.x.x.x: ISSUE: authtime 1498748124, etypes {rep=18 tkt=18 ses=18},
ldap/ipa1.srv.xxx.com(a)SRV.xxx.COM for krbtgt/SRV.xxx.COM(a)SRV.xxx.COM
Jun 29 17:55:24 ipa1.srv.xxx.com krb5kdc[1335](info): closing down fd 4

I think the problem may occure because slapd doesnt working properly after fedora upgrade

I have tried different ways of making command "ipa-server-upgrade" complete its
job but nothing worked.

Any Ideas ? :(

Thank you in advance :)

From dirsrv logs, we can see periodic failure to contact a remote server.
It could be a problem of replication agreement failing to bind.
Would you enable replication loglevel (http://www.port389.org/docs/389ds/FAQ/faq.html#Troubleshooting) to capture more logs and hopefully know which server it tries to connect to.

It is possible that one of the server, it is trying to connect to, crashed. Would you check in the various /var/log/audit/audit.log if 'ns-slapd' crashed ? (ausearch -c ns-slapd)

Thank you tbordaz, trying right now what you are suggesting :)

The truth is that there is a replica configured between 3 machines

They are all crashed at the moment

So, i'm working at the master node and after that i was hoping to manage re-initiate replicas

ipa1 tries to connect itself and then to ipa2 and ipa3

here are the logs:

[29/Jun/2017:17:37:51.151136660 +0300] set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.srv.xxx.com@SRV.xxx.COM] in keytab [FILE:/etc/dirsrv/ds.keytab]: 2 (No such file or directory)
[29/Jun/2017:17:32:51.722394533 +0300] set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.srv.xxx.com@SRV.xxx.COM] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm)
[29/Jun/2017:17:32:51.727786451 +0300] set_krb5_creds - Could not get initial credentials for principal [ldap/ipa1.srv.xxx.com@SRV.xxx.COM] in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any KDC for requested realm)

[29/Jun/2017:17:21:30.207267050 +0300] NSMMReplicationPlugin - agmt="cn=masterAgreement1-ipa2.srv.xxx.com-pki-tomcat" (ipa2:389): Replication bind with SIMPLE auth failed: LDAP error -1 (Can't contact LDAP server) ()
[29/Jun/2017:17:21:30.416202948 +0300] NSMMReplicationPlugin - agmt="cn=meToipa2.srv.xxx.com" (ipa2:389): Replication bind with GSSAPI auth failed: LDAP error -1 (Can't contact LDAP server) ()

[29/Jun/2017:17:21:30.425182684 +0300] NSMMReplicationPlugin - agmt="cn=masterAgreement1-ipa3.srv.xxx.com-pki-tomcat" (ipa3:389): Replication bind with SIMPLE auth failed: LDAP error -1 (Can't contact LDAP server) ()
[29/Jun/2017:17:21:30.566548995 +0300] NSMMReplicationPlugin - agmt="cn=meToipa3.srv.xxx.com" (ipa3:389): Replication bind with GSSAPI auth failed: LDAP error -1 (Can't contact LDAP server) ()

Note also, that file /etc/dirsrv/ds.keytab exists and i also gave it 777 permissions for debuging reasons but no changes to errors atm.
Edited by dntosas

ds.keytab rights should be something like:

-rw-------. 1 dirsrv dirsrv 630 Jun 29 12:10 /etc/dirsrv/ds.keytab

Are you running in SELinux permissive mode ?

SELinux is Disabled

SELinux status:                 disabled

UPGRADE

I enabled copr repo and updated to IPA 4.5.2

Now the ipa-server-upgrade stucks at this point:

[root@ipa1 ~]# ipa-server-upgrade
Upgrading IPA:. Estimated time: 1 minute 30 seconds
  [1/10]: stopping directory server
  [2/10]: saving configuration
  [3/10]: disabling listeners
  [4/10]: enabling DS global lock
  [5/10]: starting directory server
  [6/10]: updating schema
  [7/10]: upgrading server
  [8/10]: stopping directory server
  [9/10]: restoring configuration
  [10/10]: starting directory server
Done.
Update complete
Upgrading IPA services
Upgrading the configuration of the IPA services
[Verifying that root certificate is published]
[Migrate CRL publish directory]
CRL tree already moved
[Verifying that CA proxy configuration is correct]
DEBUG Failed to check CA status: cannot connect to 'http://ipa1.srv.xxx.com:8080/ca/admin/ca/getStatus': [Errno 111] Connection refused
2017-06-30T10:48:13Z DEBUG stderr=
2017-06-30T10:48:13Z DEBUG wait_for_open_ports: localhost [8080, 8443] timeout 300

Seems it cant take CA from tomcat

catalina output:

30-Jun-2017 13:51:26.796 WARNING [ContainerBackgroundProcessor[StandardEngine[Catalina]]] org.apache.catalina.core.ContainerBase.backgroundProcess Exception processing realm com.netscape.cms.tomcat.ProxyRealm@43dc0207 background process
 javax.ws.rs.ServiceUnavailableException: Subsystem unavailable
    at com.netscape.cms.tomcat.ProxyRealm.backgroundProcess(ProxyRealm.java:130)
    at org.apache.catalina.core.ContainerBase.backgroundProcess(ContainerBase.java:1154)
    at org.apache.catalina.core.StandardContext.backgroundProcess(StandardContext.java:5707)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1377)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1381)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.processChildren(ContainerBase.java:1381)
    at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1349)
    at java.lang.Thread.run(Thread.java:748)

I don't know if this is still valid ticket. Or if it was resolved, e.g. on users-list. Closing to test it.

Metadata Update from @pvoborni:
- Issue close_status updated to: insufficientinfo
- Issue status updated to: Closed (was: Open)

Maybe this helps someone in the future. I just ran into this issue on F26 - I thought some dnf updates were the problem. Not really. I had the latest packages for F26.

update-crypto-policies to FUTURE breaks this completely, output from /var/log/pki/pki-tomcat/ca/debug:

Internal Database Error encountered: Could not connect to LDAP server host [STRIPPED] port 636 Error netscape.ldap.LDAPException: Unable to create socket: org.mozilla.jss.ssl.SSLSocketException: org.mozilla.jss.ssl.SSLSocketExc
eption: SSL_ForceHandshake failed: (-12265) No cipher suites are present and enabled in this program. (-1)
at com.netscape.cmscore.dbs.DBSubsystem.init(DBSubsystem.java:676)
at com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:1172)
at com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:1078)
at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:570)
at com.netscape.certsrv.apps.CMS.init(CMS.java:188)
at com.netscape.certsrv.apps.CMS.start(CMS.java:1621)
at com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:114)
at javax.servlet.GenericServlet.init(GenericServlet.java:158)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:293)
at org.apache.catalina.security.SecurityUtil$1.run(SecurityUtil.java:290)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAsPrivileged(Subject.java:549)
at org.apache.catalina.security.SecurityUtil.execute(SecurityUtil.java:325)
at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:176)
at org.apache.catalina.security.SecurityUtil.doAsPrivilege(SecurityUtil.java:124)
at org.apache.catalina.core.StandardWrapper.initServlet(StandardWrapper.java:1215)
at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1140)
at org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:1027)
at org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:5038)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5348)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:145)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:753)
at org.apache.catalina.core.ContainerBase.access$000(ContainerBase.java:131)
at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:153)
at org.apache.catalina.core.ContainerBase$PrivilegedAddChild.run(ContainerBase.java:143)
at java.security.AccessController.doPrivileged(Native Method)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:727)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:717)
at org.apache.catalina.startup.HostConfig.deployDescriptor(HostConfig.java:621)
at org.apache.catalina.startup.HostConfig$DeployDescriptor.run(HostConfig.java:1835)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)

I've rolled back the crypto-policies back to DEFAULT, which resolved it for me, but... I love the update-crypto-policies approach, and FreeIPA should probably be fixed to support it on DEFAULT and FUTURE variants, if possible.

Not sure how this is related to the original issue but I'd recommend you open a ticket against dogtag reporting this, especially since you appear to have a pretty simple reproducer. https://pagure.io/dogtagpki/issues
Metadata
None
None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.