Recon Part 2

Hello All,

    This is part two of the Recon blog. Sorry it took so long to get this out but if you know me, you know once I go down a road I keep digging. In this case, I kept get deeper and deeper into the subject and this is what I came up with. 

What I will do is walk through a AD reconciliation and talk about the gateway. I will end with some tips on why Recons fail and what to look for.

First I want to talk about some key definitions.

The Gateway:

When reconciling to an Active Directory server you need to install a gateway. It installs as a service in Windows and communicates with Identity Manager using TCP port 9278. It acts a bridge between IDM and Active Directory. It goes through the com.waveset.adapter.ADSIResourceAdapter.   It uses ADSI to communicate. This Gateway needs to be the same version of IDM that you are running. If it is not you will run into issues and it might not work.

The gateway is multi-threaded. It will spin off a thread for each connection that is made to it. Connections to the gateway are pooled by Resource type (e.g., Windows NT), gateway host, and gateway port, i.e., a different pool is used for each unique combination of resource type, host, and port.

Idle connections are closed and removed from a pool after they have been idle for 60 seconds, although the check for connections that have been idle longer than 60 seconds only occurs every 5 minutes. A connection is made when the request is made (a fetch of account information) if there is not an idle connection in the corresponding pool, otherwise an idle connection is retrieved from the pool and reused. The maximum number of connections is configured on the Resource; it should be configured the same on all Resources of the same type using the same gateway because the first connection made to the gateway on a given host/port for that resource type will use that Resource's max connections value.

Here's an example how the connections, requests, and gateway threads are related:

If you have the maximum number of connections set to 10 on an Active Directory resource, and you have 2 Identity Manager servers, then you can have at most 20 simultaneous connections (10 from each Identity Manager server) to the gateway for that Active Directory resource, i.e., there can be 10 simultaneous requests outstanding to the gateway from each server and each of these will be processed on a different thread on the gateway. When the number of simultaneous requests exceeds the maximum number of connections to the gateway, additional requests will be queued until a request is completed and its connection is returned to the pool.

Note: if you change the maximum number of connections on the Resource, you will need to start and stop the server to get the change to take effect.

What is ADSI?

Active Directory Service Interface is a set of COM interfaces used to access features of directory services from different network providers.

To find out more about ADSI go to link


What are Recon Threads?

There are 2 types of threads that get called.

1. Worker Threads - As stated these are the ones who do the most work. They work across the resource thread by pulling work from each in turn.

2. Resource Threads - Only one resource is associated with each resource thread. You can run more then one recon at a time because of this.  

By default you have 3 resource threads and 6 worker threads. Note you can increase the resource threads, which allows for more resources to be reconciled. This increases the JVM memory needed. The JVM holds one 'work item' for each user IDM believes has an account on the resource. This occurs during the Account Indexing phase. The Worker threads processes the 'work item' records that get created by the Resource thread.

During the "account indexing" phase, 6 worker threads is almost always enough as it is only working with the IDM repository.

During the "ExaminingResource" phase, you might want to have more worker threads. During this phase the Worker threads get a list of all accounts on the resource and then each account is fetched and processed. For resources with long latency when getting the users, it makes sense to to have more worker threads.

Note: it is possible to have to many worker threads, they usually show up as contention for the repository. The number of worker threads is the same for both AccountIndex phase and also the ExaminingResource phase. they are also the same for all resources.

To see the threads in action after you kick off a reconciler.

Go to the debug page and run the Show_Reconciler.jsp (image below). You will see the threads and what they are doing. If your not seeing anything you might have to refresh. In here you will see:

Pending resource reconciles, these are your pending recon if you have any. Minimum worker threads , maximum worker threads. min and max resource threads. how many pending shared work items and pending account reconciles. the most important part is the worker thread list which shows you exactly what each thread is doing.  

Show_Reconciler.jsp
Now I will get into the actual process

The Recon Process:

Now I will follow the creation of a user. I did this by tracing classes. I will let you know the classes I traced and what is occurring in those steps.

When a resource gets kicked off either Manually or by the scheduler a workflow is kicked off. during this phase the scheduler picks up the request and either handles it right away or waits for the scheduled time.

I will pick this up when the recon hits the request queue and the resource thread picks it up. Here you will see the Reconciler task being launched . I got this by tracing of com.waveset.recon.ReconTask$ResourceThread .

_________________________________________________________________________________


In this step examineLighthouse,  the recontask is queuing up IDM users that claim an account on the resource,
in this case AD. We will follow the user Jedi Three.

20091015 12:58:10.906 Reconciler(0x001469b3) ReconTask$ResourceThread#getWorkload() Exit returned= 0
20091015 12:58:13.328 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#reconcileResource() Entry arg1=ResourceContext:AD
20091015 12:58:16.546 Reconciler(0x001469b3) ReconTask$ResourceThread#getWorkload() Entry no args
20091015 12:58:16.546 Reconciler(0x001469b3) ReconTask$ResourceThread#getWorkload() Exit returned= 0
20091015 12:58:16.781 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#examineLighthouse() Entry arg1=ResourceContext:AD
20091015 12:58:21.546 Reconciler(0x001469b3) ReconTask$ResourceThread#getWorkload() Entry no args
20091015 12:58:21.546 Reconciler(0x001469b3) ReconTask$ResourceThread#getWorkload() Exit returned= 0
20091015 12:58:23.109 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#examineLighthouse() Data
result= com.waveset.object.QueryResultAdapter@16eb24e
20091015 12:58:23.125 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#examineLighthouse() Info user[229]=jedi3

_________________________________________________________________________________


The next step is the waitForLighthouseWorkItems. What this does is wait for all queued user examinations are done.

20091015 12:58:23.265 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#waitForLighthouseWorkItems() Entry no args
20091015 12:58:23.265 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#waitForLighthouseWorkItems() Data users queued= 648
20091015 12:58:23.265 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#waitForLighthouseWorkItems() Data users processed= 0

_________________________________________________________________________________

The next step is examineResource . This is where we fetch all accounts for a specific resource and queue the appropriate accounts.

20091015 13:01:03.890 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#examineResource() Entry arg1=ResourceContext:AD

20091015 13:01:55.375 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#examineResource() Data numAccountsRead= 648
20091015 13:01:55.375 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#examineResource() Exit void

_________________________________________________________________________________

The next step is the queueAccountReconciles. In here is where the actual queuing for the examine resource.

20091015 13:01:03.921 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#queueAccountReconciles() Entry arg1=ResourceContext:AD,arg2=com.waveset.adapter.ResourceAdapterProxy$ExclusionCheckingAccountItera
tor@15aac89

20091015 13:01:55.359 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#queueAccountReconciles() Info account[621]=User:jedi3
20091015 13:01:55.359 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#queueAccountReconciles() Info accountId[621]=cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com
20091015 13:01:55.359 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#queueAccountReconciles() Info accountGUID[621]=<GUID=91d548204b49fe4e8d0eaf77f5799085>
20091015 13:01:55.359 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#queueAccountReconciles() Info accountDisabled[621]=false

_________________________________________________________________________________

Next step is the waitForReconcileWorkItems. In here, the thread waits until all queued accounts reconciles are processed for the resource.


20091015 13:01:55.375 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#waitForReconcileWorkItems() Entry no args
20091015 13:01:55.375 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#waitForReconcileWorkItems() Data reconciles queued= 649
20091015 13:01:55.375 Reconcile:AD(0x01fe6dd3) ReconTask$ResourceThread#waitForReconcileWorkItems() Data reconciles processed= 600

_________________________________________________________________________________

This next step is processResourceWorkflow. This is where it will run the workflow associated with the resource. I don't have one so you wouldn't see this step in the logs.

_________________________________________________________________________________

Then goes to worker thread to process. This can be seen by tracing the com.waveset.recon.ReconTask  . This is where all the work is being done. You can see the workitem being picked up ,then it goes into reconcileAccount does lot of steps and then processes the account.

20091015 10:51:51.453 Reconciler Work Thread(0x01a96e7f) ReconTask#getNextWorkItem() Data next queue index= 1
20091015 10:51:51.453 Reconciler Work Thread(0x01a96e7f) ReconTask#getNextWorkItem() Exit returned= AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD
20091015 10:51:51.453 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#reconcileAccount() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD
20091015 10:51:51.453 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#prepareForReconcile() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD

20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#prepareForReconcile() Info Read claimants: [ #ID#91C5C6C3E42F55B2:1F488F1:11FD2EB1621:-7A8A ]
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#prepareForReconcile() Data Concurrency marker= 1,320
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#prepareForReconcile() Exit returned= true
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#checkResourceAccount() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#checkResourceAccount() Exit returned= true
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#findClaimants() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#findClaimants() Info Possible claimaints: [ #ID#91C5C6C3E42F55B2:1F488F1:11FD2EB1621:-7A8A ]

20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#findClaimants() Exit returned= [ User:jedi3 ]
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyAccount() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD, arg2=[ User:jedi3 ], arg3=true
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyOwnedAccount() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD, arg2=User:jedi3
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyOwnedAccount() Data resource info= cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(accountG
UID=<GUID=91d548204b49fe4e8d0eaf77f5799085> exists=true)
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyOwnedAccount() Data exists= true
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyOwnedAccount() Data created= true
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyOwnedAccount() Data id= cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyOwnedAccount() Data GUID= <GUID=91d548204b49fe4e8d0eaf77f5799085>
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyOwnedAccount() Exit returned= CONFIRMED
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#classifyAccount() Exit returned= CONFIRMED
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#applyOrDeferResponse() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#respondOrRequeue() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD, arg2=null
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#performResponse() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD, arg2=null
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#getLockedBy() Entry no args
20091015 10:51:51.484 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#getLockedBy() Exit returned= Reconciler starwars.reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc =com@AD

20091015 10:51:51.546 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#getLockedBy() Entry no args
20091015 10:51:51.546 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#getLockedBy() Exit returned= Reconciler starwars.reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD

20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#performResponse() Exit void
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#respondOrRequeue() Data resultHasError= false
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#respondOrRequeue() Exit void
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#processAccountWorkflows() Entry arg1=AccountContext:cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#processAccountWorkflows() Data per-account workflow= null
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#processAccountWorkflows() Exit void
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#completeAccountReconcile() Entry arg1=com.waveset.recon.ReconResults@bd45d1, arg2=null, arg3=null
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#completeAccountReconcile() Exit void
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#applyOrDeferResponse() Exit void
20091015 10:51:51.609 reconcile.cn=jedi three,cn=Users,dc=atac,dc=ebay,dc=sun,dc=com@AD(0x01a96e7f) ReconTask$WorkerThread#reconcileAccount() Exit void

_________________________________________________________________________________

Gateway Trace:

While all this is occuring it is going through the gateway. I captured this in a gateway trace:

10/15/2009 10.51.44.390000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,9713):  attrName='distinguishedName'  attrValue='CN=jedi three,CN=Users,DC=atac,DC=ebay,DC=sun,DC=com'

10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,7807): doing open object
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,5137): Enter: openObject
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,2527): Enter: getIdentity(obj,result)
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,2564): Enter: getIdentity
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,2627): Exit: getIdentity
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,2628):     return value: 'LDAP://CN=jedi three,CN=Users,DC=atac,DC=ebay,DC=sun,DC=com'
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,2551): Exit: getIdentity(obj,result)
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,5152): Enter: openObject - 1
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,5162): Enter: openObject - 2
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,4734): Enter: login(wstring\*\*,EncyptedData\*\*,wstring\*\*,WavesetResult&)
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,4716): Enter: login(wstring\*\*,EncyptedData\*\*,wstring\*\*,bool,HANDLE\*,TOKEN_TYPE,WavesetResult&)
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/object/Extension.cpp,34): Enter: getRequiredResAttrValue
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/object/Extension.cpp,44): Exit: getRequiredResAttrValue
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/object/Extension.cpp,34): Enter: getRequiredResAttrValue
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/object/Extension.cpp,44): Exit: getRequiredResAttrValue
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,4727): Login: 1
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,4728): Exit: login(wstring\*\*,EncyptedData\*\*,wstring\*\*,bool,HANDLE\*,TOKEN_TYPE,WavesetResult&)
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,4737): Login: 1
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,4738): Exit: login(wstring\*\*,EncyptedData\*\*,wstring\*\*,bool,HANDLE\*,TOKEN_TYPE,WavesetResult&)
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,5176): ADsGetObject for LDAP://CN=jedi three,CN=Users,DC=atac,DC=ebay,DC=sun,DC=com
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/connect/RAEncryptor.cpp,69): RAEncryptor::Decrypt3DES: input length (16) moded to 2
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,5190): ADsGetObject
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/object/Extension.cpp,73): Enter: getOptionalResAttrValue
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/object/Extension.cpp,77): Exit: getOptionalResAttrValue
10/15/2009 10.51.46.593000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,7447): buildBindOptions bind flag = 0x1
10/15/2009 10.51.46.750000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,5266): Exit: openObject - 2
10/15/2009 10.51.46.750000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,5155): Exit: openObject - 1
10/15/2009 10.51.46.750000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,5146): Exit: openObject
10/15/2009 10.51.46.750000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,6506): Enter: buildObject
10/15/2009 10.51.46.750000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,6535): build Object IADs Class: user
10/15/2009 10.51.46.750000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,6925): Getting attr: name: 'sAMAccountName'
10/15/2009 10.51.46.781000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,344): string attribute

10/15/2009 10.51.46.781000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,6994): relativeName allocated: 1520E4
10/15/2009 10.51.46.781000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,11840): Enter: getTerminalServicesAttrs
10/15/2009 10.51.46.781000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,11874): Exit: getTerminalServicesAttrs
10/15/2009 10.51.46.781000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,7103): relativeName freed: 1520E4
10/15/2009 10.51.46.781000 [3012] (../../../../src/wps/agent/adsi/ADSIExtension.cpp,7111): Exit: buildObject

10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68):   <obj name='CN=jedi three' identity='CN=jedi three,CN=Users,DC=atac,DC=ebay,DC=sun,DC=com'>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68): <Attributes>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68):   <Attribute name='accountId' type='string' ordered='false' value='CN=jedi three'>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68):   </Attribute>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68):   <Attribute name='objectGUID' type='string' ordered='false' value='91d548204b49fe4e8d0eaf77f5799085'>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68):   </Attribute>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68):   <Attribute name='sAMAccountName' type='string' ordered='false' value='jedi3'>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68):   </Attribute>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68): </Attributes>
10/15/2009 10.51.49.359000 [3012] (../../../../src/wps/agent/object/RequestHandler.cpp,68):   </obj>

What you should see when Recon finishes:

Now after all this is done you should see ReconResults. You can see this also by going into view recon status. This is from a trace of com.waveset.recon .  

20091015 09:30:36.843 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Entry arg1=requestTime
20091015 09:30:36.843 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Exit returned= 1255618765609
20091015 09:30:36.843 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Entry arg1=startTime
20091015 09:30:36.843 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Exit returned= 1255618770203
20091015 09:30:36.843 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Entry arg1=finishTime
20091015 09:30:36.843 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Exit returned= 1255619015765

This is what a typical error would look like:

20091015 09:30:36.843 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Exit returned= [ Failed to create a new user based on resource account cn=qwert3773hh\\#55jjll890-0\\#$\\#uh test,dc=atac,dc=ebay,dc=sun,dc=com@AD: &amp;#xA;Policy Violation (accountId:'jjg$#3667willoijnndy' on Lighthouse User):&amp;#xA;Maximum length is 16.., Failed to create resource account cn=vOrjvzr wGlomOsxQce,cn=users,ou=Jeff1,dc=atac,dc=ebay,dc=sun,dc=com@AD for user ajiMkq176: &amp;#xA;Error opening container 'LDAP://dc=com/dc=sun/dc=ebay/dc=atac/ou=Jeff1/cn=users': ADsOpenObject(): 0X80072030: , 0000208D: NameErr: DSID-031001BD, problem 2001 (NO_OBJECT), data 0, best match of:&amp;#xA;&amp;#x9;'OU=Jeff1,DC=atac,DC=ebay,DC=sun,DC=com'&amp;#xA;, There is no such object on the server.&amp;#xD;&amp;#xA;. ]

20091015 09:30:36.921 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Entry arg1=statistics.usersQueued
20091015 09:30:36.921 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Exit returned= 648
20091015 09:30:36.921 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Entry arg1=statistics.usersExamined
20091015 09:30:36.921 http-8080-Processor20(0x0058213c) ReconResults#getAttribute() Exit returned= 648

Image of Recon Results

Some questions I have had in the past are :

1. Under what conditions does reconciliation fail?

Recons fail when the recon exceed it maximium error count. This is listed in your recon profile under "error Limit" by default this is set to 100 . So basically when you hit 100 errors recon with terminate. This can be changed but it depends on what you think is an acceptable level.

Recons can also fail some errors are fatal to recon, IDM, or the JVM. An example is a java.lang.OutOfMemory error. Once that occurs, the JVM cannot recover. These errors will have to be addressed based on the specific nature of the error. For example, java.lang.OutOfMemory error may require you to simply increase the allotted JVM memory. Not all exceptions are fatal to recon (in fact, most aren't), so be sure to determine that recon didn't actually abnormally end and simply didn't capture an error and continue processing. A prime indication that recon abnormally terminated is that recon is no longer processing, but the TaskResult object has incomplete data.

Other things that can happen are.

    1. Recon not stopping

They can get stuck in an endless loop. To check this enable method tracing on com.waveset.recon, level 2. Look for a pattern of the same set of methods being called over and over again with no apparent change.

    2. Recon getting stuck waiting on the resource.

If you don't see the examineResource exit then it is stuck on the Resource side. Another thing to check is for the "numAccountsRead" which will show the number of accounts read from the resource. If this isn't present, recon is waiting for the list of accounts from the resource.

If #examineResource exits, then recon is mostly done with the resource. Any other resource interaction will be done when creating MISSING accounts based off of the IDM user. You can see this in the com.waveset.recon.ReconTask.ResourceThread#queueAccountReconciles

If you determine the resource is holding recon up, the problem likely lies with the resource. If the problem is during the account listing, adjusting the resource block count or the recon timeouts may be needed. If recon is hanging during this portion, it's possible that other account iteration tasks will hang as well. You can confirm that by attempting other operations like "Extract to File" from the specific resource. See the resource account iteration for more tips.

If the problem is during the account reconciliations, look for a pattern such as always hanging on the same account or same IDM user. Additional tracing on the resource may yield additional information.

Some other thing that would cause the recons to be slow can be caused by the resource being to slow or the repository being to slow as well.

    3. To confirm the Recon has started

Don't go by the status displayed in the recon status screen because it may be simply not updating.

There are several ways to confirm that reconciliation has actually started:


1. Use http://baseUrl/idm/debug/Show_Reconciler.jsp to see if any activity is occurring in reconciliation.
2. Examine the Task Result object at least three or four times. Each examination, compare the running statistics to ensure the values are growing. Growing values mean recon is running.
3. Enable method tracing for com.waveset.recon on level 4. It should take no time to see the log file filling up with recon trace messages if recon is running during any phase of recon.

    4. To confirm Recon has stopped.

Look for the "finishTime" and also the "reconProcessingDuration" both of these will always show up for a completed recon. If it is incomplete these lines will not be present.

Another thing I like to look for is an exit() method called for the reconcileResource method. If it doesn't show, recon may still be running.

One other thing to check is the scheduler to see if it is running. To do this enable Scheduler trace and look for the event cycles and ready task cycles every few seconds or so in the application server's stdout log. If these do not show up, then the scheduler isn't running.

2. Whenever reconciliation fails, where do we check for the logs to find out RCA?

Errors being thrown can cause the TaskResult or TaskInstance object build up causing a slow-down. Just the act of handling the exceptions can sometimes slow down recon.

1. Error messages from reconcile are often stored in the TaskInstance object or the Task Result object. Examine these objects for errors.
2. The application server's standard out or standard error log may also contain thrown exceptions.
3. Resolve any captured errors and see if recon performance improves.

The key here also is to match up the task result to the task Instance .

TaskResult items do not have a "human friendly" name. It's often in the form of Recon:#ID#F7E9F0E926FF0856:18E261D:1119A991422:-7FFE. While it's obvious that this TaskResult object is for a reconcile activity, it's not immidiately clear for which recon it is for. To determine that, you must instead start by knowing what TaskInstance is used for the reconcile. The TaskInstance object will be named 'Reconciler server' where 'server' is the name of the IDM instance that the Reconcilliation executed on. Once that is known, you only need to view the TaskResult objects with names that begin with 'Recon:' and look for a line simliar to:

<TaskInstanceRef>
   <ObjectRef type='TaskInstance' id='#ID#F7E9F0E926FF0856:1C85444:1119A96D7DE:-7FFF' name='Reconciler server'/>
</TaskInstanceRef>


3. Do we need to enable tracing to troubleshoot reconciliation at all times?

No, see above. It does help when you don't see anything in the application server logs and the task results. The best things to trace are com.waveset.recon and tracing the scheduler  by going into the debug page and turning it on by selecting trace scheduler.

Well I know this is a lot of information and probably should have been broke up in to a part 3 . I hope you find this useful and use it. Until next time.

                          Jeff

Comments:

Post a Comment:
  • HTML Syntax: NOT allowed
About

I have been in support for about 10 years now and have been doing IDM support for 5 years now. I have been working for SUN for 9 years and have supported the whole JES Stack during that time.

Search

Categories
Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today