SOLVED

Searching Audit log Strange Behavior

%3CLINGO-SUB%20id%3D%22lingo-sub-2079399%22%20slang%3D%22en-US%22%3ESearching%20Audit%20log%20Strange%20Behavior%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-2079399%22%20slang%3D%22en-US%22%3E%3CP%3EBack%20in%20October%2C%20I%20created%20a%20script%20that%20dumps%20Daily%20Microsoft%20Stream%20Audit%20data%20into%20CSVs%20so%20that%20PowerBI%20Reports%20can%20be%20created.%20It%20was%20working%20fine%20until%20the%2016th%20of%20December%20and%20now%20seems%20to%20be%20very%20inconsistently%20returning%201000s%20of%20duplicate%20records%20with%20a%20ResultIndex%20of%20-1.%20A%20correct%20return%20of%20data%20usually%20returns%20a%20ResultIndex%20going%20from%201%20to%20however%20many%20records.%20Does%20anyone%20know%20why%20this%20may%20be%20occurring%3F%3C%2FP%3E%3CP%3E%26nbsp%3B%3C%2FP%3E%3CP%3E%26nbsp%3B%3C%2FP%3E%3CPRE%20class%3D%22lia-code-sample%20language-applescript%22%3E%3CCODE%3EDo%20%7B%20%0A%20try%7B%0A%20%20%20%20%20%20%20%20%24currentResults%20%3D%20Search-UnifiedAuditLog%20-StartDate%20%24startDate%20-EndDate%20%24enddate%20-SessionId%20%24sessionName%20-SessionCommand%20ReturnLargeSet%20-ResultSize%201000%20-RecordType%20MicrosoftStream%20-Operations%20StreamCreateVideo%2CStreamEditVideo%2CStreamDeleteVideo%2CStreamInvokeVideoUpload%2CStreamInvokeVideoDownload%2CStreamEditVideoPermissions%2CStreamInvokeVideoView%2CStreamInvokeVideoShare%2CStreamInvokeVideoLike%2CStreamInvokeVideoUnLike%2CStreamCreateVideoComment%2CStreamDeleteVideoComment%2CStreamInvokeVideoTextTrackUpload%2CStreamInvokeVideoThumbnailUpload%2CStreamDeleteVideoThumbnail%2CStreamInvokeVideoMakePublic%2CStreamInvokeVideoMakePrivate%2CStreamCreateGroup%2CStreamEditGroup%2CStreamDeleteGroup%2CStreamEditGroupMemberships%2CStreamCreateChannel%2CStreamEditChannel%2CStreamDeleteChannel%0A%20%20%20%20%7Dcatch%20%5BSystem.Exception%5D%20%7B%0A%20%20%20%20%20%20%20%20%20%20%20%20%24errorCount%2B%2B%0A%20%20%20%20%20%20%20%20%20%20%20%20%24ErrorMessage%20%3D%20%22%20Error%3A%20%22%20%2B%20%24_.Exception.Message%20%0A%20%20%20%20%20%20%20%20%20%20%20%20%24logmsg%20%3D%20%24ErrorMessage%0A%20%20%20%20%20%20%20%20%20%20%20%20Write-Output%20%24logmsg%0A%20%20%20%20%20%20%20%20%20%20%20%20LogToFile%20-EntryType%20%22ERROR%22%20-Message%20%24logmsg%20-Logfile%20%24lgfile%0A%20%20%20%20%7D%0A%20if%20(%24currentResults.Count%20-gt%200)%20%7B%0A%20%20%20%20%20%20%20%20%24logmsg%20%3D%20(%22%20%20Finished%20search%20%23%7B1%7D%2C%20%7B2%7D%20records%3A%20%7B0%7D%20min%22%20-f%20%5Bmath%5D%3A%3ARound((New-TimeSpan%20-Start%20%24scriptStart).TotalMinutes%2C4)%2C%20%24i%2C%20%24currentResults.Count%20)%0A%20%20%20%20%20%20%20%20Write-Output%20%24logmsg%0A%20%20%20%20%20%20%20%20LogToFile%20-EntryType%20%22INFORMATION%22%20-Message%20%24logmsg%20-Logfile%20%24lgfile%0A%20%20%23%20Accumulate%20the%20data%0A%20%20%24aggregateResults%20%2B%3D%20%24currentResults%20%23Adds%201000%20records%20at%20a%20time%0A%20%20%23%20if%20the%20results%20are%20below%201000%20then%20its%20time%20to%20stop%20the%20loop%0A%20%20if%20(%24currentResults.Count%20-lt%201000)%20%7B%0A%20%20%20%24currentResults%20%3D%20%40()%0A%20%20%7D%20else%20%7B%0A%20%20%20%24i%2B%2B%0A%20%20%7D%0A%20%7D%0A%7D%20Until%20(%24currentResults.Count%20-eq%200)%20%23%20---%20End%20of%20Session%20Search%20Loop%20---%20%23%3C%2FCODE%3E%3C%2FPRE%3E%3CP%3E%26nbsp%3B%3C%2FP%3E%3CP%3E%26nbsp%3B%3C%2FP%3E%3C%2FLINGO-BODY%3E%3CLINGO-LABS%20id%3D%22lingo-labs-2079399%22%20slang%3D%22en-US%22%3E%3CLINGO-LABEL%3EAdmin%3C%2FLINGO-LABEL%3E%3CLINGO-LABEL%3ECompliance%3C%2FLINGO-LABEL%3E%3CLINGO-LABEL%3EOffice%20365%3C%2FLINGO-LABEL%3E%3C%2FLINGO-LABS%3E%3CLINGO-SUB%20id%3D%22lingo-sub-2081657%22%20slang%3D%22en-US%22%3ERe%3A%20Searching%20Audit%20log%20Strange%20Behavior%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-2081657%22%20slang%3D%22en-US%22%3E%3CP%3E%3CA%20href%3D%22https%3A%2F%2Ftechcommunity.microsoft.com%2Ft5%2Fuser%2Fviewprofilepage%2Fuser-id%2F359502%22%20target%3D%22_blank%22%3E%40swhitestrath%3C%2FA%3E%26nbsp%3BI've%20noted%20some%20issues%20with%20audit%20log%20retrieval%20recently%20too.%20Best%20idea%20is%20to%20log%20a%20support%20incident.%20If%20you%20don't%2C%20no%20engineer%20will%20ever%20look%20to%20figure%20out%20what's%20going%20wrong.%3C%2FP%3E%3C%2FLINGO-BODY%3E%3CLINGO-SUB%20id%3D%22lingo-sub-2097102%22%20slang%3D%22en-US%22%3ERe%3A%20Searching%20Audit%20log%20Strange%20Behavior%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-2097102%22%20slang%3D%22en-US%22%3E%3CP%3E%3CA%20href%3D%22https%3A%2F%2Ftechcommunity.microsoft.com%2Ft5%2Fuser%2Fviewprofilepage%2Fuser-id%2F64%22%20target%3D%22_blank%22%3E%40Tony%20Redmond%3C%2FA%3E%26nbsp%3BI%20have%20opened%20a%20ticket%20with%20Microsoft%2C%20will%20update%20if%20they%20come%20back%20with%20anything.%20In%20the%20mean%20time%20I%20have%20just%20updated%20my%20code%20to%20check%20for%20this%20-1%26nbsp%3B%20ResultIndex%20and%20if%20its%20detects%20it%2C%20it%20waits%202%20mins%20and%20tries%20the%20command%20again.%26nbsp%3B%3C%2FP%3E%3C%2FLINGO-BODY%3E%3CLINGO-SUB%20id%3D%22lingo-sub-2097371%22%20slang%3D%22en-US%22%3ERe%3A%20Searching%20Audit%20log%20Strange%20Behavior%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-2097371%22%20slang%3D%22en-US%22%3E%3CP%3E%3CA%20href%3D%22https%3A%2F%2Ftechcommunity.microsoft.com%2Ft5%2Fuser%2Fviewprofilepage%2Fuser-id%2F359502%22%20target%3D%22_blank%22%3E%40swhitestrath%3C%2FA%3E%26nbsp%3B%20Just%20to%20be%20sure%20I%20understand%2C%20you%20see%20-1%20returned%20in%20the%20search%20results%20as%20in%20%24currentresults%5B0%5D.resultindex%3F%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EThis%20makes%20sense%20because%20ResultIndex%20tracks%20the%20position%20of%20the%20search%20in%20terms%20of%20retrieved%20results...%20So%20-1%20gives%20you%20an%20indication%20that%20the%20search%20results%20returned%20aren't%20good.%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3EQuestion%3A%20When%20you%20resume%2C%20does%20ResultIndex%20recommence%20at%20the%20right%20value%3F%20For%20instance%2C%20let's%20assume%20that%20you%20have%20retrieved%203000%20records%20so%20far%2C%20the%20first%20record%20returned%20by%20the%20next%20successful%20call%20should%20have%20a%20value%20of%203001%20in%20ResultIndex.%20Is%20that%20what%20you%20see%3F%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%0A%3CP%3E%26nbsp%3B%3C%2FP%3E%3C%2FLINGO-BODY%3E%3CLINGO-SUB%20id%3D%22lingo-sub-2097387%22%20slang%3D%22en-US%22%3ERe%3A%20Searching%20Audit%20log%20Strange%20Behavior%3C%2FLINGO-SUB%3E%3CLINGO-BODY%20id%3D%22lingo-body-2097387%22%20slang%3D%22en-US%22%3E%3CP%3E%3CA%20href%3D%22https%3A%2F%2Ftechcommunity.microsoft.com%2Ft5%2Fuser%2Fviewprofilepage%2Fuser-id%2F64%22%20target%3D%22_blank%22%3E%40Tony%20Redmond%3C%2FA%3E%26nbsp%3BI%20just%20reset%20everything%20and%20try%20again%20so%20the%20index%20returns%20to%201.%20The%20second%20time%20is%20usually%20successful.%26nbsp%3B%3C%2FP%3E%3CPRE%20class%3D%22lia-code-sample%20language-applescript%22%3E%3CCODE%3Eif(%24currentResults%5B0%5D.ResultIndex%20-eq%20%22-1%22%20-or%20%24currentResults%20-eq%20%24null)%7B%0A%20%20%20%20%20%20%20%20%20%20%20%20%24sessionName%20%3D%20(get-date%20-Format%20'u')%2B'streamauditlog'%2B%20%24i%0A%20%20%20%20%20%20%20%20%20%20%20%20%24aggregateResults%20%3D%40()%0A%20%20%20%20%20%20%20%20%20%20%20%20if(%24currentResults%5B0%5D.ResultIndex%20-eq%20%22-1%22)%7B%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20%20%20%24logmsg%20%3D%20%22-1%20Index%20Found%20Loop%20Restarted%22%0A%20%20%20%20%20%20%20%20%20%20%20%20%7D%0A%20%20%20%20%20%20%20%20%20%20%20%20if(%24currentResults%20-eq%20%24null)%7B%0A%20%20%20%20%20%20%20%20%20%20%20%20%20%20%20%20%24logmsg%20%3D%20%22No%20Results%20returned%2C%20retrying...%22%0A%20%20%20%20%20%20%20%20%20%20%20%20%7D%0A%20%20%20%20%20%20%20%20%20%20%20%20%24errorCount%2B%2B%0A%20%20%20%20%20%20%20%20%20%20%20%20LogToFile%20-EntryType%20%22ERROR%22%20-Message%20%24logmsg%20-Logfile%20%24lgfile%0A%20%20%20%20%20%20%20%20%20%20%20%20Start-Sleep%20-s%20120%0A%20%20%20%20%20%20%20%20%20%20%20%20continue%0A%20%20%20%20%20%20%20%20%7D%3C%2FCODE%3E%3C%2FPRE%3E%3CP%3E%26nbsp%3B%3C%2FP%3E%3C%2FLINGO-BODY%3E
Occasional Contributor

Back in October, I created a script that dumps Daily Microsoft Stream Audit data into CSVs so that PowerBI Reports can be created. It was working fine until the 16th of December and now seems to be very inconsistently returning 1000s of duplicate records with a ResultIndex of -1. A correct return of data usually returns a ResultIndex going from 1 to however many records. Does anyone know why this may be occurring?

 

 

Do { 
	try{
        $currentResults = Search-UnifiedAuditLog -StartDate $startDate -EndDate $enddate -SessionId $sessionName -SessionCommand ReturnLargeSet -ResultSize 1000 -RecordType MicrosoftStream -Operations StreamCreateVideo,StreamEditVideo,StreamDeleteVideo,StreamInvokeVideoUpload,StreamInvokeVideoDownload,StreamEditVideoPermissions,StreamInvokeVideoView,StreamInvokeVideoShare,StreamInvokeVideoLike,StreamInvokeVideoUnLike,StreamCreateVideoComment,StreamDeleteVideoComment,StreamInvokeVideoTextTrackUpload,StreamInvokeVideoThumbnailUpload,StreamDeleteVideoThumbnail,StreamInvokeVideoMakePublic,StreamInvokeVideoMakePrivate,StreamCreateGroup,StreamEditGroup,StreamDeleteGroup,StreamEditGroupMemberships,StreamCreateChannel,StreamEditChannel,StreamDeleteChannel
    }catch [System.Exception] {
            $errorCount++
            $ErrorMessage = " Error: " + $_.Exception.Message 
            $logmsg = $ErrorMessage
            Write-Output $logmsg
            LogToFile -EntryType "ERROR" -Message $logmsg -Logfile $lgfile
    }
	if ($currentResults.Count -gt 0) {
        $logmsg = ("  Finished search #{1}, {2} records: {0} min" -f [math]::Round((New-TimeSpan -Start $scriptStart).TotalMinutes,4), $i, $currentResults.Count )
        Write-Output $logmsg
        LogToFile -EntryType "INFORMATION" -Message $logmsg -Logfile $lgfile
		# Accumulate the data
		$aggregateResults += $currentResults #Adds 1000 records at a time
		# if the results are below 1000 then its time to stop the loop
		if ($currentResults.Count -lt 1000) {
			$currentResults = @()
		} else {
			$i++
		}
	}
} Until ($currentResults.Count -eq 0) # --- End of Session Search Loop --- #

 

 

11 Replies

@swhitestrath I've noted some issues with audit log retrieval recently too. Best idea is to log a support incident. If you don't, no engineer will ever look to figure out what's going wrong.

@Tony Redmond I have opened a ticket with Microsoft, will update if they come back with anything. In the mean time I have just updated my code to check for this -1  ResultIndex and if it detects it, it waits 2 mins and tries the command again. 

@swhitestrath  Just to be sure I understand, you see -1 returned in the search results as in $currentresults[0].resultindex? 

 

This makes sense because ResultIndex tracks the position of the search in terms of retrieved results... So -1 gives you an indication that the search results returned aren't good.

 

Question: When you resume, does ResultIndex recommence at the right value? For instance, let's assume that you have retrieved 3000 records so far, the first record returned by the next successful call should have a value of 3001 in ResultIndex. Is that what you see?

 

 

@Tony Redmond I just reset everything and try again so the index returns to 1. The second time is usually successful. 

if($currentResults[0].ResultIndex -eq "-1" -or $currentResults -eq $null){
            $sessionName = (get-date -Format 'u')+'streamauditlog'+ $i
            $aggregateResults =@()
            if($currentResults[0].ResultIndex -eq "-1"){
                $logmsg = "-1 Index Found Loop Restarted"
            }
            if($currentResults -eq $null){
                $logmsg = "No Results returned, retrying..."
            }
            $errorCount++
            LogToFile -EntryType "ERROR" -Message $logmsg -Logfile $lgfile
            Start-Sleep -s 120
            continue
        }

 

@swhitestrath OK, so you basically conclude that -1 says that the search is bad and irrecoverable and therefore needs to be restarted. That's fair. I wonder if you throw away the page of duplicate results, pause, and then restart the same search it might restart properly. Did you try that?

@Tony Redmond Yeah basically, it seems to only return 1 page of correct results and then the rest of the pages are a bunch of duplicate entries with this -1 result index. Always conscious it could be something I am doing at my side but when it loops back around and tries again, it is the exact same command but it works, which makes me think its more something at Microsoft end. 

@Tony Redmond I thought I would just run the command bare bones with no loops or other code and still get this -1 ResultIndex 

 

@swhitestrath You don't really have any other levers to pull, so it makes sense to reset and restart when bad data is returned. At least you have a method to figure out when you're getting information you can't use. But it would be interesting if Microsoft Support can throw any further light onto this topic.

best response confirmed by swhitestrath (Occasional Contributor)
Solution
Just thought I would give you an update on the response I got back from Microsoft Support.
"When the ResultCount is 0 or ResultIndex is -1, the search faced internal timeout.
Please ignore the results returned when the internal timeout occurs, and (wait 5 minutes then) try search again."

Pretty generic response but oh well.
Oh well, it's an answer...
Hi,
I found this thread by chance and I too have noticed duplicate records when exporting an audit log search into a spreadsheet
On a separate cheeky note, I want to monitor User creation, modification and deletion of Microsoft Teams and as I'm not familiar with building scripts I was wondering if you might share your script that loads audit log records into a csv file ?
- Frank