Bug 903343

Created attachment 686169 [details]
the unenrollment

Created attachment 686170 [details]
2nd sttempt = success

Can you provide the output of:

ipa role-show --all --raw 'Build Administrator'

[admin ~]$ ipa role-show --all --raw 'Build Administrator'
  dn: cn=build administrator,cn=roles,cn=accounts,dc=salab,dc=redhat,dc=com
  cn: Build Administrator
  description: Users that have permissions to enroll and build new machines.
  member: uid=builduser,cn=users,cn=accounts,dc=salab,dc=redhat,dc=com
  memberof: cn=host administrators,cn=privileges,cn=pbac,dc=salab,dc=redhat,dc=com
  memberofindirect: cn=add hosts,cn=permissions,cn=pbac,dc=salab,dc=redhat,dc=com
  memberofindirect: cn=remove hosts,cn=permissions,cn=pbac,dc=salab,dc=redhat,dc=com
  memberofindirect: cn=modify hosts,cn=permissions,cn=pbac,dc=salab,dc=redhat,dc=com
  memberofindirect: cn=manage host ssh public keys,cn=permissions,cn=pbac,dc=salab,dc=redhat,dc=com
  memberofindirect: cn=manage host keytab,cn=permissions,cn=pbac,dc=salab,dc=redhat,dc=com
  memberofindirect: cn=enroll a host,cn=permissions,cn=pbac,dc=salab,dc=redhat,dc=com
  memberofindirect: cn=add krbprincipalname to a host,cn=permissions,cn=pbac,dc=salab,dc=redhat,dc=com
  objectclass: groupofnames
  objectclass: nestedgroup
  objectclass: top
[admin ~]$

What is the situation with the host entry?
Does it exist?

Please run the following:

1) Clean everything on the client, make sure there is no host entry on the server.
2) Run your first attempt. Attach the ipa server logs. Check if the host entry is still not there. I suspect it gets created and it might be the bug. Please do klist on the client to see which tickets are available.
3) Run the second attempt, attach the ipa server log for that attempt too. I suspect that it might be running using host identity. Would be interesting to repeat the test but do kdestroy before doing the second attempt .

I smell a bug here but probably not exactly in the area you expect it.

If the account has permissions to create and modify entries the enrollment should go through. If the account does not have permissions to do something it should not go through on the second attempt.
However it might be that the two attempts happen using two different identities the first one under the identity of the user and second one under the identity of the host. The first try might be successful in provisioning host keytab and the TGT for the host might be already acquired. 
If this is the case then the privilege you create probably has permission to add host but misses permission to modify the host. Adding host modify would most likely clean things up.

I have not tried it myself. Just some thoughts on the matter.

Ok. I ran 'ipa-client-install --uninstall' and then removed the host from the IdM server. After the first run, the host does get created in IdM.

[admin ~]$ ipa host-show host237
  Host name: host237.rdu.salab.redhat.com
  Principal name: host/host237.rdu.salab.redhat.com.COM
  Password: False
  Keytab: False
  Managed by: host237.rdu.salab.redhat.com
[admin ~]$ 


But there is nothing in keytab or local tickets, as you can expect.

[root ~]$ klist -k /etc/krb5.keytab 
Keytab name: WRFILE:/etc/krb5.keytab
KVNO Principal
---- --------------------------------------------------------------------------
[root ~]$ klist
klist: No credentials cache found (ticket cache FILE:/tmp/krb5cc_0)
[root ~]$


Then subsequent enrollment works and keytab gets populated.

[admin ~]$ ipa host-show host237
  Host name: host237.rdu.salab.redhat.com
  Certificate: <snip>
  Principal name: host/host237.rdu.salab.redhat.com.COM
  SSH public key fingerprint: 5A:1A:8F:39:5E:B9:00:1D:99:A3:EC:CD:EC:F3:3C:C4 (ssh-dss), 75:63:AE:E1:24:F1:0A:D0:ED:59:90:E4:59:ED:61:19 (ssh-rsa)
  Password: False
  Keytab: True
  Managed by: host237.rdu.salab.redhat.com
  Subject: CN=host237.rdu.salab.redhat.com,O=SALAB.REDHAT.COM
  Serial Number: 268304423
  Serial Number (hex): 0xFFE0027
  Issuer: CN=Certificate Authority,O=SALAB.REDHAT.COM
  Not Before: Wed Jan 23 21:25:34 2013 UTC
  Not After: Sat Jan 24 21:25:34 2015 UTC
  Fingerprint (MD5): ae:a5:a9:fd:bc:7e:a9:42:9e:29:7b:0e:0a:10:c5:e9
  Fingerprint (SHA1): 9c:d4:54:fc:34:50:5b:c2:ef:09:7d:f8:99:05:42:2e:b8:6e:a9:62
[admin ~]$ 



If you need the logs again, I can provide them, but they should be the same as I'm doing the same thing.

I think I'll need to try to reproduce this myself to see if I can find out what is being denied. 389-ds-base is rejecting a write on some attribute though it isn't clear why it succeeds on the second attempt. There must be some difference between the two.

Was able to pretty easily reproduce this. Haven't tracked the reason down yet but here is the ACI denial:

[24/Jan/2013:14:58:04 -0500] NSACLPlugin - conn=25 op=3 (main): Deny write on entry(fqdn=edsel.example.com,cn=computers,cn=accounts,dc=example,dc=com).attr(krbPrincipalKey) to uid=builduser,cn=users,cn=accounts,dc=example,dc=com: no aci matched the subject by aci(54): aciname= "Password change service can read/write passwords", acidn="dc=example,dc=com"

I had to use 389-ds error log level 262144 rather than 128. 128 added so much overhead it caused the KDC to timeout and the enrollment to fail before it even got far enough to create the host.

Upstream ticket:
https://fedorahosted.org/freeipa/ticket/3377

Matt, as a workaround can you try this:

# ipa-ldap-updater /usr/share/ipa/updates/55-pbacmemberof.update

You'll be prompted for the Directory Manager password.

It seems like the group memberof information is not quite right. After this things should work first time.

Is there anything I need to do after that command? Like bounce services on the ipa server? It still failed for me.

[root ~]$ ipa-ldap-updater /usr/share/ipa/updates/55-pbacmemberof.update
Directory Manager password: 

ipa         : INFO     Parsing file /usr/share/ipa/updates/55-pbacmemberof.update
ipa         : INFO     New entry: cn=Update PBAC memberOf 1359059627, cn=memberof task, cn=tasks, cn=config
ipa         : INFO     Update complete
[root ~]$

What this command does is create an 389-ds task that will regenerate memberOf data. It is possible it will take a few minutes for the task to complete but it generally finishes pretty quickly. You might try the enrollment again but if it fails again then it may be a different problem.

If you can enable debug logging in 389-ds that will help track down the problem.

Run this to enable ACI debugging:

$ ldapmodify -x -D 'cn=Directory Manager' -W
dn: cn=config
changetype: modify
replace: nsslapd-errorlog-level
nsslapd-errorlog-level: 262144

^D

Do the enrollment

Run this to disable ACI debugging:

$ ldapmodify -x -D 'cn=Directory Manager' -W
dn: cn=config
changetype: modify
replace: nsslapd-errorlog-level
nsslapd-errorlog-level: 0

You won't want to leave the logging enabled for long.

The logs are in /var/log/dirsrv/slapd-YOUR_REALM/errors

Here's what error log says.

[28/Jan/2013:11:06:21 -0500] entryrdn-index - _entryrdn_index_read: Child link "fqdn=host237.rdu.salab.redhat.com" of key "C6" not found: DB_NOTFOUND: No matching key/data pair found(-30988)
[28/Jan/2013:11:06:21 -0500] entryrdn-index - _entryrdn_index_read: Child link "fqdn=host237.rdu.salab.redhat.com" of key "C6" not found: DB_NOTFOUND: No matching key/data pair found(-30988)
[28/Jan/2013:11:06:21 -0500] entryrdn-index - _entryrdn_index_read: Child link "fqdn=host237.rdu.salab.redhat.com" of key "C6" not found: DB_NOTFOUND: No matching key/data pair found(-30988)
[28/Jan/2013:11:06:21 -0500] entryrdn-index - _entryrdn_index_read: Child link "fqdn=host237.rdu.salab.redhat.com" of key "C6" not found: DB_NOTFOUND: No matching key/data pair found(-30988)
[28/Jan/2013:11:06:22 -0500] entryrdn-index - _entryrdn_index_read: Child link "cn=dns" of key "C1" not found: DB_NOTFOUND: No matching key/data pair found(-30988)

Also, for what it's worth. I think I'm being hit by BZ 845691 too. I've seen the "Failed to obtain host TGT." error during enrollment occasionally. Not sure if these can impact each other.

I think these bugs should not impact each other, Insufficient Access Error should not be raised by it. BTW I did not see any error related to access rights in your DS log excerpt (...NSACLPlugin...) - did you use the log level that Rob suggested?

Anyway, I will try to reproduce this bug tomorrow with your specific version as I was not able to reproduce it with current upstream code.

Martin,

Yes, i copy & pasted the ldapmodify commands. And thanks for confirmation about the 2 bugs not being related.

Ok, thanks. This issue is still eluding me, I just tried it on two clean RHEL-6.3 VMs and builduser was able to enroll a machine without any problem. I will need to check with Rob as he was able to reproduce.

Btw is your IPA instance a clean install in RHEL-6.3 or it is an upgrade from RHEL-6.2?

Install date of this IdM instance is 16-Aug. 6.3 was released 20-Jun. So, I see no reason why it would have been a 6.2 install. Anything I can check?

However, the instance it has replicated from, may have been installed in 6.2 time. We stood up a master instance in PHX a while back, and have been standing up instances of IdM in other SA Labs and adding them as replicas. And now that I mention this.. I need to test this behavior in another lab (using the same realm/user/etc). I'll do that and report the results.

I duplicated on a fresh 6.3 install pretty easily and saw the same errors. In 6.4 I actually got the expected ACL failure errors but re-running the memberof task seemed to correct the problem. I think we'll need to run the messages in c#14 past the 389-ds folks.

(In reply to comment #20)
> I duplicated on a fresh 6.3 install pretty easily and saw the same errors.
> In 6.4 I actually got the expected ACL failure errors but re-running the
> memberof task seemed to correct the problem. I think we'll need to run the
> messages in c#14 past the 389-ds folks.

The messages in c#14 in RHEL 6.3 (389-ds-base-1.2.10) should only be seen if you are using the BACKLDBM error log level and do not necessarily indicate an error condition.  What is your error log level?

262144, configured in #c13

(In reply to comment #22)
> 262144, configured in #c13

Ok.  There was a bug in the log level - ACLSUMMARY log level was causing BACKLDBM messages to be printed - this was fixed in 1.2.11 as part of https://fedorahosted.org/389/ticket/345

You can ignore the messages

But we aren't seeing the ACLSUMMARY messages, is there a way to make them appear in 6.3?

(In reply to comment #24)
> But we aren't seeing the ACLSUMMARY messages, is there a way to make them
> appear in 6.3?

Yes, use the BACKLDBM error log level

Matt, use an nsslapd-errorlog-level of 524288

The underlying problem is that when the host is created and we try to write krbPrincipalKey it is denied by 389-ds-base. If the host already exists (either by pre-creating it manually or as a result of a previous failed enrollement) then it succeeds. This is very easy to reproduce.

I've been unsuccessful to reproduce again in 6.4 using 389-ds-base 1.2.11. The one time I reproduced it the problem was that the memberOf data wasn't up-to-date. Refreshing that in cn=pbac fixed it. Why the data was out-of-date I don't know. It could be that I executed the test before the postop plugin was finished its work.

As a test I tried updating my non-working 6.3 system with 389-ds-base 1.2.11 and it immediately started working: enrollment works first time every time.

So I think the solution to this is going to be to upgrade to 6.4

In the meantime you'll need to pre-create host entries in order to delegate enrollment.

Thanks Rob & all. Glad this issue (looks like) and the other bug (BZ 845691) are fixed in 6.4. I'll report back if that's not the case.

Closing as CURRENTRELEASE.

I'm going to have to re-open this. It does not look like the newest idm/ipa/389 in 6.4 fixes it for me.

I performed the upgrade on both client & server. And re-ran the following command:

# ipa-ldap-updater /usr/share/ipa/updates/55-pbacmemberof.update

And then increased the debug level up to 524288 per comment #26. And performed the enrollment again and it fails with the same error.

Password for builduser.COM: 
Joining realm failed: Operation failed! Insufficient access rights

child exited with 9

Use ipa-getkeytab to obtain a host principal for this server.
Failed to obtain host TGT.
Installation failed. Force set so not rolling back changes.



The host gets created. Same behavior as before. And running enrollment again, works.

Can you include the relevant information from the 389-ds-base error log?

Sorry, I failed to mention. I increased the log to that level and there were no additional entries to the slapd error log. I can go back to the original level 262144 if you think that'd help.

Yes, 262144 should work in 6.4

The full log is attached, but I suspect the relevant error is

[01/Mar/2013:12:35:08 -0500] NSACLPlugin - conn=126 op=3 (main): Deny write on entry(fqdn=host237.rdu.salab.redhat.com,cn=computers,cn=accounts,dc=salab,dc=redhat,dc=com).attr(krbPrincipalKey) to uid=builduser,cn=users,cn=accounts,dc=salab,dc=redhat,dc=com: no aci matched the subject by aci(87): aciname= "Password change service can read/write passwords", acidn="dc=salab,dc=redhat,dc=com"

Created attachment 704259 [details]
error log after 6.4 upgrade

Here is a simple shell script I use to configure my environment:

#!/bin/sh
# assumes you already have an admin ticket
echo password | ipa user-add builduser --first=Build --last=User --password
ipa role-add 'Build Administrator' --desc='build admin'
ipa role-add-privilege --privileges='host administrators'   'Build Administrator'
ipa role-add-member --users=builduser 'build administrator'
kinit builduser

I was able to reproduce this with IPA 3.0 in 6.4.

Enrollment fails with an identical ACI error that Matt describes. I confirmed that the user is a member of the correct permissions. The ACI that should grant access is:

(targetattr = "krbprincipalkey || krblastpwdchange")(target = "ldap:///fqdn=*,cn=computers,cn=accounts,$SUFFIX")(version 3.0;acl "permission:Manage host keytab";allow (write) groupdn = "ldap:///cn=Manage host keytab,cn=permissions,cn=pbac,$SUFFIX";)

I confirmed that builduser was a member of this permission. Like Matt, I tried to rebuild memberOf by doing the 55-pbacmemberof.update which creates two memberof tasks (the syntax is the IPA update syntax):

dn: cn=Update PBAC memberOf $TIME, cn=memberof task, cn=tasks, cn=config
add: objectClass: top
add: objectClass: extensibleObject
add: cn: IPA PBAC memberOf $TIME
add: basedn: 'cn=privileges,cn=pbac,$SUFFIX'
add: filter: (objectclass=*)
add: ttl: 10

dn: cn=Update Role memberOf $TIME, cn=memberof task, cn=tasks, cn=config
add: objectClass: top
add: objectClass: extensibleObject
add: cn: Update Role memberOf $TIME
add: basedn: 'cn=roles,cn=accounts,$SUFFIX'
add: filter: (objectclass=*)
add: ttl: 10

As a test I restarted the dirsrv process and the enrollment started working.

One thing to note: I did not wait particularly long for the memberof task to finish. Perhaps it hadn't completed its thing.

I unconfigured the server and reinstalled IPA again and was not able to reproduce this, suggesting some sort of timing issue.

Re-opening this. The problem is that the task to rebuild memberof is executed before some of the members are added which can sometimes leave things in a bad state.

Fixed upstream

master: 8377f4e92f6c927d6303a4be9d22e71a90af9ab0

This patch commits to LDAP the updates in blocks of 10.
comment:12 Changed 5 seconds ago by rcritten

master: 583bf43367769ca84ebc16594f8b70287b502311

Revert patch f7e27b547547be06f511a3ddfaff8db7d0b7898f which was a test case fix which addressed the symptom of memberof not being generated properly.

Kaleem still seems to reproduce the issue. I looked at the VM but still could not find the root cause. All member and memberof links seems to be in place for builduser.

When enabled ACL plugin log, I got this output:

[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Num of ALLOW Handles:5, DENY handles:0
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Processed attr:krbPrincipalKey for entry:fqdn=vm-067.idm.lab.bos.redhat.com,cn=computers,cn=accounts,dc=testrelm,dc=com
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - 1. Evaluating ALLOW aci(52) " "selfservice:Self can write own password""
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - 2. Evaluating ALLOW aci(102) " "Hosts can manage other host Certificates and kerberos keys""
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Attr:managedby
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - 3. Evaluating ALLOW aci(104) " "Admins can manage host keytab""
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Evaluating user uid=builduser,cn=users,cn=accounts,dc=testrelm,dc=com in group cn=admins,cn=groups,cn=accounts,dc=testrelm,dc=com?
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - -- Not in cn=admins,cn=groups,cn=accounts,dc=testrelm,dc=com
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - GroupEval:Looked at too many entries:(0, 1)
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Evaluated ACL_DONT_KNOW
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Returning UNDEFINED for groupdn evaluation.
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - 4. Evaluating ALLOW aci(40) " "permission:Manage host keytab""
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Evaluating user uid=builduser,cn=users,cn=accounts,dc=testrelm,dc=com in group cn=Manage host keytab,cn=permissions,cn=pbac,dc=testrelm,dc=com?
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - -- Not in cn=Manage host keytab,cn=permissions,cn=pbac,dc=testrelm,dc=com
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - GroupEval:Looked at too many entries:(0, 2)
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Evaluated ACL_DONT_KNOW
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Returning UNDEFINED for groupdn evaluation.
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - 5. Evaluating ALLOW aci(53) " "Admins can write passwords""
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - Evaluating user uid=builduser,cn=users,cn=accounts,dc=testrelm,dc=com in group cn=admins,cn=groups,cn=accounts,dc=testrelm,dc=com?
[28/Jan/2014:14:44:57 +051800] NSACLPlugin - -- Not in cn=admins,cn=groups,cn=accounts,dc=testrelm,dc=com
[28/Jan/2014:14:44:58 +051800] NSACLPlugin - GroupEval:Looked at too many entries:(0, 1)
[28/Jan/2014:14:44:58 +051800] NSACLPlugin - Evaluated ACL_DONT_KNOW
[28/Jan/2014:14:44:58 +051800] NSACLPlugin - Returning UNDEFINED for groupdn evaluation.
[28/Jan/2014:14:44:58 +051800] NSACLPlugin - conn=8 op=3 (main): Deny write on entry(fqdn=vm-067.idm.lab.bos.redhat.com,cn=computers,cn=accounts,dc=testrelm,dc=com).attr(krbPrincipalKey) to uid=builduser,cn=users,cn=accounts,dc=testrelm,dc=com: no aci matched the subject by aci(53): aciname= "Admins can write passwords", acidn="dc=testrelm,dc=com"

builduser is an indirect member of "cn=Manage host keytab,cn=permissions,cn=pbac,dc=testrelm,dc=com" which should allow the access,:

# ipa user-show builduser --all --raw | grep member
  memberof: cn=ipausers,cn=groups,cn=accounts,dc=testrelm,dc=com
  memberof: cn=Build Administrator,cn=roles,cn=accounts,dc=testrelm,dc=com
  memberofindirect: cn=host administrators,cn=privileges,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=add hosts,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=remove hosts,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=modify hosts,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=manage host ssh public keys,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=manage host keytab,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=enroll a host,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=retrieve certificates from the ca,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=revoke certificate,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=add krbprincipalname to a host,cn=permissions,cn=pbac,dc=testrelm,dc=com

but the ACI is still refuxed with "[28/Jan/2014:14:44:58 +051800] NSACLPlugin - GroupEval:Looked at too many entries:(0, 1)".

Is this expected? Or do I miss anything?

IPA and DS version:
===================
[root@rhel70-master ~]# rpm -q ipa-server 389-ds-base
ipa-server-3.3.3-15.el7.x86_64
389-ds-base-1.3.1.6-15.el7.x86_64
[root@rhel70-master ~]# 

Here is the output seen on client machine's console.

[root@rhel70-client ~]# ipa-client-install -U --domain=testrelm.com --realm=TESTRELM.COM -p builduser -w xxxxxx --server=rhel70-master.testrelm.com
Hostname: rhel70-client.testrelm.com
Realm: TESTRELM.COM
DNS Domain: testrelm.com
IPA Server: rhel70-master.testrelm.com
BaseDN: dc=testrelm,dc=com

Synchronizing time with KDC...
Successfully retrieved CA cert
    Subject:     CN=Certificate Authority,O=TESTRELM.COM
    Issuer:      CN=Certificate Authority,O=TESTRELM.COM
    Valid From:  Tue Jan 28 08:13:29 2014 UTC
    Valid Until: Sat Jan 28 08:13:29 2034 UTC

Joining realm failed: Operation failed! Insufficient access rights

child exited with 9

Installation failed. Rolling back changes.
IPA client is not configured on this system.
[root@rhel70-client ~]# 


IPA Master :
============
[root@rhel70-master ~]# ipa role-add 'Build Administrator' --desc='build admin'
--------------------------------
Added role "Build Administrator"
--------------------------------
  Role name: Build Administrator
  Description: build admin
[root@rhel70-master ~]# ipa role-add-privilege --privileges='host administrators'   'Build Administrator'
  Role name: Build Administrator
  Description: build admin
  Privileges: Host Administrators
----------------------------
Number of privileges added 1
----------------------------
[root@rhel70-master ~]# ipa role-add-member --users=builduser 'build administrator'
  Role name: Build Administrator
  Description: build admin
  Member users: builduser
  Privileges: Host Administrators
-------------------------
Number of members added 1
-------------------------
[root@rhel70-master ~]# ipa role-show --all --raw 'Build Administrator'
  dn: cn=Build Administrator,cn=roles,cn=accounts,dc=testrelm,dc=com
  cn: Build Administrator
  description: build admin
  member: uid=builduser,cn=users,cn=accounts,dc=testrelm,dc=com
  memberof: cn=Host Administrators,cn=privileges,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=add hosts,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=remove hosts,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=modify hosts,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=manage host ssh public keys,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=manage host keytab,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=enroll a host,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=retrieve certificates from the ca,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=revoke certificate,cn=permissions,cn=pbac,dc=testrelm,dc=com
  memberofindirect: cn=add krbprincipalname to a host,cn=permissions,cn=pbac,dc=testrelm,dc=com
  objectClass: groupofnames
  objectClass: nestedgroup
  objectClass: top
[root@rhel70-master ~]#

Rich or Rob, any advise on my investigation in Comment 45? Yesterday, I could not find the reason why ACI is failing, any help appreciated.

I was able to reproduce this once locally as well but only once, which makes me think this is still a timing issue.

What coordination is used between the server and client in the test case?

(In reply to Rob Crittenden from comment #48)
> I was able to reproduce this once locally as well but only once, which makes
> me think this is still a timing issue.

Did you see what was causing the ACI to be ineffective? In the past, it used to be caused by missing memberOf links, but both member and memberOf seemed OK when I was investigating the flawed IPA server.

Yeah, I have a hard time imagining that the memberof fixup task takes very long to complete but it would explain why this fails once, then everything looks fine when we poke at it.

When the original report happened, if you were able to reproduce it, it always happened such that the first request failed. When I reproduced it locally yesterday the first enrollment failed, then all subsequent enrollments succeeded.

I think I was able to reproduce the issue constantly, for example, I was never  able to get a keytab as the builduser with ipa-getkeytab (though I am now not sure if this is the right reproducer).

The enrollment indeed started to fail again, when I deleted the client object and run ipa-client-install.

I can also confirm that this happens, I can reproduce it every time.
Joining a server via admin always worked great.
Using a user with the same privileges as in this ticket, it always fails the first time and succeeds the second. 
I ran ipa-ldap-updater /usr/share/ipa/updates/55-pbacmemberof.update, waited about 5-10 minutes, and still had the same behavior.


ipa-client-3.0.0-37
389-ds-base-1.2.11.15-31

I should mention I also got the exact same aci error:
[31/Jan/2014:20:44:10 +0000] NSACLPlugin - conn=27240 op=3 (main): Deny write on entry(fqdn=test6.sso.inova1.rsapps.net,cn=computers,cn=accounts,dc=example,dc=com).attr(krbPrincipalKey) to uid=compadd,cn=users,cn=accounts,dc=example,dc=com: no aci matched the subject by aci(275): aciname= "Password change service can read/write passwords", acidn="dc=example,dc=com"

This may or may not be the right way around it, but I was able to do the following and get it to work:
Created a new permission
ipa permission-mod "add host krbPrincipalKey" --permissions=write,add --type=host --attrs=krbPrincipalKey
And added it to my privilege. 
I then ran the fixup script above (ipa-ldap-updater /usr/share/ipa/updates/55-pbacmemberof.update)
restarted 389-ds just for fun. 

This worked, I was able to join a server the first time. 

Host enrollment has the privileges: 
Permissions: add hosts, manage host keytab, enroll a host, add krbprincipalname to a host, add host krbprincipalkey

I may not be experiencing the same bug, but I am now able to enroll a host the first time instead of it taking two times.

Thanks drewskiwooskie for investigation (and sorry for a bit stale bug, we need to take a bigger look at this - after all, it's ACI related).

I did another round of investigation and can reproduce pretty reliably. In my case, even the "add host krbPrincipalKey" did not help. Attaching a detailed ACI processing log from the failed enrollment.

Ludwig, can you or someone other from DS please help with this one? I am afraid the problem is hidden somewhere in DS ACI processing, this is what I see in the ACI log:

[13/Feb/2014:07:24:23 -0500] NSACLPlugin - 6. Evaluating ALLOW aci(95) " "permission:add host krbPrincipalKey""
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - Evaluating user uid=builduser,cn=users,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com in group cn=add host krbPrincipalKey,cn=permissions,cn=pbac,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com?
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - -- In cn=Build Administrator,cn=roles,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - -- In cn=Host Administrators,cn=privileges,cn=pbac,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - -- In cn=Add Hosts,cn=permissions,cn=pbac,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - -- Not in uid=admin,cn=users,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - -- Not in cn=admins,cn=groups,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - -- Not in cn=add host krbPrincipalKey,cn=permissions,cn=pbac,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - GroupEval:Looked at too many entries:(0, 1)
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - Evaluated ACL_DONT_KNOW
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - Returning UNDEFINED for groupdn evaluation.
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - conn=7 op=3 (main): Deny write on entry(fqdn=vm-057.idm.lab.bos.redhat.com,cn=computers,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com).attr(krbPrincipalKey) to uid=builduser,cn=users,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com: no aci matched the subject by aci(95): aciname= "permission:add host krbPrincipalKey", acidn="dc=idm,dc=lab,dc=bos,dc=redhat,dc=com"


It says user is "In cn=Host Administrators,cn=privileges...", but "Not in cn=add host krbPrincipalKey,cn=permissions,...". However, when I search the privilege, I see the memberOf to be in place:

# ldapsearch -Y GSSAPI -b ' cn=Host Administrators,cn=privileges,cn=pbac,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com'
...
# Host Administrators, privileges, pbac, idm.lab.bos.redhat.com
dn: cn=Host Administrators,cn=privileges,cn=pbac,dc=idm,dc=lab,dc=bos,dc=redha
 t,dc=com
...
memberOf: cn=add host krbprincipalkey,cn=permissions,cn=pbac,dc=idm,dc=lab,dc=
 bos,dc=redhat,dc=com
member: cn=IT Specialist,cn=roles,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,d
 c=com
member: cn=Build Administrator,cn=roles,cn=accounts,dc=idm,dc=lab,dc=bos,dc=re
 dhat,dc=com

Created attachment 862767 [details]
ACI processing log of the failed enrollment

I reproduced it once yesterday and poked at it for a while (enabled debugging, tried to catch it in gdb, etc). At one point I restarted DS and it magically worked with no changes to the ACIs. I've been unable to reproduce it again to double-check this finding.

Sounds race condition-ish. I hope Ludwig (or you!) will find the root cause, this bug is really creepy.

To add to my testing, as I posted above, I was able to get it to work, but that was in my dev environment. Package wise, my dev environment matches production exactly, as well as the replication topology etc.. The only difference is the domain name, and hardware. 
I did the same steps that I did above (that made it work in my dev environment) in our production environment, and the issue did not fix itself at all, and I was seeing the same behavior with the ACI denial. 
It has been a few days so I would assume the fixup script has had enough time to run.
It definitely sounds like some kind of race or weird bug if the steps I followed made it work in our dev environment (again, which matches production exactly except for realm name and hardware), but it does not make it work in production.

I think the core of the failure is
[13/Feb/2014:07:24:23 -0500] NSACLPlugin - GroupEval:Looked at too many entries:(0, 1)

Evaluating groupd is limited to a specific number of members (for some reasons decided long,long ago) and it does a comparison:

if (info.c_idx > max_memberlimit &&
                        max_memberlimit != -1 ) {
                slapi_log_error( SLAPI_LOG_ACL, plugin_name,
                        "GroupEval:Looked at too many entries:(%d, %d)\n",
                                info.c_idx, info.lu_idx);
this means info.c_idx is 0 and greater max_memberlimit, which means max_meberlimit is < -1, which does not make sense.
But max_memberlimit is derived from search_sizelimit, which is only correctly defined and set for search operations and we are in an add. So there could be problems of memory initialization, if it is 0 or gt 0 everything is fine, otherwise we get the failure.

In my opinion there are two problems in DS:
1] the use of searchsizelinit to control the group evaluation
2] the use of a limit at all. If groups are used in acis then they should be evaluated independent of their size, it is the responsibility of the administrator

Right, I also wondered about this line in Comment 45. It really seems that max_memberlimit is lower than -1.

Ludwig, can you attach with gdb to this process and see what really happens? I can lend you my VMs to be able to quickly debug and see what happens.

Running with gdb shows that the values for max_memberlimit vary:
(gdb) p aclpb->aclpb_max_member_sizelimit
$4 = 5000
(gdb) p aclpb->aclpb_max_member_sizelimit
$5 = 100
(gdb) p aclpb->aclpb_max_member_sizelimit
$6 = 100
(gdb) p aclpb->aclpb_max_member_sizelimit
$7 = -1442862096

when it is negative it is related to an extended operation:
#0  acllas__user_ismember_of_group (aclpb=<optimized out>, groupDN=groupDN@entry=0x7f7acf0d8a08 "cn=Manage host keytab,cn=permissions,cn=pbac,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com", clientDN=<optimized out>, 
    cache_status=cache_status@entry=3, clientCert=<optimized out>) at ldap/servers/plugins/acl/acllas.c:2152
#1  0x00007f7ac45cc2c2 in acllas_eval_one_group (groupbuf=groupbuf@entry=0x7f7acf0d8a08 "cn=Manage host keytab,cn=permissions,cn=pbac,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com", lasinfo=0x7f7aa9ff57d0, 
    lasinfo=0x7f7aa9ff57d0) at ldap/servers/plugins/acl/acllas.c:4438
#2  0x00007f7ac45d014c in DS_LASGroupDnEval (errp=<optimized out>, attr_name=<optimized out>, comparator=CMP_OP_EQ, attr_pattern=<optimized out>, cachable=<optimized out>, LAS_cookie=<optimized out>, 
    subject=0x7f7acedc82d0, resource=0x0, auth_info=0x0, global_auth=0x0) at ldap/servers/plugins/acl/acllas.c:920
#3  0x00007f7ac438f495 in ACLEvalAce (errp=errp@entry=0x0, acleval=acleval@entry=0x7f7acef03000, ace=0x7f7acf0141d0, cachable=cachable@entry=0x7f7aa9ff7978, autharray=0x0, global_auth=global_auth@entry=0x0)
    at lib/libaccess/oneeval.cpp:254
#4  0x00007f7ac438ff59 in ACL_INTEvalTestRights (errp=errp@entry=0x0, acleval=acleval@entry=0x7f7acef03000, rights=0x7f7aa9ffa5b8, rights@entry=0x7f7aa9ffa5b0, 
    map_generic=map_generic@entry=0x7f7ac47e0ad0 <ds_map_generic>, deny_type=deny_type@entry=0x7f7aa9ffa598, deny_response=deny_response@entry=0x7f7aa9ffa5a0, acl_tag=acl_tag@entry=0x7f7aa9ffa5a8, 
    expr_num=expr_num@entry=0x7f7aa9ffa594, cachable=cachable@entry=0x7f7aa9ffa500) at lib/libaccess/oneeval.cpp:782
#5  0x00007f7ac4390496 in ACL_EvalTestRights (errp=errp@entry=0x0, acleval=acleval@entry=0x7f7acef03000, rights=rights@entry=0x7f7aa9ffa5b0, map_generic=map_generic@entry=0x7f7ac47e0ad0 <ds_map_generic>, 
    deny_type=deny_type@entry=0x7f7aa9ffa598, deny_response=deny_response@entry=0x7f7aa9ffa5a0, acl_tag=acl_tag@entry=0x7f7aa9ffa5a8, expr_num=expr_num@entry=0x7f7aa9ffa594) at lib/libaccess/oneeval.cpp:992
#6  0x00007f7ac45c1049 in acl__TestRights (aclpb=aclpb@entry=0x7f7acef10d30, access=access@entry=8, right=right@entry=0x7f7aa9ffa688, result_reason=result_reason@entry=0x7f7aa9ffa690, 
    map_generic=0x7f7ac47e0ad0 <ds_map_generic>) at ldap/servers/plugins/acl/acl.c:3102
#7  0x00007f7ac45c3c91 in acl_access_allowed (pb=<optimized out>, e=e@entry=0x7f7acf2e8210, attr=attr@entry=0x7f7ac1ee64c3 "krbPrincipalKey", val=<optimized out>, access=access@entry=8)
    at ldap/servers/plugins/acl/acl.c:593
#8  0x00007f7ac45d5f27 in acl_access_allowed_main (pb=<optimized out>, e=0x7f7acf2e8210, attrs=<optimized out>, val=<optimized out>, access=8, flags=<optimized out>, errbuf=0x0)
    at ldap/servers/plugins/acl/aclplugin.c:383
#9  0x00007f7acd1a0bec in plugin_call_acl_plugin (pb=pb@entry=0x7f7acf2e82f0, e=e@entry=0x7f7acf2e8210, attrs=attrs@entry=0x7f7aa9ffa7c0, val=val@entry=0x0, access=access@entry=8, flags=flags@entry=0, 
    errbuf=errbuf@entry=0x0) at ldap/servers/slapd/plugin_acl.c:90
#10 0x00007f7acd1a10d7 in slapi_access_allowed (pb=pb@entry=0x7f7acf2e82f0, e=e@entry=0x7f7acf2e8210, attr=attr@entry=0x7f7ac1ee64c3 "krbPrincipalKey", val=val@entry=0x0, access=access@entry=8)
    at ldap/servers/slapd/plugin_acl.c:237
#11 0x00007f7ac1ee144f in ipapwd_setkeytab (pb=pb@entry=0x7f7acf2e82f0, krbcfg=0x7f7acf2f4bc0) at ipa_pwd_extop.c:803
#12 0x00007f7ac1ee20d4 in ipapwd_extop (pb=0x7f7acf2e82f0) at ipa_pwd_extop.c:1188
#13 0x00007f7acd19cda2 in plugin_call_exop_plugins (pb=pb@entry=0x7f7acf2e82f0, oid=0x7f7acf1c81a0 "2.16.840.1.113730.3.8.10.1") at ldap/servers/slapd/plugin.c:467
#14 0x00007f7acd6649b9 in do_extended (pb=0x7f7acf2e82f0) at ldap/servers/slapd/extendop.c:364
#15 0x00007f7acd65f2f3 in connection_dispatch_operation (pb=<optimized out>, op=0x7f7acf2e85a0, conn=0x7f7ab8a917a8) at ldap/servers/slapd/connection.c:650
#16 connection_threadmain () at ldap/servers/slapd/connection.c:2372
#17 0x00007f7acb781740 in _pt_root (arg=0x7f7acf031f60) at ../../../nspr/pr/src/pthreads/ptthread.c:204
#18 0x00007f7acb122df3 in start_thread (arg=0x7f7aa9ffb700) at pthread_create.c:308
#19 0x00007f7acae5039d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

The value used for the memberlimit comes from the search_sizelimot in the operation, but the structur is in a union and overlayed by the actual extende op.

(gdb) p *(((Slapi_PBlock *)0x7f7acf2e82f0)->pb_op)
$8 = {o_ber = 0x7f7acf2e81b0, o_msgid = 4, o_tag = 119, o_time = 1392634681, o_interval = 0, o_isroot = 0, o_sdn = {flag = 10 '\n', 
    udn = 0x7f7acf0a9530 "uid=builduser,cn=users,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com", dn = 0x7f7acf2f3a80 "uid=builduser,cn=users,cn=accounts,dc=idm,dc=lab,dc=bos,dc=redhat,dc=com", ndn = 0x0, 
    ndn_len = 72}, o_authtype = 0x7f7aceeacb70 "SASL GSSAPI", o_ssf = 56, o_opid = 3, o_connid = 16, o_handler_data = 0x0, o_result_handler = 0x0, o_search_entry_handler = 0x0, o_search_referral_handler = 0x0, 
  o_csngen_handler = 0x0, o_replica_attr_handler = 0x0, o_next = 0x0, o_status = 0, o_searchattrs = 0x0, o_flags = 960, o_extension = 0x7f7acf1e4910, o_target_spec = 0x0, o_abandoned_op = 0, o_params = {
    operation_type = 512, target_address = {udn = 0x0, uniqueid = 0x0, sdn = 0x0}, csn = 0x0, request_controls = 0x0, p = {p_add = {target_entry = 0x7f7acf1c81a0, parentuniqueid = 0x7f7aa9ffabf0 "$\001"}, 
      p_bind = {bind_method = -820215392, bind_creds = 0x7f7aa9ffabf0, bind_saslmechanism = 0x0, bind_ret_saslcreds = 0x0}, p_compare = {compare_ava = {ava_type = 0x7f7acf1c81a0 "2.16.840.1.113730.3.8.10.1", 
          ava_value = {bv_len = 140164814842864, bv_val = 0x0}, ava_private = 0x0}}, p_modify = {modify_mods = 0x7f7acf1c81a0}, p_modrdn = {modrdn_newrdn = 0x7f7acf1c81a0 "2.16.840.1.113730.3.8.10.1", 
        modrdn_deloldrdn = -1442862096, modrdn_newsuperior_address = {udn = 0x0, uniqueid = 0x0, sdn = 0x0}, modrdn_mods = 0x0}, 

p_search = {search_scope = -820215392, search_deref = 32634, 
        search_sizelimit = -1442862096, search_timelimit = 32634, search_filter = 0x0, search_strfilter = 0x0, search_attrs = 0x0, search_attrsonly = 0, search_is_and = 0, search_gerattrs = 0x0}, 

p_abandon = {
        abandon_targetmsgid = -820215392}, 

p_extended = {exop_oid = 0x7f7acf1c81a0 "2.16.840.1.113730.3.8.10.1", exop_value = 0x7f7aa9ffabf0}}}, 
o_results = {operation_type = 0, opreturn = 0, 
    result_controls = 0x0, result_code = 0, result_text = 0x0, result_matched = 0x0, r = {r_bind = {bind_ret_saslcreds = 0x0}, r_search = {search_result_set = 0x0, search_result_entry = 0x0, 
        opaque_backend_ptr = 0x0, nentries = 0, search_referrals = 0x0, estimate = 0}, r_extended = {exop_ret_oid = 0x0, exop_ret_value = 0x0}}}, o_pagedresults_sizelimit = -1}

so part of a pointer is interpreted as int.

If the group search should be limited this limit has to be defined independently from the search limit

Thanks for investigation, this indeed is a bug in 389-ds-base. I will clone this bug.

The 389-ds-base bug is fixed in 389-ds-base-1.3.1.6-19.el7, I just verified that I am able to enroll with builduser for the first time.

Verified.

IPA and 389-ds version:
=======================
389-ds-base.x86_64 0:1.3.1.6-21.el7
ipa-server.x86_64 0:3.3.3-19.el7

Snip from beaker automation log:
================================
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::
:: [   LOG    ] :: ipaclientinstall_bugcheck_903343 Enrolling a host into IdM/IPA always takes two attempts bz903343
::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::::

:: [   PASS   ] :: uninstall ipa client success 
:: [   PASS   ] :: Installing ipa-client (Expected 0, got 0)
:: [   LOG    ] :: execute expect file: /tmp/kinit.11648.exp
:: [   LOG    ] :: Success: kinit as [admin] with password [xxxxxxxx] was successful.
:: [   PASS   ] :: Kinit as admin user (Expected 0, got 0)
:: [   LOG    ] :: create ipa user: [builduser], firstname: [builduser1], lastname: [builduser1]  password: [xxxxxxxx]
:: [   LOG    ] :: create ipa user: [builduser], password: [xxxxxxxx]
:: [   PASS   ] :: add test user account (Expected 0, got 0)
:: [   LOG    ] :: kinit as builduser with new password xxxxxxxx was successful.
:: [   PASS   ] :: Running 'create_ipauser builduser builduser1 builduser1 xxxxxxxx' (Expected 0, got 0)
:: [   PASS   ] :: Running 'ipa role-add 'Build Administrator' --desc='build admin'' (Expected 0, got 0)
:: [   PASS   ] :: Running 'ipa role-add-privilege --privileges='host administrators'   'Build Administrator'' (Expected 0, got 0)
:: [   PASS   ] :: Running 'ipa role-add-member --users=builduser 'build administrator'' (Expected 0, got 0)
:: [   PASS   ] :: uninstall ipa client success 
:: [   PASS   ] :: Running 'ssh -o StrictHostKeyChecking=no root.test "echo xxxxxxxx|kinit admin; ipa  host-del ibm-hs21-04.testrelm.test;ipa dnsrecord-del TESTRELM.TEST ibm-hs21-04 --del-all" > /tmp/bz903343.txt' (Expected 0, got 0)
:: [   PASS   ] :: Running 'cat /tmp/bz903343.txt' (Expected 0, got 0)
:: [   PASS   ] :: Installing ipa-client (Expected 0, got 0)
:: [   PASS   ] :: Running 'cat /tmp/bz903343.txt' (Expected 0, got 0)
:: [   PASS   ] :: uninstall ipa client success 
:: [   LOG    ] :: Duration: 1m 3s
:: [   LOG    ] :: Assertions: 14 good, 0 bad
:: [   PASS   ] :: RESULT: ipaclientinstall_bugcheck_903343 Enrolling a host into IdM/IPA always takes two attempts bz903343

This request was resolved in Red Hat Enterprise Linux 7.0.

Contact your manager or support representative in case you have further questions about the request.