0
Fixed

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

Nick Mathas 9 years ago in UNIFYBroker/Novell Identity Manager updated by anonymous 5 years ago 5

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>

Affected Versions:
Fixed by Version:

Hi Patrick, as discussed asigned to you... because I think it is an Identity Broker Issue... although I am not sure.

Error caused by incorrect action taken when encountering "remove-all-values" request. Instead of removing the value(s) for that particular attribute, it cleared all attributes on the entity. Fixed to only remove the values for the specified attribute, but highlights that the operations will not work correctly with multi-valued fields.

Patch was placed in to test environment to confirm correctness. Creation of formal installer and release management still needs to occur.

v3.0.5.3 has been uploaded to the downloads page.

Re-opening to correct Billing Key