SA Water - Subscriber Errors; Automated Flows from NIM to Identity Broker

It seems that an operation called "Merge Attributes" doesn't follow all of the same rules in the driver in Novell Identity Manager.

I am seeing that when such an operation occurs (after an update to NIM) the subsequent update sent to Identity Broker fails. I have no idea why the merge operation behaves differently, If I change an attribute (such as email address) in eDirectory, the update flows and Identity Broker returns success (excerpt of trace at end);

Please not there is no point trying to correlate these errors by using the date/timestamp as the NIM server keeps on randomly assigning itself a new time... I can reproduce these errors (& successful transactions) though.

Here are the errors (warnings actually) that appear in the Identity Broker Console:

Timestamp Severity Source Module Message
26/07/2011 4:16:44 AM Warning An entity failed validation. Adapter The entity 5887c669-9f2c-4dfc-b507-009585afb47e on connector 34b83581-377c-41b5-afb9-2a705076285f failed validation 1 times for the following reasons: detnumber is a required field and is not present.

26/07/2011 4:16:44 AM Warning Adapter request to save entity to adapter space failed. Adapter "Adapter request to save entity 5887c669-9f2c-4dfc-b507-009585afb47e to adapter space 53e85508-7648-409c-bd3a-0737028eba29 failed with reason 1 items failed schema validation during Adapter operation. Check log for validation errors.. Duration: 00:00:00
Error details:
Unify.Framework.AdapterSchemaException: 1 items failed schema validation during Adapter operation. Check log for validation errors.
at Unify.Framework.Adapter.SaveEntities(IEnumerable`1 entities, Boolean reflect)
at Unify.Framework.Adapter.SaveEntity(IAdapterEntity entity, Boolean reflect)
at Unify.Framework.AdapterNotifierDecorator.SaveEntity(IAdapterEntity entity, Boolean reflect)
at Unify.Adapters.NovellIdentityManagerIdentityBrokerDriverAdapter.PerformSubscribeModifyAction(XElement actionNode, IAdapter adapter)"

Here is what I believe to be the relevent portion of the NIM Trace File:

26/07/2011 14:17:18.05v: 0 CHRIS21-IdB L3 PT:Performing operation modify for \SAWWFT\RES\Users\User\JAMYBSM1.
26/07/2011 14:17:18.05v: 0 CHRIS21-IdB L3 PT:Modifying entry \SAWWFT\RES\Users\User\JAMYBSM1.
26/07/2011 14:17:18.15v: 0 CHRIS21-IdB L3 PT:Scheduling update of application with eDirectory values.
26/07/2011 14:17:18.15v: 0 CHRIS21-IdB L3 PT:
<nds dtdversion="3.5" ndsversion="8.x">
<source>
<product version="3.5.10.20070918 ">DirXML</product>
<contact>Novell, Inc.</contact>
</source>
<input>
<modify class-name="User" event-id="5" from-merge="true" qualified-src-dn="O=RES\OU=Users\OU=User\CN=JAMYBSM1" src-dn="\SAWWFT\RES\Users\User\JAMYBSM1" src-entry-id="36598">
<association>MYBSM1</association>
<modify-attr attr-name="mobile">
<remove-all-values/>
</modify-attr>
<modify-attr attr-name="Facsimile Telephone Number">
<remove-all-values/>
</modify-attr>
<modify-attr attr-name="Internet EMail Address">
<remove-all-values/>
</modify-attr>
<modify-attr attr-name="Telephone Number">
<remove-all-values/>
</modify-attr>
</modify>
</input>
</nds>

>
>Some irrelevent Detail removed from here
>

26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:UnifySubscriptionShim: execute end
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:SubscriptionShim.execute() returned:
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:
<nds dtdversion="1.0" ndsversion="8.5">
<output>
<response event-id="1" level="error">
Unify.Framework.AdapterSchemaException: 1 items failed schema validation during Adapter operation. Check log for validation errors.
at Unify.Framework.Adapter.SaveEntities(IEnumerable`1 entities, Boolean reflect)
at Unify.Framework.Adapter.SaveEntity(IAdapterEntity entity, Boolean reflect)
at Unify.Framework.AdapterNotifierDecorator.SaveEntity(IAdapterEntity entity, Boolean reflect)
at Unify.Adapters.NovellIdentityManagerIdentityBrokerDriverAdapter.PerformSubscribeModifyAction(XElement actionNode, IAdapter adapter)
</response>
</output>
</nds>
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:Applying input transformation policies.
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:Applying policy: Read All Attributes.
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST: Applying to response #1.
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:Policy returned:
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:
<nds dtdversion="1.0" ndsversion="8.5">
<output>
<response event-id="1" level="error">
Unify.Framework.AdapterSchemaException: 1 items failed schema validation during Adapter operation. Check log for validation errors.
at Unify.Framework.Adapter.SaveEntities(IEnumerable`1 entities, Boolean reflect)
at Unify.Framework.Adapter.SaveEntity(IAdapterEntity entity, Boolean reflect)
at Unify.Framework.AdapterNotifierDecorator.SaveEntity(IAdapterEntity entity, Boolean reflect)
at Unify.Adapters.NovellIdentityManagerIdentityBrokerDriverAdapter.PerformSubscribeModifyAction(XElement actionNode, IAdapter adapter)
</response>
</output>
</nds>
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:Applying schema mapping policies to input.
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:Applying policy: CHRISMappingRules.
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:Resolving association references.
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:Processing returned document.
26/07/2011 14:17:19.60v: 0 CHRIS21-IdB L3 ST:Processing operation <response>
for .

Here is what the trace looks like for a successful transaction:

17/05/2011 15:38:56.17v: 0 Level 3 Chris21 ST:Start transaction.
17/05/2011 15:38:56.17v: 0 Level 3 Chris21 ST:Processing events for transaction.
17/05/2011 15:38:56.17v: 0 Level 3 Chris21 ST:
<nds dtdversion="3.5" ndsversion="8.x">
<source>
<product version="3.5.10.20070918 ">DirXML</product>
<contact>Novell, Inc.</contact>
</source>
<input>
<modify cached-time="20110517053856.135Z" class-name="User" event-id="W2K3-R2-001-NDS#20110517053856#1#1" qualified-src-dn="O=RES\OU=Users\OU=User\CN=AM102983" src-dn="\SAWWFT\RES\Users\User\AM102983" src-entry-id="38266" timestamp="1305610736#1">
<association state="associated">f3b39b95-57ce-40b9-a5bd-f89dcc7d9aed</association>
<modify-attr attr-name="Internet EMail Address">
<add-value>
<value timestamp="1305610736#1" type="string">totally@amazing@sawater.sa.gov.au</value>
</add-value>
</modify-attr>
</modify>
</input>
</nds>
17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST:Applying event transformation policies.
17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST:Applying policy: Updates to Chris.
17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST: Applying to modify #1.
17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST:Policy returned:
17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST:

> some repeated stuff removed from here

17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST:Applying policy: Event Transformation.
17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST: Applying to modify #1.
17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST: Evaluating selection criteria for rule 'Veto all other changes'.
17/05/2011 15:38:56.22v: 0 Level 3 Chris21 ST: (if-class-name equal "User") = TRUE.
17/05/2011 15:38:56.25v: 0 Level 3 Chris21 ST: (if-association not-associated) = FALSE.
17/05/2011 15:38:56.25v: 0 Level 3 Chris21 ST: Rule rejected.
17/05/2011 15:38:56.25v: 0 Level 3 Chris21 ST:Policy returned:
17/05/2011 15:38:56.25v: 0 Level 3 Chris21 ST:

> some stuff repeated removed from here

17/05/2011 15:38:56.25v: 0 Level 3 Chris21 ST:Subscriber processing modify for \SAWWFT\RES\Users\User\AM102983.
17/05/2011 15:38:56.25v: 0 Level 3 Chris21 ST:No command transformation policies.
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:Filtering out notification-only attributes.
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:Fixing up association references.
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:Applying schema mapping policies to output.
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:Applying policy: CHRISMappingRules.
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST: Mapping attr-name 'Internet EMail Address' to 'CC-Email'.
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST: Mapping class-name 'User' to 'person'.
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:No output transformation policies.
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:Submitting document to subscriber shim:
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:

> some stuff repeated removed from here

17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:UnifySubscriptionShim: execute start
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:UnifySubscriptionShim: createWebServiceInterface: URL: http://192.168.0.230:59990/IdentityBroker/NIMDriver.svc?wsdl
17/05/2011 15:38:56.26v: 0 Level 3 Chris21 ST:UnifySubscriptionShim: createWebServiceInterface: Creating service
17/05/2011 15:38:56.32v: 0 Level 3 Chris21 ST:UnifySubscriptionShim: createWebServiceInterface: Creating interface
17/05/2011 15:38:56.34v: 0 Level 3 Chris21 ST:UnifySubscriptionShim: createWebServiceInterface: Returning port
17/05/2011 15:38:56.71v: 0 Level 3 Chris21 PT:UnifyPublicationShim: polling
17/05/2011 15:38:56.71v: 0 Level 3 Chris21 PT:UnifyPublicationShim: createWebServiceInterface: URL: http://192.168.0.230:59990/IdentityBroker/NIMDriver.svc?wsdl
17/05/2011 15:38:56.71v: 0 Level 3 Chris21 PT:UnifyPublicationShim: createWebServiceInterface: Creating service
17/05/2011 15:38:56.89v: 0 Level 3 Chris21 PT:UnifyPublicationShim: createWebServiceInterface: Creating interface
17/05/2011 15:38:56.91v: 0 Level 3 Chris21 PT:UnifyPublicationShim: createWebServiceInterface: Returning port
17/05/2011 15:39:00.48v: 0 Level 3 Chris21 ST:UnifySubscriptionShim: execute end
17/05/2011 15:39:00.48v: 0 Level 3 Chris21 ST:SubscriptionShim.execute() returned:
17/05/2011 15:39:00.48v: 0 Level 3 Chris21 ST:
<nds dtdversion="1.0" ndsversion="8.5">
<output>
<response event-id="W2K3-R2-001-NDS#20110517053856#1#1" level="success"/>
</output>
</nds>