Requests freezing on PostProcessing and Validated

I’ve had a head scratcher in the last week. A Dev environment, everything thought to be working perfectly according to the tests we’d done so far, which had just involved a few identities at a time. But then we tried to do some bulk tests, registering 300 people at once, and things did not go well. It would get through 20 or 30 of them and then the requests queue just seemed to freeze. The Portal was still responsive but the number of requests sitting in PostProcessing and Validated status did not change, even when left overnight.

I thought it had something to do with the “Generate Unique Value” custom workflow I was using. I was generating unique values for both AccountName and MailNickname, with checks against both the Portal and AD. A lot of the requests seemed stuck on one of these steps. I replaced the workflow with a PowerShell activity – but exactly the same thing happened.

The Problem

I’ll go straight to what the root problem was, and I had to get some help from Microsoft for this – the problem is trying to query the FIM Service database for uniqueness while at the same time updating exactly the attribute it is trying to query. So I’m doing hundreds of queries like “/Person[AccountName=’value’]” while at the same time updating AccountName on multiple objects. Effectively my query is trying to hit a moving target, and the result is SQL deadlocking.

Now why it got itself in such a mess it had to stop so completely I don’t know, and the low spec of the Dev servers probably didn’t help (though the problem still occurred after we had the RAM increased on both FIM and SQL servers).

The Solution

The solution, for me anyway, is not to generate unique values in the Portal but go back to my tried and tested method of doing it as part of classic rules extensions with a lookup against the Metaverse and AD. This was supposed to be an all Declarative design, but if the result is a risk of deadlocking then the provisioning Sync Rule, at least, has had to go.

Troubleshooting

Some observations:

• Restarting the FIM Service would get the queue moving again, but just for a short while then it would freeze again.
• Restarting both the FIM Service and SQL had a better result in getting things moving – presumably because all the deadlocks disappeared.
• There was a mysterious KeyNotFoundException error in the Event Log that I’d been seeing for a while and it never seems to correspond to any errors in the Portal.
  • This turned out (thanks to Jeff who commented below) to be a bug caused by not implementing the new HideAdvancedSearchLink attribute a binding as described here: http://support.microsoft.com/kb/2906832. It had nothing to do with the requests queue freezing.

Here are some events I noticed when I turned on Verbose logging:

Level: Information
Description:
RequestDispatcher is processing RequestIdentifier ‘f3d76d22-6c6c-4a51-b3ef-85d2e76966c1’ for a ‘Enumerate’ operation on object ” with RequestStatus ‘Authorized’.

Level: Information
Description:
WS: Action.Enumerate.Execute.Enter

Level: Information
Description:
Query: QueryProcessor.ExecuteQuery.ExecuteReader.Enter

Level: Information
Description:
Request ‘f3d76d22-6c6c-4a51-b3ef-85d2e76966c1’ status was updated in-memory from ‘Authorized’ to ‘Denied’.

Level: Information
Description:
RequestIdentifier ‘f3d76d22-6c6c-4a51-b3ef-85d2e76966c1’ exited RequestDispatcher with RequestStatus ‘Denied’.

Level: Information
Description:
WS: Enumerate:UnwillingToPerform