MIM full import returns changes missed from recent delta imports

Hi Bob, looking into this now. Can you upload the extensibility files? Just to clarify, the changes not being picked up by the delta sync are all new entities that should be provisioned in MIM, updates to existing entities or both?

Thanks Beau - extensibility uploaded to linked JIRA ticket. The missing objects are all new entities that don't appear in MIM until an adapter full import is run - because the delta appears to be picking up the MOD but not the ADD.

Curtis - I think we need to up the stakes on this one now. Have you any updates on the approach you have been designing since we spoke last week? Thanks.

Has anything changed to make this more urgent, or is it just time-based escalation?

Did you hear back from the customer regarding the SQL backup process?

Without more information to go on, there's not much that would give me confidence in any single potential code change to fix the issue. You mentioned before that this is happening regularly (adds not imported via DI but then imported via subsequent FI). Are you noticing this happening on every single FI or every second one? Would you be able to increase the frequency of the scheduled FIs to help us understand if the timing correlates with anything else in the environment (connector imports, backups, etc.)?

Curtis - yes this is indeed a time-based escalation due to the fact that there is now further evidence of the problem persisting (see the last comment for the related JIRA ticket here).

There had been no response to my email to Scott so I have just been on the phone with him explaining everything is in shutdown mode and not taking calls. The general response is that Enterprise software should be resilient enough NOT to lose data if SQL timeouts are experienced - the exact response we got from Origin.

Hi Bob,

I noticed that the Changes Available operation is logged in Identity Broker as Verbose, so it should be appearing in your log files but it isn't appearing even once. There should be corresponding log entries in the Event Broker logs as Verbose as well. Could you please try changing the logging level of the Core Log Writer in EB (or configuring a new log writer) to pick up the log entries?

Curtis - have just changed this to Verbose - file is spinning wildly now - presume you want me to look at this tomorrow after the nightly restart?

Hi Bob,

No I didn't just change this, it should already be logging on verbose without a patch or restart. Just leave it on Verbose until the operation list in Event Broker which triggers the Identity Broker Changes check operation runs on its next scheduled run, and then send through the logs. I just want to make sure it's executing okay.

Curtis - verbose log files from both EvB and IdB attached to QBE-51 (Voice refuses to allow me to attach a ZIP file here - throws an exception saying archives not supported). You will no doubt be able to do this though.

I will switch EvB back from verbose to normal mode again now, but will leave IdB in verbose mode - not sure what you thought I was going to do.

Thanks Bob,From the log files there are 3510 instances of the Identity Broker Changes operation executing, and from that there are 124 instances that it returned True. For each such instance there is a corresponding DI operation execution. Is this reflected by the run history in MIM?

I should add that the first such instance occurred at 05:40:09UTC and the last such at 23:52:40UTC.

$startDate = [DateTime]::Parse("16/01/2017 11:00:00 AM")

$endDate = [DateTime]::Parse("17/01/2017 11:00:00 AM")

$rps1 = Get-RunSummary -MA "License Entitlements"

$rps2 = Get-RunSummary -MA "License Assignments"

($rps1 | Where-Object {[DateTime]$_.StartTime -ge $startDate -and [DateTime]$_.StartTime -le $endDate}).Count

($rps2 | Where-Object {[DateTime]$_.StartTime -ge $startDate -and [DateTime]$_.StartTime -le $endDate}).Count

Result:

132

284

I need to refine the above further - only want the "DI" run profiles ...

# Load the PS module
Import-Module LithnetMIISAutomation

$startDate = [DateTime]::Parse("16/01/2017 11:00:00 AM")
$endDate = [DateTime]::Parse("17/01/2017 11:00:00 AM")

$rps1 = Get-RunSummary -MA "License Entitlements" | Where-Object {$_.RunProfileName -in @("DI")}
$rps2 = Get-RunSummary -MA "License Assignments" | Where-Object {$_.RunProfileName -in @("DI")}

($rps1 | Where-Object {[DateTime]$_.StartTime -ge $startDate -and [DateTime]$_.StartTime -le $endDate}).Count
($rps2 | Where-Object {[DateTime]$_.StartTime -ge $startDate -and [DateTime]$_.StartTime -le $endDate}).Count

Results:

66
89

Curtis - there was an EvB operation list which was set up to run a FI/DS on each of the 2 IdB MAs every 4 hours, but this was last run on January 4 and has since been disabled - I suspect due it not being correctly re-activated after a Safety Catch was triggered. In enabling it just now (with no pending changes for either IdB connector having been picked up), I am now seeing a large number of changes coming through for the License Entitlements MA (1 add, 236 mods, 23 deletes, 45,374 unchanged - narrowly avoiding triggering the safety catch - resulting in a net 215 pending license changes to AAD). The Assignments MA is equally picking up a significant number of AAD changes (1 add, 63 updates, 1 delete, 45,484 unchanged).

I think that means definitely yes - we still have the problem of missing changes when relying only on MIM delta imports.

Given there has been no failure in the last 24 hours I have just turned off the scheduled 1 AM recycle of the IdB service - will go back to monitoring for the problem each day now.

Last night a MIM FI step ran at 2:17:36 and completed about 5 minutes later, picking up 60 adds, 62 updates and 23 deletions. Prior to that the DI step was repeatedly failing with a stopped-dll-exception, seemingly implying a problem with the waternark search (cleared by the full import). Logs attached:

UnifyLog20170214.zip

The full import is designed to resolve issues with the watermark. It's only an issue if the delta never works, in which case a support case should be raised with Microsoft (we have another site where this behaviour is being exhibited - the watermark gets lost by MIM). See the following issues for details:

• http://voice.unifysolutions.net/topics/2737-identity-broker-for-mim-watermark-functioanlity-enhancement/
• http://voice.unifysolutions.net/topics/2833-not-saving-watermark-leading-to-delta-imports-failing/

Any update on this Bob?

Adam - just returned from 8 weeks away today :).  No update, but the 2 issues you referred to (plus a new one) are entirely consistent with my experience at QBE (i.e. deltas alone are unreliable, usually but not necessarily exclusively after a staging error has occurred).  Andrew seems to think this is an MS issue with the way the watermark is stored by default (??) and if so I would welcome the suggested alternative ... since regular full imports are always a significant overhead, and at places like DETE and TAFE could in fact not be feasible.

I recall the missing delta changes were explained by the restart - where the restart was happening before the change entries were committed. Or are you now suggesting that there is another cause? If so, please provide the evidence and analysis so that we can look at what can be done.

Regarding the MIM bug with the watermark, this should be raised with Microsoft as mentioned.

Any evidence of another cause for the missed changes?

P.S. entirely understand that a FI is best practice where there is always the remotest chance of a DI failure.  However in this case there seems to be a major issue with the DI such that the DI is basically unreliable - i.e. the rule rather than the exception.