[Freeipa-users] Having Issues with Dogtag After Updating IPA and Rebooting

Mon Mar 23 13:24:25 UTC 2015

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: mike at colovore.com
>> C: 408.316.2154
>>   <http://www.colovore.com>
>>
>> On Sun, Mar 22, 2015 at 12:05 AM, Michael Pawlak <mike at colovore.com> 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 newipa.example.com --ca=/etc/ipa/ca.crt --password
>>> 'somepassword'
>>> Preparing replica for newipa.example.com from ipa.example.com
>>> 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 https://ipa.example.com/ipa/xml 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=ipa.example.com,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 https://ipa.example.com/ipa/xml 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=ipa.example.com,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 https://ipa.example.com/ipa/xml 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=ipa.example.com,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
>>>
>>>
>>
>>
>>
> 