freeipa

Clone
Source Code
GIT

#7480 certmonger takes too long to start up
Closed: fixed 3 years ago by rcritten. Opened 6 years ago by brianjmurrell.

Closed: fixed
Reopen Issue

Request for enhancement

As admin, I want certmonger to start up successfully on system boot so that I have a functioning system on boot and don't need to manually start certmonger after every reboot.

Issue

certmonger takes longer to start up than systemd is willing to give it.

Steps to Reproduce

  1. Install and configure freeipa
  2. Reboot system

Actual behavior

Mar 25 08:47:41 server.interlinx.bc.ca systemd[1]: Starting Certificate monitoring and PKI enrollment...
Mar 25 08:49:24 server.interlinx.bc.ca systemd[1]: Unit certmonger.service entered failed state.
Mar 25 08:49:24 server.interlinx.bc.ca systemd[1]: certmonger.service failed.

Expected behavior

certmonger service should start successfully

Version/Release/Distribution

ipa-server-4.5.0-22.el7.centos.x86_64
ipa-client-4.5.0-22.el7.centos.x86_64
389-ds-base-1.3.6.1-28.el7_4.x86_64
pki-ca-10.4.1-17.el7_4.noarch
krb5-server-1.15.1-8.el7.x86_64

Additional info:

Entire startup log with debug/trace enabled

When started up after system boot it seems to start fine:

# certmonger -d 9 -n

2018-03-26 15:09:42 [10537] Starting up.
2018-03-26 15:09:42 [10537] Changing to root directory.
2018-03-26 15:09:42 [10537] Obtaining system lock.
2018-03-26 15:09:42 [10539] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:42 [10539] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:42 [10539] Skipping NSS internal slot (NSS Generic Crypto Services).
2018-03-26 15:09:42 [10539] Found token 'NSS Certificate DB'.
2018-03-26 15:09:42 [10539] Located a certificate with the key's nickname ("linux.interlinx.bc.ca-Cert").
2018-03-26 15:09:42 [10539] Located its private key.
2018-03-26 15:09:42 [10539] Recovered public key from private key.
2018-03-26 15:09:42 [10539] Key is an RSA key.
2018-03-26 15:09:42 [10539] Key size is 2048.
2018-03-26 15:09:42 [10540] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:42 [10540] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:42 [10540] Found token 'NSS Generic Crypto Services'.
2018-03-26 15:09:42 [10540] Token is named "NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
2018-03-26 15:09:42 [10540] Found token 'NSS Certificate DB'.
2018-03-26 15:09:42 [10540] Located the certificate "linux.interlinx.bc.ca-Cert".
2018-03-26 15:09:42 [10540] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:42 [10540] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:42 [10537] Request1('20150911121908') starts in state 'MONITORING'
2018-03-26 15:09:42 [10541] Key is an RSA key.
2018-03-26 15:09:42 [10541] Key size is 2048.
2018-03-26 15:09:42 [10542] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:42 [10542] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10537] Request2('20171030135524') starts in state 'MONITORING'
2018-03-26 15:09:43 [10543] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10543] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10543] Skipping NSS internal slot (NSS Generic Crypto Services).
2018-03-26 15:09:43 [10543] Found token 'NSS Certificate DB'.
2018-03-26 15:09:43 [10543] Located a certificate with the key's nickname ("auditSigningCert cert-pki-ca").
2018-03-26 15:09:43 [10543] Located its private key.
2018-03-26 15:09:43 [10543] Recovered public key from private key.
2018-03-26 15:09:43 [10543] Key is an RSA key.
2018-03-26 15:09:43 [10543] Key size is 2048.
2018-03-26 15:09:43 [10544] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10544] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10544] Found token 'NSS Generic Crypto Services'.
2018-03-26 15:09:43 [10544] Token is named "NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
2018-03-26 15:09:43 [10544] Found token 'NSS Certificate DB'.
2018-03-26 15:09:43 [10544] Located the certificate "auditSigningCert cert-pki-ca".
2018-03-26 15:09:43 [10544] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10544] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10537] Request3('20171205124733') starts in state 'MONITORING'
2018-03-26 15:09:43 [10545] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10545] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10545] Skipping NSS internal slot (NSS Generic Crypto Services).
2018-03-26 15:09:43 [10545] Found token 'NSS Certificate DB'.
2018-03-26 15:09:43 [10545] Located a certificate with the key's nickname ("ocspSigningCert cert-pki-ca").
2018-03-26 15:09:43 [10545] Located its private key.
2018-03-26 15:09:43 [10545] Recovered public key from private key.
2018-03-26 15:09:43 [10545] Key is an RSA key.
2018-03-26 15:09:43 [10545] Key size is 2048.
2018-03-26 15:09:43 [10546] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10546] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10546] Found token 'NSS Generic Crypto Services'.
2018-03-26 15:09:43 [10546] Token is named "NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
2018-03-26 15:09:43 [10546] Found token 'NSS Certificate DB'.
2018-03-26 15:09:43 [10546] Located the certificate "ocspSigningCert cert-pki-ca".
2018-03-26 15:09:43 [10546] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10546] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10537] Request4('20171205124737') starts in state 'MONITORING'
2018-03-26 15:09:43 [10547] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10547] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10547] Skipping NSS internal slot (NSS Generic Crypto Services).
2018-03-26 15:09:43 [10547] Found token 'NSS Certificate DB'.
2018-03-26 15:09:43 [10547] Located a certificate with the key's nickname ("subsystemCert cert-pki-ca").
2018-03-26 15:09:43 [10547] Located its private key.
2018-03-26 15:09:43 [10547] Recovered public key from private key.
2018-03-26 15:09:43 [10547] Key is an RSA key.
2018-03-26 15:09:43 [10547] Key size is 2048.
2018-03-26 15:09:43 [10548] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10548] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10548] Found token 'NSS Generic Crypto Services'.
2018-03-26 15:09:43 [10548] Token is named "NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
2018-03-26 15:09:43 [10548] Found token 'NSS Certificate DB'.
2018-03-26 15:09:43 [10548] Located the certificate "subsystemCert cert-pki-ca".
2018-03-26 15:09:43 [10548] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10548] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10537] Request5('20171205124741') starts in state 'MONITORING'
2018-03-26 15:09:43 [10549] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10549] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10549] Skipping NSS internal slot (NSS Generic Crypto Services).
2018-03-26 15:09:43 [10549] Found token 'NSS Certificate DB'.
2018-03-26 15:09:43 [10549] Located the key 'caSigningCert cert-pki-ca'.
2018-03-26 15:09:43 [10549] Converted private key 'caSigningCert cert-pki-ca' to public key.
2018-03-26 15:09:43 [10549] Key is an RSA key.
2018-03-26 15:09:43 [10549] Key size is 2048.
2018-03-26 15:09:43 [10550] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10550] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10550] Found token 'NSS Generic Crypto Services'.
2018-03-26 15:09:43 [10550] Token is named "NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
2018-03-26 15:09:43 [10550] Found token 'NSS Certificate DB'.
2018-03-26 15:09:43 [10550] Located the certificate "caSigningCert cert-pki-ca".
2018-03-26 15:09:43 [10550] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10550] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10537] Request6('20171205124744') starts in state 'MONITORING'
2018-03-26 15:09:43 [10551] Key is an RSA key.
2018-03-26 15:09:43 [10551] Key size is 2048.
2018-03-26 15:09:43 [10552] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:43 [10552] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:43 [10537] Request7('20171205124747') starts in state 'MONITORING'
2018-03-26 15:09:44 [10553] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10553] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10553] Skipping NSS internal slot (NSS Generic Crypto Services).
2018-03-26 15:09:44 [10553] Found token 'NSS Certificate DB'.
2018-03-26 15:09:44 [10553] Located a certificate with the key's nickname ("Server-Cert cert-pki-ca").
2018-03-26 15:09:44 [10553] Located its private key.
2018-03-26 15:09:44 [10553] Recovered public key from private key.
2018-03-26 15:09:44 [10553] Key is an RSA key.
2018-03-26 15:09:44 [10553] Key size is 2048.
2018-03-26 15:09:44 [10554] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10554] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10554] Found token 'NSS Generic Crypto Services'.
2018-03-26 15:09:44 [10554] Token is named "NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
2018-03-26 15:09:44 [10554] Found token 'NSS Certificate DB'.
2018-03-26 15:09:44 [10554] Located the certificate "Server-Cert cert-pki-ca".
2018-03-26 15:09:44 [10554] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10554] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10537] Request8('20171205124749') starts in state 'MONITORING'
2018-03-26 15:09:44 [10555] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10555] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10555] Skipping NSS internal slot (NSS Generic Crypto Services).
2018-03-26 15:09:44 [10555] Found token 'NSS Certificate DB'.
2018-03-26 15:09:44 [10555] Located a certificate with the key's nickname ("Server-Cert").
2018-03-26 15:09:44 [10555] Located its private key.
2018-03-26 15:09:44 [10555] Recovered public key from private key.
2018-03-26 15:09:44 [10555] Key is an RSA key.
2018-03-26 15:09:44 [10555] Key size is 2048.
2018-03-26 15:09:44 [10556] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10556] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10556] Found token 'NSS Generic Crypto Services'.
2018-03-26 15:09:44 [10556] Token is named "NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
2018-03-26 15:09:44 [10556] Found token 'NSS Certificate DB'.
2018-03-26 15:09:44 [10556] Located the certificate "Server-Cert".
2018-03-26 15:09:44 [10556] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10556] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10537] Request9('20171205124756') starts in state 'MONITORING'
2018-03-26 15:09:44 [10557] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10557] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10557] Skipping NSS internal slot (NSS Generic Crypto Services).
2018-03-26 15:09:44 [10557] Found token 'NSS Certificate DB'.
2018-03-26 15:09:44 [10557] Located a certificate with the key's nickname ("Server-Cert").
2018-03-26 15:09:44 [10557] Located its private key.
2018-03-26 15:09:44 [10557] Recovered public key from private key.
2018-03-26 15:09:44 [10557] Key is an RSA key.
2018-03-26 15:09:44 [10557] Key size is 2048.
2018-03-26 15:09:44 [10558] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10558] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10558] Found token 'NSS Generic Crypto Services'.
2018-03-26 15:09:44 [10558] Token is named "NSS Generic Crypto Services", not "NSS Certificate DB", skipping.
2018-03-26 15:09:44 [10558] Found token 'NSS Certificate DB'.
2018-03-26 15:09:44 [10558] Located the certificate "Server-Cert".
2018-03-26 15:09:44 [10558] Read value "0" from "/proc/sys/crypto/fips_enabled".
2018-03-26 15:09:44 [10558] Not attempting to set NSS FIPS mode.
2018-03-26 15:09:44 [10537] Request10('20171205124815') starts in state 'MONITORING'
2018-03-26 15:09:44 [10537] CA1('SelfSign').identify starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA1('SelfSign').certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA1('SelfSign').profiles starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA1('SelfSign').default_profile starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA1('SelfSign').enrollment_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA1('SelfSign').renewal_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA1('SelfSign').capabilities starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA1('SelfSign').encryption_certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA2('IPA').identify starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA2('IPA').certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA2('IPA').profiles starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA2('IPA').default_profile starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA2('IPA').enrollment_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA2('IPA').renewal_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA2('IPA').capabilities starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA2('IPA').encryption_certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA3('certmaster').identify starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA3('certmaster').certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA3('certmaster').profiles starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA3('certmaster').default_profile starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA3('certmaster').enrollment_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA3('certmaster').renewal_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA3('certmaster').capabilities starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA3('certmaster').encryption_certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA4('dogtag-ipa-renew-agent').identify starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA4('dogtag-ipa-renew-agent').certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA4('dogtag-ipa-renew-agent').profiles starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA4('dogtag-ipa-renew-agent').default_profile starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA4('dogtag-ipa-renew-agent').enrollment_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA4('dogtag-ipa-renew-agent').renewal_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA4('dogtag-ipa-renew-agent').capabilities starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA4('dogtag-ipa-renew-agent').encryption_certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA5('local').identify starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA5('local').certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA5('local').profiles starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA5('local').default_profile starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA5('local').enrollment_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA5('local').renewal_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA5('local').capabilities starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA5('local').encryption_certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA6('dogtag-ipa-ca-renew-agent').identify starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA6('dogtag-ipa-ca-renew-agent').certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA6('dogtag-ipa-ca-renew-agent').profiles starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA6('dogtag-ipa-ca-renew-agent').default_profile starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA6('dogtag-ipa-ca-renew-agent').renewal_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA6('dogtag-ipa-ca-renew-agent').capabilities starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA6('dogtag-ipa-ca-renew-agent').encryption_certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').identify starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').profiles starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').default_profile starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').enrollment_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').renewal_reqs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').capabilities starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').encryption_certs starts (NEED_TO_REFRESH)
2018-03-26 15:09:44 [10537] Adding disabled DBus watch on FD 7 (for Write) for 0x56274d3cbe00.
2018-03-26 15:09:44 [10537] Adding a watch group for FD 7 for 0x56274d3cbe00.
2018-03-26 15:09:44 [10537] Dequeuing FD 7 for 0x56274d3cbe00:(nil).
2018-03-26 15:09:44 [10537] Not queuing FD 7 for 0x56274d3cbe00.
2018-03-26 15:09:44 [10537] Adding enabled DBus watch on FD 7 (for Read) for 0x56274d3cbe00.
2018-03-26 15:09:44 [10537] Dequeuing FD 7 for 0x56274d3cbe00:(nil).
2018-03-26 15:09:44 [10537] Queuing FD 7 for Read for 0x56274d3cbe00:0x56274d3ede30.
2018-03-26 15:09:44 [10537] Connected to system message bus with name ":1.253", unique name "org.fedorahosted.certmonger".
2018-03-26 15:09:44 [10537] Will revisit Request1('20150911121908') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request2('20171030135524') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request3('20171205124733') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request4('20171205124737') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request5('20171205124741') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request6('20171205124744') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request7('20171205124747') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request8('20171205124749') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request9('20171205124756') in 86400 seconds.
2018-03-26 15:09:44 [10537] Will revisit Request10('20171205124815') in 86400 seconds.
2018-03-26 15:09:44 [10537] CA1('SelfSign').identify moved to state 'DISABLED'
2018-03-26 15:09:44 [10537] Will revisit CA1('SelfSign').identify now.
2018-03-26 15:09:44 [10537] CA1('SelfSign').certs moved to state 'DISABLED'
2018-03-26 15:09:44 [10537] Will revisit CA1('SelfSign').certs now.
2018-03-26 15:09:44 [10537] CA1('SelfSign').profiles moved to state 'DISABLED'
2018-03-26 15:09:44 [10537] Will revisit CA1('SelfSign').profiles now.
2018-03-26 15:09:44 [10537] CA1('SelfSign').default_profile moved to state 'DISABLED'
2018-03-26 15:09:44 [10537] Will revisit CA1('SelfSign').default_profile now.
2018-03-26 15:09:44 [10537] CA1('SelfSign').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:09:44 [10537] Will revisit CA1('SelfSign').enrollment_reqs now.
2018-03-26 15:09:44 [10537] CA1('SelfSign').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:09:44 [10537] Will revisit CA1('SelfSign').renewal_reqs now.
2018-03-26 15:09:44 [10537] CA1('SelfSign').capabilities moved to state 'DISABLED'
2018-03-26 15:09:44 [10537] Will revisit CA1('SelfSign').capabilities now.
2018-03-26 15:09:44 [10537] CA1('SelfSign').encryption_certs moved to state 'DISABLED'
2018-03-26 15:09:44 [10537] Will revisit CA1('SelfSign').encryption_certs now.
2018-03-26 15:09:44 [10537] CA2('IPA').identify moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA2('IPA').identify on traffic from 10.
2018-03-26 15:09:44 [10537] CA2('IPA').certs moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA2('IPA').certs on traffic from 12.
2018-03-26 15:09:44 [10537] CA2('IPA').profiles moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA2('IPA').profiles on traffic from 14.
2018-03-26 15:09:44 [10537] CA2('IPA').default_profile moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA2('IPA').default_profile on traffic from 16.
2018-03-26 15:09:44 [10537] CA2('IPA').enrollment_reqs moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA2('IPA').enrollment_reqs on traffic from 18.
2018-03-26 15:09:44 [10537] CA2('IPA').renewal_reqs moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA2('IPA').renewal_reqs on traffic from 20.
2018-03-26 15:09:44 [10537] CA2('IPA').capabilities moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA2('IPA').capabilities on traffic from 22.
2018-03-26 15:09:44 [10537] CA2('IPA').encryption_certs moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA2('IPA').encryption_certs on traffic from 24.
2018-03-26 15:09:44 [10537] CA3('certmaster').identify moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA3('certmaster').identify on traffic from 26.
2018-03-26 15:09:44 [10537] CA3('certmaster').certs moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA3('certmaster').certs on traffic from 28.
2018-03-26 15:09:44 [10537] CA3('certmaster').profiles moved to state 'REFRESHING'
2018-03-26 15:09:44 [10537] Will revisit CA3('certmaster').profiles on traffic from 30.
2018-03-26 15:09:45 [10537] CA3('certmaster').default_profile moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA3('certmaster').default_profile on traffic from 32.
2018-03-26 15:09:45 [10537] CA3('certmaster').enrollment_reqs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA3('certmaster').enrollment_reqs on traffic from 34.
2018-03-26 15:09:45 [10537] CA3('certmaster').renewal_reqs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA3('certmaster').renewal_reqs on traffic from 36.
2018-03-26 15:09:45 [10537] CA3('certmaster').capabilities moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA3('certmaster').capabilities on traffic from 38.
2018-03-26 15:09:45 [10537] CA3('certmaster').encryption_certs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA3('certmaster').encryption_certs on traffic from 40.
2018-03-26 15:09:45 [10537] CA4('dogtag-ipa-renew-agent').identify moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA4('dogtag-ipa-renew-agent').identify on traffic from 42.
2018-03-26 15:09:45 [10537] CA4('dogtag-ipa-renew-agent').certs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA4('dogtag-ipa-renew-agent').certs on traffic from 44.
2018-03-26 15:09:45 [10537] CA4('dogtag-ipa-renew-agent').profiles moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA4('dogtag-ipa-renew-agent').profiles on traffic from 46.
2018-03-26 15:09:45 [10537] CA4('dogtag-ipa-renew-agent').default_profile moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA4('dogtag-ipa-renew-agent').default_profile on traffic from 48.
2018-03-26 15:09:45 [10537] CA4('dogtag-ipa-renew-agent').enrollment_reqs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA4('dogtag-ipa-renew-agent').enrollment_reqs on traffic from 50.
2018-03-26 15:09:45 [10537] CA4('dogtag-ipa-renew-agent').renewal_reqs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA4('dogtag-ipa-renew-agent').renewal_reqs on traffic from 52.
2018-03-26 15:09:45 [10537] CA4('dogtag-ipa-renew-agent').capabilities moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA4('dogtag-ipa-renew-agent').capabilities on traffic from 54.
2018-03-26 15:09:45 [10537] CA4('dogtag-ipa-renew-agent').encryption_certs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA4('dogtag-ipa-renew-agent').encryption_certs on traffic from 56.
2018-03-26 15:09:45 [10537] CA5('local').identify moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA5('local').identify on traffic from 58.
2018-03-26 15:09:45 [10537] CA5('local').certs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA5('local').certs on traffic from 60.
2018-03-26 15:09:45 [10537] CA5('local').profiles moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA5('local').profiles on traffic from 62.
2018-03-26 15:09:45 [10537] CA5('local').default_profile moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA5('local').default_profile on traffic from 64.
2018-03-26 15:09:45 [10537] CA5('local').enrollment_reqs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA5('local').enrollment_reqs on traffic from 66.
2018-03-26 15:09:45 [10537] CA5('local').renewal_reqs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA5('local').renewal_reqs on traffic from 68.
2018-03-26 15:09:45 [10537] CA5('local').capabilities moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA5('local').capabilities on traffic from 70.
2018-03-26 15:09:45 [10537] CA5('local').encryption_certs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA5('local').encryption_certs on traffic from 72.
2018-03-26 15:09:45 [10537] CA6('dogtag-ipa-ca-renew-agent').identify moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').identify on traffic from 74.
2018-03-26 15:09:45 [10537] CA6('dogtag-ipa-ca-renew-agent').certs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').certs on traffic from 76.
2018-03-26 15:09:45 [10537] CA6('dogtag-ipa-ca-renew-agent').profiles moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').profiles on traffic from 78.
2018-03-26 15:09:45 [10537] CA6('dogtag-ipa-ca-renew-agent').default_profile moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').default_profile on traffic from 80.
2018-03-26 15:09:45 [10537] CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs on traffic from 82.
2018-03-26 15:09:45 [10537] CA6('dogtag-ipa-ca-renew-agent').renewal_reqs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').renewal_reqs on traffic from 84.
2018-03-26 15:09:45 [10537] CA6('dogtag-ipa-ca-renew-agent').capabilities moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').capabilities on traffic from 86.
2018-03-26 15:09:45 [10537] CA6('dogtag-ipa-ca-renew-agent').encryption_certs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').encryption_certs on traffic from 88.
2018-03-26 15:09:45 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').identify moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').identify on traffic from 90.
2018-03-26 15:09:45 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').certs moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').certs on traffic from 92.
2018-03-26 15:09:45 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').profiles moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').profiles on traffic from 94.
2018-03-26 15:09:45 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').default_profile moved to state 'REFRESHING'
2018-03-26 15:09:45 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').default_profile on traffic from 96.
2018-03-26 15:09:46 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').enrollment_reqs moved to state 'REFRESHING'
2018-03-26 15:09:46 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').enrollment_reqs on traffic from 98.
2018-03-26 15:09:46 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').renewal_reqs moved to state 'REFRESHING'
2018-03-26 15:09:46 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').renewal_reqs on traffic from 100.
2018-03-26 15:09:46 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').capabilities moved to state 'REFRESHING'
2018-03-26 15:09:46 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').capabilities on traffic from 102.
2018-03-26 15:09:46 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').encryption_certs moved to state 'REFRESHING'
2018-03-26 15:09:46 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').encryption_certs on traffic from 104.
2018-03-26 15:09:46 [10537] CA1('SelfSign').identify moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA1('SelfSign').identify.
2018-03-26 15:09:46 [10537] CA1('SelfSign').certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA1('SelfSign').certs.
2018-03-26 15:09:46 [10537] CA1('SelfSign').profiles moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA1('SelfSign').profiles.
2018-03-26 15:09:46 [10537] CA1('SelfSign').default_profile moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA1('SelfSign').default_profile.
2018-03-26 15:09:46 [10537] CA1('SelfSign').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA1('SelfSign').enrollment_reqs.
2018-03-26 15:09:46 [10537] CA1('SelfSign').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA1('SelfSign').renewal_reqs.
2018-03-26 15:09:46 [10537] CA1('SelfSign').capabilities moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA1('SelfSign').capabilities.
2018-03-26 15:09:46 [10537] CA1('SelfSign').encryption_certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA1('SelfSign').encryption_certs.
2018-03-26 15:09:46 [10537] CA3('certmaster').identify data is unchanged
2018-03-26 15:09:46 [10537] CA3('certmaster').identify moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').identify now.
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').identify now.
2018-03-26 15:09:46 [10537] Waiting for instructions for CA3('certmaster').identify.
2018-03-26 15:09:46 [10537] CA3('certmaster').certs retrieval unsupported
2018-03-26 15:09:46 [10537] CA3('certmaster').certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').certs now.
2018-03-26 15:09:46 [10537] CA3('certmaster').certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA3('certmaster').certs.
2018-03-26 15:09:46 [10537] CA3('certmaster').profiles retrieval unsupported
2018-03-26 15:09:46 [10537] CA3('certmaster').profiles moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').profiles now.
2018-03-26 15:09:46 [10537] CA3('certmaster').profiles moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA3('certmaster').profiles.
2018-03-26 15:09:46 [10537] CA3('certmaster').default_profile retrieval unsupported
2018-03-26 15:09:46 [10537] CA3('certmaster').default_profile moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').default_profile now.
2018-03-26 15:09:46 [10537] CA3('certmaster').default_profile moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA3('certmaster').default_profile.
2018-03-26 15:09:46 [10537] CA3('certmaster').enrollment_reqs retrieval unsupported
2018-03-26 15:09:46 [10537] CA3('certmaster').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').enrollment_reqs now.
2018-03-26 15:09:46 [10537] CA3('certmaster').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA3('certmaster').enrollment_reqs.
2018-03-26 15:09:46 [10537] CA3('certmaster').renewal_reqs retrieval unsupported
2018-03-26 15:09:46 [10537] CA3('certmaster').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').renewal_reqs now.
2018-03-26 15:09:46 [10537] CA3('certmaster').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA3('certmaster').renewal_reqs.
2018-03-26 15:09:46 [10537] CA3('certmaster').capabilities retrieval unsupported
2018-03-26 15:09:46 [10537] CA3('certmaster').capabilities moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').capabilities now.
2018-03-26 15:09:46 [10537] CA3('certmaster').capabilities moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA3('certmaster').capabilities.
2018-03-26 15:09:46 [10537] CA3('certmaster').encryption_certs retrieval unsupported
2018-03-26 15:09:46 [10537] CA3('certmaster').encryption_certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA3('certmaster').encryption_certs now.
2018-03-26 15:09:46 [10537] CA3('certmaster').encryption_certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA3('certmaster').encryption_certs.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').identify data is unchanged
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').identify moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:09:46 [10537] Will revisit CA4('dogtag-ipa-renew-agent').identify now.
2018-03-26 15:09:46 [10537] Will revisit CA4('dogtag-ipa-renew-agent').identify now.
2018-03-26 15:09:46 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').identify.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').certs retrieval unsupported
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA4('dogtag-ipa-renew-agent').certs now.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').certs.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').default_profile retrieval unsupported
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').default_profile moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA4('dogtag-ipa-renew-agent').default_profile now.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').default_profile moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').default_profile.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').enrollment_reqs retrieval unsupported
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA4('dogtag-ipa-renew-agent').enrollment_reqs now.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').enrollment_reqs.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').renewal_reqs retrieval unsupported
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA4('dogtag-ipa-renew-agent').renewal_reqs now.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').renewal_reqs.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').capabilities retrieval unsupported
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').capabilities moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA4('dogtag-ipa-renew-agent').capabilities now.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').capabilities moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').capabilities.
2018-03-26 15:09:46 [10537] CA5('local').identify data is unchanged
2018-03-26 15:09:46 [10537] CA5('local').identify moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:09:46 [10537] Will revisit CA5('local').identify now.
2018-03-26 15:09:46 [10537] Will revisit CA5('local').identify now.
2018-03-26 15:09:46 [10537] Waiting for instructions for CA5('local').identify.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').encryption_certs retrieval unsupported
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').encryption_certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA4('dogtag-ipa-renew-agent').encryption_certs now.
2018-03-26 15:09:46 [10537] CA4('dogtag-ipa-renew-agent').encryption_certs moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').encryption_certs.
2018-03-26 15:09:46 [10537] CA5('local').profiles retrieval unsupported
2018-03-26 15:09:46 [10537] CA5('local').profiles moved to state 'DISABLED'
2018-03-26 15:09:46 [10537] Will revisit CA5('local').profiles now.
2018-03-26 15:09:46 [10537] CA5('local').profiles moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Waiting for instructions for CA5('local').profiles.
2018-03-26 15:09:47 [10537] CA5('local').default_profile retrieval unsupported
2018-03-26 15:09:47 [10537] CA5('local').default_profile moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').default_profile now.
2018-03-26 15:09:47 [10537] CA5('local').default_profile moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Waiting for instructions for CA5('local').default_profile.
2018-03-26 15:09:47 [10537] CA5('local').enrollment_reqs data is unchanged
2018-03-26 15:09:47 [10537] CA5('local').enrollment_reqs moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').enrollment_reqs now.
2018-03-26 15:09:47 [10537] Will revisit CA5('local').enrollment_reqs now.
2018-03-26 15:09:47 [10537] Waiting for instructions for CA5('local').enrollment_reqs.
2018-03-26 15:09:47 [10537] CA5('local').renewal_reqs retrieval unsupported
2018-03-26 15:09:47 [10537] CA5('local').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').renewal_reqs now.
2018-03-26 15:09:47 [10537] CA5('local').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Waiting for instructions for CA5('local').renewal_reqs.
2018-03-26 15:09:47 [10537] CA5('local').capabilities retrieval unsupported
2018-03-26 15:09:47 [10537] CA5('local').capabilities moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').capabilities now.
2018-03-26 15:09:47 [10537] CA5('local').capabilities moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Waiting for instructions for CA5('local').capabilities.
2018-03-26 15:09:47 [10537] CA5('local').certs moved to state 'REFRESHING'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').certs on traffic from 26.
2018-03-26 15:09:47 [10537] CA5('local').encryption_certs retrieval unsupported
2018-03-26 15:09:47 [10537] CA5('local').encryption_certs moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').encryption_certs now.
2018-03-26 15:09:47 [10537] CA5('local').encryption_certs moved to state 'DISABLED'
2018-03-26 15:09:47 [10537] Waiting for instructions for CA5('local').encryption_certs.
2018-03-26 15:09:47 [10537] CA5('local').certs data is unchanged
2018-03-26 15:09:47 [10537] CA5('local').certs moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').certs now.
2018-03-26 15:09:47 [10537] CA5('local').certs moved to state 'ANALYZING'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').certs on traffic from 26.
2018-03-26 15:09:47 [10610] Certificate "Local Signing Authority" valid for 18814051s.
2018-03-26 15:09:47 [10537] CA4('dogtag-ipa-renew-agent').profiles moved to state 'REFRESHING'
2018-03-26 15:09:47 [10537] Will revisit CA4('dogtag-ipa-renew-agent').profiles on traffic from 46.
2018-03-26 15:09:47 [10610] Running result is 1540905439000000.
2018-03-26 15:09:47 [10610] Certificate "Local Signing Authority 2" valid for 1410589s.
2018-03-26 15:09:47 [10610] Running result is 1523501977000000.
2018-03-26 15:09:47 [10610] Certificate "Local Signing Authority 3" no longer valid.
2018-03-26 15:09:47 [10610] Running result is 1523501977000000.
2018-03-26 15:09:47 [10610] Certificate "Local Signing Authority 4" no longer valid.
2018-03-26 15:09:47 [10610] Running result is 1523501977000000.
2018-03-26 15:09:47 [10610] Certificate "Local Signing Authority 5" no longer valid.
2018-03-26 15:09:47 [10610] Running result is 1523501977000000.
2018-03-26 15:09:47 [10610] Final result is 1523501977000000.
2018-03-26 15:09:47 [10610] Time until refresh: 705294.
2018-03-26 15:09:47 [10537] CA5('local').certs moved to state 'NEED_TO_REFRESH'
2018-03-26 15:09:47 [10537] Will revisit CA5('local').certs in 705294 seconds.
2018-03-26 15:09:47 [10537] CA4('dogtag-ipa-renew-agent').profiles data is unchanged
2018-03-26 15:09:47 [10537] CA4('dogtag-ipa-renew-agent').profiles moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:09:47 [10537] Will revisit CA4('dogtag-ipa-renew-agent').profiles now.
2018-03-26 15:09:47 [10537] Will revisit CA4('dogtag-ipa-renew-agent').profiles now.
2018-03-26 15:09:47 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').profiles.
2018-03-26 15:10:02 [10537] CA2('IPA').enrollment_reqs moved to state 'REFRESHING'
2018-03-26 15:10:02 [10537] Will revisit CA2('IPA').enrollment_reqs on traffic from 18.
2018-03-26 15:10:04 [10537] CA2('IPA').enrollment_reqs data is unchanged
2018-03-26 15:10:04 [10537] CA2('IPA').enrollment_reqs moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:10:04 [10537] Will revisit CA2('IPA').enrollment_reqs now.
2018-03-26 15:10:04 [10537] Will revisit CA2('IPA').enrollment_reqs now.
2018-03-26 15:10:04 [10537] Waiting for instructions for CA2('IPA').enrollment_reqs.
2018-03-26 15:10:13 [10537] CA2('IPA').identify moved to state 'REFRESHING'
2018-03-26 15:10:13 [10537] Will revisit CA2('IPA').identify on traffic from 10.
2018-03-26 15:10:14 [10537] CA2('IPA').default_profile retrieval unsupported
2018-03-26 15:10:14 [10537] CA2('IPA').default_profile moved to state 'DISABLED'
2018-03-26 15:10:14 [10537] Will revisit CA2('IPA').default_profile now.
2018-03-26 15:10:14 [10537] CA2('IPA').default_profile moved to state 'DISABLED'
2018-03-26 15:10:14 [10537] Waiting for instructions for CA2('IPA').default_profile.
2018-03-26 15:10:14 [10537] CA2('IPA').identify data is unchanged
2018-03-26 15:10:14 [10537] CA2('IPA').identify moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:10:14 [10537] Will revisit CA2('IPA').identify now.
2018-03-26 15:10:14 [10537] Will revisit CA2('IPA').identify now.
2018-03-26 15:10:14 [10537] Waiting for instructions for CA2('IPA').identify.
2018-03-26 15:10:24 [10537] CA2('IPA').renewal_reqs retrieval unsupported
2018-03-26 15:10:24 [10537] CA2('IPA').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:10:24 [10537] Will revisit CA2('IPA').renewal_reqs now.
2018-03-26 15:10:24 [10537] CA2('IPA').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:10:24 [10537] Waiting for instructions for CA2('IPA').renewal_reqs.
2018-03-26 15:10:24 [10537] CA2('IPA').capabilities retrieval unsupported
2018-03-26 15:10:24 [10537] CA2('IPA').capabilities moved to state 'DISABLED'
2018-03-26 15:10:24 [10537] Will revisit CA2('IPA').capabilities now.
2018-03-26 15:10:24 [10537] CA2('IPA').capabilities moved to state 'DISABLED'
2018-03-26 15:10:24 [10537] Waiting for instructions for CA2('IPA').capabilities.
2018-03-26 15:10:34 [10537] CA2('IPA').encryption_certs retrieval unsupported
2018-03-26 15:10:34 [10537] CA2('IPA').encryption_certs moved to state 'DISABLED'
2018-03-26 15:10:34 [10537] Will revisit CA2('IPA').encryption_certs now.
2018-03-26 15:10:34 [10537] CA2('IPA').encryption_certs moved to state 'DISABLED'
2018-03-26 15:10:34 [10537] Waiting for instructions for CA2('IPA').encryption_certs.
2018-03-26 15:10:44 [10537] CA2('IPA').certs moved to state 'REFRESHING'
2018-03-26 15:10:44 [10537] Will revisit CA2('IPA').certs on traffic from 12.
2018-03-26 15:10:45 [10537] CA2('IPA').certs moved to state 'REFRESHING'
2018-03-26 15:10:45 [10537] Will revisit CA2('IPA').certs on traffic from 10.
2018-03-26 15:10:45 [10537] CA2('IPA').certs moved to state 'REFRESHING'
2018-03-26 15:10:45 [10537] Will revisit CA2('IPA').certs on traffic from 10.
2018-03-26 15:10:45 [10537] CA2('IPA').certs data is unchanged
2018-03-26 15:10:45 [10537] CA2('IPA').certs moved to state 'NEED_TO_ANALYZE'
2018-03-26 15:10:45 [10537] Will revisit CA2('IPA').certs now.
2018-03-26 15:10:45 [10537] CA2('IPA').certs moved to state 'ANALYZING'
2018-03-26 15:10:45 [10537] Will revisit CA2('IPA').certs on traffic from 10.
2018-03-26 15:10:45 [10798] Certificate "INTERLINX.BC.CA IPA CA" valid for 548116439s.
2018-03-26 15:10:45 [10798] Running result is 2070207885000000.
2018-03-26 15:10:45 [10798] Final result is 2070207885000000.
2018-03-26 15:10:45 [10798] Time until refresh: 274058219.
2018-03-26 15:10:45 [10537] CA2('IPA').certs moved to state 'ANALYZING'
2018-03-26 15:10:45 [10537] Will revisit CA2('IPA').certs on traffic from 10.
2018-03-26 15:10:45 [10537] CA2('IPA').certs moved to state 'NEED_TO_REFRESH'
2018-03-26 15:10:45 [10537] Will revisit CA2('IPA').certs in 31536000 seconds.
2018-03-26 15:10:54 [10537] CA2('IPA').profiles retrieval unsupported
2018-03-26 15:10:54 [10537] CA2('IPA').profiles moved to state 'DISABLED'
2018-03-26 15:10:54 [10537] Will revisit CA2('IPA').profiles now.
2018-03-26 15:10:54 [10537] CA2('IPA').profiles moved to state 'DISABLED'
2018-03-26 15:10:54 [10537] Waiting for instructions for CA2('IPA').profiles.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').renewal_reqs retrieval unsupported
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').renewal_reqs now.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').renewal_reqs.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').encryption_certs retrieval unsupported
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').encryption_certs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').encryption_certs now.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').encryption_certs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA7('dogtag-ipa-ca-renew-agent-reuse').encryption_certs.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').profiles retrieval unsupported
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').profiles moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').profiles now.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').profiles moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').profiles.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs retrieval unsupported
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs now.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').enrollment_reqs.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').identify retrieval unsupported
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').identify moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').identify now.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').identify moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA7('dogtag-ipa-ca-renew-agent-reuse').identify.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').profiles retrieval unsupported
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').profiles moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').profiles now.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').profiles moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA7('dogtag-ipa-ca-renew-agent-reuse').profiles.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').capabilities retrieval unsupported
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').capabilities moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').capabilities now.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').capabilities moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA7('dogtag-ipa-ca-renew-agent-reuse').capabilities.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').encryption_certs retrieval unsupported
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').encryption_certs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').encryption_certs now.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').encryption_certs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').encryption_certs.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').certs retrieval unsupported
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').certs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').certs now.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').certs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA7('dogtag-ipa-ca-renew-agent-reuse').certs.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').certs retrieval unsupported
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').certs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').certs now.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').certs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').certs.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').enrollment_reqs retrieval unsupported
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').enrollment_reqs now.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').enrollment_reqs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA7('dogtag-ipa-ca-renew-agent-reuse').enrollment_reqs.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').capabilities retrieval unsupported
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').capabilities moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').capabilities now.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').capabilities moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').capabilities.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').renewal_reqs retrieval unsupported
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').renewal_reqs now.
2018-03-26 15:12:00 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').renewal_reqs moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA7('dogtag-ipa-ca-renew-agent-reuse').renewal_reqs.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').default_profile retrieval unsupported
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').default_profile moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').default_profile now.
2018-03-26 15:12:00 [10537] CA6('dogtag-ipa-ca-renew-agent').default_profile moved to state 'DISABLED'
2018-03-26 15:12:00 [10537] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').default_profile.
2018-03-26 15:12:01 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').default_profile retrieval unsupported
2018-03-26 15:12:01 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').default_profile moved to state 'DISABLED'
2018-03-26 15:12:01 [10537] Will revisit CA7('dogtag-ipa-ca-renew-agent-reuse').default_profile now.
2018-03-26 15:12:01 [10537] CA7('dogtag-ipa-ca-renew-agent-reuse').default_profile moved to state 'DISABLED'
2018-03-26 15:12:01 [10537] Waiting for instructions for CA7('dogtag-ipa-ca-renew-agent-reuse').default_profile.
2018-03-26 15:12:01 [10537] CA6('dogtag-ipa-ca-renew-agent').identify retrieval unsupported
2018-03-26 15:12:01 [10537] CA6('dogtag-ipa-ca-renew-agent').identify moved to state 'DISABLED'
2018-03-26 15:12:01 [10537] Will revisit CA6('dogtag-ipa-ca-renew-agent').identify now.
2018-03-26 15:12:01 [10537] CA6('dogtag-ipa-ca-renew-agent').identify moved to state 'DISABLED'
2018-03-26 15:12:01 [10537] Waiting for instructions for CA6('dogtag-ipa-ca-renew-agent').identify.
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:12:34 [10537] Got netlink traffic.
2018-03-26 15:12:34 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:12:34 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:13:08 [10537] Got netlink traffic.
2018-03-26 15:13:08 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:13:08 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 128 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).
2018-03-26 15:15:38 [10537] Got netlink traffic.
2018-03-26 15:15:38 [10537] Got 108 bytes from netlink socket.
2018-03-26 15:15:38 [10537] No more netlink traffic (for now).

and it continue to run in that manner.

Does the above debug show it to be taking extraordinarily long to get to a started state, and if so, why?

I'd check the status of your CA. It seems to be taking quite a long time talking to it.

Would that be the dirsrv@<REALM>.service unit?

What should I be looking for exactly?

pki-tomcatd@pki-tomcat.service

I'm not sure what to look for exactly but it provides a debug log that you might be able to use to correlate times.

Most recent pki-tomcatd@pki-tomcat.service's journal/startup log:

Mar 31 20:11:55 server.interlinx.bc.ca systemd[1]: Starting PKI Tomcat Server pki-tomcat...
Mar 31 20:12:03 server.interlinx.bc.ca pkidaemon[9707]: -----------------------
Mar 31 20:12:03 server.interlinx.bc.ca pkidaemon[9707]: Banner is not installed
Mar 31 20:12:03 server.interlinx.bc.ca pkidaemon[9707]: -----------------------
Mar 31 20:12:07 server.interlinx.bc.ca pkidaemon[9707]: ----------------------
Mar 31 20:12:07 server.interlinx.bc.ca pkidaemon[9707]: Enabled all subsystems
Mar 31 20:12:07 server.interlinx.bc.ca pkidaemon[9707]: ----------------------
Mar 31 20:12:07 server.interlinx.bc.ca systemd[1]: Started PKI Tomcat Server pki-tomcat.
Mar 31 20:12:08 server.interlinx.bc.ca server[9950]: Java virtual machine used: /usr/lib/jvm/jre-1.8.0-openjdk/bin/java
Mar 31 20:12:08 server.interlinx.bc.ca server[9950]: classpath used: /usr/share/tomcat/bin/bootstrap.jar:/usr/share/tomcat/bin/tomcat-juli.jar:/usr/share/java/commons-daemon.jar
Mar 31 20:12:08 server.interlinx.bc.ca server[9950]: main class used: org.apache.catalina.startup.Bootstrap
Mar 31 20:12:08 server.interlinx.bc.ca server[9950]: flags used: -DRESTEASY_LIB=/usr/share/java/resteasy-base
Mar 31 20:12:08 server.interlinx.bc.ca server[9950]: options used: -Dcatalina.base=/var/lib/pki/pki-tomcat -Dcatalina.home=/usr/share/tomcat -Djava.endorsed.dirs= -Djava.io.tmpdir=/var/lib/pki/pki-tomcat/temp -Djava.util.logging.config.file=/var/lib/pki/pki-tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager     -Djava.security.manager     -Djava.security.policy==/var/lib/pki/pki-tomcat/conf/catalina.policy
Mar 31 20:12:08 server.interlinx.bc.ca server[9950]: arguments used: start
Mar 31 20:12:17 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:16 PM org.apache.catalina.startup.ClassLoaderFactory validateFile
Mar 31 20:12:17 server.interlinx.bc.ca server[9950]: WARNING: Problem with JAR file [/usr/share/pki/server/common/lib/symkey.jar], exists: [false], canRead: [false]
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:35 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'enableOCSP' to 'false' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ocspResponderURL' to 'http://server.interlinx.bc.ca:9080/ca/ocsp' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ocspResponderCertNickname' to 'ocspSigningCert cert-pki-ca' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ocspCacheSize' to '1000' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ocspMinCacheEntryDuration' to '60' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ocspMaxCacheEntryDuration' to '120' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ocspTimeout' to '10' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'strictCiphers' to 'true' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'sslOptions' to 'ssl2=false,ssl3=false,tls=true' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ssl2Ciphers' to '-SSL2_RC4_128_WITH_MD5,-SSL2_RC4_128_EXPORT40_WITH_MD5,-SSL2_RC2_128_CBC_WITH_MD5,-SSL2_RC2_128_CBC_EXPORT40_WITH_MD5,-SSL2_DES_64_CBC_WITH_MD5,-SSL2_DES_192_EDE3_CBC_WITH_MD5' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'ssl3Ciphers' to '-SSL3_FORTEZZA_DMS_WITH_NULL_SHA,-SSL3_FORTEZZA_DMS_WITH_RC4_128_SHA,+SSL3_RSA_WITH_RC4_128_SHA,-SSL3_RSA_EXPORT_WITH_RC4_40_MD5,+SSL3_RSA_WITH_3DES_EDE_CBC_SHA,-SSL3_RSA_WITH_DES_CBC_SHA,-SSL3_RSA_EXPORT_WITH_RC2_CBC_40_MD5,-SSL3_FORTEZZA_DMS_WITH_FORTEZZA_CBC_SHA,-SSL_RSA_FIPS_WITH_DES_CBC_SHA,+SSL_RSA_FIPS_WITH_3DES_EDE_CBC_SHA,-SSL3_RSA_WITH_NULL_MD5,-TLS_RSA_EXPORT1024_WITH_RC4_56_SHA,-TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,+TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'tlsCiphers' to '-TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,-TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA,+TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA,+TLS_ECDH_RSA_WITH_AES_128_CBC_SHA,+TLS_ECDH_RSA_WITH_AES_256_CBC_SHA,-TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,+TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA,+TLS_RSA_WITH_3DES_EDE_CBC_SHA,+TLS_RSA_WITH_AES_128_CBC_SHA,+TLS_RSA_WITH_AES_256_CBC_SHA,+TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA,+TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA,-TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA,-TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,-TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA,+TLS_DHE_DSS_WITH_3DES_EDE_CBC_SHA,+TLS_DHE_DSS_WITH_AES_128_CBC_SHA,+TLS_DHE_DSS_WITH_AES_256_CBC_SHA,+TLS_DHE_RSA_WITH_3DES_EDE_CBC_SHA,+TLS_DHE_RSA_WITH_AES_128_CBC_SHA,+TLS_DHE_RSA_WITH_AES_256_CBC_SHA' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'sslVersionRangeStream' to 'tls1_0:tls1_2' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'sslVersionRangeDatagram' to 'tls1_1:tls1_2' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'sslRangeCiphers' to '-TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA,-TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA,+TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA,+TLS_ECDH_RSA_WITH_AES_128_CBC_SHA,+TLS_ECDH_RSA_WITH_AES_256_CBC_SHA,-TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA,+TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA,+TLS_RSA_WITH_3DES_EDE_CBC_SHA,+TLS_RSA_WITH_AES_128_CBC_SHA,+TLS_RSA_WITH_AES_256_CBC_SHA,+TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA,+TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA,-TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA,-TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA,-TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA,+TLS_DHE_DSS_WITH_3DES_EDE_CBC_SHA,+TLS_DHE_DSS_WITH_AES_128_CBC_SHA,+TLS_DHE_DSS_WITH_AES_256_CBC_SHA,+TLS_DHE_RSA_WITH_3DES_EDE_CBC_SHA,+TLS_DHE_RSA_WITH_AES_128_CBC_SHA,+TLS_DHE_RSA_WITH_AES_256_CBC_SHA,+TLS_DHE_RSA_WITH_AES_128_CBC_SHA256,+TLS_DHE_RSA_WITH_AES_256_CBC_SHA256,+TLS_RSA_WITH_AES_128_CBC_SHA256,+TLS_RSA_WITH_AES_256_CBC_SHA256,+TLS_RSA_WITH_AES_128_GCM_SHA256,+TLS_DHE_RSA_WITH_AES_128_GCM_SHA256,+TLS_DHE_DSS_WITH_AES_128_GCM_SHA256,+TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256,+TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256,+TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256,+TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256,+TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256,+TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'serverCertNickFile' to '/var/lib/pki/pki-tomcat/conf/serverCertNick.conf' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'passwordFile' to '/var/lib/pki/pki-tomcat/conf/password.conf' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'passwordClass' to 'org.apache.tomcat.util.net.jss.PlainPasswordFile' did not find a matching property.
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:36 PM org.apache.catalina.startup.SetAllPropertiesRule begin
Mar 31 20:12:36 server.interlinx.bc.ca server[9950]: WARNING: [SetAllPropertiesRule]{Server/Service/Connector} Setting property 'certdbDir' to '/var/lib/pki/pki-tomcat/alias' did not find a matching property.
Mar 31 20:12:37 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:37 PM org.apache.tomcat.util.digester.SetPropertiesRule begin
Mar 31 20:12:37 server.interlinx.bc.ca server[9950]: WARNING: [SetPropertiesRule]{Server/Service/Engine/Host} Setting property 'xmlValidation' to 'false' did not find a matching property.
Mar 31 20:12:37 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:37 PM org.apache.tomcat.util.digester.SetPropertiesRule begin
Mar 31 20:12:37 server.interlinx.bc.ca server[9950]: WARNING: [SetPropertiesRule]{Server/Service/Engine/Host} Setting property 'xmlNamespaceAware' to 'false' did not find a matching property.
Mar 31 20:12:39 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:39 PM org.apache.coyote.AbstractProtocol init
Mar 31 20:12:39 server.interlinx.bc.ca server[9950]: INFO: Initializing ProtocolHandler ["http-bio-8080"]
Mar 31 20:12:42 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:42 PM org.apache.coyote.AbstractProtocol init
Mar 31 20:12:42 server.interlinx.bc.ca server[9950]: INFO: Initializing ProtocolHandler ["http-bio-8443"]
Mar 31 20:12:45 server.interlinx.bc.ca server[9950]: Error: SSL cipher "TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256" not recognized by tomcatjss
Mar 31 20:12:45 server.interlinx.bc.ca server[9950]: Error: SSL cipher "TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256" not recognized by tomcatjss
Mar 31 20:12:46 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:46 PM org.apache.coyote.AbstractProtocol init
Mar 31 20:12:46 server.interlinx.bc.ca server[9950]: INFO: Initializing ProtocolHandler ["ajp-bio-127.0.0.1-8009"]
Mar 31 20:12:46 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:46 PM org.apache.catalina.startup.Catalina load
Mar 31 20:12:46 server.interlinx.bc.ca server[9950]: INFO: Initialization processed in 24895 ms
Mar 31 20:12:47 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:47 PM org.apache.catalina.core.StandardService startInternal
Mar 31 20:12:47 server.interlinx.bc.ca server[9950]: INFO: Starting service Catalina
Mar 31 20:12:47 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:47 PM org.apache.catalina.core.StandardEngine startInternal
Mar 31 20:12:47 server.interlinx.bc.ca server[9950]: INFO: Starting Servlet Engine: Apache Tomcat/7.0.76
Mar 31 20:12:48 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:12:47 PM org.apache.catalina.startup.HostConfig deployDescriptor
Mar 31 20:12:48 server.interlinx.bc.ca server[9950]: INFO: Deploying configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/pki.xml
Mar 31 20:13:19 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:13:19 PM org.apache.catalina.startup.TldConfig execute
Mar 31 20:13:19 server.interlinx.bc.ca server[9950]: INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Mar 31 20:13:25 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:13:25 PM org.apache.catalina.startup.HostConfig deployDescriptor
Mar 31 20:13:25 server.interlinx.bc.ca server[9950]: INFO: Deployment of configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/pki.xml has finished in 37,049 ms
Mar 31 20:13:25 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:13:25 PM org.apache.catalina.startup.HostConfig deployDescriptor
Mar 31 20:13:25 server.interlinx.bc.ca server[9950]: INFO: Deploying configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/ROOT.xml
Mar 31 20:13:38 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:13:38 PM org.apache.catalina.startup.TldConfig execute
Mar 31 20:13:38 server.interlinx.bc.ca server[9950]: INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Mar 31 20:13:38 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:13:38 PM org.apache.catalina.startup.HostConfig deployDescriptor
Mar 31 20:13:38 server.interlinx.bc.ca server[9950]: INFO: Deployment of configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/ROOT.xml has finished in 13,366 ms
Mar 31 20:13:38 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:13:38 PM org.apache.catalina.startup.HostConfig deployDescriptor
Mar 31 20:13:38 server.interlinx.bc.ca server[9950]: INFO: Deploying configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/ca.xml
Mar 31 20:13:38 server.interlinx.bc.ca server[9950]: SSLAuthenticatorWithFallback: Creating SSL authenticator with fallback
Mar 31 20:13:38 server.interlinx.bc.ca server[9950]: SSLAuthenticatorWithFallback: Setting container
Mar 31 20:14:07 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:14:07 PM org.apache.catalina.startup.TldConfig execute
Mar 31 20:14:07 server.interlinx.bc.ca server[9950]: INFO: At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
Mar 31 20:14:07 server.interlinx.bc.ca server[9950]: SSLAuthenticatorWithFallback: Initializing authenticators
Mar 31 20:14:07 server.interlinx.bc.ca server[9950]: SSLAuthenticatorWithFallback: Starting authenticators
Mar 31 20:14:09 server.interlinx.bc.ca server[9950]: CMSEngine.initializePasswordStore() begins
Mar 31 20:14:09 server.interlinx.bc.ca server[9950]: CMSEngine.initializePasswordStore(): tag=internaldb
Mar 31 20:14:09 server.interlinx.bc.ca server[9950]: CMSEngine.initializePasswordStore(): tag=replicationdb
Mar 31 20:14:26 server.interlinx.bc.ca server[9950]: CA is started.
Mar 31 20:14:27 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:14:27 PM org.apache.catalina.startup.HostConfig deployDescriptor
Mar 31 20:14:27 server.interlinx.bc.ca server[9950]: INFO: Deployment of configuration descriptor /etc/pki/pki-tomcat/Catalina/localhost/ca.xml has finished in 48,723 ms
Mar 31 20:14:27 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:14:27 PM org.apache.coyote.AbstractProtocol start
Mar 31 20:14:27 server.interlinx.bc.ca server[9950]: INFO: Starting ProtocolHandler ["http-bio-8080"]
Mar 31 20:14:27 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:14:27 PM org.apache.coyote.AbstractProtocol start
Mar 31 20:14:27 server.interlinx.bc.ca server[9950]: INFO: Starting ProtocolHandler ["http-bio-8443"]
Mar 31 20:14:27 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:14:27 PM org.apache.coyote.AbstractProtocol start
Mar 31 20:14:27 server.interlinx.bc.ca server[9950]: INFO: Starting ProtocolHandler ["ajp-bio-127.0.0.1-8009"]
Mar 31 20:14:28 server.interlinx.bc.ca server[9950]: Mar 31, 2018 8:14:28 PM org.apache.catalina.startup.Catalina start
Mar 31 20:14:28 server.interlinx.bc.ca server[9950]: INFO: Server startup in 101506 ms

There seems to be quite a lot of warnings and errors in there and it takes really, quite a long time to start up.

But isn't that exactly what ipactl is supposed to be managing... starting up services in an orderly fashion so that whatever depends on pki-tomcatd@pki-tomcat.service doesn't start until pki-tomcatd@pki-tomcat.service is fully started?

ipactl doesn't manage certmonger

The logs don't appear to cover the same time period. Pasting huge logs is probably not very efficient in any case.

One example. If you look at the certmonger logs it is trying to get a list of profiles from the CA and it takes 15 seconds:

2018-03-26 15:09:47 [10537] Waiting for instructions for CA4('dogtag-ipa-renew-agent').profiles.
2018-03-26 15:10:02 [10537] CA2('IPA').enrollment_reqs moved to state 'REFRESHING'

There are other similar wait times. It may be that your machine is underpowered so any CA commands simply take a lot of time, I don't know.

So, if certmonger depends on dirsrv@<REALM>.service why do I have this ordering in my journal:

Apr 04 07:15:08 server.interlinx.bc.ca systemd[1]: Starting Certificate monitoring and PKI enrollment...
Apr 04 07:15:09 server.interlinx.bc.ca certmonger[1390]: 2018-04-04 07:15:09 [1390] Starting up.
...
Apr 04 07:16:38 server.interlinx.bc.ca systemd[1]: certmonger.service start operation timed out. Terminating.
...
Apr 04 07:17:06 server.interlinx.bc.ca systemd[1]: Failed to start Certificate monitoring and PKI enrollment.
...
Apr 04 07:17:06 server.interlinx.bc.ca systemd[1]: Unit certmonger.service entered failed state.
Apr 04 07:17:06 server.interlinx.bc.ca systemd[1]: certmonger.service failed.
Apr 04 07:18:11 server.interlinx.bc.ca systemd[1]: Starting PKI Tomcat Server pki-tomcat...
Apr 04 07:18:19 server.interlinx.bc.ca pkidaemon[5585]: -----------------------
Apr 04 07:18:19 server.interlinx.bc.ca pkidaemon[5585]: Banner is not installed
Apr 04 07:18:19 server.interlinx.bc.ca pkidaemon[5585]: -----------------------
Apr 04 07:18:22 server.interlinx.bc.ca pkidaemon[5585]: ----------------------
Apr 04 07:18:22 server.interlinx.bc.ca pkidaemon[5585]: Enabled all subsystems
Apr 04 07:18:22 server.interlinx.bc.ca pkidaemon[5585]: ----------------------
Apr 04 07:18:23 server.interlinx.bc.ca systemd[1]: Started PKI Tomcat Server pki-tomcat.

Is there a dependency declaration missing in the unit files that ensures that dirsrv@<REALM>.service is started before certmonger.service? I'll try adding one and see if that resolves the problem.

So I added:

[Unit]
After=dirsrv.target
Wants=dirsrv.target

to certmonger.service and that seems to have resolved the certmonger.service timeout at boot.

Note that it should depend on pki-tomcatd.target if anything.

I will try that, although systemctl status indicates that it would have worked also:

# systemctl status dirsrv.target
● dirsrv.target - 389 Directory Server
   Loaded: loaded (/usr/lib/systemd/system/dirsrv.target; disabled; vendor preset: disabled)
   Active: active since Wed 2018-04-04 10:44:14 EDT; 1h 27min ago

Apr 04 10:44:14 server.interlinx.bc.ca systemd[1]: Reached target 389 Directory Server.
Apr 04 10:44:14 server.interlinx.bc.ca systemd[1]: Starting 389 Directory Server.
# systemctl status pki-tomcatd.target
● pki-tomcatd.target - PKI Tomcat Server
   Loaded: loaded (/usr/lib/systemd/system/pki-tomcatd.target; disabled; vendor preset: disabled)
   Active: active since Wed 2018-04-04 10:46:36 EDT; 1h 25min ago

Apr 04 10:46:36 server.interlinx.bc.ca systemd[1]: Reached target PKI Tomcat Server.
Apr 04 10:46:36 server.interlinx.bc.ca systemd[1]: Starting PKI Tomcat Server.

given that it started 2 minutes later than dirsrv.target even.

But it's interesting that in my limited testing, dirsrv.target seems to work.

I didn't say it wouldn't work but it doesn't really reflect the dependency right. dirsrv is a requirement of pki-tomcat so the chain is "correct" I suppose but it doesn't reflect the dependency properly.

Then again, I don't recall this ever having come up before.

Yeah, you are right:

# systemctl cat pki-tomcatd.target | grep -i after
After=syslog.target network.target dirsrv.target

So if it works being After dirsrv.target it has to work being after pki-tomcatd.target,

Then again, I don't recall this ever having come up before.

You probably just have not run freeipa on a machine slow enough that certmonger loses the race most of the time.

But getting the dependencies right should eliminate races and make ordering predictable.

I will submit a PR...

If there is a bug it is a bug in IPA, not certmonger. certmonger can run just fine outside the scope of IPA and cannot rely on it.

Yes, not saying a bug in certmonger. Just that the certmonger.service needs to be told to wait for pki-tomcatd.target which can be done by adding /etc/systemd/system/certmonger.service.d/ipa.conf with:

[Unit]
After=pki-tomcatd.target
Wants=pki-tomcatd.target

The question about solving it is can/should that be a file installed by the ipa-server RPM or is it preferred to be generated by the ipa installation process like the .../httpd.service.d/ipa.conf is?

I'd prefer the latter. If you want to do it by RPM, it needs to be installed to /usr/lib/systemd/system/certmonger.service.wants/ and certmonger needs to provide that directory. So it would mean doing two changes instead of one.

But if it's done by ipa-server-install then it can/should be done with (just) a /etc/systemd/system/certmonger.service.d/ipa.conf file containing:

[Unit]
After=pki-tomcatd.target
Wants=pki-tomcatd.target

Am I understanding that correctly?

Metadata Update from @fbarreto:
- Issue priority set to: low
- Issue set to the milestone: Future Releases
5 years ago

This was probably related to https://bugzilla.redhat.com/show_bug.cgi?id=1656519 where certmogner was closing file descriptors in an inefficient way which was quite noticeable on slower systems or those with a huge number of available descriptors.

This was fixed upstream in certmonger-0.79.9 in commit https://pagure.io/certmonger/c/9bbb628620d4e586941344e1bdbbc166a885c0a9?branch=master

Marking as fixed.

Metadata Update from @rcritten:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)
3 years ago

Login to comment on this ticket.

Metadata
None
None
None
None
low
None
None
None
None
None
None
None
None
None
None
None
None
None
None
None
None
None
None
Powered by Pagure 5.13.3
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.