Bug 1452763

Summary: ipa certmaprule change not reflected in krb5kdc workers
Product: Red Hat Enterprise Linux 7 Reporter: Scott Poore <spoore>
Component: ipaAssignee: IPA Maintainers <ipa-maint>
Status: CLOSED ERRATA QA Contact: Scott Poore <spoore>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 7.4CC: dpal, ksiddiqu, mbasti, ovasik, pvoborni, rcritten, sbose, tscherf
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ipa-4.5.0-15.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-08-01 09:51:24 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Scott Poore 2017-05-19 14:54:05 UTC
Description of problem:

While testing Smart Cards on an IPA client with PKINIT enabled in IPA, I noticed intermittent failures.  The certificate maps properly to the user but, the KDC on IPA would sometimes seem to try to match to the previous rule.
 
Version-Release number of selected component (if applicable):
krb5-server-1.15.1-8.el7.x86_64


How reproducible:
unknown.

Steps to Reproduce:
1.  IPA Server installed with PKINIT support
2.  IPA Client setup with Smart Card
3.  Cert generated on IPA server and added to card
4.  created one certmaprule and tested client
5.  deleted rule and added new rule
6.  tested authentication which should use the new rule

Actual results:
authentication would fail at times.  work others.

Expected results:
always work.

Additional info:


FYI, rules used when I saw the error:

ipa certmaprule-add ipaadcs12r2_defaultrule --maprule='(|(userCertificate;binary={cert!bin})(altSecurityIdentities=X509:<I>{issuer_dn!ad_x500}<S>{subject_dn!ad_x500}))' --matchrule='<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST' --domain=ipaadcs12r2.test --domain=testrelm.test

ipa certmaprule-del ipaadcs12r2_ipacertrule

ipa certmaprule-add testrealm_defaultrule --maprule='(|(userCertificate;binary={cert!bin})(ipacertmapdata=X509:<I>{issuer_dn!nss_x500}<S>{subject_dn!nss_x500}))' --matchrule='<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST' --domain=testrelm.test

This rule change seems to have happened between when the kdc workers loaded the rule.

[Wed May 17 17:06:43.623274 2017] [:error] [pid 8318] ipa: INFO: [jsonserver_session] admin: certmaprule_add/1(u'ipaadcs12r2_defaultrule', ipacertmapmaprule=u'(|(userCertificate;binary={cert!bin})(altSecurityIdentities=X509:<I>{issuer_dn!ad_x500}<S>{subject_dn!ad_x500}))', ipacertmapmatchrule=u'<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST', associateddomain=(<DNS name ipaadcs12r2.test>, <DNS name testrelm.test>), version=u'2.224'): SUCCESS

[Thu May 18 14:43:51.148965 2017] [:error] [pid 8319] ipa: INFO: [jsonserver_session] admin: certmaprule_del/1([u'ipaadcs12r2_defaultrule'], version=u'2.224'): SUCCESS

[Thu May 18 14:44:30.060976 2017] [:error] [pid 8318] ipa: INFO: [jsonserver_session] admin: certmaprule_add/1(u'testrealm_defaultrule', ipacertmapmaprule=u'(|(userCertificate;binary={cert!bin})(ipacertmapdata=X509:<I>{issuer_dn!nss_x500}<S>{subject_dn!nss_x500}))', ipacertmapmatchrule=u'<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST', associateddomain=(<DNS name testrelm.test>,), version=u'2.224'): SUCCESS


######## Example krb5kdc.log entries showing failure and success 


May 18 17:26:08 auto-hv-02-guest08.testrelm.test krb5kdc[8259](info): Got cert filter [(|(userCertificate;binary=\30\82\04\0d...
May 18 17:26:08 auto-hv-02-guest08.testrelm.test krb5kdc[8259](info): No matching entry found



May 18 17:41:02 auto-hv-02-guest08.testrelm.test krb5kdc[8260](info): Got cert filter [(|(userCertificate;binary=\30\82\04\0d...
May 18 17:41:02 auto-hv-02-guest08.testrelm.test krb5kdc[8260](info): AS_REQ (8 etypes {18 17 20 19 16 23 25 26}) <CLIENT_IP>: ISSUE: authtime 1495143662, etypes {rep=18 tkt=18 ses=18}, demosc1 for krbtgt/TESTRELM.TEST

Comment 2 Robbie Harwood 2017-05-19 15:38:54 UTC
This seems like an IPA bug, since you're saying an IPA command isn't working right?  I'm not set up to test smartcard stuff, in any case, so if it's something krb5's doing wrong please give me more information on what to look at.

Comment 3 Sumit Bose 2017-05-19 15:41:52 UTC
It is an issue in the IPA certauth plugin.

The certificate mapping rules are store during the initialization of the pkinit module in the ipadb_context. Since this context is not shared between different workers and the pkinit module is not initialized at startup but at first use it might be possible that different workers will use different mapping rules pkinit in not initialized at the same time and if the rules where changed between the two initializations.

To solve this the certificate mapping rules can be updated on a more regular basis like it is done e.g. in ipadb_reinit_mspac() to update the data about trusted domains.

Comment 4 Petr Vobornik 2017-05-19 15:51:03 UTC
Upstream ticket:
https://pagure.io/freeipa/issue/6963

Comment 8 Scott Poore 2017-06-07 17:03:08 UTC
Ok, first I'll show a reproducer:


# User has whole cert and not certmapdata.  Will keep this constant so kinit will go from passing to failing but, we're looking for the logs more than anything here.

[root@auto-hv-02-guest08 ~]# systemctl restart krb5kdc

[root@dhcp129-184 ~]# ipa certmaprule-add testrelm_certificate \
>   --maprule='(userCertificate;binary={cert!bin})' \
>   --matchrule='<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST'
--------------------------------------------------------------
Added Certificate Identity Mapping Rule "testrelm_certificate"
--------------------------------------------------------------
  Rule name: testrelm_certificate
  Mapping rule: (userCertificate;binary={cert!bin})
  Matching rule: <ISSUER>CN=Certificate Authority,O=TESTRELM.TEST
  Enabled: TRUE

[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 

# IN /var/log/krb5kdc.log on MASTER:

Jun 07 12:53:46 auto-hv-02-guest08.testrelm.test krb5kdc[27694](info): Got cert filter [(userCertificate;binary=\30\82\04\0d...

2017-06-07 10:53:46 MDT 
[root@dhcp129-184 ~]# kdestroy -A ; echo Secret123|kinit admin
Password for admin: 

2017-06-07 10:53:53 MDT 
[root@dhcp129-184 ~]# ipa certmaprule-del testrelm_certificate
----------------------------------------------------------------
Deleted Certificate Identity Mapping Rule "testrelm_certificate"
----------------------------------------------------------------

2017-06-07 10:53:57 MDT 
[root@dhcp129-184 ~]# ipa certmaprule-add testrelm_certmapdata \
>   --maprule='(ipacertmapdata=X509:<I>{issuer_dn!nss_x500}<S>{subject_dn!nss_x500})' \
>   --matchrule='<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST'
--------------------------------------------------------------
Added Certificate Identity Mapping Rule "testrelm_certmapdata"
--------------------------------------------------------------
  Rule name: testrelm_certmapdata
  Mapping rule: (ipacertmapdata=X509:<I>{issuer_dn!nss_x500}<S>{subject_dn!nss_x500})
  Matching rule: <ISSUER>CN=Certificate Authority,O=TESTRELM.TEST
  Enabled: TRUE

2017-06-07 10:54:01 MDT 
[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 


# IN /var/log/krb5kdc.log on MASTER we can see it uses the same worker with the old filter:

Jun 07 12:54:08 auto-hv-02-guest08.testrelm.test krb5kdc[27694](info): Got cert filter [(userCertificate;binary=\30\82\04...


2017-06-07 10:54:08 MDT 
[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 
kinit: Certificate mismatch while getting initial credentials


^^^ FAILS as EXPECTED because we do not have certmapdata defined for the user...only whole cert.

# IN /var/log/krb5kdc.log on MASTER we can see it used a new worker and pulled the new filter with certmapdata instead of whole cert:

Jun 07 12:54:26 auto-hv-02-guest08.testrelm.test krb5kdc[27695](info): Got cert filter [(ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=demosc1)]

If I were to switch again that worker would continue using that filter for a while.  With the new fix this same failure should occur in this short amount of time but, if I wait 5 minutes, it should timeout and pick up the new rule.  This is what I will test for the verification to follow.

Comment 9 Scott Poore 2017-06-07 17:29:48 UTC
Verified.

Version ::

ipa-server-4.5.0-15.el7.x86_64

Results ::

[root@auto-hv-02-guest08 ~]# systemctl restart krb5kdc

[root@dhcp129-184 ~]# ipa certmaprule-add testrelm_certificate \
>   --maprule='(userCertificate;binary={cert!bin})' \
>   --matchrule='<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST'
--------------------------------------------------------------
Added Certificate Identity Mapping Rule "testrelm_certificate"
--------------------------------------------------------------
  Rule name: testrelm_certificate
  Mapping rule: (userCertificate;binary={cert!bin})
  Matching rule: <ISSUER>CN=Certificate Authority,O=TESTRELM.TEST
  Enabled: TRUE

2017-06-07 11:11:40 MDT 

[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 

2017-06-07 11:11:52 MDT 

# IN /var/log/krb5kdc.log:

Jun 07 13:11:52 auto-hv-02-guest08.testrelm.test krb5kdc[6839](info): Got cert filter [(userCertificate;binary=\30\82\04

# ^^^ got cert filter as expected

[root@dhcp129-184 ~]# kdestroy -A ; echo Secret123|kinit admin
Password for admin: 

2017-06-07 11:12:03 MDT 

[root@dhcp129-184 ~]# ipa certmaprule-del testrelm_certificate
----------------------------------------------------------------
Deleted Certificate Identity Mapping Rule "testrelm_certificate"
----------------------------------------------------------------

2017-06-07 11:12:06 MDT 

[root@dhcp129-184 ~]# ipa certmaprule-add testrelm_certmapdata \
>   --maprule='(ipacertmapdata=X509:<I>{issuer_dn!nss_x500}<S>{subject_dn!nss_x500})' \
>   --matchrule='<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST'
--------------------------------------------------------------
Added Certificate Identity Mapping Rule "testrelm_certmapdata"
--------------------------------------------------------------
  Rule name: testrelm_certmapdata
  Mapping rule: (ipacertmapdata=X509:<I>{issuer_dn!nss_x500}<S>{subject_dn!nss_x500})
  Matching rule: <ISSUER>CN=Certificate Authority,O=TESTRELM.TEST
  Enabled: TRUE

2017-06-07 11:12:11 MDT 

[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 

2017-06-07 11:12:17 MDT 

# IN /var/log/krb5kdc.log

Jun 07 13:12:17 auto-hv-02-guest08.testrelm.test krb5kdc[6839](info): Got cert filter [(userCertificate;binary=\30\82\04

# ^^ got worker 1 again so need to retry kinit

[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 
kinit: Certificate mismatch while getting initial credentials

2017-06-07 11:12:24 MDT 

# IN /var/log/krb5kdc.log:

Jun 07 13:12:24 auto-hv-02-guest08.testrelm.test krb5kdc[6840](info): Got cert filter [(ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=demosc1)]

# ^^ worker2 gets the new filter as expected which is why the second kinit failed.

### Now we change the rule again and will watch for worker2 results to see if it changes (should not at first)

[root@dhcp129-184 ~]# kdestroy -A ; echo Secret123|kinit admin
Password for admin: 

2017-06-07 11:12:38 MDT 

[root@dhcp129-184 ~]# ipa certmaprule-del testrelm_certmapdata
----------------------------------------------------------------
Deleted Certificate Identity Mapping Rule "testrelm_certmapdata"
----------------------------------------------------------------

2017-06-07 11:12:42 MDT 

[root@dhcp129-184 ~]# ipa certmaprule-add testrelm_certificate \
>   --maprule='(userCertificate;binary={cert!bin})' \
>   --matchrule='<ISSUER>CN=Certificate Authority,O=TESTRELM.TEST'
--------------------------------------------------------------
Added Certificate Identity Mapping Rule "testrelm_certificate"
--------------------------------------------------------------
  Rule name: testrelm_certificate
  Mapping rule: (userCertificate;binary={cert!bin})
  Matching rule: <ISSUER>CN=Certificate Authority,O=TESTRELM.TEST
  Enabled: TRUE

2017-06-07 11:12:47 MDT 

[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 

2017-06-07 11:12:55 MDT 

# IN /var/log/krb5kdc.log:

Jun 07 13:12:55 auto-hv-02-guest08.testrelm.test krb5kdc[6839](info): Got cert filter [(userCertificate;binary=\30\82\04

# ^^ used worker1 so we have to try again

[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 
kinit: Certificate mismatch while getting initial credentials

2017-06-07 11:13:02 MDT 

# IN /var/log/krb5kdc.log

Jun 07 13:13:02 auto-hv-02-guest08.testrelm.test krb5kdc[6840](info): Got cert filter [(ipacertmapdata=X509:<I>O=TESTRELM.TEST,CN=Certificate Authority<S>O=TESTRELM.TEST,CN=demosc1)]

# ^^ Used worker2 with old certmapdata filter instead of new cert one...
# now will wait 5 minutes to see if this updates

[root@dhcp129-184 ~]# sleep 300

2017-06-07 11:18:16 MDT 

[root@dhcp129-184 ~]# kinit -X X509_user_identity=PKCS11:module_name=/usr/lib64/opensc-pkcs11.so demosc1
demosc1 (OpenSC Card)            PIN: 

2017-06-07 11:18:30 MDT 

# IN /var/log/krb5kdc.log

Jun 07 13:18:30 auto-hv-02-guest08.testrelm.test krb5kdc[6840](info): Got cert filter [(userCertificate;binary=\30\82\04

# ^^ and we see that worker2 has the new cert rule instead of the old certmapdata one.

Comment 10 errata-xmlrpc 2017-08-01 09:51:24 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:2304