Hi Florence,
On Mon, 7 Jan 2019, Florence Blanc-Renaud wrote:
[...]
i shaved this thread a little, since it gets confusing. Hope i kept the
interesting bits.
The errors related to "Unable to find request for serial xxx" mean
that the cert is tracked by certmonger, but there is no corresponding
LDAP entry cn=xxx,ou=ca,ou=requests,o=ipaca on the local LDAP server.
Is the replication still working between your two masters?
"ipa cert-show" broken on ipa2 often points to an out-of-date
certificate in /var/lib/ipa/ra-agent.{pem|key}. The content should be
the same as on the renewal master, and also the same as in the entry
uid=ipara,ou=People,o=ipaca (which should be replicated and identical
on all the masters, except if you have replication issues).
Replication appeared to be working, however, I did server maintenance
today, ipa1 and ipa2 got upgraded and rebooted. ipa1 works fine, ipa2
does not come up properly:
--- ipa2
$ ipactl status
Directory Service: RUNNING
krb5kdc Service: STOPPED
kadmin Service: STOPPED
You need to have a look at krb5 logs to understand why kerberos failed to
start. Please check https://www.freeipa.org/page/Troubleshooting/Kerberos
for more information.
Turns out that kerberos starts when started manually with systemctl:
---
$ ipactl status
Directory Service: RUNNING
krb5kdc Service: RUNNING
kadmin Service: RUNNING
httpd Service: RUNNING
ipa-custodia Service: RUNNING
ntpd Service: RUNNING
pki-tomcatd Service: RUNNING
ipa-otpd Service: STOPPED
ipa: INFO: The ipactl command was successful
---
Kerberos log:
---
[...]
: NEEDED_PREAUTH: ad...@example.com for krbtgt/example....@example.com,
Additional pre-authentication required
Jan 08 10:39:22 ipa2.example.com krb5kdc[21691](info): closing down fd 11
Jan 08 10:39:39 ipa2.example.com krb5kdc[21692](info): AS_REQ (8 etypes
{18 17 20 19 16 23 25 26}) 141.51.x.y: ISSUE: authtime 1546940379, etypes
{rep=18 tkt=18 ses=18}, ad...@example.com for
krbtgt/example....@example.com
Jan 08 10:39:39 ipa2.example.com krb5kdc[21692](info): closing down fd 11
Jan 08 10:40:32 ipa2.example.com krb5kdc[21692](info): TGS_REQ (8 etypes
{18 17 20 19 16 23 25 26}) 141.51.x.y: ISSUE: authtime 1546940379, etypes
{rep=18 tkt=18 ses=18}, ad...@example.com for
HTTP/ipa2.example....@example.com
Jan 08 10:40:32 ipa2.example.com krb5kdc[21692](info): closing down fd 11
---
httpd Service: RUNNING
ipa-custodia Service: STOPPED
ntpd Service: RUNNING
pki-tomcatd Service: RUNNING
ipa-otpd Service: STOPPED
ipa: INFO: The ipactl command was successful
---
--- ipa1
$ openssl x509 -in /var/lib/ipa/ra-agent.pem -text -noout | grep Serial
Serial Number: 268304391 (0xffe0007)
$ ldapsearch -x -b uid=ipara,ou=People,o=ipaca
[...]
description: 2;268304391;CN=Certificate Authority,O=EXAMPLE.COM;CN=IPA
RA,O=EXAMPLE.COM
---
Looks good.
--- ipa2
$ openssl x509 -in /var/lib/ipa/ra-agent.pem -text -noout | grep Serial
Serial Number: 268304391 (0xffe0007)
$ ldapsearch -x -b uid=ipara,ou=People,o=ipaca
[...]
description: 2;44;CN=Certificate Authority,O=EXAMPLE.COM;CN=IPA
RA,O=EXAMPLE.COM
---
Looks bad.
So yes, the replication of the suffix o=ipaca seems broken. In a
deployment with CA, the ldap server contains 2 different suffixes, one
for the IdM data (your base DN as defined in /etc/ipa/default.conf) and
another one for the CA, below o=ipaca.
You can have a look at
https://www.freeipa.org/page/Troubleshooting/Directory_Server for
replication troubleshooting, but the repl issue could be a consequence of
kerberos server not starting.
I checked the troubleshooting pages and carried out the steps described in
there, but my system (ipa2) appears to be ok as far as the steps go.
--- /var/log/ipaupgrade.log
[...]
2018-12-28T10:55:53Z DEBUG The ipa-server-upgrade command failed,
exception: RemoteRetrieveError: Failed to authenticate to CA REST API
---
--- /var/log/dirsrv/slapd-EXAMPLE-COM/errors
[...]
[28/Dec/2018:11:55:55.559648469 +0100] - ERR - set_krb5_creds - Could
not
get initial credentials for principal
[ldap/ipa2.example....@example.com]
in keytab [FILE:/etc/dirsrv/ds.keytab]: -1765328228 (Cannot contact any
KDC for requested realm)
---
--- ipa-checkcerts.py
[...]
ipa: ERROR: ra.get_certificate(): EXCEPTION (Invalid Credential.)
ra.get_certificate(): EXCEPTION (Invalid Credential.)
ipa: INFO: Checking permissions and ownership
Checking permissions and ownership
ipa: INFO: Failures:
Failures:
ipa: INFO: Unable to find request for serial 268304391
Unable to find request for serial 268304391
ipa: INFO: Unable to find request for serial 268304394
Unable to find request for serial 268304394
ipa: INFO: Unable to find request for serial 268304393
Unable to find request for serial 268304393
ipa: INFO: Unable to find request for serial 268304392
Unable to find request for serial 268304392
ipa: INFO: Unable to find request for serial 268304390
Unable to find request for serial 268304390
ipa: INFO: RA agent description does not match 2;44;CN=Certificate
Authority,O=EXAMPLE.COM;CN=IPA RA,O=EXAMPLE.COM in LDAP and
2;268304391;CN=Certificate Authority,O=EXAMPLE.COM;CN=IPA
RA,O=EXAMPLE.COM
expected
ipa: INFO: RA agent certificate not found in LDAP RA agent certificate
not
found in LDAP
[...]
---
The root cause appears to be the wrong IPA RA certificate in ipa2's
LDAP, right? I guess this has to fixed by manually importing the
proper certificate using ldapmodify, similar to the procedure
described in [1]?
It is possible to manually modify the IPA RA cert in ipa2's ldap server
but this won't solve the replication issue. It will however allow you to
run ipa cert-show.
Unfortunately, it doesn't (ipa2):
---
ipa: ERROR: Certificate operation cannot be completed: EXCEPTION (Invalid
Credential.)
---
Kerberos log:
---
Jan 08 15:42:45 ipa2.example.com krb5kdc[23520](info): AS_REQ (8 etypes
{18 17 16 23 20 19 25 26}) 141.51.124.20: NEEDED_PREAUTH:
host/ipa2.example....@example.com for krbtgt/example....@example.com,
Additional pre-authentication required
---
Works ok on ipa1.
I'm unsure how to proceed here. My obvious problem is ipa2 not getting
upgraded properly:
---
[...]
2019-01-08T09:46:07Z INFO [Updating HTTPD service IPA configuration]
2019-01-08T09:46:07Z DEBUG Starting external process
2019-01-08T09:46:07Z DEBUG args=/usr/sbin/selinuxenabled
2019-01-08T09:46:07Z DEBUG Process finished, return code=1
2019-01-08T09:46:07Z DEBUG stdout=
2019-01-08T09:46:07Z DEBUG stderr=
2019-01-08T09:46:07Z DEBUG Starting external process
2019-01-08T09:46:07Z DEBUG args=/bin/systemctl --system daemon-reload
2019-01-08T09:46:07Z DEBUG Process finished, return code=0
2019-01-08T09:46:07Z DEBUG stdout=
2019-01-08T09:46:07Z DEBUG stderr=
2019-01-08T09:46:07Z INFO [Updating HTTPD service IPA WSGI configuration]
2019-01-08T09:46:07Z INFO Nothing to do for configure_httpd_wsgi_conf
2019-01-08T09:46:07Z INFO [Updating mod_nss protocol versions]
2019-01-08T09:46:07Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:07Z INFO Protocol versions already updated
2019-01-08T09:46:07Z INFO [Updating mod_nss cipher suite]
2019-01-08T09:46:07Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:07Z DEBUG Cipher suite already updated
2019-01-08T09:46:07Z INFO [Updating mod_nss enabling OCSP]
2019-01-08T09:46:07Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:07Z INFO [Fixing trust flags in /etc/httpd/alias]
2019-01-08T09:46:07Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:07Z INFO Trust flags already processed
2019-01-08T09:46:07Z INFO [Moving HTTPD service keytab to gssproxy]
2019-01-08T09:46:07Z DEBUG Starting external process
2019-01-08T09:46:07Z DEBUG args=/usr/sbin/selinuxenabled
2019-01-08T09:46:07Z DEBUG Process finished, return code=1
2019-01-08T09:46:07Z DEBUG stdout=
2019-01-08T09:46:07Z DEBUG stderr=
2019-01-08T09:46:07Z DEBUG Starting external process
2019-01-08T09:46:07Z DEBUG args=/bin/systemctl restart gssproxy.service
2019-01-08T09:46:07Z DEBUG Process finished, return code=0
2019-01-08T09:46:07Z DEBUG stdout=
2019-01-08T09:46:07Z DEBUG stderr=
2019-01-08T09:46:07Z DEBUG Starting external process
2019-01-08T09:46:07Z DEBUG args=/bin/systemctl is-active gssproxy.service
2019-01-08T09:46:07Z DEBUG Process finished, return code=0
2019-01-08T09:46:07Z DEBUG stdout=active
2019-01-08T09:46:07Z DEBUG stderr=
2019-01-08T09:46:07Z DEBUG Restart of gssproxy.service complete
2019-01-08T09:46:07Z DEBUG Starting external process
2019-01-08T09:46:07Z DEBUG args=/bin/systemctl start httpd.service
2019-01-08T09:46:09Z DEBUG Process finished, return code=0
2019-01-08T09:46:09Z DEBUG stdout=
2019-01-08T09:46:09Z DEBUG stderr=
2019-01-08T09:46:09Z DEBUG Starting external process
2019-01-08T09:46:09Z DEBUG args=/bin/systemctl is-active httpd.service
2019-01-08T09:46:09Z DEBUG Process finished, return code=0
2019-01-08T09:46:09Z DEBUG stdout=active
2019-01-08T09:46:09Z DEBUG stderr=
2019-01-08T09:46:09Z DEBUG Start of httpd.service complete
2019-01-08T09:46:09Z INFO [Removing self-signed CA]
2019-01-08T09:46:09Z DEBUG Self-signed CA is not installed
2019-01-08T09:46:09Z INFO [Removing Dogtag 9 CA]
2019-01-08T09:46:09Z DEBUG Dogtag is version 10 or above
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysrestore/sysrestore.state'
2019-01-08T09:46:09Z DEBUG Loading Index file from
'/var/lib/ipa/sysrestore/sysrestore.index'
2019-01-08T09:46:09Z INFO [Checking for deprecated KDC configuration
files]
2019-01-08T09:46:09Z INFO [Checking for deprecated backups of Samba
configuration files]
2019-01-08T09:46:09Z DEBUG raw: ca_is_enabled(version=u'2.229')
2019-01-08T09:46:09Z DEBUG ca_is_enabled(version=u'2.229')
2019-01-08T09:46:09Z DEBUG flushing
ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket from SchemaCache
2019-01-08T09:46:09Z DEBUG retrieving schema for SchemaCache
url=ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket
conn=<ldap.ldapobject.SimpleLDAPObject instance at 0x7f8d6ccff5a8>
2019-01-08T09:46:09Z DEBUG raw: kra_is_enabled(version=u'2.229')
2019-01-08T09:46:09Z DEBUG kra_is_enabled(version=u'2.229')
2019-01-08T09:46:09Z DEBUG Cleaning up after pkispawn for the CA subsystem
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysrestore/sysrestore.state'
2019-01-08T09:46:09Z DEBUG Loading Index file from
'/var/lib/ipa/sysrestore/sysrestore.index'
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysrestore/sysrestore.state'
2019-01-08T09:46:09Z INFO [Add missing CA DNS records]
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:09Z INFO IPA CA DNS records already processed
2019-01-08T09:46:09Z INFO [Removing deprecated DNS configuration options]
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z INFO [Ensuring minimal number of connections]
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z INFO [Updating GSSAPI configuration in DNS]
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z INFO [Updating pid-file configuration in DNS]
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysrestore/sysrestore.state'
2019-01-08T09:46:09Z DEBUG Loading Index file from
'/var/lib/ipa/sysrestore/sysrestore.index'
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysrestore/sysrestore.state'
2019-01-08T09:46:09Z DEBUG Loading Index file from
'/var/lib/ipa/sysrestore/sysrestore.index'
2019-01-08T09:46:09Z INFO DNS is not configured
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysrestore/sysrestore.state'
2019-01-08T09:46:09Z DEBUG Loading Index file from
'/var/lib/ipa/sysrestore/sysrestore.index'
2019-01-08T09:46:09Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:09Z INFO [Upgrading CA schema]
2019-01-08T09:46:10Z DEBUG Processing schema LDIF file
/usr/share/pki/server/conf/schema-certProfile.ldif
2019-01-08T09:46:10Z DEBUG Processing schema LDIF file
/usr/share/pki/server/conf/schema-authority.ldif
2019-01-08T09:46:10Z DEBUG Not updating schema
2019-01-08T09:46:10Z INFO CA schema update complete (no changes)
2019-01-08T09:46:10Z INFO [Verifying that CA audit signing cert has 2 year
validity]
2019-01-08T09:46:10Z DEBUG caSignedLogCert.cfg profile validity range is
720
2019-01-08T09:46:10Z INFO [Update certmonger certificate renewal
configuration]
2019-01-08T09:46:10Z DEBUG Loading Index file from
'/var/lib/ipa/sysrestore/sysrestore.index'
2019-01-08T09:46:10Z DEBUG Starting external process
2019-01-08T09:46:10Z DEBUG args=/usr/bin/certutil -d dbm:/etc/httpd/alias
-L -n Server-Cert -a -f /etc/httpd/alias/pwdfile.txt
2019-01-08T09:46:10Z DEBUG Process finished, return code=0
2019-01-08T09:46:10Z DEBUG stdout=-----BEGIN CERTIFICATE-----
MIIFYjCCBEqgAwIBAgIED/4ABTANBgkqhkiG9w0BAQsFADBHMSUwIwYDVQQKExxE
[...]
Serial Number: 268304389 (0xffe0005)
[...]
n7aRLXFxWB8va5AxibMHYUJb08nWJRqHHwufF/YQnJdskFuDyAM=
-----END CERTIFICATE-----
2019-01-08T09:46:10Z DEBUG stderr=
2019-01-08T09:46:10Z DEBUG Loading Index file from
'/var/lib/ipa/sysrestore/sysrestore.index'
2019-01-08T09:46:10Z DEBUG Starting external process
2019-01-08T09:46:10Z DEBUG args=/usr/bin/certutil -d
dbm:/etc/dirsrv/slapd-EXAMPLE-COM/ -L -n Server-Cert -a -f
/etc/dirsrv/slapd-EXAMPLE-COM/pwdfile.txt
2019-01-08T09:46:10Z DEBUG Process finished, return code=0
2019-01-08T09:46:10Z DEBUG stdout=-----BEGIN CERTIFICATE-----
MIIFYjCCBEqgAwIBAgIED/4ABDANBgkqhkiG9w0BAQsFADBHMSUwIwYDVQQKExxE
[...]
Serial Number: 268304388 (0xffe0004)
[...]
7D6pk95Rgq6g73cZmogJBfJicVF0odkf2VkvV/aJCxTtZ4xkVds=
-----END CERTIFICATE-----
2019-01-08T09:46:10Z DEBUG stderr=
2019-01-08T09:46:10Z DEBUG Loading Index file from
'/var/lib/ipa/sysrestore/sysrestore.index'
2019-01-08T09:46:10Z DEBUG Starting external process
2019-01-08T09:46:10Z DEBUG args=/usr/bin/certutil -d
dbm:/etc/pki/pki-tomcat/alias -L -f /etc/pki/pki-tomcat/alias/pwdfile.txt
2019-01-08T09:46:10Z DEBUG Process finished, return code=0
2019-01-08T09:46:10Z DEBUG stdout=
Certificate Nickname Trust
Attributes
SSL,S/MIME,JAR/XPI
ocspSigningCert cert-pki-ca u,u,u
caSigningCert cert-pki-ca CTu,Cu,Cu
Server-Cert cert-pki-ca u,u,u
auditSigningCert cert-pki-ca u,u,Pu
subsystemCert cert-pki-ca u,u,u
2019-01-08T09:46:10Z DEBUG stderr=
2019-01-08T09:46:11Z INFO Certmonger certificate renewal configuration
already up-to-date
2019-01-08T09:46:11Z INFO [Enable PKIX certificate path discovery and
validation]
2019-01-08T09:46:11Z DEBUG Loading StateFile from
'/var/lib/ipa/sysupgrade/sysupgrade.state'
2019-01-08T09:46:11Z INFO PKIX already enabled
2019-01-08T09:46:11Z INFO [Authorizing RA Agent to modify profiles]
2019-01-08T09:46:11Z INFO [Authorizing RA Agent to manage lightweight CAs]
2019-01-08T09:46:11Z INFO [Ensuring Lightweight CAs container exists in
Dogtag database]
2019-01-08T09:46:11Z DEBUG Created connection
context.ldap2_140245392902928
2019-01-08T09:46:11Z DEBUG flushing
ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket from SchemaCache
2019-01-08T09:46:11Z DEBUG retrieving schema for SchemaCache
url=ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket
conn=<ldap.ldapobject.SimpleLDAPObject instance at 0x7f8d6cea4fc8>
2019-01-08T09:46:12Z DEBUG Destroyed connection
context.ldap2_140245392902928
2019-01-08T09:46:12Z INFO [Adding default OCSP URI configuration]
2019-01-08T09:46:12Z INFO [Ensuring CA is using LDAPProfileSubsystem]
2019-01-08T09:46:12Z INFO [Migrating certificate profiles to LDAP]
2019-01-08T09:46:12Z DEBUG Created connection
context.ldap2_140245366754832
2019-01-08T09:46:12Z DEBUG flushing
ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket from SchemaCache
2019-01-08T09:46:12Z DEBUG retrieving schema for SchemaCache
url=ldapi://%2fvar%2frun%2fslapd-EXAMPLE-COM.socket
conn=<ldap.ldapobject.SimpleLDAPObject instance at 0x7f8d6b5db128>
2019-01-08T09:46:12Z DEBUG Destroyed connection
context.ldap2_140245366754832
2019-01-08T09:46:12Z DEBUG request GET
https://ipa2.example.com:8443/ca/rest/account/login
2019-01-08T09:46:12Z DEBUG request body ''
2019-01-08T09:46:12Z DEBUG response status 401
2019-01-08T09:46:12Z DEBUG response headers Server: Apache-Coyote/1.1
Cache-Control: private
Expires: Thu, 01 Jan 1970 01:00:00 CET
WWW-Authenticate: Basic realm="Certificate Authority"
Content-Type: text/html;charset=utf-8
Content-Language: en
Content-Length: 951
Date: Tue, 08 Jan 2019 09:46:12 GMT
2019-01-08T09:46:12Z DEBUG response body '<html> [...] HTTP Status 401
[...] message [...] This request requires HTTP authentication. [...]
</html>'
2019-01-08T09:46:12Z ERROR IPA server upgrade failed: Inspect
/var/log/ipaupgrade.log and run command ipa-server-upgrade manually.
2019-01-08T09:46:12Z DEBUG File
"/usr/lib/python2.7/site-packages/ipapython/admintool.py", line 178, in
execute
return_value = self.run()
File
"/usr/lib/python2.7/site-packages/ipaserver/install/ipa_server_upgrade.py",
line 54, in run
server.upgrade()
File
"/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py",
line 2085, in upgrade
upgrade_configuration()
File
"/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py",
line 1952, in upgrade_configuration
ca_enable_ldap_profile_subsystem(ca)
File
"/usr/lib/python2.7/site-packages/ipaserver/install/server/upgrade.py",
line 396, in ca_enable_ldap_profile_subsystem
cainstance.migrate_profiles_to_ldap()
File
"/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line
1814, in migrate_profiles_to_ldap
_create_dogtag_profile(profile_id, profile_data, overwrite=False)
File
"/usr/lib/python2.7/site-packages/ipaserver/install/cainstance.py", line
1820, in _create_dogtag_profile
with api.Backend.ra_certprofile as profile_api:
File "/usr/lib/python2.7/site-packages/ipaserver/plugins/dogtag.py",
line 1302, in __enter__
raise errors.RemoteRetrieveError(reason=_('Failed to authenticate to
CA REST API'))
2019-01-08T09:46:12Z DEBUG The ipa-server-upgrade command failed,
exception: RemoteRetrieveError: Failed to authenticate to CA REST API
2019-01-08T09:46:12Z ERROR Unexpected error - see /var/log/ipaupgrade.log
for details: RemoteRetrieveError: Failed to authenticate to CA REST API
2019-01-08T09:46:12Z ERROR The ipa-server-upgrade command failed. See
/var/log/ipaupgrade.log for more information
---
