[Freeipa-users] IPA certificates expired, please help!
Linov Suresh
linov.suresh at gmail.com
Thu Jul 21 16:10:05 UTC 2016
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*
[root at 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.net at 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.net at 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
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: Connecting: 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,O=TELOIP.NET"
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: handshake complete, peer =
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,O=TELOIP.NET"
[Thu Jul 21 12:01:21 2016] [error] ipa: DEBUG: handshake complete, peer =
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: admin at 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 at 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; 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 '
admin at TELOIP.NET', cookie: 'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;
Domain=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
ipa: DEBUG: Connecting: 10.20.0.75:0
send: u'POST /ipa/session/xml HTTP/1.0\r\nHost:
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 (by 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,O=TELOIP.NET"
ipa: DEBUG: handshake complete, peer = 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; 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;
Path=/ipa; Expires=Thu, 21 Jul 2016 16:25:40 GMT; Secure; HttpOnly'
ipa: DEBUG: storing cookie 'ipa_session=bc2c7ed0eccd840dc266efaf9ece913c;
Domain=caer.teloip.net; Path=/ipa; Expires=Thu, 21 Jul 2016 16:25:40 GMT;
Secure; HttpOnly' for principal admin at TELOIP.NET
ipa: DEBUG: args=keyctl search @s user ipa_session_cookie:admin at TELOIP.NET
ipa: DEBUG: stdout=457971704
ipa: DEBUG: stderr=
ipa: DEBUG: args=keyctl search @s user ipa_session_cookie:admin at 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 at 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 at 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 at 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 <pvoborni at 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 at 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: admin at TELOIP.NET
> > <mailto:admin at 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 at 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 at 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> cert issued
> serial
> > number: 0x47 time: 39
> >
> > *[root at 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 at 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.suresh at gmail.com
> > <mailto:linov.suresh at gmail.com>> wrote:
> >
> > This could be because of incorrect trust attributes trust on the
> > certificates, the current attributes are,
> >
> > [root at 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 <pvoborni at redhat.com
> > <mailto:pvoborni at 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 at 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>
> > > Issuer: CN=Certificate Authority,O=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 at 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 <
> rcritten at redhat.com <mailto:rcritten at redhat.com>
> > > <mailto:rcritten at redhat.com <mailto:rcritten at 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20160721/e0c40cfa/attachment.htm>
More information about the Freeipa-users
mailing list