Discarding transaction because entry was deleted

Hi All,

I have an issue with the Google Apps driver. Here is the entirety of the level 3 trace when I try to migrate an account using iManager and the Google Apps driver.

[09/07/18 09:47:09.218]:IDM4GMAIL ST:Start transaction.
[09/07/18 09:47:09.218]:IDM4GMAIL ST:Discarding transaction because entry was deleted.


The association state on the user object changes to Migrate from Processed.

If I delete the association from the user account, I can migrate the account successfully and a match is found. Any subsequent migrate results in the condition above. This is happening to multiple user objects.

Google driver is version 4.1.1.5.

Any advice appreciated.

Thanks
Adam
Parents
  • Hi Adam,

    Strange thing...
    Event on subscriber channel suppose to start similarly for any driver.

    Could you increase you trace level to 5-10 and post the trace here?
  • On 9/7/2018 3:44 PM, al b wrote:
    >
    > Hi Adam,
    >
    > Strange thing...
    > Event on subscriber channel suppose to start similarly for any driver.
    >
    > Could you increase you trace level to 5-10 and post the trace here?


    The code path you seem to be hitting is an optimization item, where if
    there is an event in the cache, but the object itself is deleted, should
    you process it? Clearly not. What would processing it do? The object is
    gone. Sure you could have a use case where you might, but in general no.

    So why does the engine think it is deleted?

    Perhaps some odd kind of permission issue? (UNlikely, you would have
    gotten a 672 error in trace then).

    Maybe a higher level of trace will show more info.


  • keil0008;2487504 wrote:
    Thanks for the helpful suggestions. Still having a problem. The driver is running as the admin user.

    I stopped the driver and tried a migrate as per geoffc's suggestion. Inspecting the cache you can see the sync event without any data.



    I attempted the same on a different driver and indeed that produced the same result.


    NOTE: Don't be confused by the filename of AD_Loopback. That was just a file naming mistake.

    If I delete the association however, the object is added correctly to the cache.



    I think I'll have to raise an SR now as it's shown to affect more than just the Google Driver.


    That's very wrong. Yes, I think it's SR time on this one. You have something very strange going on there.

    Please let us know what it was when you get it figured out.
  • I will raise an SR I think. FYI. I stopped the Google Apps driver on IDVPRD01 and started it on IDVPRD02 and migrating a user (one that had previously failed) works fine. So it points to an issue with the server IDVPRD01.

    I ran a dsrepair -R yesterday and it didn't make any difference. Shifting the driver to a new server does resolve the issue. I will keep troubleshooting IDVPRD01.

    I enabled dstrace yesterday to see if I could see anything.

    I did observe some of these errors but they seem unrelated:
    09:48:00 40F1C700 Agent: WPutEntryAttrs failed, insufficient buffer (-649)


    It also appears that maybe the server object itself was trying to read the user object and failing. I would have thought it should be being read by the user the driver is confifgured to run as?

    DXML Trace (for time ref):
    [09/14/18 10:13:25.989]:IDM4AD ST:Start transaction.
    [09/14/18 10:13:25.989]:IDM4AD ST:Discarding transaction because entry was deleted.


    DSTRACE:

    10:13:25 63658700 Agent: Calling DSARead conn:0 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:13:25 63052700 Agent: Calling DSARead conn:0 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:13:25 64675700 Agent: Calling DSARead conn:0 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:13:25 64675700 Agent: Calling DSAGetEffectiveRights conn:0 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:13:25 64675700 Agent: Calling DSAResolveName conn:32 for client .[Public].
    10:13:25 64675700 Agent: Calling DSAReadObjectInfo conn:32 for client .[Public].
    10:13:25 62A4C700 Agent: Calling DSAReadObjectInfo conn:0 for client .IDVPRD01.RESOURCES.UOFAIDV.
    09/14/18
    10:13:25 62A4C700 Agent: DSAReadObjectInfo failed, no such entry (-601).
    10:13:25 62A4C700 Agent: Calling DSARead conn:0 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:13:25 62A4C700 Agent: DSARead failed, no such entry (-601).
    10:13:25 64675700 Agent: Calling DSAReadObjectInfo conn:0 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:13:25 63658700 Agent: Calling DSARead conn:0 for client .IDVPRD01.RESOURCES.UOFAIDV.
  • FYI: Here is the DSTRACE from IDVPRD02 when the migrate operation succeeds. It appears to read the object from IDVPRD01.

    The test user involved is a1999973.PEPOLE.UOFAIDV

    10:23:16 91F46700 Agent: Calling DSAResolveName conn:18 for client .[Public].
    10:23:16 BCD17700 Agent: Calling DSAStartUpdateReplica conn:16 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:23:16 BCD17700 SyncI: Start inbound sync from server [000080a7] <.IDVPRD01.RESOURCES.UOFAIDV.> for partition [000080b2] <.PEOPLE.UOFAIDV.>.
    10:23:16 BCE18700 Agent: Calling DSAUpdateReplica conn:16 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:23:16 BCE18700 SyncI: *Received packet with entry count 2 from [000080a7] <.IDVPRD01.RESOURCES.UOFAIDV.>
    09/14/2018
    10:23:16 BCE18700 SyncI: **Processing incoming value for attribute .Transitive Vector.[Attribute Definitions].[Schema Root].
    10:23:16 BCE18700 SyncI: *.IDVPRD01.RESOURCES.UOFAIDV. updated [000080b2] <.PEOPLE.UOFAIDV.>
    10:23:16 BCE18700 SyncI: *Finished applying changes to [000080b2] <.PEOPLE.UOFAIDV.>, succeeded 2005/12/16 13:06:26, 1, 1
    10:23:16 BCE18700 SyncI: **Processing incoming value for attribute .Revision.[Attribute Definitions].[Schema Root].
    10:23:16 BCE18700 SyncI: **Processing incoming value for attribute .DirXML-Associations.[Attribute Definitions].[Schema Root].
    10:23:16 BCE18700 SyncI: **Processing incoming value for attribute .modifiersName.[Attribute Definitions].[Schema Root].
    10:23:16 BCE18700 SyncI: *.IDVPRD01.RESOURCES.UOFAIDV. updated [0002d94f] <.a1999973.PEOPLE.UOFAIDV.>
    10:23:16 BCE18700 SyncI: *Finished applying changes to [0002d94f] <.a1999973.PEOPLE.UOFAIDV.>, succeeded 2018/03/22 13:38:59, 3, 2
    10:23:16 BBD07700 Agent: Calling DSAEndUpdateReplica conn:16 for client .IDVPRD01.RESOURCES.UOFAIDV.
    10:23:16 BBD07700 SyncI: Merge Transitive Vectors, succeeded for .PEOPLE.UOFAIDV.
    10:23:16 BBD07700 SyncI: Partition .PEOPLE.UOFAIDV.: Updating local Transitive Vector, succeeded
    10:23:16 BBD07700 SyncI: Objects received: 2, from server <.IDVPRD01.RESOURCES.UOFAIDV.> partition .PEOPLE.UOFAIDV..
    10:23:16 BBD07700 SyncI: End inbound sync from server <.IDVPRD01.RESOURCES.UOFAIDV.> for partition .PEOPLE.UOFAIDV., Process succeeded.
    10:23:16 BCD17700 OSync: Adding Partition mode psEntry for partition .PEOPLE.UOFAIDV. to PSQueue
    10:23:16 92148700 OSync: Skulk Partition - change cache entry count 4 for .PEOPLE.UOFAIDV.
    10:23:16 92148700 OSync: 2018/09/14 10:23:16 Start partition sync .PEOPLE.UOFAIDV. state:[0], type:[1].
    10:23:16 92148700 OSync: Sync - Start outbound sync with (#=3, state=0, type=0 partition .PEOPLE.UOFAIDV.) .IDVPRD01.RESOURCES.UOFAIDV..
    10:23:16 92148700 OSync: Sync - using version 9 on server <.IDVPRD01.RESOURCES.UOFAIDV.>.
    10:23:16 92148700 OSync: Sending to ----> .IDVPRD01.RESOURCES.UOFAIDV.
    10:23:16 92148700 OSync: Sync - sending updates to server <.IDVPRD01.RESOURCES.UOFAIDV.>.
    10:23:16 92148700 OSync: Send Partition Updates started usingDispatcher=0
  • It looks like sync issue between different servers (I hope, that you have replicas of the same partitions on both servers).

    Simple validation of this hypothesis:
    You can look the same object information in iMonitor on one server and on another server.
    Maybe you will see the differences.
  • Thanks al_b. I have validated the object I'm using for testing on both servers. You are correct, both hold a replica. IDVPRD01 holds a master and IDVPRD02 holds a read / write of all partitions.

    It's worth noting that this problem appears to affect all user objects and not a select few.

    I have another driver which has the DirXML-Assocaiations configured in the driver filter and an event is triggered on this driver after the failed migrate on the AD driver.

    As you can see in the trace, the DirXML-Associations attribute of the user object is modified when triggering a migrate using a different driver.

    <modify cached-time="20180914062036.967Z" class-name="User" event-id="IDVPRD01#20180914062036#3#1:11c5f417-0b5b-47ac-48a6-17f4c5115b0b" qualified-src-dn="O=PEOPLE\CN=a1999973" src-dn="\UOFAIDV\PEOPLE\a1999973" src-entry-id="186632" timestamp="1536906036#2">
    <association state="associated">a1999973</association>
    <modify-attr attr-name="DirXML-Associations">
    <remove-value>
    <value timestamp="1536905528#2" type="structured">
    <component name="nameSpace">4</component>
    <component name="volume">\UOFAIDV\RESOURCES\Driver Set\IDM4 Active Directory Driver</component>
    <component name="path">8ed750ac88633345b7982d89c345d7a9</component>
    </value>
    </remove-value>
    <add-value>
    <value timestamp="1536906036#2" type="structured">
    <component name="nameSpace">3</component>
    <component name="volume">\UOFAIDV\RESOURCES\Driver Set\IDM4 Active Directory Driver</component>
    <component name="path">8ed750ac88633345b7982d89c345d7a9</component>
    </value>
    </add-value>
    </modify-attr>
    </modify>
  • On 9/14/2018 2:24 AM, keil0008 wrote:
    >
    > Thanks al_b. I have validated the object I'm using for testing on both
    > servers. You are correct, both hold a replica. IDVPRD01 holds a master
    > and IDVPRD02 holds a read / write of all partitions.
    >
    > It's worth noting that this problem appears to affect all user objects
    > and not a select few.
    >
    > I have another driver which has the DirXML-Assocaiations configured in
    > the driver filter and an event is triggered on this driver after the
    > failed migrate on the AD driver.
    >
    > As you can see in the trace, the DirXML-Associations attribute of the
    > user object is modified when triggering a migrate using a different
    > driver.
    >
    >
    > Code:
    > --------------------
    > <modify cached-time="20180914062036.967Z" class-name="User" event-id="IDVPRD01#20180914062036#3#1:11c5f417-0b5b-47ac-48a6-17f4c5115b0b" qualified-src-dn="O=PEOPLE\CN=a1999973" src-dn="\UOFAIDV\PEOPLE\a1999973" src-entry-id="186632" timestamp="1536906036#2">
    > <association state="associated">a1999973</association>
    > <modify-attr attr-name="DirXML-Associations">
    > <remove-value>
    > <value timestamp="1536905528#2" type="structured">
    > <component name="nameSpace">4</component>
    > <component name="volume">\UOFAIDV\RESOURCES\Driver Set\IDM4 Active Directory Driver</component>
    > <component name="path">8ed750ac88633345b7982d89c345d7a9</component>
    > </value>
    > </remove-value>
    > <add-value>
    > <value timestamp="1536906036#2" type="structured">
    > <component name="nameSpace">3</component>
    > <component name="volume">\UOFAIDV\RESOURCES\Driver Set\IDM4 Active Directory Driver</component>
    > <component name="path">8ed750ac88633345b7982d89c345d7a9</component>
    > </value>
    > </add-value>
    > </modify-attr>
    > </modify>
    > --------------------


    This is normal. The way a Migrate FROM IDV is triggered is by changing
    the state (nameSpace component) of the current association (per driver)
    from 1 to 3 or 4.


  • Just an update. I've raised a SR. Currently working through the issue with Support. Will post here with results.
  • So it seems the solution may be a trivial one but the cause is unknown. Support pointed out that we have different versions of IDM on each server. This is despite iManager showing versions being the same. Running dxcmd on the command line shows that the problem server is running IDM 4.5.0.0 whereas the properly functioning server is running 4.5.5.0.

    Now I'm sure I'd upgraded both over time. So I went back through the logs and found that idvprd01 was indeed running 4.5.5.0 back in March this year. At which point the logs started showing 4.5.0.0 again. Looking at the .jar files on the server (dirxml.jar) etc they are showing as versions from 2014.

    At the same time in March, I had deployed a new loopback driver but that was the only change of any significance. Anyone got any ideas on how I may have inadvertently reverted my IDM engine back to 4.5.0.0? Is this possible with deploying changes from Designer? I wouldn't have thought so. I'm now quite confused.

    Regards
    Adam
  • On 11/1/2018 7:04 PM, keil0008 wrote:
    >
    > So it seems the solution may be a trivial one but the cause is unknown.
    > Support pointed out that we have different versions of IDM on each
    > server. This is despite iManager showing versions being the same.
    > Running dxcmd on the command line shows that the problem server is
    > running IDM 4.5.0.0 whereas the properly functioning server is running
    > 4.5.5.0.
    >
    > Now I'm sure I'd upgraded both over time. So I went back through the
    > logs and found that idvprd01 was indeed running 4.5.5.0 back in March
    > this year. At which point the logs started showing 4.5.0.0 again.
    > Looking at the .jar files on the server (dirxml.jar) etc they are
    > showing as versions from 2014.
    >
    > At the same time in March, I had deployed a new loopback driver but that
    > was the only change of any significance. Anyone got any ideas on how I
    > may have inadvertently reverted my IDM engine back to 4.5.0.0? Is this
    > possible with deploying changes from Designer? I wouldn't have thought
    > so. I'm now quite confused.


    Engine is mostly dirxml.jar and the vrdim library.

    Almost all the patches update the main JAR files. Designer could not do
    this.

  • Hi All,

    I just wanted to confirm that patching the IDM Engine to 4.5.5. (the version being reported in iManager but not the version of the .jar files) has resolved the issue. I appreciate everyone's help and comments.

    Cheers
Reply Children
No Data