On Fri, Jul 22, 2016 at 3:36 PM, Linov Suresh <linov.sur...@gmail.com
<mailto:linov.sur...@gmail.com>> wrote:
Thank you very much Rob.
Let me remove the duplicate certificates and try to renew the
certificates again to see if "*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"*.";
goes away?
On Fri, Jul 22, 2016 at 2:45 PM, Rob Crittenden <rcrit...@redhat.com
<mailto:rcrit...@redhat.com>> wrote:
Linov Suresh wrote:
Could you please verify, if we have set correct trust
attributes on the
certificates
*root@caer ~]# certutil -d /var/lib/pki-ca/alias/ -L*
Certificate Nickname
Trust
Attributes
SSL,S/MIME,JAR/XPI
subsystemCert cert-pki-ca
u,u,Pu
ocspSigningCert cert-pki-ca
u,u,u
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
*
*
*[root@caer ~]# certutil -d /etc/httpd/alias/ -L*
Certificate Nickname
Trust
Attributes
SSL,S/MIME,JAR/XPI
ipaCert
u,u,u
Server-Cert u,u,u
TELOIP.NET <http://TELOIP.NET> <http://TELOIP.NET> IPA CA
CT,C,C
ipaCert
u,u,u
Signing-Cert u,u,u
Server-Cert u,u,u
*[root@caer ~]# certutil -d /etc/dirsrv/slapd-TELOIP-NET/ -L*
Certificate Nickname
Trust
Attributes
SSL,S/MIME,JAR/XPI
Server-Cert
u,u,u
TELOIP.NET <http://TELOIP.NET> <http://TELOIP.NET> IPA CA
CT,,C
Server-Cert
u,u,u
[root@caer ~]#
*Please note, there are duplicate certificates in CA, HTTP
and LDAP
directory, subsystemCert cert-pki-ca, ipaCert and
Server-Cert. I was
wondering if we need to remove these duplicate certificates? *
Yeah you should remove the duplicate certs, they seem to cause
problems with dogtag at least (certmonger _should_ handle this
automatically, we'll be looking into it soonish).
To remove the duplicate cert:
1. Shutdown the service
2. Back up the NSS database
3. certutil -L -d /path/to/db -n <nickname> -a > somefile
4. split somefile into separate files so each file as a
BEGIN/END certificate
5. openssl x509 -text -in -infile somefile1..n
6. Pick the one with the most recent issuance date
7. You backed up the NSS database, right?
8. certutil -D -d /path/to/db -n <nickname>
9. certutil -A -d /path/to/db -n <nickname> -t u,u,u -a -i
somefilex
10. Start the service, watch logs for errors
For the trust use whatever the original trust value was.
You don't need the P trust flag on the subsystemCert in the CA,
only the auditSigningCert.
I doubt the duplicated Server-Cert will be a problem. NSS is
supposed to deal with this automatically, picking the "most
correct" cert to use based on the validity period.
rob
On Fri, Jul 22, 2016 at 9:36 AM, Linov Suresh
<linov.sur...@gmail.com <mailto:linov.sur...@gmail.com>
<mailto: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> <mailto: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>
<mailto: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>
<mailto: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>
<mailto: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>
<mailto: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> <mailto: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>
<mailto: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>
<mailto: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>>
<mailto: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>>
<mailto: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>
<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>
<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>
<http://caer.teloip.net>,O=TELOIP.NET
<http://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> <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>
<http://caer.teloip.net>,O=TELOIP.NET
<http://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> <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>>
<mailto: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>
<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>>
<mailto: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>
<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> <http://caer.teloip.net>
ipa: DEBUG: Connecting: 10.20.0.75:0
<http://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>
<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>
<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>
<http://xmlrpclib.py/1.0.1> (by
www.pythonware.com <http://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>
<http://caer.teloip.net>,O=TELOIP.NET
<http://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>
<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>
<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>
<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>
<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>>
<mailto: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>>
<mailto:ipa_session_cookie%3aad...@teloip.net
<mailto:ipa_session_cookie%253aad...@teloip.net>
<mailto:ipa_session_cookie%253aad...@teloip.net
<mailto:ipa_session_cookie%25253aad...@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>>
<mailto:ipa_session_cookie%3aad...@teloip.net
<mailto:ipa_session_cookie%253aad...@teloip.net>
<mailto:ipa_session_cookie%253aad...@teloip.net
<mailto:ipa_session_cookie%25253aad...@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>>
<mailto: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>>>
> <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
<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>
<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
