<div dir="ltr"><div>Rob, </div>Thanks. Any additional eyes would be greatly apprecated. </div><div class="gmail_extra"> <div><div class="gmail_signature"><div dir="ltr"><div><div dir="ltr">Michael Pawlak Web Systems Administrator | Colovore LLC E: <a href="mailto:mike@colovore.com" target="_blank">mike@colovore.com</a> C: 408.316.2154 <a href="http://www.colovore.com" target="_blank"><img src="http://s3.amazonaws.com/crunchbase_prod_assets/assets/images/resized/0028/6576/286576v1-max-250x250.png" height="33" width="131"></a></div></div></div></div></div> <div class="gmail_quote">On Mon, Mar 23, 2015 at 6:24 AM, Rob Crittenden <<a href="mailto:rcritten@redhat.com" target="_blank">rcritten@redhat.com</a>> wrote: <blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Martin Kosek wrote: > This may mean that Dogtag is not up. Can you please check with "ipactl status" > that it (pki-ca) is up and running and that there are no related SELinux AVCs? > The problem seems to be java-related: The self test plugin named selftests.container.logger.class contains a value com.netscape.cms.logging.RollingLogFile which is invalid. I've seen cases where selftest failures don't cause the CA to not start up but does prevent it from actually operating. The bottom line of the errors you are seeing is that the CA is not completely running. I've cc'd a couple of dogtag developers to see if they can help with the Java exception. rob > On 03/23/2015 04:52 AM, Michael Pawlak wrote: >> Does anybody have any thoughts on this? >> >> *Michael Pawlak* >> Web Systems Administrator | Colovore LLC >> E: <a href="mailto:mike@colovore.com">mike@colovore.com</a> >> C: <a href="tel:408.316.2154" value="+14083162154">408.316.2154</a> >> <<a href="http://www.colovore.com" target="_blank">http://www.colovore.com</a>> >> >> On Sun, Mar 22, 2015 at 12:05 AM, Michael Pawlak <<a href="mailto:mike@colovore.com">mike@colovore.com</a>> wrote: >> >>> I am not able to setup a replica using the 'ipa-replica-prepare' command. >>> After some debugging this appears related to the certmonger/dogtag system >>> that is incorporated with FreeIPA. I am including the output below of any >>> relevant logs / commands. >>> >>> ----- ipa-replica-prepare ----- >>> >>> ipa-replica-prepare <a href="http://newipa.example.com" target="_blank">newipa.example.com</a> --ca=/etc/ipa/ca.crt --password >>> 'somepassword' >>> Preparing replica for <a href="http://newipa.example.com" target="_blank">newipa.example.com</a> from <a href="http://ipa.example.com" target="_blank">ipa.example.com</a> >>> Creating SSL certificate for the Directory Server >>> Certificate operation cannot be completed: Unable to communicate with CMS >>> (Not Found) >>> >>> ----- ipa-getcert list ----- >>> >>> Number of certificates and requests being tracked: 8. >>> Request ID '20140811232518': >>> status: CA_UNREACHABLE >>> ca-error: Server at <a href="https://ipa.example.com/ipa/xml" target="_blank">https://ipa.example.com/ipa/xml</a> failed request, >>> will retry: 4301 (RPC failed at server. Certificate operation cannot be >>> completed: Unable to communicate with CMS (Not Found)). >>> stuck: no >>> key pair storage: >>> type=NSSDB,location='/etc/dirsrv/slapd-PKI-IPA',nickname='Server-Cert',token='NSS >>> Certificate DB',pinfile='/etc/dirsrv/slapd-PKI-IPA/pwdfile.txt' >>> certificate: >>> type=NSSDB,location='/etc/dirsrv/slapd-PKI-IPA',nickname='Server-Cert',token='NSS >>> Certificate DB' >>> CA: IPA >>> issuer: CN=Certificate Authority,O=EXAMPLE >>> subject: CN=<a href="http://ipa.example.com" target="_blank">ipa.example.com</a>,O=EXAMPLE >>> expires: 2016-08-11 23:24:36 UTC >>> key usage: >>> digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment >>> eku: id-kp-serverAuth,id-kp-clientAuth >>> pre-save command: >>> post-save command: >>> track: yes >>> auto-renew: yes >>> Request ID '20140811232742': >>> status: CA_UNREACHABLE >>> ca-error: Server at <a href="https://ipa.example.com/ipa/xml" target="_blank">https://ipa.example.com/ipa/xml</a> failed request, >>> will retry: 4301 (RPC failed at server. Certificate operation cannot be >>> completed: Unable to communicate with CMS (Not Found)). >>> stuck: no >>> key pair storage: >>> type=NSSDB,location='/etc/dirsrv/slapd-EXAMPLE',nickname='Server-Cert',token='NSS >>> Certificate DB',pinfile='/etc/dirsrv/slapd-COLOVORE/pwdfile.txt' >>> certificate: >>> type=NSSDB,location='/etc/dirsrv/slapd-EXAMPLE',nickname='Server-Cert',token='NSS >>> Certificate DB' >>> CA: IPA >>> issuer: CN=Certificate Authority,O=EXAMPLE >>> subject: CN=<a href="http://ipa.example.com" target="_blank">ipa.example.com</a>,O=EXAMPLE >>> expires: 2016-08-11 23:24:34 UTC >>> key usage: >>> digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment >>> eku: id-kp-serverAuth,id-kp-clientAuth >>> pre-save command: >>> post-save command: >>> track: yes >>> auto-renew: yes >>> Request ID '20140811232843': >>> status: CA_UNREACHABLE >>> ca-error: Server at <a href="https://ipa.example.com/ipa/xml" target="_blank">https://ipa.example.com/ipa/xml</a> failed request, >>> will retry: 4301 (RPC failed at server. Certificate operation cannot be >>> completed: Unable to communicate with CMS (Not Found)). >>> stuck: no >>> key pair storage: >>> type=NSSDB,location='/etc/httpd/alias',nickname='Server-Cert',token='NSS >>> Certificate DB',pinfile='/etc/httpd/alias/pwdfile.txt' >>> certificate: >>> type=NSSDB,location='/etc/httpd/alias',nickname='Server-Cert',token='NSS >>> Certificate DB' >>> CA: IPA >>> issuer: CN=Certificate Authority,O=EXAMPLE >>> subject: CN=<a href="http://ipa.example.com" target="_blank">ipa.example.com</a>,O=EXAMPLE >>> expires: 2016-08-11 23:24:37 UTC >>> key usage: >>> digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment >>> eku: id-kp-serverAuth,id-kp-clientAuth >>> pre-save command: >>> post-save command: >>> track: yes >>> auto-renew: yes >>> >>> ----- /etc/pki-ca/password.conf ----- >>> >>> internal=829325937546 >>> internaldb=somepassword >>> replicationdb=1270571739 >>> >>> ----- /var/log/pki-ca/debug ----- >>> >>> [22/Mar/2015:06:45:10][main]: CMSEngine: done init id=profile >>> [22/Mar/2015:06:45:10][main]: CMSEngine: initialized profile >>> [22/Mar/2015:06:45:10][main]: CMSEngine: initSubsystem id=selftests >>> [22/Mar/2015:06:45:10][main]: CMSEngine: ready to init id=selftests >>> [22/Mar/2015:06:45:10][main]: SelfTestSubsystem::init(): ENTERING . . . >>> [22/Mar/2015:06:45:10][main]: SelfTestSubsystem::init(): loading self >>> test logger parameters >>> [22/Mar/2015:06:45:10][main]: CMS:Caught EBaseException >>> The self test plugin named selftests.container.logger.class contains a >>> value com.netscape.cms.logging.RollingLogFile which is invalid. >>> at >>> com.netscape.cmscore.selftests.SelfTestSubsystem.init(SelfTestSubsystem.java:1422) >>> at >>> com.netscape.cmscore.apps.CMSEngine.initSubsystem(CMSEngine.java:866) >>> at >>> com.netscape.cmscore.apps.CMSEngine.initSubsystems(CMSEngine.java:795) >>> at com.netscape.cmscore.apps.CMSEngine.init(CMSEngine.java:316) >>> at com.netscape.certsrv.apps.CMS.init(CMS.java:153) >>> at com.netscape.certsrv.apps.CMS.start(CMS.java:1530) >>> at >>> com.netscape.cms.servlet.base.CMSStartServlet.init(CMSStartServlet.java:85) >>> at >>> org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1173) >>> at >>> org.apache.catalina.core.StandardWrapper.load(StandardWrapper.java:993) >>> at >>> org.apache.catalina.core.StandardContext.loadOnStartup(StandardContext.java:4425) >>> at >>> org.apache.catalina.core.StandardContext.start(StandardContext.java:4738) >>> at >>> org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:791) >>> at >>> org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:771) >>> at >>> org.apache.catalina.core.StandardHost.addChild(StandardHost.java:526) >>> at >>> org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1041) >>> at >>> org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:964) >>> at >>> org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:502) >>> at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1277) >>> at >>> org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:321) >>> at >>> org.apache.catalina.util.LifecycleSupport.fireLifecycleEvent(LifecycleSupport.java:142) >>> at >>> org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1053) >>> at org.apache.catalina.core.StandardHost.start(StandardHost.java:722) >>> at >>> org.apache.catalina.core.ContainerBase.start(ContainerBase.java:1045) >>> at >>> org.apache.catalina.core.StandardEngine.start(StandardEngine.java:443) >>> at >>> org.apache.catalina.core.StandardService.start(StandardService.java:516) >>> at >>> org.apache.catalina.core.StandardServer.start(StandardServer.java:710) >>> at org.apache.catalina.startup.Catalina.start(Catalina.java:593) >>> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) >>> at >>> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) >>> at >>> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) >>> at java.lang.reflect.Method.invoke(Method.java:606) >>> at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:289) >>> at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:414) >>> [22/Mar/2015:06:45:10][main]: CMSEngine.shutdown() >>> [22/Mar/2015:06:45:25][http-9444-1]: according to ccMode, authorization >>> for servlet: caProfileSubmitSSLClient is LDAP based, not XML {1}, use >>> default authz mgr: {2}. >>> [22/Mar/2015:06:45:25][http-9444-1]: according to ccMode, authorization >>> for servlet: caProfileSubmitSSLClient is LDAP based, not XML {1}, use >>> default authz mgr: {2}. >>> [22/Mar/2015:06:50:09][Timer-0]: CMSEngine: getPasswordStore(): password >>> store initialized before. >>> [22/Mar/2015:06:50:09][Timer-0]: CMSEngine: getPasswordStore(): password >>> store initialized. >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: About to start >>> updateCertStatus >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Starting updateCertStatus >>> (entered lock) >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In updateCertStatus() >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> LdapBoundConnFactory::getConn() >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: masterConn is connected: >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: conn is connected >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: mNumConns now 2 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: >>> getInvalidCertificatesByNotBeforeDate filter (certStatus=INVALID) >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: >>> getInvalidCertificatesByNotBeforeDate: about to call findCertRecordsInList >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> LdapBoundConnFactory::getConn() >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: masterConn is connected: >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: conn is connected >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: mNumConns now 1 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> findCertRecordsInListRawJumpto with Jumpto 20150322065510Z >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In DBVirtualList filter >>> attrs startFrom sortKey pageSize filter: (certStatus=INVALID) attrs: >>> [objectclass, certRecordId, x509cert] pageSize -200 startFrom >>> 20150322065510Z >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: returnConn: mNumConns now 2 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> getInvalidCertsByNotBeforeDate finally. >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: returnConn: mNumConns now 3 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getEntries returning 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: mTop 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Getting Virtual List size: >>> 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: index may be empty >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> LdapBoundConnFactory::getConn() >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: masterConn is connected: >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: conn is connected >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: mNumConns now 2 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: >>> getValidCertsByNotAfterDate filter (certStatus=VALID) >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> LdapBoundConnFactory::getConn() >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: masterConn is connected: >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: conn is connected >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: mNumConns now 1 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> findCertRecordsInListRawJumpto with Jumpto 20150322065510Z >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In DBVirtualList filter >>> attrs startFrom sortKey pageSize filter: (certStatus=VALID) attrs: >>> [objectclass, certRecordId, x509cert] pageSize -200 startFrom >>> 20150322065510Z >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: returnConn: mNumConns now 2 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: returnConn: mNumConns now 3 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getEntries returning 1 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: mTop 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Getting Virtual List size: >>> 69 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: transidValidCertificates: >>> list size: 69 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: transitValidCertificates: >>> ltSize 1 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getElementAt: 0 mTop 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: reverse direction getting >>> index 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Record does not >>> qualify,notAfter Sat Jul 09 05:12:31 UTC 2016 date Sun Mar 22 06:55:10 UTC >>> 2015 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: transitCertList EXPIRED >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> LdapBoundConnFactory::getConn() >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: masterConn is connected: >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: conn is connected >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: mNumConns now 2 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: >>> getRevokedCertificatesByNotAfterDate filter (certStatus=REVOKED) >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: >>> getRevokedCertificatesByNotAfterDate: about to call findCertRecordsInList >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> LdapBoundConnFactory::getConn() >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: masterConn is connected: >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: conn is connected >>> true >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getConn: mNumConns now 1 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In >>> findCertRecordsInListRawJumpto with Jumpto 20150322065510Z >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: In DBVirtualList filter >>> attrs startFrom sortKey pageSize filter: (certStatus=REVOKED) attrs: >>> [objectclass, certRevokedOn, certRecordId, certRevoInfo, notAfter, >>> x509cert] pageSize -200 startFrom 20150322065510Z >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: returnConn: mNumConns now 2 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: returnConn: mNumConns now 3 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getEntries returning 1 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: mTop 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Getting Virtual List size: >>> 5 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: >>> transitRevokedExpiredCertificates: list size: 5 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: >>> transitRevokedExpiredCertificates: ltSize 1 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: getElementAt: 0 mTop 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: reverse direction getting >>> index 0 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: transitRevokedExpired: >>> curRec: 0 CertRecord: 268369925 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Record does not >>> qualify,notAfter Wed Jul 20 06:25:57 UTC 2016 date Sun Mar 22 06:55:10 UTC >>> 2015 >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: transitCertList >>> REVOKED_EXPIRED >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: updateCertStatus done >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Starting cert checkRanges >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Server not completely >>> started. Returning .. >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: cert checkRanges done >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Starting request >>> checkRanges >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: Server not completely >>> started. Returning .. >>> [22/Mar/2015:06:55:10][CertStatusUpdateThread]: request checkRanges done >>> >>> >> >> >> > </blockquote></div> </div>