I'm facing another issue now, my kerberos tickets are not renewing, *[root@caer ~]# ipa cert-show 1* ipa: ERROR: Ticket expired
*[root@caer ~]# klist* Ticket cache: FILE:/tmp/krb5cc_0 Default principal: ad...@teloip.net Valid starting Expires Service principal 07/20/16 14:42:26 07/21/16 14:42:22 krbtgt/teloip....@teloip.net 07/20/16 14:42:36 07/21/16 14:42:22 HTTP/caer.teloip....@teloip.net 07/21/16 11:40:15 07/21/16 14:42:22 ldap/caer.teloip....@teloip.net I need to manually renew the tickets every day, *[root@caer ~]# kinit admin* Password for ad...@teloip.net: Warning: Your password will expire in 6 days on Thu Jul 28 15:20:15 2016 *[root@caer ~]# klist * Ticket cache: FILE:/tmp/krb5cc_0 Default principal: ad...@teloip.net Valid starting Expires Service principal 07/22/16 09:34:52 07/23/16 09:34:49 krbtgt/teloip....@teloip.net On Thu, Jul 21, 2016 at 12:23 PM, Rob Crittenden <rcrit...@redhat.com> wrote: > 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@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....@teloip.net >> <mailto:caer.teloip....@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....@teloip.net >> <mailto:caer.teloip....@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: ad...@teloip.net >> <mailto:ad...@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@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 >> 'ad...@teloip.net <mailto:ad...@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 ad...@teloip.net >> <mailto:ad...@teloip.net> >> ipa: DEBUG: args=keyctl search @s user >> ipa_session_cookie:ad...@teloip.net >> <mailto:ipa_session_cookie%3aad...@teloip.net> >> ipa: DEBUG: stdout=457971704 >> >> ipa: DEBUG: stderr= >> ipa: DEBUG: args=keyctl search @s user >> ipa_session_cookie:ad...@teloip.net >> <mailto:ipa_session_cookie%3aad...@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@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@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@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 <pvobo...@redhat.com >> <mailto:pvobo...@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@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: ad...@teloip.net >> <mailto:ad...@teloip.net> >> > <mailto:ad...@teloip.net <mailto:ad...@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@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@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@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@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.sur...@gmail.com <mailto:linov.sur...@gmail.com> >> > <mailto:linov.sur...@gmail.com <mailto:linov.sur...@gmail.com>>> >> wrote: >> > >> > This could be because of incorrect trust attributes trust on the >> > certificates, the current attributes are, >> > >> > [root@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 < >> pvobo...@redhat.com <mailto:pvobo...@redhat.com> >> > <mailto:pvobo...@redhat.com <mailto:pvobo...@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@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@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 >> <rcrit...@redhat.com <mailto:rcrit...@redhat.com> >> <mailto:rcrit...@redhat.com <mailto:rcrit...@redhat.com>> >> > > <mailto:rcrit...@redhat.com <mailto:rcrit...@redhat.com> >> <mailto:rcrit...@redhat.com <mailto:rcrit...@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 >> >> >> >
-- Manage your subscription for the Freeipa-users mailing list: https://www.redhat.com/mailman/listinfo/freeipa-users Go to http://freeipa.org for more info on the project