On Fri, Jul 22, 2016 at 9:36 AM, Linov Suresh <linov.sur...@gmail.com
<mailto:linov.sur...@gmail.com>> wrote:
I'm facing another issue now, my kerberos tickets are not renewing,
*[root@caer ~]# ipa cert-show 1*
ipa: ERROR: Ticket expired
*[root@caer ~]# klist*
Ticket cache: FILE:/tmp/krb5cc_0
Default principal: ad...@teloip.net <mailto:ad...@teloip.net>
Valid starting Expires Service principal
07/20/16 14:42:26 07/21/16 14:42:22 krbtgt/teloip....@teloip.net
<mailto:teloip....@teloip.net>
07/20/16 14:42:36 07/21/16 14:42:22
HTTP/caer.teloip....@teloip.net <mailto:caer.teloip....@teloip.net>
07/21/16 11:40:15 07/21/16 14:42:22
ldap/caer.teloip....@teloip.net <mailto:caer.teloip....@teloip.net>
I need to manually renew the tickets every day,
*[root@caer ~]# kinit admin*
Password for ad...@teloip.net <mailto:ad...@teloip.net>:
Warning: Your password will expire in 6 days on Thu Jul 28 15:20:15 2016
*[root@caer ~]# klist *
Ticket cache: FILE:/tmp/krb5cc_0
Default principal: ad...@teloip.net <mailto:ad...@teloip.net>
Valid starting Expires Service principal
07/22/16 09:34:52 07/23/16 09:34:49 krbtgt/teloip....@teloip.net
<mailto:teloip....@teloip.net>
On Thu, Jul 21, 2016 at 12:23 PM, Rob Crittenden
<rcrit...@redhat.com <mailto:rcrit...@redhat.com>> wrote:
Linov Suresh wrote:
The httpd_error log doesn't contain the part where `ipa
cert-show 1` was
run. If it is from the same time.
*I am not sure about that, please see httpd_error when `ipa
cert-show 1`
was run*
The IPA API log isn't going to show much in this case.
Requests to the CA are proxied through IPA. The CA WAR is not
running on tomcat so when Apache tries to proxy the request
tomcat returns a 404, Not Found.
You need to start with the dogtag debug and selftest logs to see
what is going on. The logs are pretty verbose and can be
challenging to read.
rob
[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>
<mailto: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>
<mailto: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>
<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>
<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>
<http://caer.teloip.net>,O=TELOIP.NET <http://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> <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>
<http://caer.teloip.net>,O=TELOIP.NET <http://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> <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>
<mailto: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>
<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>
<mailto:ad...@teloip.net <mailto:ad...@teloip.net>>', cookie:
'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;
Domain=caer.teloip.net <http://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> <http://caer.teloip.net>
ipa: DEBUG: Connecting: 10.20.0.75:0 <http://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>
<http://caer.teloip.net>\r\nAccept-Language: en-us\r\nReferer:
https://caer.teloip.net/ipa/xml\r\nCookie
<https://caer.teloip.net/ipa/xml%5Cr%5CnCookie>:
ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;\r\nUser-Agent:
xmlrpclib.py/1.0.1 <http://xmlrpclib.py/1.0.1>
<http://xmlrpclib.py/1.0.1> (by www.pythonware.com
<http://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>
<http://caer.teloip.net>,O=TELOIP.NET <http://TELOIP.NET>
<http://TELOIP.NET>"
ipa: DEBUG: handshake complete, peer = 10.20.0.75:443
<http://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>
<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>
<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>
<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>
<mailto: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>
<mailto:ipa_session_cookie%3aad...@teloip.net
<mailto:ipa_session_cookie%253aad...@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>
<mailto:ipa_session_cookie%3aad...@teloip.net
<mailto:ipa_session_cookie%253aad...@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>
<mailto: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>>
> <mailto: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>
<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>>
> <mailto: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>>
> <mailto: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>
> <http://TELOIP.NET>
> > Issuer: CN=Certificate
Authority,O=TELOIP.NET <http://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>>>
> > <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
<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
