- UNIFYBroker Forum
-
Questions
Unify.Product.IdentityBroker.LDAPModifyException: Cannot add the value to the existing, non-multivalue field
There's an error being reported in MIM Sync on exports to a particular IdB connector several times a day. I haven't worried too much about it because the export actually works and the error is never exactly repeated (so it's not repeatedly failing to export the same change) - however I'm trying to clean up the monitoring so reported errors are worth looking into.
The error occurs seemingly randomly, as in there is no pattern of specific entity or time of day that I can see. It is always the same adapter, which backs on to a SQL connector talking to a SQL table (not a view). The error is always much the same except the attribute always changes - again I don't see a pattern. None of the attributes are multi-valued in the target table, IdB or MIM.
Here's an example of the error reported in MIM. I'm showing the healthcheck version so you can see the entity specified and the timestamp:
ErrorDN: CN=25600,OU=LANDesk,DC=IdentityBroker
ErrorDetail:
ErrorFirstOccurred: 2017-11-06T07:59:03
ErrorMessage: Internal Server Error #9:
Unify.Product.IdentityBroker.LDAPModifyException: Cannot add the value
41-50-53-34 to the existing, non-multivalue field Classification. at
Unify.Product.IdentityBroker.LDAPModifyRequestToEntityConverter.HandleAttributeValueAdd(IModifyRequestOperation
op, IAdapterEntity entity, IEntitySchema schema) at
Unify.Product.IdentityBroker.LDAPModifyRequestToEntityConverter.Transform(IRfcModifyRequest
sourceValue, IAdapterEntity origEntity) at
Unify.Product.IdentityBroker.ModifyRequestHandler.InnerApplyTransformation(IHandleRequestCoreRequest
request, LDAPModifyRequestToEntityConverter converter)
ErrorSyncType: export-error
ErrorType: Other
HCRecordType: FIMSync_Run_ErrorObject
MVObjectGUID: 540553ea-7e48-e711-80c7-005056a374e3
MaName: LANDesk
RunID: 6e0a6558-280f-4625-b0cc-9aea0ae83564
TimeInErrorDays: 0
_time: 2017-11-06T07:59:03
I've looked at the IdB logs for the same time but there is no error reported there. The logs agree that an export was being run to the expected connector. The only entity specifically mentioned does not match the entity reported in the MIM Sync error:
20171106,07:58:59,UNIFY Identity Broker,LDAP Engine,Information,A client has connected to the LDAP endpoint from address: 127.0.0.1:52744.,Normal 20171106,07:59:04,UNIFY Identity Broker,LDAP Engine,Information,A client has connected to the LDAP endpoint from address: 127.0.0.1:52750.,Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP Bulk Start request. Handling of LDAP Bulk Start request received from user IdBLDAP on connection 127.0.0.1:52744 completed successfully. Duration 00:00:18.1411237.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP Root DSE request. Handling of LDAP Root DSE request from user IdBLDAP on connection 127.0.0.1:52750 for the Root DSE completed successfully. Duration: 00:00:13.1409918.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP search request. Handling of LDAP search request from user IdBLDAP on connection 127.0.0.1:52750 targeting DC=IdentityBroker with a scope of SingleLevel completed successfully. Duration: 00:00:12.1409653.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP Bulk End request. Handling of LDAP Bulk End request received from user IdBLDAP on connection 127.0.0.1:52744 completed successfully with operations failed: 1. Duration 00:00:16.1254477.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP Bulk Update request. Handling of LDAP Bulk Update request received from user IdBLDAP on connection 127.0.0.1:52744 completed successfully without results available for logging. Duration 00:00:17.1410874.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP bind request. Handling of LDAP bind request received on connection 127.0.0.1:52750 to connect as user IdBLDAP completed successfully. The bind was successful. Duration: 00:00:14.1410105.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP schema request. Handling of LDAP schema request from user IdBLDAP on connection 127.0.0.1:52750 for the server schema completed successfully. Duration: 00:00:11.1096809.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP unbind request. Handling of LDAP unbind request received on connection 127.0.0.1:52744 to connect as user IdBLDAP completed successfully. Duration: 00:00:15.1410375.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP schema request. Handling of LDAP schema request from user IdBLDAP on connection 127.0.0.1:52750 for the server schema completed successfully. Duration: 00:00:09.4690085.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP schema request. Handling of LDAP schema request from user IdBLDAP on connection 127.0.0.1:52750 for the server schema completed successfully. Duration: 00:00:08.6408457.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP bind request. Handling of LDAP bind request received on connection 127.0.0.1:52744 to connect as user IdBLDAP completed successfully. The bind was successful. Duration: 00:00:19.1411493.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP schema request. Handling of LDAP schema request from user IdBLDAP on connection 127.0.0.1:52750 for the server schema completed successfully. Duration:<span class="redactor-selection-marker" id="selection-marker-1"></span> 00:00:07.6408392.",Normal dmfjsg 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP schema request. Handling of LDAP schema request from user IdBLDAP on connection 127.0.0.1:52750 for the server schema completed successfully. Duration: 00:00:06.6251852.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP schema request. Handling of LDAP schema request from user IdBLDAP on connection 127.0.0.1:52750 for the server schema completed successfully. Duration: 00:00:05.6407763.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP Root DSE request. Handling of LDAP Root DSE request from user IdBLDAP on connection 127.0.0.1:52750 for the Root DSE completed successfully. Duration: 00:00:04.6876294.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP change log request. Handling of LDAP change log request from user IdBLDAP on connection 127.0.0.1:52750 completed successfully. Added: 1. Modified: 0. Renamed: 0. Deleted: 0. Total: 1. Duration: 00:00:04.1407369.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP change log request. Handling of LDAP change log request from user IdBLDAP on connection 127.0.0.1:52750 completed successfully. Added: 3. Modified: 2. Renamed: 0. Deleted: 0. Total: 5. Duration: 00:00:03.1407136.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP search request. Handling of LDAP search request from user IdBLDAP on connection 127.0.0.1:52750 targeting CN=25777,OU=LANDesk,DC=IdentityBroker with a scope of BaseObject completed successfully. Results: 1. Duration: 00:00:02.1406773.",Normal 20171106,07:59:19,UNIFY Identity Broker,LDAP engine,Information,"Handling of LDAP unbind request. Handling of LDAP unbind request received on connection 127.0.0.1:52750 to connect as user IdBLDAP completed successfully. Duration: 00:00:00.0156256.",Normal 20171106,07:59:20,UNIFY Identity Broker,Change detection engine,Information,"Change detection engine import all items started. Change detection engine import all items for connector Aurion Security Records started.",Normal
Answer
Hi Carol,
The error "Cannot add the value 41-50-53-34 to the existing, non-multivalue field Classification" indicates that MIM is attempting to export an update to an entity which adds a value to a field for which the entity already has a value, and that field is not multi-valued. This isn't logged in Identity Broker as an error because as far as Identity Broker is concerned, it correctly responded to an invalid request with a failure - there is no error of processing in Identity Broker.
This usually indicates that the data in Identity Broker and the MIM connector space have grown out of sync, and can be resolved with an import + sync cycle. The fact that this issue resolves itself suggests this is likely.
It certainly isn't serious, just annoying because it happens several times a day. All MAs are Full Import/Full Sync'd overnight then run deltas for the rest of the day. The flow rules are almost all Direct (including this example), so MIM should not be attempting to "add" an additional value - which makes me think the issue may be with the IdB Management Agent. I'm using the ECMA 2 MA.
Would it be possible to capture a pending export and a network trace of the corresponding export operation the next time you see this come up? We could use that to verify what operation the MA is requested to perform and whether it is processing it correctly.
The problem is by the time I see it it's already happened. It's not happening in dev or test either, but I think that's just because there's no data changes there at the moment. Usual problem with intermittent errors. I'll have a think about it, and let me know if you think of anything else - keeping in mind that this is a Prod server so I can't just go changing things without going through the change control process.
For now I'll just document it as a "known issue" in this solution.
Do you ever see the error repeated across two or more consecutive exports, or does it resolve itself after a single error? You could also try inspecting the import + sync cycle that processed immediately before the first successful export after a failure. If the data was out of sync and an import + sync cycle is resolving it, the import would show the updates that were brought back in to correct it.
The following DIDS is always fine and reports the correct number of updates, and does not re-queue the export - so yes it does resolve itself straight away.
By "the correct number of updates" do you mean including the failed update? To me, all of these symptoms sound consistent with the following scenario:
- MIM exports an update to an entity to add a value to a blank field
- IDB already has a value for this field, and fails the operation
- MIM reports failure as an error, leaves as pending export
- MIM runs a DIDS operation which brings in the (existing) value, resolves pending export
I believe the original question has been answered, please let me know if there is anything further you would like assistance with.
I'll see if I can enable export logging for the MA to get more info. The main problem is also having to implement something to archive the logs so they're not overwritten, so I won't be able to get that in today.
This is still happening and I had the opportinuty to observe it many times in Dev this week, while troubleshooting a connector script.
The specific scenario I've seen this week is MIM exports a string value through IdB to a Powershell connector script. The connector update script fails to do what it should, then when the polling import runs a NULL value is imported into the connector/adapter. MIM picks up the NULL and attempts to re-export the attribute value (which I expect and want to happen), but the export fils with this "Cannot add value" error reported back from IdB.
The only way I found to get the export to run was to clear the adapter and "Generate changes". Running a Full Import of the connector did not clear the error.
I've attached some screen shots showing that MIM is attempting to export two string values and the adapter has NULL for these values.
Note the original error I posted above had a SQL connector at the other end so I don't think this is related to the connector type.
Here's the error to go with these screen shots:
Internal Server Error #9: Unify.Product.IdentityBroker.LDAPModifyException: Cannot add the value 5C-5C-44-4E-41-43-30-31-44-43-57-30-32-2E-64-65-76-2E-6E-6D-69-2E-69-6E-64-5C-48-6F-6D-65-32 to the existing, non-multivalue field ParentFolder.
at Unify.Product.IdentityBroker.LDAPModifyRequestToEntityConverter.HandleAttributeValueAdd(IModifyRequestOperation op, IAdapterEntity entity, IEntitySchema schema)
at Unify.Product.IdentityBroker.LDAPModifyRequestToEntityConverter.Transform(IRfcModifyRequest sourceValue, IAdapterEntity origEntity)
at Unify.Product.IdentityBroker.ModifyRequestHandler.InnerApplyTransformation(IHandleRequestCoreRequest request, LDAPModifyRequestToEntityConverter converter)
Hi Carol, Thanks for the update.
The specific scenario I've seen this week is MIM exports a string value through IdB to a Powershell connector script. The connector update script fails to do what it should, then when the polling import runs a NULL value is imported into the connector/adapter. MIM picks up the NULL and attempts to re-export the attribute value (which I expect and want to happen), but the export fils with this "Cannot add value" error reported back from IdB.
Can you clarify this point a little? Is the original export, where the update script fails, being reported to MIM as failed?
I think I understand the scenario you are describing, could you please specify which version of Identity Broker and Identity Broker for Microsoft Identity Manager you are using?
In this particular case there was no error being reported back - part of what I was working on was improving the error reporting of the update script.
I've got IdB 5.2.1. The FIMAdapter dll version is 5.1.0.0.
Thanks Carol. On the topic of error reporting in the update script, please make sure to look at PowerShell Connector Failed Operations.
I think I have reproduced your issue, and I'm investigating the cause now.
Yes I am using the advice in that document - my trial and error was more about capturing errors back from individual ps cmdlets which aren't always consistent in the way they report errors.
That's very good news that you've reproduced it!
Hi Carol,
Could you please try applying the following patch and see if you can reproduce the issue?
Will give it a go. Does that go in the Program Files\UNIFY Solutions\Identity Broker\Services folder?
I have gone through the "export value -> import null -> re-export value" scenario and it looks to be ok now - I did not see that error and the second export ran.
I have seen the error on another MA but I think that's just the transient one I sometimes see which is usually sorted out on the next MA import.
Hi Curtis, I appear to have this problem too (UNIFYBroker 5.3.1 Rev 0). Did that patch ever make it into the base UNIFYBroker product, or should I try it out?
Hi Adrian,
I cannot find any record of the changes made in the patch Curtis provided so I cannot say for certain whether or not they made it into future releases. The patch was made for v5.2 so will not work with v5.3. Instead, can you upgrade to the latest Broker release, v5.3.2? There have been several changes made since v5.3.1 RC1 to the parts of Broker that Curtis seemed to suspect were the cause of this issue. If this does not fix the problem, I will investigate further.
Thanks Curtis,
We are about to go live so will take this approach if we see the issue then, and separately plan to update Broker for the next release cycle regardless.
Customer support service by UserEcho
Hi Carol,
The error "Cannot add the value 41-50-53-34 to the existing, non-multivalue field Classification" indicates that MIM is attempting to export an update to an entity which adds a value to a field for which the entity already has a value, and that field is not multi-valued. This isn't logged in Identity Broker as an error because as far as Identity Broker is concerned, it correctly responded to an invalid request with a failure - there is no error of processing in Identity Broker.
This usually indicates that the data in Identity Broker and the MIM connector space have grown out of sync, and can be resolved with an import + sync cycle. The fact that this issue resolves itself suggests this is likely.