• State Verified Answer
  • Replies 1 reply
  • Subscribers 95 subscribers
  • Views 1539 views
  • Users 0 members are here
Options
Related

PS Connector Insert - Works for Sync, not got AdHoc Projection

gwickert
over 3 years ago

Hi All,

I have a PS connector which is giving me trouble. The connector overview is as follows - using 8.1.4.

  • PS connector
  • Runs MS Exchange Mailbox Commands
    • Add-RecipientPermission
    • Remove-RecipientPermission
    • Get-RecipientPermission
  • A custom table CCCO3EMbxGrantSendAs holds the records which represent SendAs permissions.
    • CCC_ObjectKeyGrantSendAsTo = Trustee - dynamic foreign key - right now only accepts O3EMailbox objects.
    • CCC_UID_O3EMailbox = Identity - FK to O3EMailbox
  • When a record is inserted into the table, I want it to run Add-RecipientPermission - Identity <identity> -Trustee <trustee> -AccessRights SendAs
  • When a record is removed from the table, I want it to run Remove-RecipientPermission - Identity <identity> -Trustee <trustee> -AccessRights SendAs
  • An AdHoc projection process is on CCCO3EMbxGrantSendAs listing to Insert/Delete events. I pass in the appropriate DPRProjectionConfig + VariableSet UID. 
  • I also have both of the above attributes in the ForceSyncOf parameter.
  • I have virtual properties converting the above 2 attributes + mappings to the appropriate PS inputs.
    • CCC_ObjectKeyGrantSendAsTo = O3EMailbox.MicrosoftOnlineServicesID = -Trustee
    • CCC_UID_O3EMailbox = Identity - O3EMailbox.Name = -Identity
  • My matching rule is two virtual properties which are <Identity><Trustee>
  • I statically pass in SendAs to each command in my MethodConfiguration.
  • I have a provisioning workflow with:
    • Object in OneIM and not Target = Insert in Target
    • Object in Target and not OneIM = Delete in Target.

What I am seeing is that when I insert a record, it triggers my process, however the PowerShell is not called. When I delete a record (and make sure its associated record is in the target), the correct powershell is called and it is all good. Further, when I run a sync, both insert and delete work fine. Both also work fine via target system browser. My fall back is to use sync rather than AdHoc...thoughit is ideal to have AdHoc as these records will be provisioning via access request, so real time provisioning of these after approval would be nice.

I believe I have narrowed this down to an issue with the engine's intersection process which it used to determine if adds/removes are needed.

I would expect:

  • On insert, Left would = 1 obj and right would = 0
  • On delete, Left would = 0 obj and right would = 1

What I see in trace logs of an AdHoc projection:

  • On insert, left = 1 and right = 1 (Bad)
  • On delete, left = 0 and right = 1 (Good)

See below for the intersection part of the trace from insert:

2021-08-19 14:49:24.2502 DEBUG (GenericPool PoshContext_0) : Getting item... 
2021-08-19 14:49:24.2502 DEBUG (GenericPool PoshContext_0) : Got existing item: VI.Projector.Powershell.Connector.PoshContext 
2021-08-19 14:49:24.2658 TRACE (SystemConnector Posh-90F8EE) : 	Executing command: 
2021-08-19 14:49:24.2658 TRACE (SystemConnector Posh-90F8EE) : 	  Command: Get-RecipientPermission
    Parameters:
      -AccessRights SendAs
      -identity <Identity>
      -trustee <Trustee>
 
2021-08-19 14:49:24.9422 DEBUG (GenericPool PoshContext_0) : Cleaning up item... 
2021-08-19 14:49:25.6355 TRACE (SystemConnector Posh-90F8EE) : 	Returned PSObjects: 0 
2021-08-19 14:49:25.6355 WARN (SystemConnector Posh-90F8EE) : 	Returned PSObject was $null or result was empty. If calling a custom cmdlet consider throwing an exception instead of returning $null. 
2021-08-19 14:49:25.6511 DEBUG (GenericPool PoshContext_0) : Release item: VI.Projector.Powershell.Connector.PoshContext 
2021-08-19 14:49:25.6511 DEBUG (SystemConnector Posh-90F8EE) : 	Result: State (Success) Objects (1) Failures (0) 
2021-08-19 14:49:25.6511 DEBUG (SystemConnector Posh-90F8EE) : 	Dumping the first of them:
	Object: <Identity>
	SchemaType: O3EMbxGrantSendAsTo
	State: New
	Uid: d82ad58a-c1dc-4d8a-b959-c7766432f8ea
	LoadedProperties: Identity, Trustee, vrtKey
	ChangedProperties: 
	IsChanged: False
	IsDifferent: False
	Values:
		- Identity: <Identity>
		- Identity[O]: <Identity>
		- Trustee: <Trustee>
		- Trustee[O]: <Trustee>
		- vrtKey: <Identity><Trustee>
		- vrtKey[O]: <Identity><Trustee>

 
2021-08-19 14:49:25.6511 DEBUG (SystemConnector Posh-90F8EE) : 	Performing post filtering. 
2021-08-19 14:49:25.6511 DEBUG (SystemConnector Posh-90F8EE) : 	Filter results in 1 objects. 
2021-08-19 14:49:25.6511 DEBUG (SystemConnection 3e98b07c-6bd2-4889-a6db-1004ea414c83) : 	QueryObjects result (out of scope): 1 system objects. 
2021-08-19 14:49:25.6511 DEBUG (StopWatch SW) : Querying objects of prototype (<Identity>). done in 1.41s. 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : <Identity>@O3EMbxGrantSendAsTo[].GetValue[O](Identity) returns <Identity> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : <Identity>@O3EMbxGrantSendAsTo[].GetValue[O](Trustee) returns <Trustee> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : <Identity>@O3EMbxGrantSendAsTo[].GetValue[O](vrtKey) returns <Identity><Trustee> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](CCC_UID_O3EMailbox) returns 17a33094-9f37-4eb8-bf7c-a33775588906 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Getting item... 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Got existing item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Resolving instance of type VI.Projector.Filter.Formatter.INativeSystemFilterFormatter. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Instance VI.Projector.Database.SqlFilterFormatter resolved. 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Release item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : QueryObjects: Querying objects of O3EMailbox_Master. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : 	Options: NativeSystemFilter=True, ObjectDataFilter=False, ObjectFilter=False
	Properties: UID_O3EMailbox, Name
	UseReferenceScope=True 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Getting item... 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Got existing item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Querying objects... 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : 	...ByFilter. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : 	Got creation revision  
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : O3EMailbox: Getting collection, load type: Slim 
2021-08-19 14:49:25.6823 TRACE (SqlLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	ClaimConnectionAsync - read write, _transaction == null 
2021-08-19 14:49:25.6823 TRACE (SqlLog ) : -- Connection 3 switched from Available to Working after comparison 
2021-08-19 14:49:25.6823 TRACE (SqlLog ) : --> existing connection 3 
2021-08-19 14:49:25.6823 DEBUG (SqlLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	(< 1 ms) - select UID_O3EMailbox, Name from O3EMailbox where ((UID_O3EMailbox = '17a33094-9f37-4eb8-bf7c-a33775588906')) 
2021-08-19 14:49:25.6823 TRACE (SqlLog ) : -- Connection 3 switched from Working to Available 
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Collection: Run statement and fetch data done in 1ms. 
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Collection.Count: 1 
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Getting collection done in 1ms. 
2021-08-19 14:49:25.6823 DEBUG (SystemObjectData <static>) : Creating SystemObjectData based on entity (%DisplayName%) columns (Name, UID_O3EMailbox). 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : 	Result: State (Success) Objects (1) Failures (0) 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Release item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : 	QueryObjects result (out of scope): 1 system objects. 
2021-08-19 14:49:25.6823 DEBUG (StopWatch SW) : Querying objects of schema class (O3EMailbox_Master). done in 2ms. 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : %DisplayName%@O3EMailbox[].GetValue(Name) returns <Identity> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : %DisplayName%@O3EMailbox[].GetValue(UID_O3EMailbox) returns 17a33094-9f37-4eb8-bf7c-a33775588906 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](vrtMailboxIdentity) returns <Identity> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](CCC_ObjectKeyGrantSendAsTo) returns <Key><T>O3EMailbox</T><P>403aa5e0-87ea-4a3b-8feb-280d9c69df76</P></Key> 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Getting item... 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Got existing item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Resolving instance of type VI.Projector.Filter.Formatter.INativeSystemFilterFormatter. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Instance VI.Projector.Database.SqlFilterFormatter resolved. 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Release item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : QueryObjects: Querying objects of O3EMailbox_Master. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : 	Options: NativeSystemFilter=True, ObjectDataFilter=False, ObjectFilter=False
	Properties: XObjectKey, MicrosoftOnlineServicesID
	UseReferenceScope=True 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Getting item... 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Got existing item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Querying objects... 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : 	...ByFilter. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : 	Got creation revision  
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : O3EMailbox: Getting collection, load type: Slim 
2021-08-19 14:49:25.6823 TRACE (SqlLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	ClaimConnectionAsync - read write, _transaction == null 
2021-08-19 14:49:25.6823 TRACE (SqlLog ) : -- Connection 3 switched from Available to Working after comparison 
2021-08-19 14:49:25.6823 TRACE (SqlLog ) : --> existing connection 3 
2021-08-19 14:49:25.6823 DEBUG (SqlLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	(1 ms) - select XObjectKey, MicrosoftOnlineServicesID, UID_O3EMailbox from O3EMailbox where ((XObjectKey = N'<Key><T>O3EMailbox</T><P>403aa5e0-87ea-4a3b-8feb-280d9c69df76</P></Key>')) 
2021-08-19 14:49:25.6823 TRACE (SqlLog ) : -- Connection 3 switched from Working to Available 
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Collection: Run statement and fetch data done in 1ms. 
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Collection.Count: 1 
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Getting collection done in 1ms. 
2021-08-19 14:49:25.6823 DEBUG (SystemObjectData <static>) : Creating SystemObjectData based on entity (%DisplayName%) columns (MicrosoftOnlineServicesID, UID_O3EMailbox, XObjectKey). 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : 	Result: State (Success) Objects (1) Failures (0) 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Release item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : 	QueryObjects result (out of scope): 1 system objects. 
2021-08-19 14:49:25.6823 DEBUG (StopWatch SW) : Querying objects of schema class (O3EMailbox_Master). done in 2ms. 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : %DisplayName%@O3EMailbox[].GetValue(MicrosoftOnlineServicesID) returns <Trustee> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : %DisplayName%@O3EMailbox[].GetValue(XObjectKey) returns <Key><T>O3EMailbox</T><P>403aa5e0-87ea-4a3b-8feb-280d9c69df76</P></Key> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](vrtObjectKeyGrantSendAs) returns <Trustee> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](vrtKey) returns <Identity><Trustee> 
2021-08-19 14:49:25.6823 DEBUG (StopWatch SW) : Intersecting 1 and 1 objects with map (GrantSendAs) done in 15ms. 
2021-08-19 14:49:25.6823 DEBUG (ProjectorEngine 28d38263-652c-47be-afde-6175071917ec) : 		Calculating intersection of 1 left objects and 1 right objects. 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : <Identity>@O3EMbxGrantSendAsTo[].GetValue[O](Identity) returns <Identity> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : <Identity>@O3EMbxGrantSendAsTo[].GetValue[O](Trustee) returns <Trustee> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : <Identity>@O3EMbxGrantSendAsTo[].GetValue[O](vrtKey) returns <Identity><Trustee> 
2021-08-19 14:49:25.6823 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](CCC_UID_O3EMailbox) returns 17a33094-9f37-4eb8-bf7c-a33775588906 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Getting item... 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Got existing item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Resolving instance of type VI.Projector.Filter.Formatter.INativeSystemFilterFormatter. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Instance VI.Projector.Database.SqlFilterFormatter resolved. 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Release item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : QueryObjects: Querying objects of O3EMailbox_Master. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : 	Options: NativeSystemFilter=True, ObjectDataFilter=False, ObjectFilter=False
	Properties: UID_O3EMailbox, Name
	UseReferenceScope=True 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Getting item... 
2021-08-19 14:49:25.6823 DEBUG (GenericPool ISystemConnector_0) : Got existing item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : Querying objects... 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : 	...ByFilter. 
2021-08-19 14:49:25.6823 DEBUG (SystemConnector OneIM-394CB7) : 	Got creation revision  
2021-08-19 14:49:25.6823 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : O3EMailbox: Getting collection, load type: Slim 
2021-08-19 14:49:25.6823 TRACE (SqlLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	ClaimConnectionAsync - read write, _transaction == null 
2021-08-19 14:49:25.6980 TRACE (SqlLog ) : -- Connection 3 switched from Available to Working after comparison 
2021-08-19 14:49:25.6980 TRACE (SqlLog ) : --> existing connection 3 
2021-08-19 14:49:25.6980 DEBUG (SqlLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	(< 1 ms) - select UID_O3EMailbox, Name from O3EMailbox where ((UID_O3EMailbox = '17a33094-9f37-4eb8-bf7c-a33775588906')) 
2021-08-19 14:49:25.6980 TRACE (SqlLog ) : -- Connection 3 switched from Working to Available 
2021-08-19 14:49:25.6980 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Collection: Run statement and fetch data done in 1ms. 
2021-08-19 14:49:25.6980 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Collection.Count: 1 
2021-08-19 14:49:25.6980 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Getting collection done in 1ms. 
2021-08-19 14:49:25.6980 DEBUG (SystemObjectData <static>) : Creating SystemObjectData based on entity (%DisplayName%) columns (Name, UID_O3EMailbox). 
2021-08-19 14:49:25.6980 DEBUG (SystemConnector OneIM-394CB7) : 	Result: State (Success) Objects (1) Failures (0) 
2021-08-19 14:49:25.6980 DEBUG (GenericPool ISystemConnector_0) : Release item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6980 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : 	QueryObjects result (out of scope): 1 system objects. 
2021-08-19 14:49:25.6980 DEBUG (StopWatch SW) : Querying objects of schema class (O3EMailbox_Master). done in 1ms. 
2021-08-19 14:49:25.6980 TRACE (SchemaElement static) : %DisplayName%@O3EMailbox[].GetValue(Name) returns <Identity> 
2021-08-19 14:49:25.6980 TRACE (SchemaElement static) : %DisplayName%@O3EMailbox[].GetValue(UID_O3EMailbox) returns 17a33094-9f37-4eb8-bf7c-a33775588906 
2021-08-19 14:49:25.6980 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](vrtMailboxIdentity) returns <Identity> 
2021-08-19 14:49:25.6980 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](CCC_ObjectKeyGrantSendAsTo) returns <Key><T>O3EMailbox</T><P>403aa5e0-87ea-4a3b-8feb-280d9c69df76</P></Key> 
2021-08-19 14:49:25.6980 DEBUG (GenericPool ISystemConnector_0) : Getting item... 
2021-08-19 14:49:25.6980 DEBUG (GenericPool ISystemConnector_0) : Got existing item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6980 DEBUG (SystemConnector OneIM-394CB7) : Resolving instance of type VI.Projector.Filter.Formatter.INativeSystemFilterFormatter. 
2021-08-19 14:49:25.6980 DEBUG (SystemConnector OneIM-394CB7) : Instance VI.Projector.Database.SqlFilterFormatter resolved. 
2021-08-19 14:49:25.6980 DEBUG (GenericPool ISystemConnector_0) : Release item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6980 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : QueryObjects: Querying objects of O3EMailbox_Master. 
2021-08-19 14:49:25.6980 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : 	Options: NativeSystemFilter=True, ObjectDataFilter=False, ObjectFilter=False
	Properties: XObjectKey, MicrosoftOnlineServicesID
	UseReferenceScope=True 
2021-08-19 14:49:25.6980 DEBUG (GenericPool ISystemConnector_0) : Getting item... 
2021-08-19 14:49:25.6980 DEBUG (GenericPool ISystemConnector_0) : Got existing item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6980 DEBUG (SystemConnector OneIM-394CB7) : Querying objects... 
2021-08-19 14:49:25.6980 DEBUG (SystemConnector OneIM-394CB7) : 	...ByFilter. 
2021-08-19 14:49:25.6980 DEBUG (SystemConnector OneIM-394CB7) : 	Got creation revision  
2021-08-19 14:49:25.6980 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : O3EMailbox: Getting collection, load type: Slim 
2021-08-19 14:49:25.6980 TRACE (SqlLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	ClaimConnectionAsync - read write, _transaction == null 
2021-08-19 14:49:25.6980 TRACE (SqlLog ) : -- Connection 3 switched from Available to Working after comparison 
2021-08-19 14:49:25.6980 TRACE (SqlLog ) : --> existing connection 3 
2021-08-19 14:49:25.6980 DEBUG (SqlLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	(< 1 ms) - select XObjectKey, MicrosoftOnlineServicesID, UID_O3EMailbox from O3EMailbox where ((XObjectKey = N'<Key><T>O3EMailbox</T><P>403aa5e0-87ea-4a3b-8feb-280d9c69df76</P></Key>')) 
2021-08-19 14:49:25.6980 TRACE (SqlLog ) : -- Connection 3 switched from Working to Available 
2021-08-19 14:49:25.6980 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Collection: Run statement and fetch data done in 1ms. 
2021-08-19 14:49:25.6980 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Collection.Count: 1 
2021-08-19 14:49:25.6980 DEBUG (ObjectLog cf1c63be-2973-44ac-af59-8c1a4e1caa7f) : 	Getting collection done in 1ms. 
2021-08-19 14:49:25.6980 DEBUG (SystemObjectData <static>) : Creating SystemObjectData based on entity (%DisplayName%) columns (MicrosoftOnlineServicesID, UID_O3EMailbox, XObjectKey). 
2021-08-19 14:49:25.6980 DEBUG (SystemConnector OneIM-394CB7) : 	Result: State (Success) Objects (1) Failures (0) 
2021-08-19 14:49:25.6980 DEBUG (GenericPool ISystemConnector_0) : Release item: <DBServerName>\OneIMDEV 
2021-08-19 14:49:25.6980 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : 	QueryObjects result (out of scope): 1 system objects. 
2021-08-19 14:49:25.6980 DEBUG (StopWatch SW) : Querying objects of schema class (O3EMailbox_Master). done in 1ms. 
2021-08-19 14:49:25.6980 TRACE (SchemaElement static) : %DisplayName%@O3EMailbox[].GetValue(MicrosoftOnlineServicesID) returns <Trustee> 
2021-08-19 14:49:25.6980 TRACE (SchemaElement static) : %DisplayName%@O3EMailbox[].GetValue(XObjectKey) returns <Key><T>O3EMailbox</T><P>403aa5e0-87ea-4a3b-8feb-280d9c69df76</P></Key> 
2021-08-19 14:49:25.6980 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](vrtObjectKeyGrantSendAs) returns <Trustee> 
2021-08-19 14:49:25.6980 TRACE (SchemaElement static) : d47c6325-9afd-4010-b337-cc657d07de05@CCCO3EMbxGrantSendAsTo[].GetValue[O](vrtKey) returns <Identity><Trustee> 
2021-08-19 14:49:25.6980 DEBUG (StopWatch SW) : Intersecting 1 and 1 objects with map (GrantSendAs) done in 3ms. 
2021-08-19 14:49:25.6980 DEBUG (ProjectorEngine 28d38263-652c-47be-afde-6175071917ec) : 		--> Intersection results in 1 pairs. 
2021-08-19 14:49:25.7136 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : ProcessContext has changed from (52ff03e1-852c-4c98-a3f1-c82f0b4f8025) to (<null>). 
2021-08-19 14:49:25.7136 DEBUG (SystemConnection 3e98b07c-6bd2-4889-a6db-1004ea414c83) : ProcessContext has changed from (52ff03e1-852c-4c98-a3f1-c82f0b4f8025) to (<null>). 
2021-08-19 14:49:25.7136 TRACE (SystemObjectData <static>) : Applying properties () on object d47c6325-9afd-4010-b337-cc657d07de05 of SchemaType CCCO3EMbxGrantSendAsTo... 
2021-08-19 14:49:25.7136 DEBUG (ProjectorEngine 28d38263-652c-47be-afde-6175071917ec) : 	There are no differences of failed objects to the previous execution of step (GrantSendAs)! These failures do not cause a retry! 
2021-08-19 14:49:25.7136 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : Leaving update phase. 
2021-08-19 14:49:25.7136 DEBUG (SystemConnection 3e98b07c-6bd2-4889-a6db-1004ea414c83) : Leaving update phase. 
2021-08-19 14:49:25.7136 DEBUG (SystemConnector Posh-90F8EE) : Leaving update phase. 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : Executing step (GrantSendAs)... done in 1.71s. 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (SQL): 18ms (1.04%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (Session): 0ms (0.00%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (Cache): 6ms (0.36%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (Entities): 19ms (1.09%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (XmlProjectorReader): 0ms (0.00%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (DatabaseReader): 0ms (0.00%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (One Identity Manager (<DBServerName>\OneIMDEV)): 72ms (4.22%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (PoshNet40 (Exchange Online - Extended Attributes)): 1.41s (82.60%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for (ProjectorEngine): 18ms (1.03%) 
2021-08-19 14:49:25.7136 DEBUG (StopWatch SW) : 	Time consumption for the rest: 165ms (9.67%). (This result might be affected by multithreading!)

Important lines I feel are:

2021-08-19 14:49:25.6980 DEBUG (StopWatch SW) : Intersecting 1 and 1 objects with map (GrantSendAs) done in 3ms.
2021-08-19 14:49:25.6980 DEBUG (ProjectorEngine 28d38263-652c-47be-afde-6175071917ec) : --> Intersection results in 1 pairs.

I'd think for an insert there should not be any pairs?

For delete (I will omit the full log) I see an intersection message that makes sense:

2021-08-19 14:31:24.7634 DEBUG (StopWatch SW) : Intersecting 0 and 1 objects with map (GrantSendAs) done in 0ms.
2021-08-19 14:31:24.7634 DEBUG (ProjectorEngine 1a758b0b-74fe-4299-9aed-40ed133a62e8) : --> Intersection results in 0 pairs.

CausingEntityPatch: <Patch Display="a87603c3-3b81-4771-bb2c-ff4bccd1f698"><Key><T>CCCO3EMbxGrantSendAsTo</T><P>a87603c3-3b81-4771-bb2c-ff4bccd1f698</P></Key><Diff><Data State="PermissionBased" /></Diff></Patch>

Anyone know where to from here? Any settings that may cause this type of behavior? Stumped that delete is fine for both sync and AdHoc, and that insert works via sync but not AdHoc...so close!

  • +1 over 3 years ago

    Found the issue here - feels like a bug with the engines handling of null return from Get-Object CmdLets. 

    TLDR

    When this was not working via AdHoc, the following message was in the logs. I didn't think too much of it given it was WARN, and it ran the PowerShell OK. I naturally figured it was a warning...

    2021-08-19 14:49:25.6355 WARN (SystemConnector Posh-90F8EE) : 	Returned PSObject was $null or result was empty. If calling a custom cmdlet consider throwing an exception instead of returning $null.

    The CmdLet I'm using is the Exchange Add-RecipientPermission CmdLet. Turns out this returns null when no results are returned.

    A colleague eventually suggested I do what the warning says as it can't hurt to try...and sure enough, wrapping the exchange CmdLet in a simple $null check and throwing an exception if so - worked! I also noticed afterwards that the OOTB exchange connector implements this pattern.

    Full bug detail

    Interesting parts from the non working trace - note that it says:
    Result: State (Success) Objects (1) Failures (0)
    'dumping the first of them <insert object which magically appears from nowhere>'

    Even though nothing was returned by the CmdLet. If no objects are returned, it seems to dump the prototype from earlier in the log which is used to run the Get-Object query. If this didn't dump the prototype/treat the prototype as a target system object, I believe this would be a non-issue.

    It then warns about null and throwing an exception - but doesn't mention that it breaks adhoc projections if you don't follow the warning's advice. Updating this to error level and using absolute language "You must throw an exception" would also help.

    Ideally, having OneIM handle this would mean that we don't need to write little wrappers for these CmdLets. Could even reduce the code on the OOTB connectors too!

    2021-08-19 14:49:24.2502 DEBUG (GenericPool PoshContext_0) : Getting item... 
2021-08-19 14:49:24.2502 DEBUG (GenericPool PoshContext_0) : Got existing item: VI.Projector.Powershell.Connector.PoshContext 
2021-08-19 14:49:24.2658 TRACE (SystemConnector Posh-90F8EE) : 	Executing command: 
2021-08-19 14:49:24.2658 TRACE (SystemConnector Posh-90F8EE) : 	  Command: Get-RecipientPermission
    Parameters:
      -AccessRights SendAs
      -identity <Identity>
      -trustee <Trustee>
 
2021-08-19 14:49:24.9422 DEBUG (GenericPool PoshContext_0) : Cleaning up item... 
2021-08-19 14:49:25.6355 TRACE (SystemConnector Posh-90F8EE) : 	Returned PSObjects: 0 
2021-08-19 14:49:25.6355 WARN (SystemConnector Posh-90F8EE) : 	Returned PSObject was $null or result was empty. If calling a custom cmdlet consider throwing an exception instead of returning $null. 
2021-08-19 14:49:25.6511 DEBUG (GenericPool PoshContext_0) : Release item: VI.Projector.Powershell.Connector.PoshContext 
2021-08-19 14:49:25.6511 DEBUG (SystemConnector Posh-90F8EE) : 	Result: State (Success) Objects (1) Failures (0) 
2021-08-19 14:49:25.6511 DEBUG (SystemConnector Posh-90F8EE) : 	Dumping the first of them:
	Object: <Identity>
	SchemaType: O3EMbxGrantSendAsTo
	State: New
	Uid: d82ad58a-c1dc-4d8a-b959-c7766432f8ea
	LoadedProperties: Identity, Trustee, vrtKey
	ChangedProperties: 
	IsChanged: False
	IsDifferent: False
	Values:
		- Identity: <Identity>
		- Identity[O]: <Identity>
		- Trustee: <Trustee>
		- Trustee[O]: <Trustee>
		- vrtKey: <Identity><Trustee>
		- vrtKey[O]: <Identity><Trustee>

 
2021-08-19 14:49:25.6511 DEBUG (SystemConnector Posh-90F8EE) : 	Performing post filtering. 
2021-08-19 14:49:25.6511 DEBUG (SystemConnector Posh-90F8EE) : 	Filter results in 1 objects. 
2021-08-19 14:49:25.6511 DEBUG (SystemConnection 3e98b07c-6bd2-4889-a6db-1004ea414c83) : 	QueryObjects result (out of scope): 1 system objects. 

...

2021-08-19 14:49:25.6980 DEBUG (StopWatch SW) : Intersecting 1 and 1 objects with map (GrantSendAs) done in 3ms. 
2021-08-19 14:49:25.6980 DEBUG (ProjectorEngine 28d38263-652c-47be-afde-6175071917ec) : 		--> Intersection results in 1 pairs. 
2021-08-19 14:49:25.7136 DEBUG (SystemConnection 6e030e4f-ee51-4cf2-bec8-b98354bbb2e0) : ProcessContext has changed from (52ff03e1-852c-4c98-a3f1-c82f0b4f8025) to (<null>).

    The end of this as mentioned results in a pair being produced from the intersection which is not right.

    See below for a trace where I use a custom get-object and throw an exception. Notice that it doesn't dump out the prototype.

    2021-08-20 12:03:09.9763 DEBUG (GenericPool PoshContext_0) : Getting item... 
2021-08-20 12:03:09.9763 DEBUG (GenericPool PoshContext_0) : Got existing item: VI.Projector.Powershell.Connector.PoshContext 
2021-08-20 12:03:09.9919 TRACE (SystemConnector Posh-5FBF53) : 	Executing command: 
2021-08-20 12:03:09.9919 TRACE (SystemConnector Posh-5FBF53) : 	  Command: Get-OneIMRecipientPermission
    Parameters:
      -AccessRights SendAs
      -identity <Identity>
      -trustee <Trustee>
 
2021-08-20 12:03:10.3356 DEBUG (GenericPool PoshContext_0) : Release item: VI.Projector.Powershell.Connector.PoshContext 
2021-08-20 12:03:10.3356 DEBUG (SystemConnector Posh-5FBF53) : 	Result: State (Success) Objects (0) Failures (0) 
2021-08-20 12:03:10.3356 DEBUG (SystemConnector Posh-5FBF53) : 	Dumping the first of them:
 
2021-08-20 12:03:10.3356 DEBUG (SystemConnector Posh-5FBF53) : 	Performing post filtering. 
2021-08-20 12:03:10.3356 DEBUG (SystemConnector Posh-5FBF53) : 	Filter results in 0 objects. 
2021-08-20 12:03:10.3356 DEBUG (SystemConnection fc9b2066-b953-45a4-b4b9-0def81be3b24) : 	QueryObjects result (out of scope): 0 system objects. 
2021-08-20 12:03:10.3356 DEBUG (StopWatch SW) : Querying objects of prototype (<Identity>). done in 361ms. 
2021-08-20 12:03:10.3356 TRACE (ProjectorEngine b32e7ea8-de67-4787-82ab-2ad59663c4d1) : 		Counterpart for (6a9da0e5-f20a-4936-91fd-522e4c7bc5fc) not found. 
2021-08-20 12:03:10.3513 DEBUG (StopWatch SW) : Intersecting 1 and 0 objects with map (GrantSendAs) done in 0ms. 
2021-08-20 12:03:10.3513 DEBUG (ProjectorEngine b32e7ea8-de67-4787-82ab-2ad59663c4d1) : 		Calculating intersection of 1 left objects and 0 right objects. 
2021-08-20 12:03:10.3513 DEBUG (StopWatch SW) : Intersecting 1 and 0 objects with map (GrantSendAs) done in 0ms. 
2021-08-20 12:03:10.3513 DEBUG (ProjectorEngine b32e7ea8-de67-4787-82ab-2ad59663c4d1) : 		--> Intersection results in 0 pairs.

    The end of this results in 1 left 0 right objects and no pairs from intersection. 

    Hope this helps someone with a similar issue!

    Glen.