Thank you very much Rob. Let me remove the duplicate certificates and try to renew the certificates again to see if "*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 <http://caer.teloip.net:9180/ca/ee/ca/profileSubmit?profileId=caServerCert&serial_num=63&renewal=true&xml=true>"*." goes away?
On Fri, Jul 22, 2016 at 2:45 PM, Rob Crittenden <[email protected]> wrote: > Linov Suresh wrote: > >> Could you please verify, if we have set correct trust attributes on the >> certificates >> >> *root@caer ~]# certutil -d /var/lib/pki-ca/alias/ -L* >> >> Certificate Nickname Trust >> Attributes >> >> SSL,S/MIME,JAR/XPI >> >> subsystemCert cert-pki-ca u,u,Pu >> ocspSigningCert cert-pki-ca u,u,u >> 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 >> * >> * >> *[root@caer ~]# certutil -d /etc/httpd/alias/ -L* >> >> Certificate Nickname Trust >> Attributes >> >> SSL,S/MIME,JAR/XPI >> >> ipaCert u,u,u >> Server-Cert u,u,u >> TELOIP.NET <http://TELOIP.NET> IPA CA >> CT,C,C >> ipaCert u,u,u >> Signing-Cert u,u,u >> Server-Cert u,u,u >> >> *[root@caer ~]# certutil -d /etc/dirsrv/slapd-TELOIP-NET/ -L* >> >> Certificate Nickname Trust >> Attributes >> >> SSL,S/MIME,JAR/XPI >> >> Server-Cert u,u,u >> TELOIP.NET <http://TELOIP.NET> IPA CA >> CT,,C >> Server-Cert u,u,u >> [root@caer ~]# >> >> *Please note, there are duplicate certificates in CA, HTTP and LDAP >> directory, subsystemCert cert-pki-ca, ipaCert and Server-Cert. I was >> wondering if we need to remove these duplicate certificates? * >> > > Yeah you should remove the duplicate certs, they seem to cause problems > with dogtag at least (certmonger _should_ handle this automatically, we'll > be looking into it soonish). > > To remove the duplicate cert: > > 1. Shutdown the service > 2. Back up the NSS database > 3. certutil -L -d /path/to/db -n <nickname> -a > somefile > 4. split somefile into separate files so each file as a BEGIN/END > certificate > 5. openssl x509 -text -in -infile somefile1..n > 6. Pick the one with the most recent issuance date > 7. You backed up the NSS database, right? > 8. certutil -D -d /path/to/db -n <nickname> > 9. certutil -A -d /path/to/db -n <nickname> -t u,u,u -a -i somefilex > 10. Start the service, watch logs for errors > > For the trust use whatever the original trust value was. > > You don't need the P trust flag on the subsystemCert in the CA, only the > auditSigningCert. > > I doubt the duplicated Server-Cert will be a problem. NSS is supposed to > deal with this automatically, picking the "most correct" cert to use based > on the validity period. > > rob > > >> >> On Fri, Jul 22, 2016 at 9:36 AM, Linov Suresh <[email protected] >> <mailto:[email protected]>> wrote: >> >> 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: [email protected] <mailto:[email protected]> >> >> Valid starting Expires Service principal >> 07/20/16 14:42:26 07/21/16 14:42:22 krbtgt/[email protected] >> <mailto:[email protected]> >> 07/20/16 14:42:36 07/21/16 14:42:22 >> HTTP/[email protected] <mailto:[email protected]> >> 07/21/16 11:40:15 07/21/16 14:42:22 >> ldap/[email protected] <mailto:[email protected]> >> >> I need to manually renew the tickets every day, >> >> *[root@caer ~]# kinit admin* >> Password for [email protected] <mailto:[email protected]>: >> 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: [email protected] <mailto:[email protected]> >> >> Valid starting Expires Service principal >> 07/22/16 09:34:52 07/23/16 09:34:49 krbtgt/[email protected] >> <mailto:[email protected]> >> >> >> On Thu, Jul 21, 2016 at 12:23 PM, Rob Crittenden >> <[email protected] <mailto:[email protected]>> 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/[email protected] >> <mailto:[email protected]> >> <mailto:[email protected] >> <mailto:[email protected]>>, 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/[email protected] >> <mailto:[email protected]> >> <mailto:[email protected] >> <mailto:[email protected]>>, 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> >> <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> >> <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> >> <http://caer.teloip.net>,O=TELOIP.NET <http://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> < >> 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> >> <http://caer.teloip.net>,O=TELOIP.NET <http://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> < >> 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: >> [email protected] <mailto:[email protected]> >> <mailto:[email protected] <mailto:[email protected]>>: >> 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> >> <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 >> '[email protected] <mailto:[email protected]> >> <mailto:[email protected] <mailto:[email protected]>>', cookie: >> 'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c; >> Domain=caer.teloip.net <http://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> <http://caer.teloip.net> >> ipa: DEBUG: Connecting: 10.20.0.75:0 <http://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> >> <http://caer.teloip.net>\r\nAccept-Language: >> en-us\r\nReferer: >> https://caer.teloip.net/ipa/xml\r\nCookie >> <https://caer.teloip.net/ipa/xml%5Cr%5CnCookie>: >> ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;\r\nUser-Agent: >> xmlrpclib.py/1.0.1 <http://xmlrpclib.py/1.0.1> >> <http://xmlrpclib.py/1.0.1> (by www.pythonware.com >> <http://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> >> <http://caer.teloip.net>,O=TELOIP.NET <http://TELOIP.NET> >> <http://TELOIP.NET>" >> ipa: DEBUG: handshake complete, peer = 10.20.0.75:443 >> <http://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> >> <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> >> <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> >> <http://caer.teloip.net>; Path=/ipa; Expires=Thu, 21 Jul >> 2016 16:25:40 >> GMT; Secure; HttpOnly' for principal [email protected] >> <mailto:[email protected]> >> <mailto:[email protected] <mailto:[email protected]>> >> ipa: DEBUG: args=keyctl search @s user >> ipa_session_cookie:[email protected] >> <mailto:ipa_session_cookie%[email protected]> >> <mailto:ipa_session_cookie%[email protected] >> <mailto:ipa_session_cookie%[email protected]>> >> ipa: DEBUG: stdout=457971704 >> >> ipa: DEBUG: stderr= >> ipa: DEBUG: args=keyctl search @s user >> ipa_session_cookie:[email protected] >> <mailto:ipa_session_cookie%[email protected]> >> <mailto:ipa_session_cookie%[email protected] >> <mailto:ipa_session_cookie%[email protected]>> >> 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 >> <[email protected] <mailto:[email protected]> >> <mailto:[email protected] <mailto:[email protected]>>> >> 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: >> [email protected] <mailto:[email protected]> >> <mailto:[email protected] <mailto:[email protected]>> >> > <mailto:[email protected] <mailto:[email protected]> >> <mailto:[email protected] <mailto:[email protected]>>>: >> >> 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> >> <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 > >
-- 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
