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

Michael Pawlak mike at colovore.com
Sun Mar 22 07:05:17 UTC 2015 

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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20150322/8f99ddc1/attachment.htm>

More information about the Freeipa-users mailing list