FIM 2010 R2: SQL timeout on using large sets in other sets

Last week a strange error appears in my environment, I was adding the All expected rule resources set to another set to give read permissions to operational admins, so that they can see the EREs on the provisioning tab of user resources. I build a set for these operational admins containing all resources that they should have read access to, in that set I include serveral objecttypes like teams and groups and also the above sets which has large amount of members.

Here is the set I’m trying to build:

EditSetError2

I do this directly in production, and all went fine, however to don’t break my deployment through the 3 stages (dev, test, prod) I also try to make this change in my other 2 environments, but then I their I got an Postprocessing Error.

I have to say that all 3 environments running on identical physical machines, with nearly the same configuration. (Windows Server 2008 R2, SQL2008R2 and FIM 2010 R2 SP1).

Here is the error I got in portal:

EditSetError1

Error processing your request: The server was unwilling to perform the requested operation.
Reason: Unspecified.
Attributes:
Correlation Id: 1292580b-150f-4921-9beb-c8761476787e
Request Id:
Details: Request could not be dispatched.

I figured out that there are also 2 errors in FIM Eventlog:

.Net SqlClient Data Provider: System.Data.SqlClient.SqlException: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection)
   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj)
   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)
   at System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
   at System.Data.SqlClient.SqlDataReader.get_MetaData()
   at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
   at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, DbAsyncResult result)
   at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
   at System.Data.SqlClient.SqlCommand.ExecuteReader()
   at Microsoft.ResourceManagement.Data.DataAccess.DoRequestCreation(RequestType request, Guid cause, Guid requestMarker, Boolean doEvaluation, Int16 serviceId, Int16 servicePartitionId)

and this:

Requestor: urn:uuid:7fb2b853-24f0-4498-9534-4e10589723c4
Correlation Identifier: 1292580b-150f-4921-9beb-c8761476787e
Microsoft.ResourceManagement.WebServices.Exceptions.UnwillingToPerformException: Other ---> System.Data.SqlClient.SqlException: Timeout expired. The timeout period elapsed prior to completion of the operation or the server is not responding.
at Microsoft.ResourceManagement.WebServices.RequestDispatcher.CreateRequest(UniqueIdentifier requestor, UniqueIdentifier targetIdentifier, OperationType operation, String businessJustification, List`1 requestParameters, CultureInfo locale, Boolean isChildRequest, Guid cause, Boolean doEvaluation, Nullable`1 serviceId, Nullable`1 servicePartitionId, UniqueId messageIdentifier, UniqueIdentifier requestContextIdentifier, Boolean maintenanceMode)
at Microsoft.ResourceManagement.WebServices.ResourceManagementService.Put(Message request)
--- End of inner exception stack trace ---

I found out that the request is taking more time than the SQL timeout configured in FIM Service, which is 58 seconds by default. But why only in dev and test and not in production.

Sadly I have an answer on this, since I don’t do further debugging with SQL profiler, as the following changes to the FIM Service configuration file resolves the issue.

To extend the timeout modify the FIM service configuration file Microsoft.ResourceManagement.Service.exe.config by adding the both timeout parameter:

<resourceManagementService externalHostName="myfimservice" dataReadTimeoutInSeconds="1200" dataWriteTimeoutInSeconds="1200"/>

These parameters are also documented within the config file.

I’ve tried the value 120 and 300 first but the request seems to take longer, after that I decided to use value 1200. After the request completed I could see the request takes more than 6 minutes to complete. In production it could complete within the 58 seconds timeout. Very strange behavior.

However after extending the timeout and restart FIM Service the portal will still present you a timeout but the request will complete in background, you can check this in request history. There is also a possibility to extend this timeout in portal by changing the web.config, but for me that was not necessary.

Beside getting rid of that error there are still 2 question i could not answer myself:

1. Why did that affect dev and test but not production (having in mind the environments are identical) ?

2. What takes so long to add a set to another set, even it has a large amount of members ?

If you could answer one or both of them so please leave me a comment or mail.

 

FIM 2010 R2: Searching for Request Details in msidmCompositeType

With Forefront Identity Manager 2010 R2 Microsoft add some performance modifications to Service and Portal. By default exports from the FIM Management Agent are batched (aggregated) up to 1000 changes. So in request details you may see only an Update to msidmCompositeType ‘’ Request which includes all the changes of maybe multiple objects in the RequestParameter attribute.

Craig has also post a short description on how to deal with this objecttype.

Since this is very good for performance on exports, it is very bad for searching changes in the request log in portal. In my environment I even see changes that seems to be only relevant to one object, holding changes to multiple objects. In this particular case the requests display name is Update to msidmCompisiteType ‘myuser’ Request, but in the RequestParameter attribute I also found changes to other objects.

While you cannot actually searching the request log for changes to a specific object, especially with the new batch object type, I’ve decided to create a little script for this in PowerShell of course.

The script is based on the FIMAutomation snap-in and also the FIM PowerShell Module from Craig. Because I missed some attribute in output of the Get-FIMRequestParameter cmdlet I have modified this a little bit.

Giving an objectType, attribute and value to search, the script will retrieve all changes to this object searching all direct/single requests and also all batched updates.

To use this script you must in addition to install the FIMPowerShellModule modify the FIMPowerShellModule.psm1 file like below. I’ve only added the Mode and Target properties to the output of the Get-FIMRequestParameter function.

$RequestParameter | foreach-Object{
    New-Object PSObject -Property @{
        Mode = ([xml]$_).RequestParameter.Mode
	Target = ([xml]$_).RequestParameter.Target
        PropertyName = ([xml]$_).RequestParameter.PropertyName
        Value = ([xml]$_).RequestParameter.Value.'#text'
        Operation = ([xml]$_).RequestParameter.Operation
     } |
     Write-Output

Here is my PowerShell Script, see also comments inside the code:

param($objectType, $attribute, $searchValue)
#objectType = The objectType of the target object you are trying to get requests for.
#attribute = The attribute of the target object you want to use for searching
#searchValue = The value of the attribute of the target object you are searching requests for
#
#ex. Get-FIMRequestDetails.ps1 -objectType "Person" -attribute "AccountName" -searchValue "pstapf"
#
#This gets all requests matching the given target object.

# Load FIMAutomation SnapIn and FIMPowershellModule (http://fimpowershellmodule.codeplex.com)
if(@(get-pssnapin | where-object {$_.Name -eq "FIMAutomation"} ).count -eq 0) {add-pssnapin FIMAutomation}
Import-Module C:\Windows\System32\WindowsPowerShell\V1.0\Modules\FIM\FIMPowerShellModule.psm1

# Check if the object you are searching requests for exists in portal and get its GUID
$filter = "/" + $objectType + "[" + $attribute + "=" + $searchValue + "]"
$searchObject = Export-FIMConfig -OnlyBaseResources -CustomConfig $filter

If ($searchObject -ne $null)
{
    $searchObjectGuid = $searchObject.ResourceManagementObject.ObjectIdentifier.Replace("urn:uuid:","")
    Write-Host "Object found:" $searchValue " with GUID:" $searchObjectGuid
}
else
{
    Write-Host "The object you are searching for does not exists in FIM Portal"
    Exit
}

# Get the aggregated requests of the object you search for
$export=@()
$filter = "/Request[Target=/msidmCompositeType[/msidmElement=/" + $objectType + "[" + $attribute + "=" + $searchValue + "]]]"
$export = Export-FIMConfig -OnlyBaseResources -CustomConfig $filter

# Get the single requests of the object you search for
$filter = "/Request[Target=/" + $objectType + "[" + $attribute + "=" + $searchValue + "]]"
$export += Export-FIMConfig -OnlyBaseResources -CustomConfig $filter
$requestlist = $export | Convert-FimExportToPSObject | Sort-Object msidmCompletedTime

# Get the RequestParameter of the object you search fo from all requests and add some requestDetails
If ($requestlist.count -gt 0)
{
    $resultItems = @()
    foreach ($requestItem in $requestList)
    {
        $resultItems += $requestItem | Get-FimRequestParameter | where { $_.Target -eq $searchObjectGuid } | ForEach-Object {
        New-Object PSObject -Property @{
            Target = $_.Target
            Operation = $_.Operation
            Mode = $_.Mode
            Attribute = $_.PropertyName
            Value = $_.Value
            RequestName = $requestItem.DisplayName
            RequestGuid = $requestItem.ObjectID.Replace("urn:uuid:","")
            CompleteTime = $requestItem.msidmCompletedTime
            Status = $requestItem.RequestStatus
            }
        }
    }
    $resultItems

}
else
{
    Write-Host "No request found for the object you searched for."
}

Using Notes:

Script output is PSObject, so you can pipe the output to many other cmdlets, like Out-GridView or Convertto-Html for example. In addition you can filter the output by date also on your own.

Out-GridView is a very neat cmdlet for this, as you can show/hide columns and also do some basic filtering, try a Status:Completed filter for example.

OutGridView

Here is also some output with ConverTo-Html with some basic CSS:

OutHtml