[Freeipa-users] ACIerrors is httpd log

Rob Crittenden rcritten at redhat.com
Wed Dec 14 14:54:07 UTC 2016


Jim Richard wrote:
> just now getting back to this, have been truncating httpd logs via cron
> since then to keep from filing up my disk.
> 
> So, does this ring any bells :)

No but the complete, unredacted logs were VERY helpful, thanks.

So the code looks like this in 3.0, which IIRC you are running:

        try:
            self.check_access()
        except errors.ACIError, acierr:
            self.debug("Not granted by ACI to retrieve certificate,
looking at principal")
            bind_principal = getattr(context, 'principal')
            if not bind_principal.startswith('host/'):
                raise acierr

By default hosts aren't in the ACI that allows one to retrieve certs but
if you bind as one it is later given a pass. It would seem that is
failing, though it is also clear from the log that the client is binding
with a host principal, so I'm baffled.

I think it would probably be best to add more debug logging around these
lines to try to see what is going on, something like:

self.debug("bind_principal = %s", bind_principal)

And then later, the same aci error can be raised after checking the
hostname. I'd add in a debug log there too, to look soemthing like:

if hostname != cert.subject.common_name:    #pylint: disable=E1101
    self.debug('hostname %s doesn't match subject %s', hostname,
cert.subject.common_name)
    raise acierr

You'd make these changes in
/usr/lib/python2.7/site-packages/ipalib/plugins/cert.py then restart
httpd. I'd make a backup of the file first to make reverting easier.

rob

> 
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: IPA: virtual verify
> retrieve certificate
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: Not granted by ACI to
> retrieve certificate, looking at principal
> [Wed Dec 14 00:38:39 2016] [error] ipa: INFO:
> host/phoenix-168.nym1.placeiq.net at PLACEIQ.NET
> <mailto:host/phoenix-168.nym1.placeiq.net at placeiq.net>:
> cert_request(u'MIID4zCCAssCAQAwPTEUMBIGA1UEChMLUExBQ0VJUS5ORVQxJTAjBgNVBAMTHHBob2VuaXgtMTY4Lm55bTEucGxhY2VpcS5uZXQwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIBAQDboyDDyTaP4+LxYThfy1w7C67TN2qBp8JjA7Y55gnthyUp/PUUXmm3FUQ4yG4cBqDSxZcUWzl+eA33/ceSIp0HtVl34ZkkUitY1hmUvu2nh16ReR65YC+qRqkAIypOilLdPzXIWZ7u5LbM/Xpj3/Npzm18UupAAznNXkZnojuPmAQ+ulPGypyefLnhr5my6hIaR1atTm1ZvHTG3raMJOJhFe4jMeI/tgPVdNCUfOUdEKhmmCm5KivxhTtHMEcH+8obuQnbaSokJscxlzHBLiyQGqhAn5gznXg0mlVCC0H4mwdB1g2g9cG+SxSua/7XCm+AnGXlc75MZAt594QBTc3fAgMBAAGgggFfMHsGCSqGSIb3DQEJFDFuHmwASQBQAEEAIABNAGEAYwBoAGkAbgBlACAAQwBlAHIAdABpAGYAaQBjAGEAdABlACAALQAgAHAAaABvAGUAbgBpAHgALQAxADYAOAAuAG4AeQBtADEALgBwAGwAYQBjAGUAaQBxAC4AbgBlAHQwgd8GCSqGSIb3DQEJDjGB0TCBzjCBmwYDVR0RAQEABIGQMIGNoD0GCisGAQQBgjcUAgOgLwwtaG9zdC9waG9lbml4LTE2OC5ueW0xLnBsYWNlaXEubmV0QFBMQUNFSVEuTkVUoEwGBisGAQUCAqBCMECgDRsLUExBQ0VJUS5ORVShLzAtoAMCAQGhJjAkGwRob3N0GxxwaG9lbml4LTE2OC5ueW0xLnBsYWNlaXEubmV0MAwGA1UdEwEB/wQCMAAwIAYDVR0OAQEABBYEFKDhj0rZ6mZwJfrJx3pCI12dct5WMA0GCSqG!
 SIb3DQEBCw
UAA4IBAQC/zeFtiiiJXi9bws2NWx2u/vB7aTVRci2yb9wb70dUzcpeJ3qRTqsE5I+D3MHxLYnixrG4iMEaWgEyuJy4SIWqW1YVSrHwhJZufyRnxy7luNXON+TBBBI0Gro5gICy9XiDKbA/q6clYzEbwDLe6Es/U5/h4Bl/ziV61KYCJN0P1bMWI21A73iP3EQHx2lefYxI8BJN68hJLQiK+E0IWGCqfvipTHA0bHYSQy6WFmmS96v0wr93jy783iromycZeXWzFJyx+LruVPmPOewmUOJ2Y2NJNPJv35pPYUw5Dt2hlLgWZ18po8C+XYqvMbzxM2DFlxMX3Ff+ZiwCRYSGknFI',
> principal=u'host/phoenix-168.nym1.placeiq.net at PLACEIQ.NET
> <mailto:principal=u'host/phoenix-168.nym1.placeiq.net at placeiq.net>',
> add=True): ACIError
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: response: ACIError:
> Insufficient access: Gettext('not allowed to perform this command',
> domain='ipa', localedir=None)
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: no session id in request,
> generating empty session data with id=9beb89831ebfca453453ad48feaaa4d0
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: store session:
> session_id=9beb89831ebfca453453ad48feaaa4d0
> start_timestamp=2016-12-14T00:38:39 access_timestamp=2016-12-14T00:38:39
> expiration_timestamp=1970-01-01T00:00:00
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG:
> finalize_kerberos_acquisition: xmlserver
> ccache_name="FILE:/tmp/krb5cc_apache_SQg9kf"
> session_id="9beb89831ebfca453453ad48feaaa4d0"
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: reading ccache data from
> file "/tmp/krb5cc_apache_SQg9kf"
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: get_credential_times:
> principal=krbtgt/PLACEIQ.NET at PLACEIQ.NET
> <mailto:principal=krbtgt/PLACEIQ.NET at placeiq.net>, authtime=12/14/16
> 00:38:36, starttime=12/14/16 00:38:37, endtime=12/15/16 00:38:36,
> renew_till=01/01/70 00:00:00
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: KRB5_CCache
> FILE:/tmp/krb5cc_apache_SQg9kf endtime=1481762316 (12/15/16 00:38:36)
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG:
> set_session_expiration_time: duration_type=inactivity_timeout
> duration=1200 max_age=1481762016 expiration=1481677119.46
> (2016-12-14T00:58:39)
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: store session:
> session_id=9beb89831ebfca453453ad48feaaa4d0
> start_timestamp=2016-12-14T00:38:39 access_timestamp=2016-12-14T00:38:39
> expiration_timestamp=2016-12-14T00:58:39
> [Wed Dec 14 00:38:39 2016] [error] ipa: DEBUG: Destroyed connection
> context.ldap2
> 
> 
> 
> 
> <http://www.placeiq.com/><http://www.placeiq.com/><http://www.placeiq.com/>
> Jim Richard
> <https://twitter.com/placeiq><https://twitter.com/placeiq><https://twitter.com/placeiq>
> <https://www.facebook.com/PlaceIQ><https://www.facebook.com/PlaceIQ>
> <https://www.linkedin.com/company/placeiq><https://www.linkedin.com/company/placeiq>
> SYSTEM ADMINISTRATOR III
> /(646) 338-8905 / 
> 
> 
> PlaceIQ:Alibaba
> <http://placeiq.com/2016/10/26/the-making-of-a-location-data-industry-milestone/>
> 
> 
> 
> 
>> On Dec 2, 2016, at 5:29 PM, Rob Crittenden <rcritten at redhat.com
>> <mailto:rcritten at redhat.com>> wrote:
>>
>> Jim Richard wrote:
>>> Hmm ya. So before I rebuilt anything I thought maybe it was my DNS
>>> records but it looks like that’s not it.
>>>
>>> More background, I used to have sso-109 and sso-110, both CA’s. I
>>> rebuilt sso-110 without CA.
>>>
>>> My DNS is external, BIND on another host.
>>>
>>> Using the following (at the end of the message) host/key issue as an
>>> example. On this host, in sssd.conf, ipa_server and krb5_server values
>>> are both _srv_ so that means they’ll discover from DNS right?
>>>
>>> But in my krb5.conf I have:
>>>
>>> [realms]
>>>  PLACEIQ.NET <http://placeiq.net> <http://placeiq.net> = {
>>>    kdc = sso-110.nym1.placeiq.net <http://sso-110.nym1.placeiq.net>
>>> <http://sso-110.nym1.placeiq.net>:88
>>>    master_kdc = sso-110.nym1.placeiq.net
>>> <http://sso-110.nym1.placeiq.net>
>>> <http://sso-110.nym1.placeiq.net>:88
>>>    admin_server = sso-110.nym1.placeiq.net
>>> <http://sso-110.nym1.placeiq.net>
>>> <http://sso-110.nym1.placeiq.net>:749
>>>    default_domain = placeiq.net <http://placeiq.net> <http://placeiq.net>
>>>    pkinit_anchors = FILE:/etc/ipa/ca.crt
>>>  }
>>>
>>>
>>> Is there any other IPA related config file that might reference a
>>> host name?
>>>
>>> I’ll include my DNS records at the end here, do they look correct for a
>>> two server setup, one with a CA (sso-109) and the other no CA (sso-110)?
>>>
>>> I never have been sure about the “kerberos-master” entries, what makes
>>> an IPA host a “kerberos master” and is this related to the CA in any way?
>>>
>>> ; ldap servers
>>> _ldap._tcp      IN SRV 0 100 389    sso-109.nym1.placeiq.net
>>> <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>> _ldap._tcp      IN SRV 0 100 389    sso-110.nym1.placeiq.net
>>> <http://sso-110.nym1.placeiq.net>
>>> <http://sso-110.nym1.placeiq.net>.
>>>
>>> ;kerberos realm
>>> _kerberos               IN TXT PLACEIQ.NET <http://placeiq.net>
>>> <http://placeiq.net>
>>>
>>> ; kerberos servers
>>> _kerberos._tcp          IN SRV 0 100 88
>>>         sso-109.nym1.placeiq.net <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>> _kerberos._tcp          IN SRV 0 100 88
>>>         sso-110.nym1.placeiq.net <http://sso-110.nym1.placeiq.net>
>>> <http://sso-110.nym1.placeiq.net>.
>>>
>>> _kerberos._udp          IN SRV 0 100 88
>>>         sso-109.nym1.placeiq.net <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>> _kerberos._udp          IN SRV 0 100 88
>>>         sso-110.nym1.placeiq.net <http://sso-110.nym1.placeiq.net>
>>> <http://sso-110.nym1.placeiq.net>.
>>>
>>> _kerberos-master._tcp   IN SRV 0 100 88
>>>         sso-109.nym1.placeiq.net <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>> _kerberos-master._udp   IN SRV 0 100 88
>>>         sso-109.nym1.placeiq.net <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>> _kerberos-adm._tcp      IN SRV 0 100 749
>>>        sso-109.nym1.placeiq.net <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>> _kerberos-adm._udp      IN SRV 0 100 749
>>>        sso-109.nym1.placeiq.net <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>>
>>> _kpasswd._tcp           IN SRV 0 100 464
>>>        sso-109.nym1.placeiq.net <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>> _kpasswd._tcp           IN SRV 0 100 464
>>>        sso-110.nym1.placeiq.net <http://sso-110.nym1.placeiq.net>
>>> <http://sso-110.nym1.placeiq.net>.
>>>
>>> _kpasswd._udp           IN SRV 0 100 464
>>>        sso-109.nym1.placeiq.net <http://sso-109.nym1.placeiq.net>
>>> <http://sso-109.nym1.placeiq.net>.
>>> _kpasswd._udp           IN SRV 0 100 464
>>>        sso-110.nym1.placeiq.net <http://sso-110.nym1.placeiq.net>
>>> <http://sso-110.nym1.placeiq.net>.
>>>
>>> ; CNAME for IPA CA replicas (used for CRL, OCSP)
>>> ipa-ca                  IN A                    10.1.41.109
>>>
>>>
>>>
>>> Number of certificates and requests being tracked: 1.
>>> Request ID '20141110221330':
>>>        status: MONITORING
>>>        ca-error: Server at https://sso-110.nym1.placeiq.net/ipa/xml
>>> denied our request, giving up: 2100 (RPC failed at server.  Insufficient
>>> access: not allowed to perform this command).
>>>        stuck: no
>>>        key pair storage:
>>> type=NSSDB,location='/etc/pki/nssdb',nickname='IPA Machine Certificate -
>>> phoenix-142.nym1.placeiq.net <http://phoenix-142.nym1.placeiq.net>
>>> <http://phoenix-142.nym1.placeiq.net>',token='NSS Certificate DB'
>>>        certificate: type=NSSDB,location='/etc/pki/nssdb',nickname='IPA
>>> Machine Certificate - phoenix-142.nym1.placeiq.net
>>> <http://phoenix-142.nym1.placeiq.net>',token='NSS Certificate DB'
>>>        CA: IPA
>>>        issuer: CN=Certificate Authority,O=PLACEIQ.NET
>>> <http://placeiq.net>
>>>        subject: CN=phoenix-142.nym1.placeiq.net
>>> <http://phoenix-142.nym1.placeiq.net>,O=PLACEIQ.NET <http://placeiq.net>
>>>        expires: 2016-11-10 22:13:31 UTC
>>>        key usage:
>>> digitalSignature,nonRepudiation,keyEncipherment,dataEncipherment
>>>        eku: id-kp-serverAuth,id-kp-clientAuth
>>>        pre-save command:
>>>        post-save command:
>>>        track: yes
>>>        auto-renew: yes
>>>
>>>
>>>
>>> We are moving to latest version on RHEL so we’ll have paid support but
>>> before than, gaining this understanding is massively valuable :)
>>
>> I'm pretty certain this has nothing to do with servers being removed.
>> IPA isn't saying it can't find something, it's saying you aren't allowed
>> to do something.
>>
>> Why that is the case I don't know. A way to maybe find out would involve
>> enabling debugging on the server. You can do this by creating
>> /etc/ipa/server.conf with these contents:
>>
>> [global]
>> debug=True
>>
>> Restart httpd and watch. I'd leave it on just long enough to see the
>> problem, then turn it off again given you are already having disk space
>> issues.
>>
>> There is no way to dynamically do this w/o restarting the service.
>>
>> rob
>>
> 




More information about the Freeipa-users mailing list