October 20, 2013 6 Comments
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:
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:
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)
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.