[Freeipa-users] IPA certificates expired, please help!
Rob Crittenden
rcritten at redhat.com
Thu Jul 21 16:23:44 UTC 2016
Linov Suresh wrote:
> The httpd_error log doesn't contain the part where `ipa cert-show 1` was
> run. If it is from the same time.
>
> *I am not sure about that, please see httpd_error when `ipa cert-show 1`
> was run*
The IPA API log isn't going to show much in this case.
Requests to the CA are proxied through IPA. The CA WAR is not running on
tomcat so when Apache tries to proxy the request tomcat returns a 404,
Not Found.
You need to start with the dogtag debug and selftest logs to see what is
going on. The logs are pretty verbose and can be challenging to read.
rob
>
> [root at caer ~]# *tail -f /var/log/httpd/error_log*
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: WSGI
> xmlserver_session.__call__:
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: found session cookie_id =
> bc2c7ed0eccd840dc266efaf9ece913c
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: found session data in
> cache with id=bc2c7ed0eccd840dc266efaf9ece913c
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
> xmlserver_session.__call__: session_id=bc2c7ed0eccd840dc266efaf9ece913c
> start_timestamp=2016-07-21T11:58:54 access_timestamp=2016-07-21T12:01:21
> expiration_timestamp=2016-07-21T12:18:54
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: storing ccache data into
> file "/var/run/ipa_memcached/krbcc_13554"
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: get_credential_times:
> principal=HTTP/caer.teloip.net at TELOIP.NET
> <mailto:caer.teloip.net at TELOIP.NET>, authtime=07/21/16 10:31:46,
> starttime=07/21/16 10:43:26, endtime=07/22/16 10:31:44,
> renew_till=12/31/69 19:00:00
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: get_credential_times:
> principal=HTTP/caer.teloip.net at TELOIP.NET
> <mailto:caer.teloip.net at TELOIP.NET>, authtime=07/21/16 10:31:46,
> starttime=07/21/16 10:43:26, endtime=07/22/16 10:31:44,
> renew_till=12/31/69 19:00:00
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: KRB5_CCache
> FILE:/var/run/ipa_memcached/krbcc_13554 endtime=1469197904 (07/22/16
> 10:31:44)
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
> set_session_expiration_time: duration_type=inactivity_timeout
> duration=1200 max_age=1469197604 expiration=1469118081.77
> (2016-07-21T12:21:21)
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: WSGI xmlserver.__call__:
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: Created connection
> context.ldap2
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: WSGI
> WSGIExecutioner.__call__:
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: raw: cert_show(u'1')
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: cert_show(u'1')
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: IPA: virtual verify
> retrieve certificate
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
> ipaserver.plugins.dogtag.ra.get_certificate()
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: https_request
> 'https://caer.teloip.net:443/ca/agent/ca/displayBySerial'
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: https_request post
> 'xml=true&serialNumber=1'
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: NSSConnection init
> caer.teloip.net <http://caer.teloip.net>
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: Connecting: 10.20.0.75:0
> <http://10.20.0.75:0>
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
> auth_certificate_callback: check_sig=True is_server=False
> *.*
> *.*
> *.*
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: approved_usage =
> SSLServer intended_usage = SSLServer
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: cert valid True for
> "CN=caer.teloip.net <http://caer.teloip.net>,O=TELOIP.NET
> <http://TELOIP.NET>"
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: handshake complete, peer
> = 10.20.0.75:443 <http://10.20.0.75:443>
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
> auth_certificate_callback: check_sig=True is_server=False
> *.*
> *.*
> *.*
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: approved_usage =
> SSLServer intended_usage = SSLServer
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: cert valid True for
> "CN=caer.teloip.net <http://caer.teloip.net>,O=TELOIP.NET
> <http://TELOIP.NET>"
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: handshake complete, peer
> = 10.20.0.75:443 <http://10.20.0.75:443>
> [Thu Jul 21 12:01:21 2016] [error] ipa: ERROR:
> ipaserver.plugins.dogtag.ra.get_certificate(): Unable to communicate
> with CMS (Not Found)
> [Thu Jul 21 12:01:21 2016] [error] ipa: INFO: admin at TELOIP.NET
> <mailto:admin at TELOIP.NET>: cert_show(u'1'): CertificateOperationError
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: response:
> CertificateOperationError: Certificate operation cannot be completed:
> Unable to communicate with CMS (Not Found)
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: Destroyed connection
> context.ldap2
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: reading ccache data from
> file "/var/run/ipa_memcached/krbcc_13554"
> [Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: store session:
> session_id=bc2c7ed0eccd840dc266efaf9ece913c
> start_timestamp=2016-07-21T11:58:54 access_timestamp=2016-07-21T12:01:21
> expiration_timestamp=2016-07-21T12:21:21
>
>
> Does `ipa cert-show` communicate with the same replica? Could be
> verified by `ipa -vv cert-show`
>
> *It's asking for the serial number of the certificate. If I give 64
> (serial number of ipaCert ), I get ipa: ERROR: Certificate operation
> cannot be completed: Unable to communicate with CMS (Not Found)*
>
> *[root at caer ~]# ipa -vv cert-show*
> ipa: DEBUG: importing all plugin modules in
> '/usr/lib/python2.6/site-packages/ipalib/plugins'...
> *.*
> *.*
> *.*
> ipa: DEBUG: stdout=ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;
> Domain=caer.teloip.net <http://caer.teloip.net>; Path=/ipa; Expires=Thu,
> 21 Jul 2016 16:25:32 GMT; Secure; HttpOnly
> ipa: DEBUG: stderr=
> ipa: DEBUG: found session_cookie in persistent storage for principal
> 'admin at TELOIP.NET <mailto:admin at TELOIP.NET>', cookie:
> 'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c; Domain=caer.teloip.net
> <http://caer.teloip.net>; Path=/ipa; Expires=Thu, 21 Jul 2016 16:25:32
> GMT; Secure; HttpOnly'
> ipa: DEBUG: setting session_cookie into context
> 'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;'
> ipa: INFO: trying https://caer.teloip.net/ipa/session/xml
> ipa: DEBUG: Created connection context.xmlclient
> Serial number: 64
> ipa: DEBUG: raw: cert_show(u'64')
> ipa: DEBUG: cert_show(u'64')
> ipa: INFO: Forwarding 'cert_show' to server
> u'https://caer.teloip.net/ipa/session/xml'
> ipa: DEBUG: NSSConnection init caer.teloip.net <http://caer.teloip.net>
> ipa: DEBUG: Connecting: 10.20.0.75:0 <http://10.20.0.75:0>
> send: u'POST /ipa/session/xml HTTP/1.0\r\nHost: caer.teloip.net
> <http://caer.teloip.net>\r\nAccept-Language: en-us\r\nReferer:
> https://caer.teloip.net/ipa/xml\r\nCookie:
> ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;\r\nUser-Agent:
> xmlrpclib.py/1.0.1 <http://xmlrpclib.py/1.0.1> (by www.pythonware.com
> <http://www.pythonware.com>)\r\nContent-Type:
> text/xml\r\nContent-Length: 268\r\n\r\n'
> ipa: DEBUG: auth_certificate_callback: check_sig=True is_server=False
> *.*
> *.*
> *.*
> ipa: DEBUG: approved_usage = SSLServer intended_usage = SSLServer
> ipa: DEBUG: cert valid True for "CN=caer.teloip.net
> <http://caer.teloip.net>,O=TELOIP.NET <http://TELOIP.NET>"
> ipa: DEBUG: handshake complete, peer = 10.20.0.75:443
> <http://10.20.0.75:443>
> send: "<?xml version='1.0'
> encoding='UTF-8'?>\n<methodCall>\n<methodName>cert_show</methodName>\n<params>\n<param>\n<value><array><data>\n<value><string>64</string></value>\n</data></array></value>\n</param>\n<param>\n<value><struct>\n</struct></value>\n</param>\n</params>\n</methodCall>\n"
> reply: 'HTTP/1.1 200 Success\r\n'
> header: Date: Thu, 21 Jul 2016 16:05:40 GMT
> header: Server: Apache/2.2.15 (CentOS)
> header: Set-Cookie: ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;
> Domain=caer.teloip.net <http://caer.teloip.net>; Path=/ipa; Expires=Thu,
> 21 Jul 2016 16:25:40 GMT; Secure; HttpOnly
> header: Connection: close
> header: Content-Type: text/xml; charset=utf-8
> ipa: DEBUG: received Set-Cookie
> 'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c; Domain=caer.teloip.net
> <http://caer.teloip.net>; Path=/ipa; Expires=Thu, 21 Jul 2016 16:25:40
> GMT; Secure; HttpOnly'
> ipa: DEBUG: storing cookie
> 'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c; Domain=caer.teloip.net
> <http://caer.teloip.net>; Path=/ipa; Expires=Thu, 21 Jul 2016 16:25:40
> GMT; Secure; HttpOnly' for principal admin at TELOIP.NET
> <mailto:admin at TELOIP.NET>
> ipa: DEBUG: args=keyctl search @s user
> ipa_session_cookie:admin at TELOIP.NET
> <mailto:ipa_session_cookie%3Aadmin at TELOIP.NET>
> ipa: DEBUG: stdout=457971704
>
> ipa: DEBUG: stderr=
> ipa: DEBUG: args=keyctl search @s user
> ipa_session_cookie:admin at TELOIP.NET
> <mailto:ipa_session_cookie%3Aadmin at TELOIP.NET>
> ipa: DEBUG: stdout=457971704
>
> ipa: DEBUG: stderr=
> ipa: DEBUG: args=keyctl pupdate 457971704
> ipa: DEBUG: stdout=
> ipa: DEBUG: stderr=
> body: "<?xml version='1.0'
> encoding='UTF-8'?>\n<methodResponse>\n<fault>\n<value><struct>\n<member>\n<name>faultCode</name>\n<value><int>4301</int></value>\n</member>\n<member>\n<name>faultString</name>\n<value><string>Certificate
> operation cannot be completed: Unable to communicate with CMS (Not
> Found)</string></value>\n</member>\n</struct></value>\n</fault>\n</methodResponse>\n"
> ipa: DEBUG: Caught fault 4301 from server
> https://caer.teloip.net/ipa/session/xml: Certificate operation cannot be
> completed: Unable to communicate with CMS (Not Found)
> ipa: DEBUG: Destroyed connection context.xmlclient
> ipa: ERROR: Certificate operation cannot be completed: Unable to
> communicate with CMS (Not Found)
> [root at caer ~]#
>
>
> But more interesting is: SelfTestSubsystem: The CRITICAL self test
> plugin called selftests.container.instance.SystemCertsVerification
> running at startup FAILED!
>
> Are you sure that CA is running?
> # ipactl status
> *Yes, CA is runnig, *
>
> *[root at caer ~]# ipactl status*
> Directory Service: RUNNING
> KDC Service: RUNNING
> KPASSWD Service: RUNNING
> DNS Service: RUNNING
> MEMCACHE Service: RUNNING
> HTTP Service: RUNNING
> CA Service: RUNNING
>
> This looks like that self test fail and therefore CA shouldn't start. It
> also says that some of CA cert is not valid. Which one might be seen in
> /var/log/pki-ca/debug but a bigger chunk would be needed.
>
> *[root at caer ~]# tail -100 /var/log/pki-ca/debug *
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: getConn: conn is
> connected true
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: getConn: mNumConns now 1
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: In
> findCertRecordsInListRawJumpto with Jumpto 20160721114829Z
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: In DBVirtualList filter
> attrs startFrom sortKey pageSize filter: (certStatus=REVOKED) attrs:
> [objectclass, certRevokedOn, certRecordId, certRevoInfo, notAfter,
> x509cert] pageSize -200 startFrom 20160721114829Z
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: returnConn: mNumConns now 2
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: returnConn: mNumConns now 3
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: getEntries returning 0
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: mTop 0
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Getting Virtual List size: 0
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: index may be empty
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: updateCertStatus done
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Starting cert checkRanges
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Serial numbers left in
> range: 268369849
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Last Serial Number: 71
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Serial Numbers
> available: 268369849
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: cert checkRanges done
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Starting request checkRanges
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Serial numbers left in
> range: 9989888
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Last Serial Number: 112
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: Serial Numbers
> available: 9989888
> [21/Jul/2016:11:48:29][CertStatusUpdateThread]: request checkRanges done
> [21/Jul/2016:11:53:28][Timer-0]: CMSEngine: getPasswordStore(): password
> store initialized before.
> [21/Jul/2016:11:53:28][Timer-0]: CMSEngine: getPasswordStore(): password
> store initialized.
> [21/Jul/2016:11:58:28][Timer-0]: CMSEngine: getPasswordStore(): password
> store initialized before.
> [21/Jul/2016:11:58:28][Timer-0]: CMSEngine: getPasswordStore(): password
> store initialized.
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: About to start
> updateCertStatus
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Starting
> updateCertStatus (entered lock)
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In updateCertStatus()
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> LdapBoundConnFactory::getConn()
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
> true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
> connected true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 2
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]:
> getInvalidCertificatesByNotBeforeDate filter (certStatus=INVALID)
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]:
> getInvalidCertificatesByNotBeforeDate: about to call findCertRecordsInList
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> LdapBoundConnFactory::getConn()
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
> true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
> connected true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 1
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> findCertRecordsInListRawJumpto with Jumpto 20160721115829Z
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In DBVirtualList filter
> attrs startFrom sortKey pageSize filter: (certStatus=INVALID) attrs:
> [objectclass, certRecordId, x509cert] pageSize -200 startFrom
> 20160721115829Z
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 2
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> getInvalidCertsByNotBeforeDate finally.
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 3
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getEntries returning 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: mTop 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Getting Virtual List size: 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: index may be empty
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> LdapBoundConnFactory::getConn()
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
> true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
> connected true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 2
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]:
> getValidCertsByNotAfterDate filter (certStatus=VALID)
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> LdapBoundConnFactory::getConn()
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
> true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
> connected true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 1
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> findCertRecordsInListRawJumpto with Jumpto 20160721115829Z
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In DBVirtualList filter
> attrs startFrom sortKey pageSize filter: (certStatus=VALID) attrs:
> [objectclass, certRecordId, x509cert] pageSize -200 startFrom
> 20160721115829Z
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 2
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 3
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getEntries returning 1
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: mTop 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Getting Virtual List
> size: 14
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]:
> transidValidCertificates: list size: 14
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]:
> transitValidCertificates: ltSize 1
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getElementAt: 0 mTop 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: reverse direction
> getting index 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Record does not
> qualify,notAfter Thu Jan 12 09:11:48 EST 2017 date Thu Jul 21 11:58:29
> EDT 2016
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: transitCertList EXPIRED
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> LdapBoundConnFactory::getConn()
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
> true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
> connected true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 2
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]:
> getRevokedCertificatesByNotAfterDate filter (certStatus=REVOKED)
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]:
> getRevokedCertificatesByNotAfterDate: about to call findCertRecordsInList
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> LdapBoundConnFactory::getConn()
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
> true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
> connected true
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 1
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
> findCertRecordsInListRawJumpto with Jumpto 20160721115829Z
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: In DBVirtualList filter
> attrs startFrom sortKey pageSize filter: (certStatus=REVOKED) attrs:
> [objectclass, certRevokedOn, certRecordId, certRevoInfo, notAfter,
> x509cert] pageSize -200 startFrom 20160721115829Z
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 2
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 3
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: getEntries returning 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: mTop 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Getting Virtual List size: 0
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: index may be empty
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: updateCertStatus done
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Starting cert checkRanges
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Serial numbers left in
> range: 268369849
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Last Serial Number: 71
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Serial Numbers
> available: 268369849
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: cert checkRanges done
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Starting request checkRanges
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Serial numbers left in
> range: 9989888
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Last Serial Number: 112
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: Serial Numbers
> available: 9989888
> [21/Jul/2016:11:58:29][CertStatusUpdateThread]: request checkRanges done
> [21/Jul/2016:12:03:28][Timer-0]: CMSEngine: getPasswordStore(): password
> store initialized before.
> [21/Jul/2016:12:03:28][Timer-0]: CMSEngine: getPasswordStore(): password
> store initialized.
>
> On Thu, Jul 21, 2016 at 11:46 AM, Petr Vobornik <pvoborni at redhat.com
> <mailto:pvoborni at redhat.com>> wrote:
>
> On 07/21/2016 05:14 PM, Linov Suresh wrote:
> > I set debug=true in /etc/ipa/default.conf
> >
> > Here are my logs,
>
> The httpd_error log doesn't contain the part where `ipa cert-show 1` was
> run. If it is from the same time. Does `ipa cert-show` communicate with
> the same replica? Could be verified by `ipa -vv cert-show`
>
> But more interesting is:
>
> SelfTestSubsystem: The CRITICAL self test plugin called
> selftests.container.instance.SystemCertsVerification running at startup
> FAILED!
>
> Are you sure that CA is running?
> # ipactl status
>
> This looks like that self test fail and therefore CA shouldn't start. It
> also says that some of CA cert is not valid. Which one might be seen in
> /var/log/pki-ca/debug but a bigger chunk would be needed.
>
> >
> > *[root at caer ~]# tail -f /var/log/httpd/error_log*
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: WSGI
> WSGIExecutioner.__call__:
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: raw:
> user_show(u'admin',
> > rights=False, all=False, raw=False, version=u'2.46')
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG:
> user_show(u'admin', rights=False,
> > all=False, raw=False, version=u'2.46')
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: get_memberof:
> > entry_dn=uid=admin,cn=users,cn=accounts,dc=teloip,dc=net
> >
> memberof=[ipapython.dn.DN('cn=admins,cn=groups,cn=accounts,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=replication
> > administrators,cn=privileges,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=add
> > replication agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=modify replication
> > agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=remove
> > replication agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=unlock user
> > accounts,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=manage
> > service keytab,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=trust
> admins,cn=groups,cn=accounts,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=host
> enrollment,cn=privileges,cn=pbac,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=manage host
> > keytab,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=enroll a
> > host,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=add host
> > password,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=add
> > krbprincipalname to a host,cn=permissions,cn=pbac,dc=teloip,dc=net')]
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: get_memberof: result
> >
> direct=[ipapython.dn.DN('cn=admins,cn=groups,cn=accounts,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=trust
> admins,cn=groups,cn=accounts,dc=teloip,dc=net')]
> > indirect=[ipapython.dn.DN('cn=replication
> > administrators,cn=privileges,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=add
> > replication agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=modify replication
> > agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=remove
> > replication agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=unlock user
> > accounts,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=manage
> > service keytab,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=host
> enrollment,cn=privileges,cn=pbac,dc=teloip,dc=net'),
> > ipapython.dn.DN('cn=manage host
> > keytab,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=enroll a
> > host,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=add host
> > password,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=add
> > krbprincipalname to a host,cn=permissions,cn=pbac,dc=teloip,dc=net')]
> > [Thu Jul 21 11:00:38 2016] [error] ipa: INFO: admin at TELOIP.NET
> <mailto:admin at TELOIP.NET>
> > <mailto:admin at TELOIP.NET <mailto:admin at TELOIP.NET>>:
> user_show(u'admin', rights=False, all=False,
> > raw=False, version=u'2.46'): SUCCESS
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: response: entries returned 1
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: Destroyed connection context.ldap2
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: reading ccache data from file
> > "/var/run/ipa_memcached/krbcc_13554"
> > [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: store session:
> > session_id=10c5de02f8ae0f3969b96ef0f2e3a96d start_timestamp=2016-07-21T10:43:26
> > access_timestamp=2016-07-21T11:00:38 expiration_timestamp=2016-07-21T11:20:38
> >
> > *[root at caer ~]# tail -f /var/log/pki-ca/debug*
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: RequestQueue: curReqId: 9990001
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: getElementAt: 1 mTop 107
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: reverse direction getting index 4
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: RequestQueue: curReqId: 112
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: RequestQueue: getLastRequestId :
> > returning value 112
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: Repository: mLastSerialNo: 112
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: Serial numbers left in range:
> > 9989888
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: Last Serial Number: 112
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: Serial Numbers available: 9989888
> > [21/Jul/2016:11:08:29][CertStatusUpdateThread]: request checkRanges done
> >
> > *[root at caer ~]# tail -f /var/log/pki-ca/transactions*
> > 6563.CRLIssuingPoint-MasterCRL - [20/Jul/2016:17:00:00 EDT] [20]
> [1] CRL Update
> > completed. CRL ID: MasterCRL CRL Number: 8,912 last update time:
> 7/20/16 5:00 PM
> > next update time: 7/20/16 9:00 PM Number of entries in the CRL:
> 11 time: 25 CRL
> > time: 25 delta CRL time: 0 (0,0,0,0,0,0,0,8,17,0,0,25,25)
> > 6563.CRLIssuingPoint-MasterCRL - [20/Jul/2016:21:00:00 EDT] [20]
> [1] CRL update
> > started. CRL ID: MasterCRL CRL Number: 8,913 Delta CRL
> Enabled: false CRL
> > Cache Enabled: true Cache Recovery Enabled: true Cache Cleared:
> false Cache:
> > 11,0,0,0
> > 6563.CRLIssuingPoint-MasterCRL - [20/Jul/2016:21:00:00 EDT] [20]
> [1] CRL Update
> > completed. CRL ID: MasterCRL CRL Number: 8,913 last update time:
> 7/20/16 9:00 PM
> > next update time: 7/21/16 1:00 AM Number of entries in the CRL:
> 11 time: 11 CRL
> > time: 11 delta CRL time: 0 (0,0,0,0,0,0,0,6,5,0,0,11,11)
> > 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:01:00:00 EDT] [20]
> [1] CRL update
> > started. CRL ID: MasterCRL CRL Number: 8,914 Delta CRL
> Enabled: false CRL
> > Cache Enabled: true Cache Recovery Enabled: true Cache Cleared:
> false Cache:
> > 11,0,0,0
> > 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:01:00:00 EDT] [20]
> [1] CRL Update
> > completed. CRL ID: MasterCRL CRL Number: 8,914 last update time:
> 7/21/16 1:00 AM
> > next update time: 7/21/16 5:00 AM Number of entries in the CRL:
> 11 time: 13 CRL
> > time: 13 delta CRL time: 0 (0,0,0,0,0,0,0,6,7,0,0,13,13)
> > 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:05:00:00 EDT] [20]
> [1] CRL update
> > started. CRL ID: MasterCRL CRL Number: 8,915 Delta CRL
> Enabled: false CRL
> > Cache Enabled: true Cache Recovery Enabled: true Cache Cleared:
> false Cache:
> > 11,0,0,0
> > 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:05:00:00 EDT] [20]
> [1] CRL Update
> > completed. CRL ID: MasterCRL CRL Number: 8,915 last update time:
> 7/21/16 5:00 AM
> > next update time: 7/21/16 9:00 AM Number of entries in the CRL:
> 11 time: 16 CRL
> > time: 16 delta CRL time: 0 (0,0,0,0,0,0,0,8,8,0,0,16,16)
> > 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:09:00:00 EDT] [20]
> [1] CRL update
> > started. CRL ID: MasterCRL CRL Number: 8,916 Delta CRL
> Enabled: false CRL
> > Cache Enabled: true Cache Recovery Enabled: true Cache Cleared:
> false Cache:
> > 11,0,0,0
> > 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:09:00:00 EDT] [20]
> [1] CRL Update
> > completed. CRL ID: MasterCRL CRL Number: 8,916 last update time:
> 7/21/16 9:00 AM
> > next update time: 7/21/16 1:00 PM Number of entries in the CRL:
> 11 time: 13 CRL
> > time: 13 delta CRL time: 0 (0,0,0,0,0,0,0,6,7,0,0,13,13)
> > 10657.http-9443-2 - [21/Jul/2016:10:28:19 EDT] [20] [1] renewal
> reqID 112
> > fromAgent userID: ipara authenticated by certUserDBAuthMgr is
> completed DN
> > requested: CN=CA Audit,O=TELOIP.NET <http://TELOIP.NET>
> <http://TELOIP.NET> cert issued serial
> > number: 0x47 time: 39
> >
> > *[root at caer ~]# tail -f /var/log/pki-ca/selftests.log*
> > 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem: loading all
> > self test plugin logger parameters
> > 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem: loading all
> > self test plugin instances
> > 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem: loading all
> > self test plugin instance parameters
> > 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem: loading
> > self test plugins in on-demand order
> > 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem: loading
> > self test plugins in startup order
> > 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem: Self test
> > plugins have been successfully loaded!
> > 14116.main - [21/Jul/2016:10:58:30 EDT] [20] [1] SelfTestSubsystem: Running self
> > test plugins specified to be executed at startup:
> > 14116.main - [21/Jul/2016:10:58:30 EDT] [20] [1] CAPresence: CA is present
> > 14116.main - [21/Jul/2016:10:58:30 EDT] [20] [1] SystemCertsVerification: system
> > certs verification failure
> > 14116.main - [21/Jul/2016:10:58:30 EDT] [20] [1] SelfTestSubsystem: The CRITICAL
> > self test plugin called selftests.container.instance.SystemCertsVerification
> > running at startup FAILED!
> >
> > But intrestingly, [root at caer ~]# ipa cert-show 1 returns "*ipa:
> ERROR:
> > Certificate operation cannot be completed: Unable to communicate with CMS (Not
> > Found)*"
> >
> > On Thu, Jul 21, 2016 at 10:04 AM, Linov Suresh <linov.suresh at gmail.com <mailto:linov.suresh at gmail.com>
> > <mailto:linov.suresh at gmail.com <mailto:linov.suresh at gmail.com>>> wrote:
> >
> > This could be because of incorrect trust attributes trust on the
> > certificates, the current attributes are,
> >
> > [root at caer ~]# certutil -L -d /var/lib/pki-ca/alias
> >
> > Certificate Nickname Trust Attributes
> > SSL,S/MIME,JAR/XPI
> >
> > ocspSigningCert cert-pki-ca u,u,Pu
> > subsystemCert cert-pki-ca u,u,Pu
> > caSigningCert cert-pki-ca CTu,Cu,Cu
> > subsystemCert cert-pki-ca u,u,Pu
> > Server-Cert cert-pki-ca u,u,u
> > auditSigningCert cert-pki-ca u,u,Pu
> >
> > I'm going to fix the trust attributes and try.
> >
> > On Thu, Jul 21, 2016 at 9:45 AM, Petr Vobornik <pvoborni at redhat.com <mailto:pvoborni at redhat.com>
> > <mailto:pvoborni at redhat.com <mailto:pvoborni at redhat.com>>> wrote:
> >
> > On 07/20/2016 09:41 PM, Linov Suresh wrote:
> > > I have restarted the pki-cad and checked if
> communication with the CA is
> > > working, but no luck,
> > >
> > > Debug logs in /var/log/pki-ca do not have anything
> unusual. Can you think of
> > > anything other than this?
> >
> > /var/log/httpd/error_log when /etc/ipa.conf is set to
> debug=true
> >
> https://www.freeipa.org/page/Troubleshooting#ipa_command_crashes_or_returns_no_data
> >
> > /var/log/pki-ca/debug
> > /var/log/pki-ca/transactions
> > /var/log/pki-ca/selftest.log
> >
> > >
> > > [root at caer ~]# ipa cert-show 1
> > > Certificate:
> MIIDizCCAnOgAwIBAgIBATANBgkqhkiG9w0BAQsFADA1MRMwEQYDVQQKEwpURUxP
> > >
> SVAuTkVUMR4wHAYDVQQDExVDZXJ0aWZpY2F0ZSBBdXRob3JpdHkwHhcNMTExMjE0
> > >
> MjIyOTU2WhcNMTkxMjE0MjIyOTU2WjA1MRMwEQYDVQQKEwpURUxPSVAuTkVUMR4w
> > >
> HAYDVQQDExVDZXJ0aWZpY2F0ZSBBdXRob3JpdHkwggEiMA0GCSqGSIb3DQEBAQUA
> > >
> A4IBDwAwggEKAoIBAQDegJ5XVR0JSc76s9FPkkkuug3PtZi5Ysad0Dr1I5ngjTOV
> > >
> ctm/P7buk2g8LxBSXLO+7Rq7PTtTD5AJ7vQjrv2RtoYTPdRebAuukTKd6RhtYa5e
> > >
> tX7z0DBjQ8g9Erqf9GzLxlQqim8ZvscATBhf6MLb5cXA/pWHYuE2j0OlnrSNWqsb
> > >
> UgwMsM73RlsNACsvLUk4iJY0wuxj4L/0EBQWUPGr8qBk3QBST4LDnInuvvGsAFNe
> > >
> tyebENMRWnEaDFYKPapACrtKAl3hQNDB7dVGk64Dd7paXss9F8vgVnofgFpjiJs7
> > >
> 5DNtKhKxzFQyanINU+uuIVs/CNIO3jV9I26ems2zAgMBAAGjgaUwgaIwHwYDVR0j
> > >
> BBgwFoAUx5/ZpwOfXZQ5KNwC42cBW+Y+bGIwDwYDVR0TAQH/BAUwAwEB/zAOBgNV
> > >
> HQ8BAf8EBAMCAcYwHQYDVR0OBBYEFMef2acDn12UOSjcAuNnAVvmPmxiMD8GCCsG
> > >
> AQUFBwEBBDMwMTAvBggrBgEFBQcwAYYjaHR0cDovL2NhZXIudGVsb2lwLm5ldDo5
> > >
> MTgwL2NhL29jc3AwDQYJKoZIhvcNAQELBQADggEBAHGElN0OcepokvNIN8f4mvTj
> > >
> kL9wcuZwbbX9gZGdKSZf5Redp4tsJW8EJCy8yu9F5U+Ym3RcvJBiby9gHCVVbW+y
> > >
> 5IgziiJ3kd4UlVJCDVKtbdq62bODcatFsMH8wJSMW6Cw096RyfGgu2qSyXzdZ2xV
> > >
> nMovO3+Eaz2n0x4ZvaEj9Ixym/KI+QPCAL7gPkK36X4JYgM3CXUCYCN/QJY/psFt
> > >
> e+121ubSZX5u3Yntux4KziJ3cx9wZ74iKff1BOVxOCi0JyLn2k15bvBXGvxxgmhK
> > >
> b8YUVbDJDb9oWSbixl/TQI9PZysXYIvBNJM8h+HRKIJksKGQhKOERzrYoqABt30=
> > > Subject: CN=Certificate Authority,O=TELOIP.NET
> <http://TELOIP.NET> <http://TELOIP.NET>
> > <http://TELOIP.NET>
> > > Issuer: CN=Certificate Authority,O=TELOIP.NET
> <http://TELOIP.NET> <http://TELOIP.NET>
> > <http://TELOIP.NET>
> > > Not Before: Wed Dec 14 22:29:56 2011 UTC
> > > Not After: Sat Dec 14 22:29:56 2019 UTC
> > > Fingerprint (MD5):
> c9:27:1d:84:4c:2c:97:38:a4:7b:9a:c0:78:3e:7f:7a
> > > Fingerprint (SHA1):
> ce:d7:11:84:70:dd:cb:4e:e2:08:f5:c0:ac:ff:b3:c5:bb:81:77:7e
> > > Serial number (hex): 0x1
> > > Serial number: 1
> > > [root at caer ~]#
> > >
> > > *ca-error: Internal error: no response to
> > >
> >
> "http://caer.teloip.net:9180/ca/ee/ca/profileSubmit?profileId=caServerCert&serial_num=63&renewal=true&xml=true".
> > > *
> > >
> > >
> > >
> > > On Wed, Jul 20, 2016 at 2:22 PM, Rob Crittenden
> <rcritten at redhat.com <mailto:rcritten at redhat.com>
> <mailto:rcritten at redhat.com <mailto:rcritten at redhat.com>>
> > > <mailto:rcritten at redhat.com <mailto:rcritten at redhat.com>
> <mailto:rcritten at redhat.com <mailto:rcritten at redhat.com>>>> wrote:
> > >
> > > Linov Suresh wrote:
> > >
> > > Thanks for your help Rob, I will create a
> separate thread for IPA
> > > replication issue. But we are still getting
> > > *
> > > *
> > > *ca-error: Internal error: no response to
> > >
> "http://caer.teloip.net:9180/ca/ee/ca/profileSubmit?profileId=caServerCert&serial_num=60&renewal=true&xml=true".*
> > >
> > > Could you please help us to fix this?
> > >
> > >
> > > I think your CA isn't quite fixed yet. I'd restart
> pki-cad then do something
> > > like: ipa cert-show 1
> > >
> > > You should get back a cert (doesn't really matter
> what cert).
> > >
> > > Otherwise I'd check the CA debug log somewhere in
> /var/log/pki
> > >
> > > rob
> > >
>
>
> --
> Petr Vobornik
>
>
More information about the Freeipa-users
mailing list