#50369 LDAP modify for autogenerated value does not replace the value
Opened 4 months ago by abbra. Modified 3 months ago

In FreeIPA, we have a plugin ipa-pwd-extop that performs operations on passwords in the entries. One of operations is to generate ipaNTHash attribute value based on the content of krbPrincipalKey -- if keys in krbPrincipalKey attribute have arcfour-hmac value (RC4), it is gets copied to ipaNTHash attribute, replacing the ADD mod operation that contained ipaNTHash: MagicRegen.

With 389-ds-base in Fedora 30, 389-ds-base-1.4.1.2-2.fc30.x86_64, this does not work anymore. ipa-pwd-extop plugin still generates the value in request to produce it by ipasam module from Samba but the changed value is not written to the database.

This is how it looks from Samba side:

2019/05/14 16:38:40.111501,  5, pid=15908, effective(0, 0), real(0, 0)] ../../source3/lib/smbldap.c:1495(smbldap_modify)
  smbldap_modify: dn => [krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test]
[2019/05/14 16:38:41.532656,  5, pid=15908, effective(0, 0), real(0, 0)] ../../source3/lib/smbldap.c:1307(smbldap_search_ext)
  smbldap_search_ext: base => [krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test], filter => [(objectclass=*)], scope => [0]
[2019/05/14 16:38:41.533289,  5, pid=15908, effective(0, 0), real(0, 0)] ipa_sam.c:3517(init_sam_from_ldap)
  NT hash from LDAP has the wrong size. Perhaps password was not re-set?

The latter message is a reaction on the size of the retrieved value -- it has to be 16 bytes while "MagicRegen" is returned which is 10 bytes long.

On the 389-ds-base instance side I can see with instrumented ipa-pwd-extop plugin that the request is processed properly:

[14/May/2019:16:38:40.112705751 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 517]: ipapwd: ipaNTHash is in the list of modifications. Modifications: 0
[14/May/2019:16:38:40.249452708 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 527]: ipapwd: content of modification: MagicRegen
[14/May/2019:16:38:40.382811636 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 536]: ipapwd: magic regen found: 1
[14/May/2019:16:38:40.507998605 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 608]: ipapwd_entry_checks: is_root(0), is_krb(1), is_smb(0), is_ipant(1), attr(ipaNTHash), rc = 0
[14/May/2019:16:38:40.641647834 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 616]: ipapwd_gen_checks: rc = 0
[14/May/2019:16:38:40.782713006 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 625]: got to magic regen: is_krb(1)
[14/May/2019:16:38:40.907741380 +0000] - ERR - ipapwd_regen_nthash - [file prepost.c, line 959]: ipapwd_regen_nthash: does ipaNTHash exist already? 0
[14/May/2019:16:38:41.041040733 +0000] - ERR - ipapwd_regen_nthash - [file prepost.c, line 967]: ipapwd_regen_nthash: does krbPrincipalKey exist? 1
[14/May/2019:16:38:41.182993311 +0000] - ERR - ipapwd_regen_nthash - [file prepost.c, line 990]: Processing Kerberos keys. Total 3 keys
[14/May/2019:16:38:41.324346418 +0000] - ERR - ipapwd_regen_nthash - [file prepost.c, line 1024]: Found rc4 key and copied it to ipaNTHash: ESC<D2><DA><E6>n<E9><99>L-<ED><91><E8><D1>^MI5

actual generated value is not important (it is simply printed with %.*s format, to show that something is there). In audit log we can see that it is actually the same:

time: 20190514163841
dn: krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test
result: 0
changetype: modify
replace: modifiersname
modifiersname: krbprincipalname=cifs/master.example.test@example.test,cn=servi
 ces,cn=accounts,dc=example,dc=test
-
replace: modifytimestamp
modifytimestamp: 20190514163840Z
-
replace: entryusn
entryusn: 1836
-
add: ipaNTHash
ipaNTHash:: G9La5m7pmUwt7ZHo0Q1JNQ==
-

If I decode ipaNTHash, it is the same value as in the ipa-pwd-extop log:

# echo G9La5m7pmUwt7ZHo0Q1JNQ== | base64 -d | od -tx1
0000000 1b d2 da e6 6e e9 99 4c 2d ed 91 e8 d1 0d 49 35
0000020

However, id2entry database shows the value is wrong and if I try to retrieve it, I get wrong value too.

# dbscan -f /var/lib/dirsrv/slapd-EXAMPLE-TEST/db/userRoot/id2entry.db -K 514
id 514
    rdn: krbprincipalname=cifs/client.example.test@EXAMPLE.TEST
    krbCanonicalName: cifs/client.example.test@EXAMPLE.TEST
    objectClass: krbprincipal
    objectClass: krbprincipalaux
    objectClass: krbticketpolicyaux
    objectClass: ipaobject
    objectClass: ipaservice
    objectClass: pkiuser
    objectClass: ipakrbprincipal
    objectClass: ipaidobject
    objectClass: posixaccount
    objectClass: top
    objectClass: ipantuserattrs
    krbPrincipalName: cifs/client.example.test@EXAMPLE.TEST
    krbPrincipalName: CLIENT$@EXAMPLE.TEST
    ipaKrbPrincipalAlias: cifs/client.example.test@EXAMPLE.TEST
    uid: cifs/client.example.test
    uid: CLIENT$
    cn: CLIENT
    homeDirectory: /dev/null
    managedBy: fqdn=client.example.test,cn=computers,cn=accounts,dc=example,dc=tes
     t
    creatorsName: fqdn=client.example.test,cn=computers,cn=accounts,dc=example,dc=
     test
    modifiersName: krbprincipalname=cifs/master.example.test@example.test,cn=servi
     ces,cn=accounts,dc=example,dc=test
    createTimestamp: 20190514133035Z
    modifyTimestamp: 20190514163840Z
    nsUniqueId: 5f4d3c01-764c11e9-a079a37d-03050573
    ipaUniqueID: 74ab3a8e-764c-11e9-826a-52540011b4ad
    parentid: 5
    entryid: 514
    uidNumber: 89600017
    gidNumber: 89600017
    entryusn: 1836
    ipaNTSecurityIdentifier: S-1-5-21-1326256250-4276970629-2157751575-1017
    krbPrincipalKey:: MIIBc6ADAgEBoQMCAQGiAwIBAaMDAgEBpIIBWzCCAVcwa6AuMCygAwIBAKEl
     BCNFWEFNUExFLlRFU1RjaWZzY2xpZW50LmV4YW1wbGUudGVzdKE5MDegAwIBEaEwBC4QAK8jiZBZ6
     JKFhCEZ6RlVShxyaZ2RSnYO9m9S3nmiF4SJnjoOnrB6kKDAPPw9MHugLjAsoAMCAQChJQQjRVhBTV
     BMRS5URVNUY2lmc2NsaWVudC5leGFtcGxlLnRlc3ShSTBHoAMCARKhQAQ+IAAMeYnCG7aw3xZ/PVw
     6WlDra52lK9ApTXaDNPdsSmyy1Mwfd6PDHbwoXElpsUEvtckIh8ie066Djyc3Ulgwa6AuMCygAwIB
     AKElBCNFWEFNUExFLlRFU1RjaWZzY2xpZW50LmV4YW1wbGUudGVzdKE5MDegAwIBF6EwBC4QAJ9hb
     qyTzUSSEIXB2AuHZifY3lkXN7v7m1WucNOYq7k6AKkd+72dJySgXf6H
    krbLastPwdChange: 20190514133036Z
    krbExtraData:: AAL8wtpcY2lmcy9jbGllbnQuZXhhbXBsZS50ZXN0QEVYQU1QTEUuVEVTVAA=
    ipaNTHash: MagicRegen

I don't know when this regression happened, but it is critical to have Samba operating in FreeIPA environment and affects trust to Active Directory.


I0> grep -r -n -e 'MagicRegen' ldap
ldap/schema/10dna-plugin.ldif:48:attributeTypes: ( 2.16.840.1.113730.3.1.2119 NAME 'dnaMagicRegen'
ldap/schema/10dna-plugin.ldif:192:        dnaMagicRegen $
ldap/servers/plugins/dna/posix.ldif:24:dnaMagicRegen: 499
ldap/servers/plugins/dna/posix.ldif:36:dnaMagicRegen: 499
ldap/servers/plugins/dna/dna.c:47:#define DNA_GENERATE "dnaMagicRegen"
ldap/servers/plugins/dna/subtest.ldif:18:dnaMagicRegen: assign
ldap/servers/plugins/dna/subtest.ldif:29:dnaMagicRegen: assign

The value does not come from 389 I don't think ... but if we look in the FreeIPA source.

 I0> grep -r -n -e 'MagicRegen' .
./daemons/ipa-sam/ipa_sam.c:3182:   smbldap_set_mod(&mods, LDAP_MOD_ADD, LDAP_ATTRIBUTE_NTHASH, "MagicRegen");
./daemons/ipa-sam/ipa_sam.c:3460:        * ipaNTHash to MagicRegen value.
./daemons/ipa-slapi-plugins/ipa-pwd-extop/prepost.c:441:#define NTHASH_REGEN_VAL "MagicRegen"
./daemons/ipa-slapi-plugins/ipa-uuid/ipa_uuid.c:64:#define IPAUUID_GENERATE         "ipaUuidMagicRegen"
./install/updates/20-uuid.update:8:default: ipaUuidMagicRegen: autogenerate
./install/share/uuid.ldif:8:ipaUuidMagicRegen: autogenerate
./install/share/uuid.ldif:20:ipaUuidMagicRegen: autogenerate
./install/share/dna.ldif:12:dnaMagicRegen: -1

I think you should probably be looking into the ipa-pwd-extop code more, because I don't think this is a fault in 389 as the source tree has no reference to "MagicRegen", so there is no way we could provide that value. Please eliminate the ipa-pwd-extop code as the fault first, before we consider this a 389 issue, as today I believe the evidence would point to this being a fault in ipa-pwd-extop instead.

Metadata Update from @firstyear:
- Custom field origin adjusted to None
- Custom field reviewstatus adjusted to None

4 months ago

@firstyear as I wrote in the description, ipa-pwd-extop does its job and generates the needed value. It is even written into audit log. What happens next is beyond ipa-pwd-extop. Please look in more details in the description.

@abbra We don't have anything in the 389 code that could possibly generate that value though. That means the value "MagicRegen" must originally come from the ipa code, so I'd really like stronger proof of the error being in 389 please. IE bisection of the 389-ds-base version against IPA to show an exact commit, or something else like a gdb dump of the in memory entry at the return of the ipa-pwd-extop functions of each stage of it's hooks to show where in the operation sequence it is being modified.

The audit log you shown looks like 389 is doing the right thing, and has the ipaNTHash value correctly set, so I would assert that is evidence 389 is correctly handling this value here.

I think my comment stands, that this is insufficent evidence for fingers to be pointed in either direction, so I'd like stronger proof from you about where the error originates.

I'm not talking about 389-ds generating the value, quite opposite to that.

I'm pointing that when a client sends 'ipaNTHash: MagicRegen' attribute/value pair in a mod ADD, it gets properly replaced by ipa-pwd-extop plugin to the right hash value it extracts from krbPrincipalKey attribute values. As result, the mod ADD operation the client sent is replaced with the new content and that one is provided further to 389-ds. Audit log shows that this is indeed what happened.

Could you please explain at which stage the content of is audit log is written? Is it done after all plugins have processed the request?

modify.c: ~1030

Order is:

pre-plugin
be-modify
audit
post-plugin

edit: this means if something fails in post, the operation will be reverted, which will be in access log. Additionally, it means post plugins can still change content, or revert it.

Thus why I'm asking for you to provide more concrete evidence of a fault.

It appears ipa-pwd-extop has a post handler, so I think you should look at this possibly ...

Thanks, I'll check that. No changes were done in post handler for quite a long time.

Below is the access log (with internal operations) of that modification attempt listed in the audit log. Posting it here to have a reference point. My understanding is that operation 12 is the one where modification request with MagicRegen happens and its result has no error reported to the client.

# grep 'conn=44 ' /var/log/dirsrv/slapd-EXAMPLE-TEST/access|grep 16:38
[14/May/2019:16:38:39.750453619 +0000] conn=44 fd=109 slot=109 connection from local to /var/run/slapd-EXAMPLE-TEST.socket
[14/May/2019:16:38:39.750668253 +0000] conn=44 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[14/May/2019:16:38:39.941889487 +0000] conn=44 (Internal) op=0(1)(2) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.942277557 +0000] conn=44 (Internal) op=0(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000393023
[14/May/2019:16:38:39.942288654 +0000] conn=44 (Internal) op=0(1)(2) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.942455901 +0000] conn=44 (Internal) op=0(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000170582
[14/May/2019:16:38:39.942462320 +0000] conn=44 (Internal) op=0(1)(2) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.942645727 +0000] conn=44 (Internal) op=0(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000185230
[14/May/2019:16:38:39.943143256 +0000] conn=44 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[14/May/2019:16:38:39.943444650 +0000] conn=44 (Internal) op=1(1)(2) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.943620892 +0000] conn=44 (Internal) op=1(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000180806
[14/May/2019:16:38:39.943629363 +0000] conn=44 (Internal) op=1(1)(2) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.943798422 +0000] conn=44 (Internal) op=1(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000171351
[14/May/2019:16:38:39.943806018 +0000] conn=44 (Internal) op=1(1)(2) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.943966659 +0000] conn=44 (Internal) op=1(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000163547
[14/May/2019:16:38:39.944257504 +0000] conn=44 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[14/May/2019:16:38:39.944309777 +0000] conn=44 (Internal) op=2(1)(1) SRCH base="dc=example,dc=test" scope=2 filter="(krbPrincipalName=cifs/master.example.test@EXAMPLE.TEST)" attrs=ALL
[14/May/2019:16:38:39.944446124 +0000] conn=44 (Internal) op=2(1)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:39.944452253 +0000] conn=44 (Internal) op=2(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000150000
[14/May/2019:16:38:39.944491811 +0000] conn=44 (Internal) op=2(2)(1) SRCH base="dc=example,dc=test" scope=2 filter="(krbPrincipalName=cifs/master.example.test@EXAMPLE.TEST)" attrs=ALL
[14/May/2019:16:38:39.944530985 +0000] conn=44 (Internal) op=2(2)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:39.944535716 +0000] conn=44 (Internal) op=2(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000048517
[14/May/2019:16:38:39.944566047 +0000] conn=44 (Internal) op=2(3)(1) SRCH base="krbprincipalname=cifs/master.example.test@example.test,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="nsLookThroughLimit nsIDListScanLimit nsPagedLookThroughLimit nsPagedIDListScanLimit nsRangeSearchLookThroughLimit nsSizeLimit nsTimeLimit nsPagedSizeLimit nsIdleTimeout"
[14/May/2019:16:38:39.944598862 +0000] conn=44 (Internal) op=2(3)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:39.944603013 +0000] conn=44 (Internal) op=2(3)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000042582
[14/May/2019:16:38:39.944753990 +0000] conn=44 (Internal) op=2(6)(1) SRCH base="krbprincipalname=cifs/master.example.test@example.test,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[14/May/2019:16:38:39.944778033 +0000] conn=44 (Internal) op=2(6)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:39.944782161 +0000] conn=44 (Internal) op=2(6)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000038714
[14/May/2019:16:38:39.944842269 +0000] conn=44 op=1 RESULT err=14 tag=97 nentries=0 etime=0.0001737564, SASL bind in progress
[14/May/2019:16:38:39.945152793 +0000] conn=44 op=3 SRCH base="" scope=0 filter="(objectClass=*)" attrs="supportedControl"
[14/May/2019:16:38:39.945419922 +0000] conn=44 (Internal) op=3(1)(1) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.945595809 +0000] conn=44 (Internal) op=3(1)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000180834
[14/May/2019:16:38:39.945604911 +0000] conn=44 (Internal) op=3(2)(1) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.945773979 +0000] conn=44 (Internal) op=3(2)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000171991
[14/May/2019:16:38:39.945781374 +0000] conn=44 (Internal) op=3(3)(1) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.945965038 +0000] conn=44 (Internal) op=3(3)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000186410
[14/May/2019:16:38:39.946040308 +0000] conn=44 op=2 RESULT err=0 tag=97 nentries=0 etime=0.0001829318 dn="krbprincipalname=cifs/master.example.test@example.test,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:39.946269910 +0000] conn=44 op=3 ENTRY dn=""
[14/May/2019:16:38:39.946428976 +0000] conn=44 op=4 SRCH base="" scope=0 filter="(objectClass=*)" attrs="namingContexts defaultnamingcontext"
[14/May/2019:16:38:39.946681676 +0000] conn=44 (Internal) op=4(1)(1) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.946864928 +0000] conn=44 (Internal) op=4(1)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000187708
[14/May/2019:16:38:39.946874424 +0000] conn=44 (Internal) op=4(2)(1) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.947039360 +0000] conn=44 (Internal) op=4(2)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000168065
[14/May/2019:16:38:39.947045348 +0000] conn=44 (Internal) op=4(3)(1) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.947205799 +0000] conn=44 (Internal) op=4(3)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000162571
[14/May/2019:16:38:39.947290677 +0000] conn=44 op=3 RESULT err=0 tag=101 nentries=1 etime=0.0002214075
[14/May/2019:16:38:39.947358092 +0000] conn=44 op=4 ENTRY dn=""
[14/May/2019:16:38:39.947496073 +0000] conn=44 op=5 SRCH base="" scope=0 filter="(objectClass=*)" attrs="supportedExtension"
[14/May/2019:16:38:39.947737945 +0000] conn=44 (Internal) op=5(1)(1) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.947919429 +0000] conn=44 (Internal) op=5(1)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000185946
[14/May/2019:16:38:39.947928883 +0000] conn=44 (Internal) op=5(2)(1) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.948098311 +0000] conn=44 (Internal) op=5(2)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000172179
[14/May/2019:16:38:39.948104862 +0000] conn=44 (Internal) op=5(3)(1) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[14/May/2019:16:38:39.948275376 +0000] conn=44 (Internal) op=5(3)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000172659
[14/May/2019:16:38:39.948340883 +0000] conn=44 op=4 RESULT err=0 tag=101 nentries=1 etime=0.0001960251
[14/May/2019:16:38:39.948407877 +0000] conn=44 op=5 ENTRY dn=""
[14/May/2019:16:38:39.948578115 +0000] conn=44 op=6 SRCH base="dc=example,dc=test" scope=0 filter="(objectClass=domainRelatedObject)" attrs="associatedDomain"
[14/May/2019:16:38:39.948721780 +0000] conn=44 op=5 RESULT err=0 tag=101 nentries=1 etime=0.0001269744
[14/May/2019:16:38:39.948778916 +0000] conn=44 op=6 ENTRY dn="dc=example,dc=test"
[14/May/2019:16:38:39.948859791 +0000] conn=44 op=6 RESULT err=0 tag=101 nentries=1 etime=0.0000336064
[14/May/2019:16:38:39.948924694 +0000] conn=44 op=7 SRCH base="dc=example,dc=test" scope=2 filter="(objectClass=krbrealmcontainer)" attrs="cn"
[14/May/2019:16:38:39.949335691 +0000] conn=44 op=7 ENTRY dn="cn=EXAMPLE.TEST,cn=kerberos,dc=example,dc=test"
[14/May/2019:16:38:39.949419676 +0000] conn=44 op=7 RESULT err=0 tag=101 nentries=1 etime=0.0000537618
[14/May/2019:16:38:39.949498370 +0000] conn=44 op=8 SRCH base="dc=example,dc=test" scope=2 filter="(objectClass=ipaNTDomainAttrs)" attrs="ipaNTFlatName ipaNTSecurityIdentifier ipaNTFallbackPrimaryGroup objectClass"
[14/May/2019:16:38:39.949933120 +0000] conn=44 op=8 ENTRY dn="cn=example.test,cn=ad,cn=etc,dc=example,dc=test"
[14/May/2019:16:38:39.950085736 +0000] conn=44 op=9 SRCH base="cn=Default SMB Group,cn=groups,cn=accounts,dc=example,dc=test" scope=0 filter="(objectClass=*)" attrs="ipaNTSecurityIdentifier gidNumber"
[14/May/2019:16:38:39.950255959 +0000] conn=44 op=8 RESULT err=0 tag=101 nentries=1 etime=0.0000803370
[14/May/2019:16:38:39.950309720 +0000] conn=44 op=9 ENTRY dn="cn=Default SMB Group,cn=groups,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:39.950573228 +0000] conn=44 op=9 RESULT err=0 tag=101 nentries=1 etime=0.0000529412
[14/May/2019:16:38:39.950649518 +0000] conn=44 op=10 SRCH base="cn=EXAMPLE.TEST,cn=kerberos,dc=example,dc=test" scope=0 filter="(objectClass=krbrealmcontainer)" attrs="krbDefaultEncSaltTypes"
[14/May/2019:16:38:39.950827529 +0000] conn=44 op=10 ENTRY dn="cn=EXAMPLE.TEST,cn=kerberos,dc=example,dc=test"
[14/May/2019:16:38:39.953407298 +0000] conn=44 op=10 RESULT err=0 tag=101 nentries=1 etime=0.0002800181
[14/May/2019:16:38:39.953460926 +0000] conn=44 op=0 RESULT err=14 tag=97 nentries=0 etime=0.0202970920, SASL bind in progress
[14/May/2019:16:38:40.110271542 +0000] conn=44 op=11 SRCH base="dc=example,dc=test" scope=2 filter="(&(objectClass=ipaNTUserAttrs)(uid=cifs/client.example.test))" attrs=ALL
[14/May/2019:16:38:40.111288423 +0000] conn=44 op=11 ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:40.111316838 +0000] conn=44 op=11 RESULT err=0 tag=101 nentries=1 etime=0.0001182397
[14/May/2019:16:38:40.111594173 +0000] conn=44 op=12 MOD dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:40.111610125 +0000] conn=44 (Internal) op=12(1)(1) SRCH base="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[14/May/2019:16:38:40.111702219 +0000] conn=44 (Internal) op=12(1)(1) ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:40.111708143 +0000] conn=44 (Internal) op=12(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000105856
[14/May/2019:16:38:41.532883925 +0000] conn=44 op=13 SRCH base="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(objectClass=*)" attrs="ipaNTHash"
[14/May/2019:16:38:41.533244157 +0000] conn=44 op=13 ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:41.533980473 +0000] conn=44 op=13 RESULT err=0 tag=101 nentries=1 etime=0.0001197115
[14/May/2019:16:38:41.535783341 +0000] conn=44 op=14 SRCH base="dc=example,dc=test" scope=2 filter="(&(objectClass=ipaNTUserAttrs)(|(ipaNTSecurityIdentifier=S-1-5-21-1326256250-4276970629-2157751575-1001)))" attrs="uid ipaNTSecurityIdentifier"
[14/May/2019:16:38:41.536212856 +0000] conn=44 op=14 RESULT err=0 tag=101 nentries=0 etime=0.0000494138
[14/May/2019:16:38:41.536313820 +0000] conn=44 op=15 SRCH base="dc=example,dc=test" scope=2 filter="(&(objectClass=ipaNTGroupAttrs)(|(ipaNTSecurityIdentifier=S-1-5-21-1326256250-4276970629-2157751575-1001)))" attrs="cn displayName ipaNTSecurityIdentifier"
[14/May/2019:16:38:41.536705369 +0000] conn=44 op=15 ENTRY dn="cn=Default SMB Group,cn=groups,cn=accounts,dc=example,dc=test"
[14/May/2019:16:38:41.539367375 +0000] conn=44 op=15 RESULT err=0 tag=101 nentries=1 etime=0.0003103512
[14/May/2019:16:38:41.539458076 +0000] conn=44 op=16 SRCH base="dc=example,dc=test" scope=2 filter="(&(ipaNTSecurityIdentifier=S-1-5-32-545)(|(objectClass=ipaNTGroupAttrs)(objectClass=ipaNTUserAttrs)))" attrs="objectClass gidNumber uidNumber"
[14/May/2019:16:38:41.544525810 +0000] conn=44 op=16 RESULT err=0 tag=101 nentries=0 etime=0.0005118714 notes=U
[14/May/2019:16:38:41.544610990 +0000] conn=44 op=12 RESULT err=0 tag=103 nentries=0 etime=1.0433071809
[14/May/2019:16:38:41.567718674 +0000] conn=44 (Internal) op=6(1)(1) SRCH base="cn=anonymous-limits,cn=etc,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="nsLookThroughLimit nsIDListScanLimit nsPagedLookThroughLimit nsPagedIDListScanLimit nsRangeSearchLookThroughLimit nsSizeLimit nsTimeLimit nsPagedSizeLimit nsIdleTimeout"
[14/May/2019:16:38:41.567800090 +0000] conn=44 (Internal) op=6(1)(1) ENTRY dn="cn=anonymous-limits,cn=etc,dc=example,dc=test"
[14/May/2019:16:38:41.567808311 +0000] conn=44 (Internal) op=6(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000107125
[14/May/2019:16:38:41.817760316 +0000] conn=44 (Internal) op=7(1)(1) SRCH base="cn=anonymous-limits,cn=etc,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="nsLookThroughLimit nsIDListScanLimit nsPagedLookThroughLimit nsPagedIDListScanLimit nsRangeSearchLookThroughLimit nsSizeLimit nsTimeLimit nsPagedSizeLimit nsIdleTimeout"
[14/May/2019:16:38:41.817809887 +0000] conn=44 (Internal) op=7(1)(1) ENTRY dn="cn=anonymous-limits,cn=etc,dc=example,dc=test"
[14/May/2019:16:38:41.817814951 +0000] conn=44 (Internal) op=7(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000071369
[14/May/2019:16:38:41.818242602 +0000] conn=44 (Internal) op=8(1)(1) SRCH base="cn=anonymous-limits,cn=etc,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="nsLookThroughLimit nsIDListScanLimit nsPagedLookThroughLimit nsPagedIDListScanLimit nsRangeSearchLookThroughLimit nsSizeLimit nsTimeLimit nsPagedSizeLimit nsIdleTimeout"
[14/May/2019:16:38:41.818272614 +0000] conn=44 (Internal) op=8(1)(1) ENTRY dn="cn=anonymous-limits,cn=etc,dc=example,dc=test"
[14/May/2019:16:38:41.818277959 +0000] conn=44 (Internal) op=8(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000044073
[14/May/2019:16:38:41.818875068 +0000] conn=44 (Internal) op=9(1)(1) SRCH base="cn=anonymous-limits,cn=etc,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="nsLookThroughLimit nsIDListScanLimit nsPagedLookThroughLimit nsPagedIDListScanLimit nsRangeSearchLookThroughLimit nsSizeLimit nsTimeLimit nsPagedSizeLimit nsIdleTimeout"
[14/May/2019:16:38:41.818934315 +0000] conn=44 (Internal) op=9(1)(1) ENTRY dn="cn=anonymous-limits,cn=etc,dc=example,dc=test"
[14/May/2019:16:38:41.818940241 +0000] conn=44 (Internal) op=9(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000075197
[14/May/2019:16:38:41.820309101 +0000] conn=44 (Internal) op=10(1)(1) SRCH base="cn=anonymous-limits,cn=etc,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="nsLookThroughLimit nsIDListScanLimit nsPagedLookThroughLimit nsPagedIDListScanLimit nsRangeSearchLookThroughLimit nsSizeLimit nsTimeLimit nsPagedSizeLimit nsIdleTimeout"
[14/May/2019:16:38:41.820427296 +0000] conn=44 (Internal) op=10(1)(1) ENTRY dn="cn=anonymous-limits,cn=etc,dc=example,dc=test"
[14/May/2019:16:38:41.820449287 +0000] conn=44 (Internal) op=10(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000149856
[14/May/2019:16:38:42.471614404 +0000] conn=44 op=-1 fd=109 closed - B1

I'm going to look at the code later, need to work on something else right now.

I will never reject that a change in DS did change the behaviour, it could be quite likely. But looking at the data provided I don't get what is going on.

ipaNThash is a single valued attribute, in the audit log we see a add: ipaNTHash, I assume that no value of ipaNTHash existed, otherwise the add would be a schema violation. But this means MagicRegen was not there before and must have been created during the operation, but DS has no knowledge of this string.
The data of the entry also show that the operation was applied, the value of modifytimestamp and entryusn is correct. Could you do the search again as DM requesting nscpentrywsi, to see if the value of the ipaNTHash has the same CSN as the other changed attributes

@lkrispen the flow is this:

  • there is no ipaNTHash attribute in the entry
  • client sends a MOD ADD with 'ipaNTHash: MagicRegen'
  • the mods get intercepted by ipa-pwd-extop plugin and, if possible, is replaced by another MOD ADD, with 'ipaNTHash: <actual hash="" value="">'

As to the nscpEntryWSI search, I don't get any CSN returned. I get the same entry attributes as without nscpentrywsi but prefixed with nscpentrywsi: string.

@lkrispen the flow is this:

there is no ipaNTHash attribute in the entry
client sends a MOD ADD with 'ipaNTHash: MagicRegen'
the mods get intercepted by ipa-pwd-extop plugin and, if possible, is replaced by another MOD ADD, with 'ipaNTHash: <actual hash="" value="">'

Thanks this makes more sens now. So the client sends an op, the plugin intercepts it and changes it (as seen in the audit log), but the original mods are applied and stored.
This looks more like it is in DS land.
Do you know what version the behaviour was correct the last time ?

@tbordaz @mreynolds There have been changes around handling postop plugins to avoid the crashes after a failed plugin call. Do you think it could have a side effect like this ?

@abbra could you reproduce this with plugin logging ?

nsslapd-errorlog-level: 65536
nsslapd-plugin-logging: on

Access log:

[15/May/2019:09:58:33.303717372 +0000] conn=56 fd=99 slot=99 connection from local to /var/run/slapd-EXAMPLE-TEST.socket
[15/May/2019:09:58:33.304130611 +0000] conn=56 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[15/May/2019:09:58:33.519342727 +0000] conn=56 (Internal) op=0(1)(1) SRCH base="" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:33.519619399 +0000] conn=56 (Internal) op=0(1)(2) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:33.519991287 +0000] conn=56 (Internal) op=0(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000374790
[15/May/2019:09:58:33.520001888 +0000] conn=56 (Internal) op=0(1)(2) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:33.520175091 +0000] conn=56 (Internal) op=0(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000176696
[15/May/2019:09:58:33.520181403 +0000] conn=56 (Internal) op=0(1)(2) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:33.520381218 +0000] conn=56 (Internal) op=0(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000201658
[15/May/2019:09:58:33.520450267 +0000] conn=56 (Internal) op=0(1)(1) ENTRY dn=""
[15/May/2019:09:58:33.520458947 +0000] conn=56 (Internal) op=0(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0001123724
[15/May/2019:09:58:35.093572108 +0000] conn=56 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[15/May/2019:09:58:35.093633009 +0000] conn=56 (Internal) op=1(1)(1) SRCH base="" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:35.093942040 +0000] conn=56 (Internal) op=1(1)(2) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.094431980 +0000] conn=56 (Internal) op=1(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000492237
[15/May/2019:09:58:35.094444333 +0000] conn=56 (Internal) op=1(1)(2) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.094615016 +0000] conn=56 (Internal) op=1(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000174462
[15/May/2019:09:58:35.094621626 +0000] conn=56 (Internal) op=1(1)(2) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.094785014 +0000] conn=56 (Internal) op=1(1)(2) RESULT err=0 tag=48 nentries=0 etime=0.0000165797
[15/May/2019:09:58:35.094866444 +0000] conn=56 (Internal) op=1(1)(1) ENTRY dn=""
[15/May/2019:09:58:35.094875521 +0000] conn=56 (Internal) op=1(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0001256953
[15/May/2019:09:58:35.094954933 +0000] conn=56 op=0 RESULT err=14 tag=97 nentries=0 etime=1.1208804851, SASL bind in progress
[15/May/2019:09:58:35.517913751 +0000] conn=56 op=1 RESULT err=14 tag=97 nentries=0 etime=0.0424381745, SASL bind in progress
[15/May/2019:09:58:35.518173632 +0000] conn=56 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[15/May/2019:09:58:35.518294660 +0000] conn=56 (Internal) op=2(1)(1) SRCH base="dc=example,dc=test" scope=2 filter="(krbPrincipalName=cifs/master.example.test@EXAMPLE.TEST)" attrs=ALL
[15/May/2019:09:58:35.518459959 +0000] conn=56 (Internal) op=2(1)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.518466362 +0000] conn=56 (Internal) op=2(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000184040
[15/May/2019:09:58:35.518514429 +0000] conn=56 (Internal) op=2(2)(1) SRCH base="dc=example,dc=test" scope=2 filter="(krbPrincipalName=cifs/master.example.test@EXAMPLE.TEST)" attrs=ALL
[15/May/2019:09:58:35.518554205 +0000] conn=56 (Internal) op=2(2)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.518558864 +0000] conn=56 (Internal) op=2(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000049333
[15/May/2019:09:58:35.518592797 +0000] conn=56 (Internal) op=2(3)(1) SRCH base="krbprincipalname=cifs/master.example.test@example.test,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="nsLookThroughLimit nsIDListScanLimit nsPagedLookThroughLimit nsPagedIDListScanLimit nsRangeSearchLookThroughLimit nsSizeLimit nsTimeLimit nsPagedSizeLimit nsIdleTimeout"
[15/May/2019:09:58:35.518647445 +0000] conn=56 (Internal) op=2(3)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.518654629 +0000] conn=56 (Internal) op=2(3)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000067298
[15/May/2019:09:58:35.518713289 +0000] conn=56 (Internal) op=2(4)(1) SRCH base="krbprincipalname=cifs/master.example.test@example.test,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:35.518736236 +0000] conn=56 (Internal) op=2(4)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.518739905 +0000] conn=56 (Internal) op=2(4)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000031818
[15/May/2019:09:58:35.518773993 +0000] conn=56 (Internal) op=2(5)(1) SRCH base="cn=Default Service Password Policy,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:35.518800014 +0000] conn=56 (Internal) op=2(5)(1) ENTRY dn="cn=Default Service Password Policy,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.518803342 +0000] conn=56 (Internal) op=2(5)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000033479
[15/May/2019:09:58:35.925867619 +0000] conn=56 (Internal) op=2(6)(1) SRCH base="krbprincipalname=cifs/master.example.test@example.test,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:35.925982531 +0000] conn=56 (Internal) op=2(6)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.925994856 +0000] conn=56 (Internal) op=2(6)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000154803
[15/May/2019:09:58:35.926414547 +0000] conn=56 op=3 SRCH base="" scope=0 filter="(objectClass=*)" attrs="supportedControl"
[15/May/2019:09:58:35.926742810 +0000] conn=56 (Internal) op=3(1)(1) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.927104611 +0000] conn=56 (Internal) op=3(1)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000366397
[15/May/2019:09:58:35.927116056 +0000] conn=56 (Internal) op=3(2)(1) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.927351903 +0000] conn=56 (Internal) op=3(2)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000238997
[15/May/2019:09:58:35.927362095 +0000] conn=56 (Internal) op=3(3)(1) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.927569616 +0000] conn=56 (Internal) op=3(3)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000210884
[15/May/2019:09:58:35.927976518 +0000] conn=56 op=2 RESULT err=0 tag=97 nentries=0 etime=0.0409904743 dn="krbprincipalname=cifs/master.example.test@example.test,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.928027042 +0000] conn=56 (Internal) op=2(7)(1) SRCH base="krbprincipalname=cifs/master.example.test@example.test,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:35.928112079 +0000] conn=56 (Internal) op=2(7)(1) ENTRY dn="krbprincipalname=cifs/master.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.928117788 +0000] conn=56 (Internal) op=2(7)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000108508
[15/May/2019:09:58:35.928159888 +0000] conn=56 (Internal) op=2(8)(1) SRCH base="cn=Default Service Password Policy,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:35.928190408 +0000] conn=56 (Internal) op=2(8)(1) ENTRY dn="cn=Default Service Password Policy,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.928194245 +0000] conn=56 (Internal) op=2(8)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000039244
[15/May/2019:09:58:35.928332697 +0000] conn=56 op=3 ENTRY dn=""
[15/May/2019:09:58:35.928473933 +0000] conn=56 op=3 RESULT err=0 tag=101 nentries=1 etime=0.0002170999
[15/May/2019:09:58:35.928554558 +0000] conn=56 op=4 SRCH base="" scope=0 filter="(objectClass=*)" attrs="namingContexts defaultnamingcontext"
[15/May/2019:09:58:35.928848233 +0000] conn=56 (Internal) op=4(1)(1) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.929086257 +0000] conn=56 (Internal) op=4(1)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000242691
[15/May/2019:09:58:35.929095881 +0000] conn=56 (Internal) op=4(2)(1) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.929306021 +0000] conn=56 (Internal) op=4(2)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000212833
[15/May/2019:09:58:35.929315053 +0000] conn=56 (Internal) op=4(3)(1) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.929503592 +0000] conn=56 (Internal) op=4(3)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000192152
[15/May/2019:09:58:35.929628819 +0000] conn=56 op=4 ENTRY dn=""
[15/May/2019:09:58:35.929707118 +0000] conn=56 op=4 RESULT err=0 tag=101 nentries=1 etime=0.0001198052
[15/May/2019:09:58:35.929800853 +0000] conn=56 op=5 SRCH base="" scope=0 filter="(objectClass=*)" attrs="supportedExtension"
[15/May/2019:09:58:35.930094483 +0000] conn=56 (Internal) op=5(1)(1) SRCH base="cn=config,cn=userRoot,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.930315510 +0000] conn=56 (Internal) op=5(1)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000225590
[15/May/2019:09:58:35.930325523 +0000] conn=56 (Internal) op=5(2)(1) SRCH base="cn=config,cn=ipaca,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.930489965 +0000] conn=56 (Internal) op=5(2)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000167707
[15/May/2019:09:58:35.930495448 +0000] conn=56 (Internal) op=5(3)(1) SRCH base="cn=config,cn=changelog,cn=ldbm database,cn=plugins,cn=config" scope=1 filter="objectclass=vlvsearch" attrs=ALL
[15/May/2019:09:58:35.930654500 +0000] conn=56 (Internal) op=5(3)(1) RESULT err=0 tag=48 nentries=0 etime=0.0000160884
[15/May/2019:09:58:35.930791467 +0000] conn=56 op=5 ENTRY dn=""
[15/May/2019:09:58:35.930917474 +0000] conn=56 op=5 RESULT err=0 tag=101 nentries=1 etime=0.0001160180
[15/May/2019:09:58:35.931013547 +0000] conn=56 op=6 SRCH base="dc=example,dc=test" scope=0 filter="(objectClass=domainRelatedObject)" attrs="associatedDomain"
[15/May/2019:09:58:35.931168401 +0000] conn=56 op=6 ENTRY dn="dc=example,dc=test"
[15/May/2019:09:58:35.931261504 +0000] conn=56 op=6 RESULT err=0 tag=101 nentries=1 etime=0.0000315722
[15/May/2019:09:58:35.931337543 +0000] conn=56 op=7 SRCH base="dc=example,dc=test" scope=2 filter="(objectClass=krbrealmcontainer)" attrs="cn"
[15/May/2019:09:58:35.931530860 +0000] conn=56 op=7 ENTRY dn="cn=EXAMPLE.TEST,cn=kerberos,dc=example,dc=test"
[15/May/2019:09:58:35.931626458 +0000] conn=56 op=7 RESULT err=0 tag=101 nentries=1 etime=0.0000333966
[15/May/2019:09:58:35.931702912 +0000] conn=56 op=8 SRCH base="dc=example,dc=test" scope=2 filter="(objectClass=ipaNTDomainAttrs)" attrs="ipaNTFlatName ipaNTSecurityIdentifier ipaNTFallbackPrimaryGroup objectClass"
[15/May/2019:09:58:35.931930652 +0000] conn=56 op=8 ENTRY dn="cn=example.test,cn=ad,cn=etc,dc=example,dc=test"
[15/May/2019:09:58:35.932037577 +0000] conn=56 op=8 RESULT err=0 tag=101 nentries=1 etime=0.0000378423
[15/May/2019:09:58:35.932114216 +0000] conn=56 op=9 SRCH base="cn=Default SMB Group,cn=groups,cn=accounts,dc=example,dc=test" scope=0 filter="(objectClass=*)" attrs="ipaNTSecurityIdentifier gidNumber"
[15/May/2019:09:58:35.932332978 +0000] conn=56 op=9 ENTRY dn="cn=Default SMB Group,cn=groups,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:35.932599199 +0000] conn=56 op=9 RESULT err=0 tag=101 nentries=1 etime=0.0000527692
[15/May/2019:09:58:35.932672888 +0000] conn=56 op=10 SRCH base="cn=EXAMPLE.TEST,cn=kerberos,dc=example,dc=test" scope=0 filter="(objectClass=krbrealmcontainer)" attrs="krbDefaultEncSaltTypes"
[15/May/2019:09:58:35.932834966 +0000] conn=56 op=10 ENTRY dn="cn=EXAMPLE.TEST,cn=kerberos,dc=example,dc=test"
[15/May/2019:09:58:35.935793800 +0000] conn=56 op=10 RESULT err=0 tag=101 nentries=1 etime=0.0003158711
[15/May/2019:09:58:36.245574516 +0000] conn=56 op=11 SRCH base="dc=example,dc=test" scope=2 filter="(&(objectClass=ipaNTUserAttrs)(uid=cifs/client.example.test))" attrs=ALL
[15/May/2019:09:58:36.246555364 +0000] conn=56 op=11 ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:36.246580053 +0000] conn=56 op=11 RESULT err=0 tag=101 nentries=1 etime=0.0001102616
[15/May/2019:09:58:36.246862410 +0000] conn=56 op=12 MOD dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:36.246877950 +0000] conn=56 (Internal) op=12(1)(1) SRCH base="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:36.247012131 +0000] conn=56 (Internal) op=12(1)(1) ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:36.247018687 +0000] conn=56 (Internal) op=12(1)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000148489
[15/May/2019:09:58:36.792488501 +0000] conn=56 (Internal) op=12(2)(1) SRCH base="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:36.792686109 +0000] conn=56 (Internal) op=12(2)(1) ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:36.792698155 +0000] conn=56 (Internal) op=12(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000235936
[15/May/2019:09:58:36.925889002 +0000] conn=56 (Internal) op=12(3)(1) SRCH base="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:36.926091289 +0000] conn=56 (Internal) op=12(3)(1) ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:36.926103435 +0000] conn=56 (Internal) op=12(3)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000233339
[15/May/2019:09:58:40.917520351 +0000] conn=56 (Internal) op=12(4)(1) SRCH base="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:40.917758921 +0000] conn=56 (Internal) op=12(4)(1) ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:40.917770208 +0000] conn=56 (Internal) op=12(4)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000293418
[15/May/2019:09:58:41.052354572 +0000] conn=56 (Internal) op=1(2)(1) SRCH base="cn=anonymous-limits,cn=etc,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs="nsLookThroughLimit nsIDListScanLimit nsPagedLookThroughLimit nsPagedIDListScanLimit nsRangeSearchLookThroughLimit nsSizeLimit nsTimeLimit nsPagedSizeLimit nsIdleTimeout"
[15/May/2019:09:58:41.052405899 +0000] conn=56 (Internal) op=1(2)(1) ENTRY dn="cn=anonymous-limits,cn=etc,dc=example,dc=test"
[15/May/2019:09:58:41.052411542 +0000] conn=56 (Internal) op=1(2)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000067568
[15/May/2019:09:58:41.184135517 +0000] conn=56 (Internal) op=12(5)(1) SRCH base="cn=EXAMPLE.TEST,cn=kerberos,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:41.184238139 +0000] conn=56 (Internal) op=12(5)(1) ENTRY dn="cn=EXAMPLE.TEST,cn=kerberos,dc=example,dc=test"
[15/May/2019:09:58:41.184249448 +0000] conn=56 (Internal) op=12(5)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000139675
[15/May/2019:09:58:41.184317970 +0000] conn=56 (Internal) op=12(6)(1) SRCH base="cn=ipa_pwd_extop,cn=plugins,cn=config" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:41.184394710 +0000] conn=56 (Internal) op=12(6)(1) ENTRY dn="cn=ipa_pwd_extop,cn=plugins,cn=config"
[15/May/2019:09:58:41.184400239 +0000] conn=56 (Internal) op=12(6)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000087303
[15/May/2019:09:58:41.184500354 +0000] conn=56 (Internal) op=12(7)(1) SRCH base="cn=ipaConfig,cn=etc,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:41.184543130 +0000] conn=56 (Internal) op=12(7)(1) ENTRY dn="cn=ipaConfig,cn=etc,dc=example,dc=test"
[15/May/2019:09:58:41.184547276 +0000] conn=56 (Internal) op=12(7)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000051892
[15/May/2019:09:58:42.309037008 +0000] conn=56 (Internal) op=12(8)(1) SRCH base="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL
[15/May/2019:09:58:42.309175256 +0000] conn=56 (Internal) op=12(8)(1) ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:42.309185075 +0000] conn=56 (Internal) op=12(8)(1) RESULT err=0 tag=48 nentries=1 etime=0.0000166246
[15/May/2019:09:58:44.975806226 +0000] conn=56 op=13 SRCH base="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test" scope=0 filter="(objectClass=*)" attrs="ipaNTHash"
[15/May/2019:09:58:44.976199693 +0000] conn=56 op=12 RESULT err=0 tag=103 nentries=0 etime=8.1270618766
[15/May/2019:09:58:44.976352334 +0000] conn=56 op=13 ENTRY dn="krbprincipalname=cifs/client.example.test@EXAMPLE.TEST,cn=services,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:44.978914731 +0000] conn=56 op=13 RESULT err=0 tag=101 nentries=1 etime=0.0003203160
[15/May/2019:09:58:44.978978229 +0000] conn=56 op=14 SRCH base="dc=example,dc=test" scope=2 filter="(&(objectClass=ipaNTUserAttrs)(|(ipaNTSecurityIdentifier=S-1-5-21-1326256250-4276970629-2157751575-1001)))" attrs="uid ipaNTSecurityIdentifier"
[15/May/2019:09:58:44.979334361 +0000] conn=56 op=14 RESULT err=0 tag=101 nentries=0 etime=0.0000392838
[15/May/2019:09:58:44.979377674 +0000] conn=56 op=15 SRCH base="dc=example,dc=test" scope=2 filter="(&(objectClass=ipaNTGroupAttrs)(|(ipaNTSecurityIdentifier=S-1-5-21-1326256250-4276970629-2157751575-1001)))" attrs="cn displayName ipaNTSecurityIdentifier"
[15/May/2019:09:58:44.979733278 +0000] conn=56 op=15 ENTRY dn="cn=Default SMB Group,cn=groups,cn=accounts,dc=example,dc=test"
[15/May/2019:09:58:44.982140727 +0000] conn=56 op=15 RESULT err=0 tag=101 nentries=1 etime=0.0002792004
[15/May/2019:09:58:44.982188048 +0000] conn=56 op=16 SRCH base="dc=example,dc=test" scope=2 filter="(&(ipaNTSecurityIdentifier=S-1-5-32-545)(|(objectClass=ipaNTGroupAttrs)(objectClass=ipaNTUserAttrs)))" attrs="objectClass gidNumber uidNumber"
[15/May/2019:09:58:44.985016303 +0000] conn=56 op=16 RESULT err=0 tag=101 nentries=0 etime=0.0002859722 notes=U
[15/May/2019:09:58:50.747719423 +0000] conn=56 op=-1 fd=99 closed - B1

errors log for the same period:

[15/May/2019:09:58:33.126362209 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:33.360315199 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:33.659588573 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:33.801732625 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:33.926627764 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:34.067904400 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:34.217944523 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:34.368665719 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:34.517893691 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:34.659572661 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:34.801341572 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:34.951349876 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:35.092710287 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:35.226230107 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:35.376455929 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:35.518016399 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:35.651289009 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:35.784358956 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:35.927917208 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:36.084672560 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:36.384693440 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:36.517562731 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:36.650929002 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:36.792748467 +0000] - DEBUG - ipa-range-check - Not an ID range object, nothing to do.
[15/May/2019:09:58:36.926194954 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:37.059162358 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:37.200858517 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:37.334234153 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:37.467899713 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:37.609233509 +0000] - DEBUG - NSUniqueAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:37.743007161 +0000] - DEBUG - ipa-topology-plugin - --> ipa_topo_pre_mod
[15/May/2019:09:58:37.876056834 +0000] - DEBUG - ipa-topology-plugin - <-- ipa_topo_pre_mod
[15/May/2019:09:58:38.017780050 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 517]: ipapwd: ipaNTHash is in the list of modifications. Modifications: 0
[15/May/2019:09:58:38.176032467 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 527]: ipapwd: content of modification: MagicRegen
[15/May/2019:09:58:39.184749101 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 536]: ipapwd: magic regen found: 1
[15/May/2019:09:58:40.918404643 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 608]: ipapwd_entry_checks: is_root(0), is_krb(1), is_smb(0), is_ipant(1), attr(ipaNTHash), rc = 0
[15/May/2019:09:58:41.184786527 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 616]: ipapwd_gen_checks: rc = 0
[15/May/2019:09:58:41.467589032 +0000] - ERR - ipapwd_pre_mod - [file prepost.c, line 625]: got to magic regen: is_krb(1)
[15/May/2019:09:58:41.600819331 +0000] - ERR - ipapwd_regen_nthash - [file prepost.c, line 959]: ipapwd_regen_nthash: does ipaNTHash exist already? 0
[15/May/2019:09:58:41.717444456 +0000] - ERR - ipapwd_regen_nthash - [file prepost.c, line 967]: ipapwd_regen_nthash: does krbPrincipalKey exist? 1
[15/May/2019:09:58:41.859124656 +0000] - ERR - ipapwd_regen_nthash - [file prepost.c, line 990]: Processing Kerberos keys. Total 3 keys
[15/May/2019:09:58:42.009387844 +0000] - ERR - ipapwd_regen_nthash - [file prepost.c, line 1024]: Found rc4 key and copied it to ipaNTHash: ESC<D2><DA><E6>n<E9><99>L-<ED><91><E8><D1>^MI5
[15/May/2019:09:58:42.159233888 +0000] - DEBUG - NS7bitAttr - preop_modify - MODIFY begin
[15/May/2019:09:58:42.309622753 +0000] - DEBUG - roles-plugin - --> roles_post_op
[15/May/2019:09:58:42.450854184 +0000] - DEBUG - roles-plugin - --> roles_cache_change_notify
[15/May/2019:09:58:42.600806125 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:42.736337838 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:42.885068962 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:43.019228589 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:43.134069579 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:43.277896091 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:43.410150490 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:43.552421923 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:43.900909181 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:44.309513281 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:44.484109388 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:44.617387596 +0000] - DEBUG - roles-plugin - <-- roles_cache_change_notify - Not a role entry
[15/May/2019:09:58:44.758956359 +0000] - DEBUG - roles-plugin - <-- roles_post_op
[15/May/2019:09:58:44.900840309 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:45.258887497 +0000] - DEBUG - ipa-topology-plugin - --> ipa_topo_post_mod
[15/May/2019:09:58:45.409323954 +0000] - DEBUG - ipa-topology-plugin - <-- ipa_topo_post_mod
[15/May/2019:09:58:45.684176012 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:45.958841515 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:46.100615672 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:46.242373697 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:46.383908119 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:46.517891520 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:46.650554476 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:46.792800947 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:46.942259811 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:47.075937801 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:47.217317460 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:47.359722912 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:47.509522627 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:47.659159233 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:47.800846562 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:47.959150268 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:48.092528443 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:48.233975384 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:48.367171806 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:48.500914458 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:48.642563469 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:48.784078371 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:48.925504996 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:49.059051150 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:49.192141031 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:49.334272407 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:49.475432662 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:49.625332215 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:49.767099261 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:49.909442416 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:50.050397696 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:50.192110933 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:50.325725645 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:50.442118450 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:50.567041358 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:50.717449528 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:51.210849168 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:51.352018506 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:51.500462042 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:51.626162630 +0000] - DEBUG - ipa-lockout-plugin - preop returning 0: success

[15/May/2019:09:58:51.759216275 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

[15/May/2019:09:58:51.908881760 +0000] - DEBUG - ipa-lockout-plugin - postop returning 0: success

@tbordaz @mreynolds There have been changes around handling postop plugins to avoid the crashes after a failed plugin call. Do you think it could have a side effect like this ?

@lkrispen The ones I recall are related to entry cache corruption (flushing cache) and also mep plugin that use to process postop even if the operation was failing.

@lkrispen The ones I recall are related to entry cache corruption (flushing cache) and also mep plugin that use to process postop even if the operation was failing.

yes, and I was on the wrong track, the ipaNTHash is handled in the BE_TXN_PRE calls.
I also checked ldbm_modify and didn't see a recent change that could have this effect.

@abbra again the question, do you remember when it was working correctly ?

I wonder if it ever worked :-)

We have this piece of code in ldbm_back_modify, after the call of the BE_TXN_PRE plugins:

        if (new_mod_count < mod_count) {
             slapi_log_err(SLAPI_LOG_ERR, "ldbm_back_modify",
                      "Error: BE_TXN_PRE_MODIFY plugin has removed "
                      "mods from the original list - mod count was [%d] now [%d] "
                      "mods will not be applied - mods list changes must be done "
                      "in the BE_PRE_MODIFY plugin, not the BE_TXN_PRE_MODIFY\n",
                      mod_count, new_mod_count);
        } else if (new_mod_count > mod_count) { /* apply the new betxnpremod mods */
             /* apply the mods, check for syntax, schema problems, etc. */
            if (modify_apply_check_expand(pb, operation, &mods[mod_count], e, ec, &postentry,
                                      &ldap_result_code, &ldap_result_message)) {
            goto error_return;
            }
         } /* else if new_mod_count == mod_count then betxnpremod plugin did nothing */

as far as I see, the ipa plugin does just change the value for one mod and not the number of mods

I just tried 1.4.0.20-7.module-el8+2750+1f4079fb in RHEL 8.0 release candidate (sorry, no updated version in a VM yet) and it fails the same way.

@lkrispen ipa-pwd-extop removes and re-adds a single mod, so number of mods is the same.

@lkrispen ipa-pwd-extop removes and re-adds a single mod, so number of mods is the same.

so the question is what could have changed, if it ever worked. the check if mod count changed i there for ages, but it is executed after ALL be_txn plugins have been called. If there once was anotehr plugin which added an op this might have been hidden, or if the client did not send the MagigRegen and it was just added, not removed.

I think it is due to 6c17ec5 (managed entry sometimes doesn't delete the managed entry) where the code you mentioned above was added.

So this wasn't triggered in past for trust to AD case because we never needed to regenerate the ipaNTHash for actual trusted domain object accounts. The code in ipasam to cause this regeneration was added to handle cases when users were converted to have SIDs but never used to login to Samba yet.

Now, for running Samba on IPA domain member, I need to manipulate with cifs/... service principal arcfour-hmac key on IPA master. The service principal has a password set through ipa-getkeytab which means only Kerberos keys are generated and ipaNTHash (as well as userPassword) aren't generated (they are not needed). ipasam on Samba domain controller needs RC4 hash to mutually authenticate and validate secure channel connection coming from Samba domain member, thus it goes to dynamically request ipaNTHash generation as it is missing.

A solution could be to have some other mods added here in the plugin itself or adding some sort of checksumming before and after plugin runs in ldb_back_modify(). Would remembering old mods pointer and comparing it with a new retrieved one help here?

@abbra I think that jumping to solutions is a bit premature ...

@lkrispen I wasn't discounting that the error was in DS, I believed there was insufficient evidence to make these claims, and I wanted more data to analyse first.

@lkrispen ipa-pwd-extop removes and re-adds a single mod, so number of mods is the same.

This line however, could be indicative of the issue. Do we use the updated mods from the pblock? Or do we use a different (previous) mod structure from the operation/pblock instead? This would certainly have the effect of allowing the mods to be updated, and then audit displaying a certain set of mods, but then the ldbm_modify uses a different mod structure for application causing the MagicRegen to be stored instead.

It could be useful to break on the ldbm_modify routines and display the internal state of the entries and the mods we are applying at that point to determine if we are applying the mods as they were received in the operation, or the mods as they have been altered by the plugin.

This line however, could be indicative of the issue. Do we use the updated mods from the pblock? Or do we use a different (previous) mod structure from the operation/pblock instead? This would certainly have the effect of allowing the mods to be updated, and then audit displaying a certain set of mods, but then the ldbm_modify uses a different mod structure for application causing the MagicRegen to be stored instead.

we do apply the mods to the entry before the preop calls, so that the plugins will see the entry.
then the plugins are called and could modify the list of mods
after the call we decide if the plugins have changed the mods and if so repplay the mods
but our decision is incorrect and the entry is not modified again, so the entry with the original set of mods is written to the database and when we do audit logging we take the modified mods from the pblock.

So we need to fix the decision if mods were changed, not just look at the number of mods. But we should find a smart way, because most of the time mods are not changed and comparing two lists of mods can be expensive

@lkrispen Well, since the mods are stored in the pblock, do they need to be re-inserted there? So on mod change, we could have a flag in pblock like "mods_changed", and when we read the mods to apply them we reset the flag?

The flow would be:

parse mods
add to pblock
apply mods (reset flag)
plugins called
-> plugin changes mod (set's flag to altered)
if flag == altered:
    re-apply mods
be->modify

Would we re-apply mods to the original entries? Or to the already-modified entries though?

I was thinking about a "flag" solution, but it would require all plugins to become aware to set this flag.

the reapply is done in modify_apply_check_expand(), I haven't check how it is done exactly and correctly, will do when my test case works

We could set the flag anytime we change the mods in the pblock, so they don't need to be aware? But that relies on the case that the modifications are re-added to the pblock rather than them-self altered in place.

Alternately - are our mods "stateful"? We could just assume they changed and re-apply after the plugins have been called? No flag needed, just apply them twice incase a plugin has altered them ....

Would it be acceptable that the plugin (ipa-pwd-extop) instead of altering a mod, actually adds an other mod to the mods. It would make decision easier.

@tbordaz Yes it would I think. But I think the issue is other plugins may exist that try to alter the modification lists in place, rather than appending more or other mods. This is why perhaps it may be safe to just apply the mods again, always, after plugins have run.

Alternately, ipa-pwd-extop could do this in post, and issue a slapi_internal_mod instead of changing the mod structure itself.

Would it be acceptable that the plugin (ipa-pwd-extop) instead of altering a mod, actually adds an other mod to the mods. It would make decision easier.

but why should it, and even if ipa-pwd-extop would be nice to do it, what with other plugins, we cannot writ to the plugin guide, if you modify a mod, please also add a fake mod because we are to stupid to detect it otherwise

Alternately, ipa-pwd-extop could do this in post, and issue a slapi_internal_mod instead of changing the mod structure itself.

we should stop making suggestions what a plugin could do differently, there is a bug in our code and we have to fix it, not relying on plugins to workaround

@firstyear I agree it would be nicer to detect a change in mods. reparsing the mods creates a systematic performance overhead. Possibly we can add a flag in the pblock to parse only on-demand.

well, I found the reasoning for the current handling, and you could argue again if the behaviour is a bug or not: https://pagure.io/389-ds-base/issue/387#comment-120145

The last lines in the comment are:

 So a betxnpreop that wants to alter the mods list can do one of the following:
 1) alter the mods list instead in the bepreop
 2) extend the mods list with ''undo'' ops e.g. add a mod/delete to counter an earlier mod/add.

Unfortunately this is not documented

@abbra for the ipa-pwd-extop this could mean, instead of:
-remove add: MagicRegen
-add add: "newhash"

do

  • keep add: MagicRegen
  • add
    replace: ipaNTHash
    ipaNTHash: "newhash"

this would not require a dummy mod and even have one op less to do

@lkrispen thanks. I have added https://pagure.io/freeipa/issue/7953 to track the change. I am currently testing the patch.

Perhaps we should formalise the correct method for a plugin to alter modifications in light of this?

if you find the proper place to do it, our plugin guide could benefit by some attention

@lkrispen IIRC the plugin guide hasn't been updated in a long time ... it could be good to check with @mmuehlfeldrh about the status of this document, and perhaps it could be a good idea to start our own plugin guide on the wiki instead. I'm not fully sure of the right answer here ... but we should at least say what our constraints are in terms of how to allow mods to be changed.

For information I created #1711221 against the plugin guide.

@lkrispen IIRC the plugin guide hasn't been updated in a long time ... it could be good to check with @mmuehlfeldrh about the status of this document, and perhaps it could be a good idea to start our own plugin guide on the wiki instead. I'm not fully sure of the right answer here ... but we should at least say what our constraints are in terms of how to allow mods to be changed.

Plugin guide didn't have updates for ages. Instead of maintaining it separately, plan was to leverage doxygen to generate documentation from comments, but that's a huge amount of work and not so huge number of people.

Metadata Update from @mreynolds:
- Issue assigned to lkrispen
- Issue set to the milestone: 1.4.1

3 months ago

Login to comment on this ticket.

Metadata