Hi,

yesterday we found that no events were propageted on the publisher of
the new eDir Driver. At the same time we found the size of the changelog
increasing ( >= 200 MB / apprx. 70k events)

The troublemaker was an modify operation on an object which the driver
recognized through a matching rule as allready associated. Since this
can happen with a weak data quality and/or bad matching policies it
should not make really a headache - but in this case the driver did not
delete the event from the changelog; instead it polled it again and
again - not processing any other event from the changelog.

The only thing we could do to fix this was deleting the association in
the IDM directory. After this was done all the (remaining) events from
the changelog were processed.

In this particular case it was eaven more strange since the association
in the IDM directory had the correct value, but in lover-case?! I do not
have a clue how this could happen since all objects I checked so far
store the value in uppercase like the GUID in the connected eDirectory.
(But I cant tell fur sure that it was only one object which will couse
that kind of trouble since we have 30k+ objects in sync here.

Just for reference I will include a trace at the end of this post.

My only question is: Is this really a bug or do we have to write a
policy to get rid of the matching error?

Here the trace:

[02/25/14 13:02:25.151]:TU-ID PT:TU-ID: Received the reponse from the
engine after processing...
[02/25/14 13:02:25.151]:TU-ID PT:TU-ID: The connection status isConnect
is true
[02/25/14 13:02:25.151]:TU-ID PT:TU-ID: Event processing failed:
Retrying after 30 sec for ChangeNumber 34
[02/25/14 13:02:55.152]:TU-ID PT:TU-ID: The connection status isConnect
is true
[02/25/14 13:02:55.152]:TU-ID PT:Receiving DOM document from
application.
[02/25/14 13:02:55.152]:TU-ID PT:
<nds dtdversion="4.0">
<source>
<product instance="TU-ID" version="4.0.1.0">Identity Manager
Bi-directional Driver for eDirectory</product>
<contact>Novell, Inc.</contact>
</source>
<input>
<modify class-name="inetOrgPerson"
src-dn="CN=sk0815Doe,OU=STUD,O=TU">
<association>00A557CC47E0DF11B3BA000BCD9DC9C0</association>
<modify-attr attr-name="fullName">
<remove-value>
<value>GivenNameX SurnameX</value>
</remove-value>
</modify-attr>
</modify>
</input>
</nds>
[02/25/14 13:02:55.154]:TU-ID PT:No input transformation policies.
[02/25/14 13:02:55.154]:TU-ID PT:Applying schema mapping policies to
input.
[02/25/14 13:02:55.154]:TU-ID PT:Applying policy:
%+C%14CtudaNDS2tucf-smp%-C.
[02/25/14 13:02:55.155]:TU-ID PT: Mapping class-name 'inetOrgPerson' to
'User'.
[02/25/14 13:02:55.155]:TU-ID PT: Mapping attr-name 'fullName' to 'Full
Name'.
[02/25/14 13:02:55.155]:TU-ID PT:Resolving association references.
[02/25/14 13:02:55.155]:TU-ID PT:Applying event transformation
policies.
[02/25/14 13:02:55.156]:TU-ID PT:Applying policy:
%+C%14CtudaNDS2tucf-pub-etp-Filter%-C.
[02/25/14 13:02:55.156]:TU-ID PT: Applying to modify #1.
[02/25/14 13:02:55.156]:TU-ID PT: Evaluating selection criteria for
rule 'context filter'.
[02/25/14 13:02:55.157]:TU-ID PT: (if-operation match
"add|move|delete|rename|modify-password|modify") = TRUE.
[02/25/14 13:02:55.157]:TU-ID PT: (if-src-dn not-in-container
"OU=Stud,O=TU") = FALSE.
[02/25/14 13:02:55.157]:TU-ID PT: Rule rejected.
[02/25/14 13:02:55.157]:TU-ID PT: Evaluating selection criteria for
rule 'Scope Filter'.
[02/25/14 13:02:55.158]:TU-ID PT: (if-operation match
"move|delete|rename") = FALSE.
[02/25/14 13:02:55.158]:TU-ID PT: Rule rejected.
[02/25/14 13:02:55.158]:TU-ID PT:Policy returned:
[02/25/14 13:02:55.158]:TU-ID PT:
<nds dtdversion="4.0">
<source>
<product instance="TU-ID" version="4.0.1.0">Identity Manager
Bi-directional Driver for eDirectory</product>
<contact>Novell, Inc.</contact>
</source>
<input>
<modify class-name="User" src-dn="CN=sk0815Doe,OU=STUD,O=TU">
<association>00A557CC47E0DF11B3BA000BCD9DC9C0</association>
<modify-attr attr-name="Full Name">
<remove-value>
<value>GivenNameX SurnameX</value>
</remove-value>
</modify-attr>
</modify>
</input>
</nds>
[02/25/14 13:02:55.165]:TU-ID PT:*No associated objects.*
[02/25/14 13:02:55.165]:TU-ID PT:Applying publisher filter.
[02/25/14 13:02:55.165]:TU-ID PT:Publisher processing modify for
CN=sk0815Doe,OU=STUD,O=TU.
[02/25/14 13:02:55.166]:TU-ID PT:Converting <modify> to <add>
[02/25/14 13:02:55.166]:TU-ID PT:Reading relevant attributes from
00A557CC47E0DF11B3BA000BCD9DC9C0.
[02/25/14 13:02:55.166]:TU-ID PT:

..........

[02/25/14 13:02:55.209]:TU-ID PT:Synthetic add:
[02/25/14 13:02:55.209]:TU-ID PT:
<nds dtdversion="4.0">
<source>
<product instance="TU-ID" version="4.0.1.0">Identity Manager
Bi-directional Driver for eDirectory</product>
<contact>Novell, Inc.</contact>
</source>
<input>
<add class-name="User" src-dn="cn=sk0815Doe,ou=STUD,o=TU">
<association
state="associated">*00A557CC47E0DF11B3BA000BCD9DC9 C0*</association>
<add-attr attr-name="Full Name">
<value type="string">SurnameX, GivenNameX</value>
</add-attr>
<add-attr attr-name="idmUserChristianName">
<value type="string">GivenNameX</value>
</add-attr>
<add-attr attr-name="idmUserExpiryDate">
<value type="time">2082758400</value>
</add-attr>
<add-attr attr-name="idmUserSurname">
<value type="string">SurnameX</value>
</add-attr>
<add-attr attr-name="Internet EMail Address">
<value type="string">SurnameX@cellulose.XYZ123.de</value>
</add-attr>
<add-attr attr-name="nspmDistributionPassword"><!-- content
suppressed -->
</add-attr>
</add>
</input>
</nds>
[02/25/14 13:02:55.211]:TU-ID PT:Applying object matching policies.
[02/25/14 13:02:55.212]:TU-ID PT:Applying policy:
%+C%14CtudaNDS2tucf-pub-mp%-C.
[02/25/14 13:02:55.212]:TU-ID PT: Applying to add #1.
[02/25/14 13:02:55.212]:TU-ID PT: Evaluating selection criteria for
rule 'find matching users'.
[02/25/14 13:02:55.213]:TU-ID PT: (if-class-name equal "user") =
TRUE.
[02/25/14 13:02:55.214]:TU-ID PT: Rule selected.
[02/25/14 13:02:55.214]:TU-ID PT: Applying rule 'find matching
users'.
[02/25/14 13:02:55.214]:TU-ID PT: Action:
do-find-matching-object(scope="entry",arg-dn(token-global-variable("gcvAccountContextActive")+"\"+token-src-name())).
[02/25/14 13:02:55.214]:TU-ID PT:
arg-dn(token-global-variable("gcvAccountContextActive")+"\"+token-src-name())
[02/25/14 13:02:55.215]:TU-ID PT:
token-global-variable("gcvAccountContextActive")
[02/25/14 13:02:55.215]:TU-ID PT: Token Value:
"XYZ123\User\active".
[02/25/14 13:02:55.215]:TU-ID PT: token-text("\")
[02/25/14 13:02:55.215]:TU-ID PT: token-src-name()
[02/25/14 13:02:55.216]:TU-ID PT: Token Value: "sk0815Doe".
[02/25/14 13:02:55.216]:TU-ID PT: Arg Value:
"XYZ123\User\active\sk0815Doe".
[02/25/14 13:02:55.216]:TU-ID PT: Query from policy
[02/25/14 13:02:55.216]:TU-ID PT:
<nds dtdversion="4.0" ndsversion="8.x">
<source>
<product edition="Advanced" version="4.0.2.3">DirXML</product>
<contact>Novell, Inc.</contact>
</source>
<input>
<query class-name="User" dest-dn="XYZ123\User\active\sk0815Doe"
scope="entry">
<search-class class-name="User"/>
<read-attr/>
</query>
</input>
</nds>
[02/25/14 13:02:55.217]:TU-ID PT: Pumping XDS to eDirectory.
[02/25/14 13:02:55.217]:TU-ID PT: Performing operation query for
XYZ123\User\active\sk0815Doe.
[02/25/14 13:02:55.218]:TU-ID PT: --JCLNT--
\IDMS\XYZ123\res\DriverSet\TU-ID - Publisher : Duplicating : context =
1933180996, tempContext = 1933181063
[02/25/14 13:02:55.220]:TU-ID PT: --JCLNT--
\IDMS\XYZ123\res\DriverSet\TU-ID - Publisher : Calling free on
tempContext = 1933181063
[02/25/14 13:02:55.221]:TU-ID PT: Query from policy result
[02/25/14 13:02:55.221]:TU-ID PT:
<nds dtdversion="4.0" ndsversion="8.x">
<source>
<product edition="Advanced" version="4.0.2.3">DirXML</product>
<contact>Novell, Inc.</contact>
</source>
<output>
<instance class-name="User" event-id="0"
qualified-src-dn="O=XYZ123\OU=User\OU=active\CN=sk0815Doe"
src-dn="\IDMS\XYZ123\User\active\sk0815Doe" src-entry-id="151493">
<association
state="associated">*00a557cc47e0df11b3ba000bcd9dc9 c0*</association>
</instance>
<status event-id="0" level="success"></status>
</output>
</nds>
[02/25/14 13:02:55.222]:TU-ID PT: Match found:
src-dn='\IDMS\XYZ123\User\active\sk0815Doe'
[02/25/14 13:02:55.223]:TU-ID PT:Policy returned:
[02/25/14 13:02:55.223]:TU-ID PT:
<nds dtdversion="4.0">
<source>
<product instance="TU-ID" version="4.0.1.0">Identity Manager
Bi-directional Driver for eDirectory</product>
<contact>Novell, Inc.</contact>
</source>
<input>
<add class-name="User" dest-dn="?" dest-entry-id="-1"
src-dn="cn=sk0815Doe,ou=STUD,o=TU">
<association
state="associated">*00A557CC47E0DF11B3BA000BCD9DC9 C0*</association>
........
<operation-data
error.do-find-matching-object="\IDMS\XYZ123\User\active\sk0815Doe"/>
</add>
</input>
</nds>
[02/25/14 13:02:55.226]:TU-ID PT:
DirXML Log Event -------------------
Driver: \IDMS\XYZ123\res\DriverSet\TU-ID
Channel: Publisher
Object: CN=sk0815Doe,OU=STUD,O=TU
Status: Error
Message: Code(-9063) Object matching policy found an object that
is already associated: {0}.


--
tschloesser
------------------------------------------------------------------------
tschloesser's Profile: https://forums.netiq.com/member.php?userid=3232
View this thread: https://forums.netiq.com/showthread.php?t=50115