> -----Original Message-----
> From: Rob Crittenden [mailto:rcrit...@redhat.com]
> Sent: Wednesday, October 23, 2013 6:58 PM
> To: Thomson, Ryan; freeipa-users@redhat.com
> Subject: Re: [Freeipa-users] Failure decoding Certificate Signing Request
>
> I think this still points to NSS not being initialized. The way we currently
> use
> NSS in the server is Apache fires things up using mod_nss, then because we
> are a child of Apache via mod_wsgi, we inherit the open NSS database in
> /etc/httpd/alias. This gives us the CA cert and the client cert we need in
> order to talk to dogtag.
>
> What I thought, and the excellent debugging above confirms, is that at some
> point the NSS database is being shut down. At some point we need to do
> some crypto and try to initialize it ourselves to no avail. We shouldn't ever
> need to do it in the server and thus don't have access to PINs and such
> because we don't need them. We do initialize things from time to time on
> the client side but we tend to do a database-less initialization
> (nss_init_nodb()).
>
> I'm not really sure what this tells us though. It would appear that SSL is
> working in Apache, because you are able to get far enough to make a
> request and have it fail. So the NSS database is still initialized in Apache,
> but
> for some reason the wsgi code doesn't seem to agree.
>
> Would it be possible for you to stop and restart Apache and run some simple
> IPA command like ipa user-show admin (and let me know if it succeeds)?
> Then send me the error_log?
>
> If you are in SELinux enforcing mode it would also be helpful to check for any
> AVCs. Maybe we simply can't access the database.
>
> thanks
>
> rob
I am able to stop/wait/start apache and then execute "ipa user-show admin"
successfully.
Relevant error log from /var/log/httpd/error_log:
[Mon Oct 07 18:36:51 2013] [error] ipa: DEBUG: WSGI wsgi_dispatch.__call__:
[Mon Oct 07 18:36:51 2013] [error] ipa: DEBUG: WSGI xmlserver.__call__:
[Mon Oct 07 18:36:51 2013] [error] ipa: DEBUG: Created connection context.ldap2
[Mon Oct 07 18:36:51 2013] [error] ipa: DEBUG: WSGI WSGIExecutioner.__call__:
[Mon Oct 07 18:36:51 2013] [error] ipa: DEBUG: raw: user_show(u'admin',
rights=False, all=False, raw=False, version=u'2.46')
[Mon Oct 07 18:36:51 2013] [error] ipa: DEBUG: user_show(u'admin',
rights=False, all=False, raw=False, version=u'2.46')
[Mon Oct 07 18:36:51 2013] [error] ipa: DEBUG: retrieving schema for
SchemaCache url=ldapi://%2fvar%2frun%2fslapd-FMRI-UBC-CA.socket
conn=<ldap.ldapobject.SimpleLDAPObject instance at 0x7f4db74f07e8>
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: get_memberof:
entry_dn=uid=admin,cn=users,cn=accounts,dc=fully,dc=qualified,dc=domain
memberof=[ipapython.dn.DN('cn=admins,cn=groups,cn=accounts,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=replication
administrators,cn=privileges,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=add replication
agreements,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=modify replication
agreements,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=remove replication
agreements,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=host
enrollment,cn=privileges,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=manage host
keytab,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=enroll a
host,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=add krbprincipalname to a host,cn=p!
ermissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=unlock user
accounts,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=manage service
keytab,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=trust
admins,cn=groups,cn=accounts,dc=fully,dc=qualified,dc=domain')]
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: get_memberof: result
direct=[ipapython.dn.DN('cn=admins,cn=groups,cn=accounts,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=trust
admins,cn=groups,cn=accounts,dc=fully,dc=qualified,dc=domain')]
indirect=[ipapython.dn.DN('cn=replication
administrators,cn=privileges,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=add replication
agreements,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=modify replication
agreements,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=remove replication
agreements,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=host
enrollment,cn=privileges,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=manage host
keytab,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=enroll a
host,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=ad!
d krbprincipalname to a
host,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=unlock user
accounts,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain'),
ipapython.dn.DN('cn=manage service
keytab,cn=permissions,cn=pbac,dc=fully,dc=qualified,dc=domain')]
[Mon Oct 07 18:36:52 2013] [error] ipa: INFO: admin@FULLY.QUALIFIED.DOMAIN:
user_show(u'admin', rights=False, all=False, raw=False, version=u'2.46'):
SUCCESS
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: response: entries returned 1
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: no session id in request,
generating empty session data with id=47992da2d1630a11bc106cc6390147e8
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: store session:
session_id=47992da2d1630a11bc106cc6390147e8 start_timestamp=2013-10-07T18:36:52
access_timestamp=2013-10-07T18:36:52 expiration_timestamp=1969-12-31T16:00:00
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: finalize_kerberos_acquisition:
xmlserver ccache_name="FILE:/tmp/krb5cc_apache_mFOaRq"
session_id="47992da2d1630a11bc106cc6390147e8"
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: reading ccache data from file
"/tmp/krb5cc_apache_mFOaRq"
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: get_credential_times:
principal=HTTP/HOSTNAME.FULLY.QUALIFIED.DOMAIN@FULLY.QUALIFIED.DOMAIN,
authtime=10/07/13 18:36:21, starttime=10/07/13 18:36:51, endtime=10/08/13
18:36:19, renew_till=12/31/69 16:00:00
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: KRB5_CCache
FILE:/tmp/krb5cc_apache_mFOaRq endtime=1381282579 (10/08/13 18:36:19)
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: set_session_expiration_time:
duration_type=inactivity_timeout duration=1200 max_age=1381282279
expiration=1381197412.49 (2013-10-07T18:56:52)
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: store session:
session_id=47992da2d1630a11bc106cc6390147e8 start_timestamp=2013-10-07T18:36:52
access_timestamp=2013-10-07T18:36:52 expiration_timestamp=2013-10-07T18:56:52
[Mon Oct 07 18:36:52 2013] [error] ipa: DEBUG: Destroyed connection
context.ldap2
And the command output with debugging on:
root@HOSTNAME:~
# date
Mon Oct 7 18:36:43 PDT 2013
root@HOSTNAME:~
# klist
Ticket cache: FILE:/tmp/krb5cc_0
Default principal: admin@FULLY.QUALIFIED.DOMAIN
Valid starting Expires Service principal
10/07/13 18:36:21 10/08/13 18:36:19
krbtgt/FULLY.QUALIFIED.DOMAIN@FULLY.QUALIFIED.DOMAIN
root@HOSTNAME:~
# ipa user-show admin
ipa: DEBUG: importing all plugin modules in
'/usr/lib/python2.6/site-packages/ipalib/plugins'...
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/aci.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/automember.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/automount.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/baseldap.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/batch.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/cert.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/config.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/delegation.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/dns.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/group.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/hbacrule.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/hbacsvc.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/hbacsvcgroup.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/hbactest.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/host.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/hostgroup.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/idrange.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/internal.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/kerberos.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/krbtpolicy.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/migration.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/misc.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/netgroup.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/passwd.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/permission.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/ping.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/privilege.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/pwpolicy.py'
ipa: DEBUG: args=klist -V
ipa: DEBUG: stdout=Kerberos 5 version 1.10.3
ipa: DEBUG: stderr=
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/role.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/selfservice.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/selinuxusermap.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/service.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/sudocmd.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/sudocmdgroup.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/sudorule.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/trust.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/user.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/virtual.py'
ipa: DEBUG: importing plugin module
'/usr/lib/python2.6/site-packages/ipalib/plugins/xmlclient.py'
ipa: DEBUG: args=keyctl search @s user
ipa_session_cookie:admin@FULLY.QUALIFIED.DOMAIN
ipa: DEBUG: stdout=311493198
ipa: DEBUG: stderr=
ipa: DEBUG: args=keyctl pipe 311493198
ipa: DEBUG: stdout=ipa_session=0b5649ff40d800567f75f34aef2cce11;
Domain=HOSTNAME.FULLY.QUALIFIED.DOMAIN; Path=/ipa; Expires=Mon, 07 Oct 2013
04:29:31 GMT; Secure; HttpOnly
ipa: DEBUG: stderr=
ipa: DEBUG: found session_cookie in persistent storage for principal
'admin@FULLY.QUALIFIED.DOMAIN', cookie:
'ipa_session=0b5649ff40d800567f75f34aef2cce11;
Domain=HOSTNAME.FULLY.QUALIFIED.DOMAIN; Path=/ipa; Expires=Mon, 07 Oct 2013
04:29:31 GMT; Secure; HttpOnly'
ipa: DEBUG: deleting session data for principal 'admin@FULLY.QUALIFIED.DOMAIN':
cookie named 'ipa_session'; expired at Mon, 07 Oct 2013 04:29:31 GMT'
ipa: DEBUG: args=keyctl search @s user
ipa_session_cookie:admin@FULLY.QUALIFIED.DOMAIN
ipa: DEBUG: stdout=311493198
ipa: DEBUG: stderr=
ipa: DEBUG: args=keyctl unlink 311493198 @s
ipa: DEBUG: stdout=
ipa: DEBUG: stderr=
ipa: INFO: trying https://HOSTNAME.FULLY.QUALIFIED.DOMAIN/ipa/xml
ipa: DEBUG: Created connection context.xmlclient
ipa: DEBUG: raw: user_show(u'admin', rights=False, all=False, raw=False,
version=u'2.46')
ipa: DEBUG: user_show(u'admin', rights=False, all=False, raw=False,
version=u'2.46')
ipa: INFO: Forwarding 'user_show' to server
u'https://HOSTNAME.FULLY.QUALIFIED.DOMAIN/ipa/xml'
ipa: DEBUG: NSSConnection init HOSTNAME.FULLY.QUALIFIED.DOMAIN
ipa: DEBUG: Connecting: 142.103.89.209:0
ipa: DEBUG: auth_certificate_callback: check_sig=True is_server=False
Data:
Version: 3 (0x2)
Serial Number: 22 (0x16)
Signature Algorithm:
Algorithm: PKCS #1 SHA-256 With RSA Encryption
Issuer: CN=Certificate Authority,O=FULLY.QUALIFIED.DOMAIN
Validity:
Not Before: Thu Apr 11 23:23:18 2013 UTC
Not After: Tue Oct 08 23:23:18 2013 UTC
Subject: CN=HOSTNAME.FULLY.QUALIFIED.DOMAIN,O=FULLY.QUALIFIED.DOMAIN
Subject Public Key Info:
Public Key Algorithm:
Algorithm: PKCS #1 RSA Encryption
RSA Public Key:
Modulus:
b0:b0:50:1f:e9:72:26:d5:dd:ff:70:ba:66:bb:a6:90:
bf:02:e9:7f:9b:73:10:9b:d9:a5:84:f7:34:c6:ed:03:
ca:48:11:5e:50:9d:19:9f:22:24:8a:17:35:69:d0:69:
0e:f7:a8:37:2d:46:11:98:5e:df:a8:2c:93:96:a7:66:
e4:3d:20:c1:72:e2:94:46:36:0b:84:44:2e:94:a9:98:
7a:da:1d:3a:f0:13:53:47:0d:b1:30:21:9d:55:a8:32:
09:be:c6:d3:98:2e:6c:a1:a1:34:02:9a:7f:df:ba:4b:
f1:c9:10:c4:0b:70:e7:08:de:98:24:c4:a6:d2:4a:e5:
0c:41:e7:f6:80:a5:7a:25:b7:8d:0e:b9:aa:b7:ff:4f:
cd:85:b5:3e:1c:e0:6f:83:e5:c1:86:ec:e0:6f:dd:f2:
3a:6b:60:ce:3f:63:46:9a:75:5e:e3:20:76:d3:36:53:
07:1f:34:77:a7:42:3e:58:0d:30:15:f6:47:e3:a2:d3:
46:b0:cf:62:1b:00:2a:28:18:39:5c:35:3b:ff:c6:7a:
c2:9d:08:75:17:92:d3:7f:58:6d:c8:bc:55:c3:6f:3e:
17:f7:55:bf:e6:3c:af:cc:8a:18:59:f1:46:50:07:36:
09:38:87:4b:38:67:44:f6:b6:bb:cf:f0:af:88:30:5f
Exponent:
65537 (0x10001)
Signed Extensions: (5)
Name: Certificate Authority Key Identifier
Critical: False
Key ID:
3a:41:f5:c1:b7:ff:bb:79:13:d1:23:92:61:16:fc:7d:
a7:d1:82:d2
Serial Number: None
General Names: [0 total]
Name: Authority Information Access
Critical: False
Name: Certificate Key Usage
Critical: True
Usages:
Digital Signature
Non-Repudiation
Key Encipherment
Data Encipherment
Name: Extended Key Usage
Critical: False
Usages:
TLS Web Server Authentication Certificate
Name: Certificate Subject Key ID
Critical: False
Data:
e0:56:1f:d5:73:7c:5f:7f:60:5e:d7:3c:88:43:8d:97:
b7:f5:fb:24
Signature:
Signature Algorithm:
Algorithm: PKCS #1 SHA-256 With RSA Encryption
Signature:
85:60:83:4c:d5:80:28:9c:ec:69:b0:26:7a:4f:fc:99:
e1:4e:3d:78:54:59:d7:46:b3:cf:fb:81:8e:16:67:18:
b4:c4:98:3f:16:54:05:ef:6e:79:5f:62:81:65:e3:a8:
e7:7b:68:12:25:1f:af:dc:bf:3a:f7:74:72:9d:1d:51:
ae:e8:12:73:4c:a8:19:ad:54:03:22:a6:c0:56:29:1a:
cc:70:81:5e:fb:38:c0:f7:16:d5:9b:34:2c:16:43:84:
b3:7f:bb:86:83:fd:9a:d7:f5:67:a8:f4:c3:33:58:5e:
89:7a:f6:9f:a8:d7:b6:f9:0b:47:d7:6e:46:53:32:63:
e6:da:23:54:89:bc:4f:12:16:6d:eb:d4:f0:55:08:46:
64:69:46:55:20:90:ab:61:c4:f2:b6:d5:50:b5:48:07:
c0:f9:da:8e:fb:dd:53:e6:9f:1f:4e:d9:ec:af:a6:ad:
75:76:75:e4:b7:b3:ad:56:52:66:f4:9b:71:0d:b1:92:
a1:fc:16:c7:66:41:dd:b4:2f:df:34:ed:ad:29:26:40:
4f:85:a5:98:2c:9b:f0:18:42:3d:97:aa:73:16:3b:ac:
48:a9:8c:af:77:b3:24:d0:0d:07:ff:11:79:a9:24:a8:
2a:08:bd:e1:84:e3:6a:6f:2c:8e:62:78:8e:86:95:73
Fingerprint (MD5):
27:7d:ec:86:4f:07:65:9f:27:1e:eb:c4:af:9b:b0:b1
Fingerprint (SHA1):
df:60:7a:1b:54:22:bd:f2:2c:ea:ee:51:17:23:ae:2d:
f2:57:69:88
ipa: DEBUG: approved_usage = SSLServer intended_usage = SSLServer
ipa: DEBUG: cert valid True for
"CN=HOSTNAME.FULLY.QUALIFIED.DOMAIN,O=FULLY.QUALIFIED.DOMAIN"
ipa: DEBUG: handshake complete, peer = 142.103.89.209:443
ipa: DEBUG: received Set-Cookie 'ipa_session=47992da2d1630a11bc106cc6390147e8;
Domain=HOSTNAME.FULLY.QUALIFIED.DOMAIN; Path=/ipa; Expires=Tue, 08 Oct 2013
01:56:52 GMT; Secure; HttpOnly'
ipa: DEBUG: storing cookie 'ipa_session=47992da2d1630a11bc106cc6390147e8;
Domain=HOSTNAME.FULLY.QUALIFIED.DOMAIN; Path=/ipa; Expires=Tue, 08 Oct 2013
01:56:52 GMT; Secure; HttpOnly' for principal admin@FULLY.QUALIFIED.DOMAIN
ipa: DEBUG: args=keyctl search @s user
ipa_session_cookie:admin@FULLY.QUALIFIED.DOMAIN
ipa: DEBUG: stdout=
ipa: DEBUG: stderr=keyctl_search: Required key not available
ipa: DEBUG: args=keyctl search @s user
ipa_session_cookie:admin@FULLY.QUALIFIED.DOMAIN
ipa: DEBUG: stdout=
ipa: DEBUG: stderr=keyctl_search: Required key not available
ipa: DEBUG: args=keyctl padd user
ipa_session_cookie:admin@FULLY.QUALIFIED.DOMAIN @s
ipa: DEBUG: stdout=655885819
ipa: DEBUG: stderr=
ipa: DEBUG: Destroyed connection context.xmlclient
User login: admin
Last name: Administrator
Home directory: /home/admin
Login shell: /bin/bash
UID: 1615800000
GID: 1615800000
Account disabled: False
Password: True
Member of groups: admins, trust admins
Kerberos keys available: True
SELinux is currently in permissive mode:
root@HOSTNAME:~
# getenforce
Permissive
Thank you,
--Ryan
_______________________________________________
Freeipa-users mailing list
Freeipa-users@redhat.com
https://www.redhat.com/mailman/listinfo/freeipa-users
