[root@caer ~]# *tail -f /var/log/httpd/error_log*
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: WSGI
xmlserver_session.__call__:
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: found session cookie_id =
bc2c7ed0eccd840dc266efaf9ece913c
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: found session data in
cache with id=bc2c7ed0eccd840dc266efaf9ece913c
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
xmlserver_session.__call__: session_id=bc2c7ed0eccd840dc266efaf9ece913c
start_timestamp=2016-07-21T11:58:54 access_timestamp=2016-07-21T12:01:21
expiration_timestamp=2016-07-21T12:18:54
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: storing ccache data into
file "/var/run/ipa_memcached/krbcc_13554"
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: get_credential_times:
principal=HTTP/caer.teloip....@teloip.net
<mailto:caer.teloip....@teloip.net>, authtime=07/21/16 10:31:46,
starttime=07/21/16 10:43:26, endtime=07/22/16 10:31:44,
renew_till=12/31/69 19:00:00
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: get_credential_times:
principal=HTTP/caer.teloip....@teloip.net
<mailto:caer.teloip....@teloip.net>, authtime=07/21/16 10:31:46,
starttime=07/21/16 10:43:26, endtime=07/22/16 10:31:44,
renew_till=12/31/69 19:00:00
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: KRB5_CCache
FILE:/var/run/ipa_memcached/krbcc_13554 endtime=1469197904 (07/22/16
10:31:44)
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
set_session_expiration_time: duration_type=inactivity_timeout
duration=1200 max_age=1469197604 expiration=1469118081.77
(2016-07-21T12:21:21)
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: WSGI xmlserver.__call__:
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: Created connection
context.ldap2
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: WSGI
WSGIExecutioner.__call__:
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: raw: cert_show(u'1')
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: cert_show(u'1')
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: IPA: virtual verify
retrieve certificate
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
ipaserver.plugins.dogtag.ra.get_certificate()
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: https_request
'https://caer.teloip.net:443/ca/agent/ca/displayBySerial'
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: https_request post
'xml=true&serialNumber=1'
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: NSSConnection init
caer.teloip.net <http://caer.teloip.net>
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: Connecting: 10.20.0.75:0
<http://10.20.0.75:0>
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
auth_certificate_callback: check_sig=True is_server=False
*.*
*.*
*.*
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: approved_usage =
SSLServer intended_usage = SSLServer
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: cert valid True for
"CN=caer.teloip.net <http://caer.teloip.net>,O=TELOIP.NET
<http://TELOIP.NET>"
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: handshake complete, peer
= 10.20.0.75:443 <http://10.20.0.75:443>
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG:
auth_certificate_callback: check_sig=True is_server=False
*.*
*.*
*.*
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: approved_usage =
SSLServer intended_usage = SSLServer
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: cert valid True for
"CN=caer.teloip.net <http://caer.teloip.net>,O=TELOIP.NET
<http://TELOIP.NET>"
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: handshake complete, peer
= 10.20.0.75:443 <http://10.20.0.75:443>
[Thu Jul 21 12:01:21 2016] [error] ipa: ERROR:
ipaserver.plugins.dogtag.ra.get_certificate(): Unable to communicate
with CMS (Not Found)
[Thu Jul 21 12:01:21 2016] [error] ipa: INFO: ad...@teloip.net
<mailto:ad...@teloip.net>: cert_show(u'1'): CertificateOperationError
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: response:
CertificateOperationError: Certificate operation cannot be completed:
Unable to communicate with CMS (Not Found)
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: Destroyed connection
context.ldap2
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: reading ccache data from
file "/var/run/ipa_memcached/krbcc_13554"
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: store session:
session_id=bc2c7ed0eccd840dc266efaf9ece913c
start_timestamp=2016-07-21T11:58:54 access_timestamp=2016-07-21T12:01:21
expiration_timestamp=2016-07-21T12:21:21
Does `ipa cert-show` communicate with the same replica? Could be
verified by `ipa -vv cert-show`
*It's asking for the serial number of the certificate. If I give 64
(serial number of ipaCert ), I get ipa: ERROR: Certificate operation
cannot be completed: Unable to communicate with CMS (Not Found)*
*[root@caer ~]# ipa -vv cert-show*
ipa: DEBUG: importing all plugin modules in
'/usr/lib/python2.6/site-packages/ipalib/plugins'...
*.*
*.*
*.*
ipa: DEBUG: stdout=ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;
Domain=caer.teloip.net <http://caer.teloip.net>; Path=/ipa; Expires=Thu,
21 Jul 2016 16:25:32 GMT; Secure; HttpOnly
ipa: DEBUG: stderr=
ipa: DEBUG: found session_cookie in persistent storage for principal
'ad...@teloip.net <mailto:ad...@teloip.net>', cookie:
'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c; Domain=caer.teloip.net
<http://caer.teloip.net>; Path=/ipa; Expires=Thu, 21 Jul 2016 16:25:32
GMT; Secure; HttpOnly'
ipa: DEBUG: setting session_cookie into context
'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;'
ipa: INFO: trying https://caer.teloip.net/ipa/session/xml
ipa: DEBUG: Created connection context.xmlclient
Serial number: 64
ipa: DEBUG: raw: cert_show(u'64')
ipa: DEBUG: cert_show(u'64')
ipa: INFO: Forwarding 'cert_show' to server
u'https://caer.teloip.net/ipa/session/xml'
ipa: DEBUG: NSSConnection init caer.teloip.net <http://caer.teloip.net>
ipa: DEBUG: Connecting: 10.20.0.75:0 <http://10.20.0.75:0>
send: u'POST /ipa/session/xml HTTP/1.0\r\nHost: caer.teloip.net
<http://caer.teloip.net>\r\nAccept-Language: en-us\r\nReferer:
https://caer.teloip.net/ipa/xml\r\nCookie:
ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;\r\nUser-Agent:
xmlrpclib.py/1.0.1 <http://xmlrpclib.py/1.0.1> (by www.pythonware.com
<http://www.pythonware.com>)\r\nContent-Type:
text/xml\r\nContent-Length: 268\r\n\r\n'
ipa: DEBUG: auth_certificate_callback: check_sig=True is_server=False
*.*
*.*
*.*
ipa: DEBUG: approved_usage = SSLServer intended_usage = SSLServer
ipa: DEBUG: cert valid True for "CN=caer.teloip.net
<http://caer.teloip.net>,O=TELOIP.NET <http://TELOIP.NET>"
ipa: DEBUG: handshake complete, peer = 10.20.0.75:443
<http://10.20.0.75:443>
send: "<?xml version='1.0'
encoding='UTF-8'?>\n<methodCall>\n<methodName>cert_show</methodName>\n<params>\n<param>\n<value><array><data>\n<value><string>64</string></value>\n</data></array></value>\n</param>\n<param>\n<value><struct>\n</struct></value>\n</param>\n</params>\n</methodCall>\n"
reply: 'HTTP/1.1 200 Success\r\n'
header: Date: Thu, 21 Jul 2016 16:05:40 GMT
header: Server: Apache/2.2.15 (CentOS)
header: Set-Cookie: ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;
Domain=caer.teloip.net <http://caer.teloip.net>; Path=/ipa; Expires=Thu,
21 Jul 2016 16:25:40 GMT; Secure; HttpOnly
header: Connection: close
header: Content-Type: text/xml; charset=utf-8
ipa: DEBUG: received Set-Cookie
'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c; Domain=caer.teloip.net
<http://caer.teloip.net>; Path=/ipa; Expires=Thu, 21 Jul 2016 16:25:40
GMT; Secure; HttpOnly'
ipa: DEBUG: storing cookie
'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c; Domain=caer.teloip.net
<http://caer.teloip.net>; Path=/ipa; Expires=Thu, 21 Jul 2016 16:25:40
GMT; Secure; HttpOnly' for principal ad...@teloip.net
<mailto:ad...@teloip.net>
ipa: DEBUG: args=keyctl search @s user
ipa_session_cookie:ad...@teloip.net
<mailto:ipa_session_cookie%3aad...@teloip.net>
ipa: DEBUG: stdout=457971704
ipa: DEBUG: stderr=
ipa: DEBUG: args=keyctl search @s user
ipa_session_cookie:ad...@teloip.net
<mailto:ipa_session_cookie%3aad...@teloip.net>
ipa: DEBUG: stdout=457971704
ipa: DEBUG: stderr=
ipa: DEBUG: args=keyctl pupdate 457971704
ipa: DEBUG: stdout=
ipa: DEBUG: stderr=
body: "<?xml version='1.0'
encoding='UTF-8'?>\n<methodResponse>\n<fault>\n<value><struct>\n<member>\n<name>faultCode</name>\n<value><int>4301</int></value>\n</member>\n<member>\n<name>faultString</name>\n<value><string>Certificate
operation cannot be completed: Unable to communicate with CMS (Not
Found)</string></value>\n</member>\n</struct></value>\n</fault>\n</methodResponse>\n"
ipa: DEBUG: Caught fault 4301 from server
https://caer.teloip.net/ipa/session/xml: Certificate operation cannot be
completed: Unable to communicate with CMS (Not Found)
ipa: DEBUG: Destroyed connection context.xmlclient
ipa: ERROR: Certificate operation cannot be completed: Unable to
communicate with CMS (Not Found)
[root@caer ~]#
But more interesting is: SelfTestSubsystem: The CRITICAL self test
plugin called selftests.container.instance.SystemCertsVerification
running at startup FAILED!
Are you sure that CA is running?
# ipactl status
*Yes, CA is runnig, *
*[root@caer ~]# ipactl status*
Directory Service: RUNNING
KDC Service: RUNNING
KPASSWD Service: RUNNING
DNS Service: RUNNING
MEMCACHE Service: RUNNING
HTTP Service: RUNNING
CA Service: RUNNING
This looks like that self test fail and therefore CA shouldn't start. It
also says that some of CA cert is not valid. Which one might be seen in
/var/log/pki-ca/debug but a bigger chunk would be needed.
*[root@caer ~]# tail -100 /var/log/pki-ca/debug *
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: getConn: conn is
connected true
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: getConn: mNumConns now 1
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: In
findCertRecordsInListRawJumpto with Jumpto 20160721114829Z
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: In DBVirtualList filter
attrs startFrom sortKey pageSize filter: (certStatus=REVOKED) attrs:
[objectclass, certRevokedOn, certRecordId, certRevoInfo, notAfter,
x509cert] pageSize -200 startFrom 20160721114829Z
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: returnConn: mNumConns now 2
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: returnConn: mNumConns now 3
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: getEntries returning 0
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: mTop 0
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Getting Virtual List size: 0
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: index may be empty
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: updateCertStatus done
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Starting cert checkRanges
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Serial numbers left in
range: 268369849
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Last Serial Number: 71
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Serial Numbers
available: 268369849
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: cert checkRanges done
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Starting request checkRanges
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Serial numbers left in
range: 9989888
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Last Serial Number: 112
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: Serial Numbers
available: 9989888
[21/Jul/2016:11:48:29][CertStatusUpdateThread]: request checkRanges done
[21/Jul/2016:11:53:28][Timer-0]: CMSEngine: getPasswordStore(): password
store initialized before.
[21/Jul/2016:11:53:28][Timer-0]: CMSEngine: getPasswordStore(): password
store initialized.
[21/Jul/2016:11:58:28][Timer-0]: CMSEngine: getPasswordStore(): password
store initialized before.
[21/Jul/2016:11:58:28][Timer-0]: CMSEngine: getPasswordStore(): password
store initialized.
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: About to start
updateCertStatus
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Starting
updateCertStatus (entered lock)
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In updateCertStatus()
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
LdapBoundConnFactory::getConn()
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
connected true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 2
[21/Jul/2016:11:58:29][CertStatusUpdateThread]:
getInvalidCertificatesByNotBeforeDate filter (certStatus=INVALID)
[21/Jul/2016:11:58:29][CertStatusUpdateThread]:
getInvalidCertificatesByNotBeforeDate: about to call findCertRecordsInList
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
LdapBoundConnFactory::getConn()
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
connected true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 1
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
findCertRecordsInListRawJumpto with Jumpto 20160721115829Z
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In DBVirtualList filter
attrs startFrom sortKey pageSize filter: (certStatus=INVALID) attrs:
[objectclass, certRecordId, x509cert] pageSize -200 startFrom
20160721115829Z
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 2
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
getInvalidCertsByNotBeforeDate finally.
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 3
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getEntries returning 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: mTop 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Getting Virtual List size: 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: index may be empty
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
LdapBoundConnFactory::getConn()
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
connected true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 2
[21/Jul/2016:11:58:29][CertStatusUpdateThread]:
getValidCertsByNotAfterDate filter (certStatus=VALID)
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
LdapBoundConnFactory::getConn()
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
connected true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 1
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
findCertRecordsInListRawJumpto with Jumpto 20160721115829Z
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In DBVirtualList filter
attrs startFrom sortKey pageSize filter: (certStatus=VALID) attrs:
[objectclass, certRecordId, x509cert] pageSize -200 startFrom
20160721115829Z
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 2
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 3
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getEntries returning 1
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: mTop 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Getting Virtual List
size: 14
[21/Jul/2016:11:58:29][CertStatusUpdateThread]:
transidValidCertificates: list size: 14
[21/Jul/2016:11:58:29][CertStatusUpdateThread]:
transitValidCertificates: ltSize 1
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getElementAt: 0 mTop 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: reverse direction
getting index 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Record does not
qualify,notAfter Thu Jan 12 09:11:48 EST 2017 date Thu Jul 21 11:58:29
EDT 2016
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: transitCertList EXPIRED
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
LdapBoundConnFactory::getConn()
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
connected true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 2
[21/Jul/2016:11:58:29][CertStatusUpdateThread]:
getRevokedCertificatesByNotAfterDate filter (certStatus=REVOKED)
[21/Jul/2016:11:58:29][CertStatusUpdateThread]:
getRevokedCertificatesByNotAfterDate: about to call findCertRecordsInList
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
LdapBoundConnFactory::getConn()
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: masterConn is connected:
true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: conn is
connected true
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getConn: mNumConns now 1
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In
findCertRecordsInListRawJumpto with Jumpto 20160721115829Z
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: In DBVirtualList filter
attrs startFrom sortKey pageSize filter: (certStatus=REVOKED) attrs:
[objectclass, certRevokedOn, certRecordId, certRevoInfo, notAfter,
x509cert] pageSize -200 startFrom 20160721115829Z
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 2
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: returnConn: mNumConns now 3
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: getEntries returning 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: mTop 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Getting Virtual List size: 0
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: index may be empty
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: updateCertStatus done
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Starting cert checkRanges
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Serial numbers left in
range: 268369849
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Last Serial Number: 71
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Serial Numbers
available: 268369849
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: cert checkRanges done
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Starting request checkRanges
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Serial numbers left in
range: 9989888
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Last Serial Number: 112
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: Serial Numbers
available: 9989888
[21/Jul/2016:11:58:29][CertStatusUpdateThread]: request checkRanges done
[21/Jul/2016:12:03:28][Timer-0]: CMSEngine: getPasswordStore(): password
store initialized before.
[21/Jul/2016:12:03:28][Timer-0]: CMSEngine: getPasswordStore(): password
store initialized.
On Thu, Jul 21, 2016 at 11:46 AM, Petr Vobornik <pvobo...@redhat.com
<mailto:pvobo...@redhat.com>> wrote:
On 07/21/2016 05:14 PM, Linov Suresh wrote:
> I set debug=true in /etc/ipa/default.conf
>
> Here are my logs,
The httpd_error log doesn't contain the part where `ipa cert-show 1` was
run. If it is from the same time. Does `ipa cert-show` communicate with
the same replica? Could be verified by `ipa -vv cert-show`
But more interesting is:
SelfTestSubsystem: The CRITICAL self test plugin called
selftests.container.instance.SystemCertsVerification running at startup
FAILED!
Are you sure that CA is running?
# ipactl status
This looks like that self test fail and therefore CA shouldn't start. It
also says that some of CA cert is not valid. Which one might be seen in
/var/log/pki-ca/debug but a bigger chunk would be needed.
>
> *[root@caer ~]# tail -f /var/log/httpd/error_log*
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: WSGI
WSGIExecutioner.__call__:
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: raw:
user_show(u'admin',
> rights=False, all=False, raw=False, version=u'2.46')
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG:
user_show(u'admin', rights=False,
> all=False, raw=False, version=u'2.46')
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: get_memberof:
> entry_dn=uid=admin,cn=users,cn=accounts,dc=teloip,dc=net
>
memberof=[ipapython.dn.DN('cn=admins,cn=groups,cn=accounts,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=replication
> administrators,cn=privileges,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=add
> replication agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=modify replication
> agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=remove
> replication agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=unlock user
> accounts,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=manage
> service keytab,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=trust
admins,cn=groups,cn=accounts,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=host
enrollment,cn=privileges,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=manage host
> keytab,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=enroll a
> host,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=add host
> password,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=add
> krbprincipalname to a host,cn=permissions,cn=pbac,dc=teloip,dc=net')]
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: get_memberof: result
>
direct=[ipapython.dn.DN('cn=admins,cn=groups,cn=accounts,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=trust
admins,cn=groups,cn=accounts,dc=teloip,dc=net')]
> indirect=[ipapython.dn.DN('cn=replication
> administrators,cn=privileges,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=add
> replication agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=modify replication
> agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=remove
> replication agreements,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=unlock user
> accounts,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=manage
> service keytab,cn=permissions,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=host
enrollment,cn=privileges,cn=pbac,dc=teloip,dc=net'),
> ipapython.dn.DN('cn=manage host
> keytab,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=enroll a
> host,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=add host
> password,cn=permissions,cn=pbac,dc=teloip,dc=net'),
ipapython.dn.DN('cn=add
> krbprincipalname to a host,cn=permissions,cn=pbac,dc=teloip,dc=net')]
> [Thu Jul 21 11:00:38 2016] [error] ipa: INFO: ad...@teloip.net
<mailto:ad...@teloip.net>
> <mailto:ad...@teloip.net <mailto:ad...@teloip.net>>:
user_show(u'admin', rights=False, all=False,
> raw=False, version=u'2.46'): SUCCESS
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: response: entries returned
1
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: Destroyed connection
context.ldap2
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: reading ccache data from
file
> "/var/run/ipa_memcached/krbcc_13554"
> [Thu Jul 21 11:00:38 2016] [error] ipa: DEBUG: store session:
> session_id=10c5de02f8ae0f3969b96ef0f2e3a96d
start_timestamp=2016-07-21T10:43:26
> access_timestamp=2016-07-21T11:00:38
expiration_timestamp=2016-07-21T11:20:38
>
> *[root@caer ~]# tail -f /var/log/pki-ca/debug*
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: RequestQueue: curReqId:
9990001
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: getElementAt: 1 mTop 107
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: reverse direction getting
index 4
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: RequestQueue: curReqId:
112
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: RequestQueue:
getLastRequestId :
> returning value 112
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: Repository:
mLastSerialNo: 112
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: Serial numbers left in
range:
> 9989888
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: Last Serial Number: 112
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: Serial Numbers available:
9989888
> [21/Jul/2016:11:08:29][CertStatusUpdateThread]: request checkRanges done
>
> *[root@caer ~]# tail -f /var/log/pki-ca/transactions*
> 6563.CRLIssuingPoint-MasterCRL - [20/Jul/2016:17:00:00 EDT] [20]
[1] CRL Update
> completed. CRL ID: MasterCRL CRL Number: 8,912 last update time:
7/20/16 5:00 PM
> next update time: 7/20/16 9:00 PM Number of entries in the CRL:
11 time: 25 CRL
> time: 25 delta CRL time: 0 (0,0,0,0,0,0,0,8,17,0,0,25,25)
> 6563.CRLIssuingPoint-MasterCRL - [20/Jul/2016:21:00:00 EDT] [20]
[1] CRL update
> started. CRL ID: MasterCRL CRL Number: 8,913 Delta CRL
Enabled: false CRL
> Cache Enabled: true Cache Recovery Enabled: true Cache Cleared:
false Cache:
> 11,0,0,0
> 6563.CRLIssuingPoint-MasterCRL - [20/Jul/2016:21:00:00 EDT] [20]
[1] CRL Update
> completed. CRL ID: MasterCRL CRL Number: 8,913 last update time:
7/20/16 9:00 PM
> next update time: 7/21/16 1:00 AM Number of entries in the CRL:
11 time: 11 CRL
> time: 11 delta CRL time: 0 (0,0,0,0,0,0,0,6,5,0,0,11,11)
> 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:01:00:00 EDT] [20]
[1] CRL update
> started. CRL ID: MasterCRL CRL Number: 8,914 Delta CRL
Enabled: false CRL
> Cache Enabled: true Cache Recovery Enabled: true Cache Cleared:
false Cache:
> 11,0,0,0
> 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:01:00:00 EDT] [20]
[1] CRL Update
> completed. CRL ID: MasterCRL CRL Number: 8,914 last update time:
7/21/16 1:00 AM
> next update time: 7/21/16 5:00 AM Number of entries in the CRL:
11 time: 13 CRL
> time: 13 delta CRL time: 0 (0,0,0,0,0,0,0,6,7,0,0,13,13)
> 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:05:00:00 EDT] [20]
[1] CRL update
> started. CRL ID: MasterCRL CRL Number: 8,915 Delta CRL
Enabled: false CRL
> Cache Enabled: true Cache Recovery Enabled: true Cache Cleared:
false Cache:
> 11,0,0,0
> 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:05:00:00 EDT] [20]
[1] CRL Update
> completed. CRL ID: MasterCRL CRL Number: 8,915 last update time:
7/21/16 5:00 AM
> next update time: 7/21/16 9:00 AM Number of entries in the CRL:
11 time: 16 CRL
> time: 16 delta CRL time: 0 (0,0,0,0,0,0,0,8,8,0,0,16,16)
> 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:09:00:00 EDT] [20]
[1] CRL update
> started. CRL ID: MasterCRL CRL Number: 8,916 Delta CRL
Enabled: false CRL
> Cache Enabled: true Cache Recovery Enabled: true Cache Cleared:
false Cache:
> 11,0,0,0
> 6563.CRLIssuingPoint-MasterCRL - [21/Jul/2016:09:00:00 EDT] [20]
[1] CRL Update
> completed. CRL ID: MasterCRL CRL Number: 8,916 last update time:
7/21/16 9:00 AM
> next update time: 7/21/16 1:00 PM Number of entries in the CRL:
11 time: 13 CRL
> time: 13 delta CRL time: 0 (0,0,0,0,0,0,0,6,7,0,0,13,13)
> 10657.http-9443-2 - [21/Jul/2016:10:28:19 EDT] [20] [1] renewal
reqID 112
> fromAgent userID: ipara authenticated by certUserDBAuthMgr is
completed DN
> requested: CN=CA Audit,O=TELOIP.NET <http://TELOIP.NET>
<http://TELOIP.NET> cert issued serial
> number: 0x47 time: 39
>
> *[root@caer ~]# tail -f /var/log/pki-ca/selftests.log*
> 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem:
loading all
> self test plugin logger parameters
> 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem:
loading all
> self test plugin instances
> 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem:
loading all
> self test plugin instance parameters
> 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem:
loading
> self test plugins in on-demand order
> 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem:
loading
> self test plugins in startup order
> 14116.main - [21/Jul/2016:10:58:29 EDT] [20] [1] SelfTestSubsystem: Self
test
> plugins have been successfully loaded!
> 14116.main - [21/Jul/2016:10:58:30 EDT] [20] [1] SelfTestSubsystem:
Running self
> test plugins specified to be executed at startup:
> 14116.main - [21/Jul/2016:10:58:30 EDT] [20] [1] CAPresence: CA is
present
> 14116.main - [21/Jul/2016:10:58:30 EDT] [20] [1] SystemCertsVerification:
system
> certs verification failure
> 14116.main - [21/Jul/2016:10:58:30 EDT] [20] [1] SelfTestSubsystem: The
CRITICAL
> self test plugin called
selftests.container.instance.SystemCertsVerification
> running at startup FAILED!
>
> But intrestingly, [root@caer ~]# ipa cert-show 1 returns "*ipa:
ERROR:
> Certificate operation cannot be completed: Unable to communicate with CMS
(Not
> Found)*"
>
> On Thu, Jul 21, 2016 at 10:04 AM, Linov Suresh <linov.sur...@gmail.com
<mailto:linov.sur...@gmail.com>
> <mailto:linov.sur...@gmail.com <mailto:linov.sur...@gmail.com>>> wrote:
>
> This could be because of incorrect trust attributes trust on the
> certificates, the current attributes are,
>
> [root@caer ~]# certutil -L -d /var/lib/pki-ca/alias
>
> Certificate Nickname Trust
Attributes
>
SSL,S/MIME,JAR/XPI
>
> ocspSigningCert cert-pki-ca u,u,Pu
> subsystemCert cert-pki-ca u,u,Pu
> caSigningCert cert-pki-ca
CTu,Cu,Cu
> subsystemCert cert-pki-ca u,u,Pu
> Server-Cert cert-pki-ca u,u,u
> auditSigningCert cert-pki-ca u,u,Pu
>
> I'm going to fix the trust attributes and try.
>
> On Thu, Jul 21, 2016 at 9:45 AM, Petr Vobornik <pvobo...@redhat.com
<mailto:pvobo...@redhat.com>
> <mailto:pvobo...@redhat.com <mailto:pvobo...@redhat.com>>> wrote:
>
> On 07/20/2016 09:41 PM, Linov Suresh wrote:
> > I have restarted the pki-cad and checked if
communication with the CA is
> > working, but no luck,
> >
> > Debug logs in /var/log/pki-ca do not have anything
unusual. Can you think of
> > anything other than this?
>
> /var/log/httpd/error_log when /etc/ipa.conf is set to
debug=true
>
https://www.freeipa.org/page/Troubleshooting#ipa_command_crashes_or_returns_no_data
>
> /var/log/pki-ca/debug
> /var/log/pki-ca/transactions
> /var/log/pki-ca/selftest.log
>
> >
> > [root@caer ~]# ipa cert-show 1
> > Certificate:
MIIDizCCAnOgAwIBAgIBATANBgkqhkiG9w0BAQsFADA1MRMwEQYDVQQKEwpURUxP
> >
SVAuTkVUMR4wHAYDVQQDExVDZXJ0aWZpY2F0ZSBBdXRob3JpdHkwHhcNMTExMjE0
> >
MjIyOTU2WhcNMTkxMjE0MjIyOTU2WjA1MRMwEQYDVQQKEwpURUxPSVAuTkVUMR4w
> >
HAYDVQQDExVDZXJ0aWZpY2F0ZSBBdXRob3JpdHkwggEiMA0GCSqGSIb3DQEBAQUA
> >
A4IBDwAwggEKAoIBAQDegJ5XVR0JSc76s9FPkkkuug3PtZi5Ysad0Dr1I5ngjTOV
> >
ctm/P7buk2g8LxBSXLO+7Rq7PTtTD5AJ7vQjrv2RtoYTPdRebAuukTKd6RhtYa5e
> >
tX7z0DBjQ8g9Erqf9GzLxlQqim8ZvscATBhf6MLb5cXA/pWHYuE2j0OlnrSNWqsb
> >
UgwMsM73RlsNACsvLUk4iJY0wuxj4L/0EBQWUPGr8qBk3QBST4LDnInuvvGsAFNe
> >
tyebENMRWnEaDFYKPapACrtKAl3hQNDB7dVGk64Dd7paXss9F8vgVnofgFpjiJs7
> >
5DNtKhKxzFQyanINU+uuIVs/CNIO3jV9I26ems2zAgMBAAGjgaUwgaIwHwYDVR0j
> >
BBgwFoAUx5/ZpwOfXZQ5KNwC42cBW+Y+bGIwDwYDVR0TAQH/BAUwAwEB/zAOBgNV
> >
HQ8BAf8EBAMCAcYwHQYDVR0OBBYEFMef2acDn12UOSjcAuNnAVvmPmxiMD8GCCsG
> >
AQUFBwEBBDMwMTAvBggrBgEFBQcwAYYjaHR0cDovL2NhZXIudGVsb2lwLm5ldDo5
> >
MTgwL2NhL29jc3AwDQYJKoZIhvcNAQELBQADggEBAHGElN0OcepokvNIN8f4mvTj
> >
kL9wcuZwbbX9gZGdKSZf5Redp4tsJW8EJCy8yu9F5U+Ym3RcvJBiby9gHCVVbW+y
> >
5IgziiJ3kd4UlVJCDVKtbdq62bODcatFsMH8wJSMW6Cw096RyfGgu2qSyXzdZ2xV
> >
nMovO3+Eaz2n0x4ZvaEj9Ixym/KI+QPCAL7gPkK36X4JYgM3CXUCYCN/QJY/psFt
> >
e+121ubSZX5u3Yntux4KziJ3cx9wZ74iKff1BOVxOCi0JyLn2k15bvBXGvxxgmhK
> >
b8YUVbDJDb9oWSbixl/TQI9PZysXYIvBNJM8h+HRKIJksKGQhKOERzrYoqABt30=
> > Subject: CN=Certificate Authority,O=TELOIP.NET
<http://TELOIP.NET> <http://TELOIP.NET>
> <http://TELOIP.NET>
> > Issuer: CN=Certificate Authority,O=TELOIP.NET
<http://TELOIP.NET> <http://TELOIP.NET>
> <http://TELOIP.NET>
> > Not Before: Wed Dec 14 22:29:56 2011 UTC
> > Not After: Sat Dec 14 22:29:56 2019 UTC
> > Fingerprint (MD5):
c9:27:1d:84:4c:2c:97:38:a4:7b:9a:c0:78:3e:7f:7a
> > Fingerprint (SHA1):
ce:d7:11:84:70:dd:cb:4e:e2:08:f5:c0:ac:ff:b3:c5:bb:81:77:7e
> > Serial number (hex): 0x1
> > Serial number: 1
> > [root@caer ~]#
> >
> > *ca-error: Internal error: no response to
> >
>
"http://caer.teloip.net:9180/ca/ee/ca/profileSubmit?profileId=caServerCert&serial_num=63&renewal=true&xml=true";.
> > *
> >
> >
> >
> > On Wed, Jul 20, 2016 at 2:22 PM, Rob Crittenden
<rcrit...@redhat.com <mailto:rcrit...@redhat.com>
<mailto:rcrit...@redhat.com <mailto:rcrit...@redhat.com>>
> > <mailto:rcrit...@redhat.com <mailto:rcrit...@redhat.com>
<mailto:rcrit...@redhat.com <mailto:rcrit...@redhat.com>>>> wrote:
> >
> > Linov Suresh wrote:
> >
> > Thanks for your help Rob, I will create a
separate thread for IPA
> > replication issue. But we are still getting
> > *
> > *
> > *ca-error: Internal error: no response to
> >
"http://caer.teloip.net:9180/ca/ee/ca/profileSubmit?profileId=caServerCert&serial_num=60&renewal=true&xml=true".*
> >
> > Could you please help us to fix this?
> >
> >
> > I think your CA isn't quite fixed yet. I'd restart
pki-cad then do something
> > like: ipa cert-show 1
> >
> > You should get back a cert (doesn't really matter
what cert).
> >
> > Otherwise I'd check the CA debug log somewhere in
/var/log/pki
> >
> > rob
> >
--
Petr Vobornik
