Audit log rework for better resilience

Author: Zacgoose

Config/CIPPTimers.json

@@ -19,34 +19,14 @@
   },
   {
     "Id": "44a40668-ed71-403c-8c26-b32e320086ad",
-    "Command": "Start-AuditLogOrchestrator",
-    "Description": "Orchestrator to download audit logs",
+    "Command": "Start-AuditLogPlannerV2",
+    "Description": "Audit log V2 planner: create searches, download and process",
     "Cron": "0 */15 * * * *",
     "Priority": 2,
     "RunOnProcessor": true,
     "PreferredProcessor": "auditlog",
     "IsSystem": true
   },
-  {
-    "Id": "01cd512a-15c4-44a9-b8cb-1e5d879cfd2d",
-    "Command": "Start-AuditLogProcessingOrchestrator",
-    "Description": "Orchestrator to process audit logs",
-    "Cron": "0 */15 * * * *",
-    "Priority": 3,
-    "RunOnProcessor": true,
-    "PreferredProcessor": "auditlog",
-    "IsSystem": true
-  },
-  {
-    "Id": "03475c86-4314-4d7b-90f2-5a0639e3899b",
-    "Command": "Start-AuditLogSearchCreation",
-    "Description": "Timer to create audit log searches",
-    "Cron": "0 */30 * * * *",
-    "Priority": 4,
-    "RunOnProcessor": true,
-    "PreferredProcessor": "auditlog",
-    "IsSystem": true
-  },
   {
     "Id": "5ff6c500-e420-4a3b-8532-ace2e4da4f7d",
     "Command": "Start-ApplicationOrchestrator",

Modules/CIPPCore/Public/AuditLogs/Get-CippAuditLogNextAttempt.ps1

@@ -0,0 +1,27 @@
+function Get-CippAuditLogNextAttempt {
+    <#
+    .SYNOPSIS
+        Compute the next-attempt UTC time for a retried audit-log coverage row (exponential backoff).
+    .DESCRIPTION
+        Used by the V2 audit-log pipeline to schedule retries of failed search creations and
+        downloads in the AuditLogCoverage ledger. Exponential backoff with jitter, capped. Because
+        the timers run every 15 minutes, small delays effectively mean "retry next run"; larger ones
+        defer a persistently failing window before it is eventually dead-lettered by the caller.
+    .PARAMETER Attempts
+        The attempt count that has just been consumed (1 = first failure).
+    .OUTPUTS
+        [datetime] (UTC) when the row becomes eligible to retry.
+    .FUNCTIONALITY
+        Internal
+    #>
+    [CmdletBinding()]
+    param(
+        [int]$Attempts,
+        [int]$BaseMinutes = 5,
+        [int]$CapMinutes = 240
+    )
+    $exp = [Math]::Max(0, $Attempts - 1)
+    $delay = [Math]::Min($BaseMinutes * [Math]::Pow(2, $exp), $CapMinutes)
+    $jitter = Get-Random -Minimum 0.8 -Maximum 1.2
+    return (Get-Date).ToUniversalTime().AddMinutes($delay * $jitter)
+}

Modules/CIPPCore/Public/AuditLogs/Get-CippAuditLogPlannedWindows.ps1

@@ -0,0 +1,95 @@
+function Get-CippAuditLogPlannedWindows {
+    <#
+    .SYNOPSIS
+        Compute the 35-minute audit-log search windows a tenant is missing (gaps + the newest settled).
+    .DESCRIPTION
+        Pure helper for the V2 audit-log pipeline. Windows are 35 minutes long on a 30-minute stride,
+        so consecutive windows overlap by 5 minutes (covers boundary stragglers; alerting dedups by
+        record id). Window ENDS sit on the 30-minute grid minus the settle (i.e. :25 / :55), which is
+        exactly `floor_to_30min(now) - settle`. With the planner timer firing at :00/:15/:30/:45 and a
+        5-minute settle, a fresh window becomes creatable exactly at a :00/:30 tick - no tick delay -
+        and the :15/:45 ticks naturally have no new window (they do retries + download/process).
+
+        Backfill of older gaps is bounded by -HorizonHours and capped at -MaxPerRun per call (oldest
+        first). A brand-new tenant is seeded with only the newest settled window.
+    .PARAMETER ExistingRows
+        The tenant's current AuditLogCoverage rows. Reconciliation rows (RowKey 'RECON-*') are ignored
+        here; only regular 14-digit window keys are considered.
+    .PARAMETER Now
+        Reference time (UTC). Defaults to now.
+    .OUTPUTS
+        Array of [pscustomobject]@{ RowKey; WindowStart; WindowEnd } sorted oldest-first.
+    .FUNCTIONALITY
+        Internal
+    #>
+    [CmdletBinding()]
+    param(
+        [object[]]$ExistingRows,
+        [datetime]$Now = (Get-Date).ToUniversalTime(),
+        [int]$SettleMinutes = 5,
+        [int]$WindowMinutes = 35,
+        [int]$StrideMinutes = 30,
+        [int]$HorizonHours = 24,
+        [int]$MaxPerRun = 6
+    )
+
+    $Now = $Now.ToUniversalTime()
+
+    # Newest window end: floor to the 30-min grid, minus the settle (lands on :25 / :55).
+    $FloorMinute = $Now.Minute - ($Now.Minute % $StrideMinutes)
+    $Floor = [datetime]::new($Now.Year, $Now.Month, $Now.Day, $Now.Hour, $FloorMinute, 0, [System.DateTimeKind]::Utc)
+    $NewestEnd = $Floor.AddMinutes(-$SettleMinutes)
+
+    $HorizonStart = $Now.AddHours(-$HorizonHours)
+
+    # Existing regular window keys (ignore reconciliation rows).
+    $ExistingKeys = [System.Collections.Generic.HashSet[string]]::new([System.StringComparer]::OrdinalIgnoreCase)
+    $ExistingStarts = [System.Collections.Generic.List[datetime]]::new()
+    foreach ($Row in $ExistingRows) {
+        if ($Row.RowKey -notmatch '^\d{14}$') { continue }
+        [void]$ExistingKeys.Add([string]$Row.RowKey)
+        if ($null -ne $Row.WindowStart) {
+            try { $ExistingStarts.Add(([datetimeoffset]$Row.WindowStart).UtcDateTime) } catch {}
+        }
+    }
+
+    # Brand-new tenant: seed only the newest settled window.
+    if ($ExistingStarts.Count -eq 0) {
+        $Start = $NewestEnd.AddMinutes(-$WindowMinutes)
+        if ($Start -lt $HorizonStart) { return @() }
+        return , ([pscustomobject]@{
+                RowKey      = $Start.ToString('yyyyMMddHHmmss')
+                WindowStart = $Start
+                WindowEnd   = $NewestEnd
+            })
+    }
+
+    # Established tenant: backfill missing windows from the lower bound up to NewestEnd (oldest first).
+    $EarliestExisting = ($ExistingStarts | Measure-Object -Minimum).Minimum
+    $LowerEnd = if ($EarliestExisting -gt $HorizonStart) { $EarliestExisting.AddMinutes($WindowMinutes) } else { $HorizonStart.AddMinutes($WindowMinutes) }
+
+    $Owed = [System.Collections.Generic.List[object]]::new()
+    $End = $NewestEnd
+    while ($End -ge $LowerEnd) {
+        $Start = $End.AddMinutes(-$WindowMinutes)
+        $Key = $Start.ToString('yyyyMMddHHmmss')
+        if (-not $ExistingKeys.Contains($Key)) {
+            $Owed.Add([pscustomobject]@{ RowKey = $Key; WindowStart = $Start; WindowEnd = $End })
+        }
+        $End = $End.AddMinutes(-$StrideMinutes)
+    }
+
+    # $Owed is newest-first from the loop; reorder to oldest-first ([0]=oldest, [-1]=newest).
+    $Owed.Reverse()
+    if ($Owed.Count -le $MaxPerRun) {
+        return @($Owed)
+    }
+
+    # Backlog exceeds the per-run cap: always include the NEWEST window so the live period can
+    # be created promptly (current-first, see Push-AuditLogSearchCreationV2), plus the oldest
+    # (MaxPerRun-1) so historical gaps still drain - oldest first - before they age out of the
+    # horizon. Without seeding the newest here it would never be Planned during a backlog.
+    $Newest = $Owed[$Owed.Count - 1]
+    $Backfill = @($Owed[0..($MaxPerRun - 2)])
+    return @($Backfill + $Newest)
+}

Modules/CIPPCore/Public/AuditLogs/Get-CippAuditLogReconciliationWindows.ps1

@@ -0,0 +1,68 @@
+function Get-CippAuditLogReconciliationWindows {
+    <#
+    .SYNOPSIS
+        Compute the 12-hour reconciliation audit-log windows a tenant is missing.
+    .DESCRIPTION
+        The fast 35-minute path searches each period soon after it closes, so late-landing / backfilled
+        audit events (Microsoft can publish them hours later) can be missed. This helper produces wide
+        catch-all windows aligned to 00:00-12:00 and 12:00-00:00 UTC, each created 3 hours after the
+        block closes (a generous settle so backfilled data has landed). They flow through the normal
+        download/process path; alerting dedups by record id, so overlap with the fast path is harmless.
+    .PARAMETER ExistingRows
+        The tenant's current AuditLogCoverage rows. Only reconciliation rows (RowKey 'RECON-*') are
+        considered when finding gaps.
+    .PARAMETER Now
+        Reference time (UTC). Defaults to now.
+    .OUTPUTS
+        Array of [pscustomobject]@{ RowKey; WindowStart; WindowEnd } sorted oldest-first. RowKey is
+        'RECON-<windowStart yyyyMMddHHmmss>'.
+    .FUNCTIONALITY
+        Internal
+    #>
+    [CmdletBinding()]
+    param(
+        [object[]]$ExistingRows,
+        [datetime]$Now = (Get-Date).ToUniversalTime(),
+        [int]$SettleHours = 3,
+        [int]$HorizonHours = 24,
+        [int]$MaxPerRun = 6
+    )
+
+    $Now = $Now.ToUniversalTime()
+
+    # Newest 12h block end (00:00 / 12:00 UTC) whose close is at least SettleHours in the past.
+    $T = $Now.AddHours(-$SettleHours)
+    $BoundaryHour = if ($T.Hour -lt 12) { 0 } else { 12 }
+    $NewestEnd = [datetime]::new($T.Year, $T.Month, $T.Day, $BoundaryHour, 0, 0, [System.DateTimeKind]::Utc)
+    $HorizonStart = $Now.AddHours(-$HorizonHours)
+
+    $ExistingKeys = [System.Collections.Generic.HashSet[string]]::new([System.StringComparer]::OrdinalIgnoreCase)
+    foreach ($Row in $ExistingRows) {
+        if ($Row.RowKey -like 'RECON-*') { [void]$ExistingKeys.Add([string]$Row.RowKey) }
+    }
+
+    # No reconciliation history: seed only the newest settled block (avoid a first-run backfill spike;
+    # the fast 35-min path already covers recent history). Established tenants backfill gaps below.
+    if ($ExistingKeys.Count -eq 0) {
+        $Start = $NewestEnd.AddHours(-12)
+        if ($Start -lt $HorizonStart) { return @() }
+        return , ([pscustomobject]@{ RowKey = 'RECON-' + $Start.ToString('yyyyMMddHHmmss'); WindowStart = $Start; WindowEnd = $NewestEnd })
+    }
+
+    $Owed = [System.Collections.Generic.List[object]]::new()
+    $End = $NewestEnd
+    while ($End -ge $HorizonStart) {
+        $Start = $End.AddHours(-12)
+        $Key = 'RECON-' + $Start.ToString('yyyyMMddHHmmss')
+        if (-not $ExistingKeys.Contains($Key)) {
+            $Owed.Add([pscustomobject]@{ RowKey = $Key; WindowStart = $Start; WindowEnd = $End })
+        }
+        $End = $End.AddHours(-12)
+    }
+
+    $Owed.Reverse()
+    if ($Owed.Count -gt $MaxPerRun) {
+        return @($Owed[0..($MaxPerRun - 1)])
+    }
+    return @($Owed)
+}

Modules/CIPPCore/Public/AuditLogs/New-CippAuditLogSearchV2.ps1

@@ -0,0 +1,86 @@
+function New-CippAuditLogSearchV2 {
+    <#
+    .SYNOPSIS
+        Create a Microsoft Graph audit-log search for the V2 pipeline and return a classified result.
+    .DESCRIPTION
+        Thin wrapper over New-GraphPOSTRequest (which now honours 429 backoff). Unlike the V1
+        New-CippAuditLogSearch, this writes to NO table - the AuditLogCoverage ledger is updated by
+        the caller. Failures are classified so the caller can decide whether to retry (transient) or
+        stop (auditing disabled).
+    .PARAMETER TenantFilter
+        Tenant default domain or customerId.
+    .PARAMETER StartTime
+        Window start (inclusive).
+    .PARAMETER EndTime
+        Window end (exclusive).
+    .PARAMETER RecordTypeFilters
+        Record types to capture. Defaults to the four the V1 pipeline used.
+    .OUTPUTS
+        [pscustomobject]@{ Id; Status; Outcome; Message }  Outcome in 'Created','AuditingDisabled','Transient'.
+    .FUNCTIONALITY
+        Internal
+    #>
+    [CmdletBinding(SupportsShouldProcess = $true)]
+    param(
+        [Parameter(Mandatory = $true)][string]$TenantFilter,
+        [Parameter(Mandatory = $true)][datetime]$StartTime,
+        [Parameter(Mandatory = $true)][datetime]$EndTime,
+        [string[]]$RecordTypeFilters = @('exchangeAdmin', 'azureActiveDirectory', 'azureActiveDirectoryAccountLogon', 'azureActiveDirectoryStsLogon'),
+        [int]$MaxAttempts = 3,
+        [string]$DisplayName = ('CIPP Audit Search V2 - ' + (Get-Date).ToString('yyyy-MM-dd HH:mm:ss'))
+    )
+
+    $Body = @{
+        displayName         = $DisplayName
+        filterStartDateTime = $StartTime.ToUniversalTime().ToString('yyyy-MM-ddTHH:mm:ss')
+        filterEndDateTime   = $EndTime.ToUniversalTime().ToString('yyyy-MM-ddTHH:mm:ss')
+        recordTypeFilters   = @($RecordTypeFilters)
+    } | ConvertTo-Json -Compress
+
+    if (-not $PSCmdlet.ShouldProcess($TenantFilter, 'Create audit log search')) {
+        return [pscustomobject]@{ Id = $null; Status = 'WhatIf'; Outcome = 'Transient'; Message = 'WhatIf'; Throttled = $false }
+    }
+
+    for ($Attempt = 1; $Attempt -le $MaxAttempts; $Attempt++) {
+        try {
+            # maxRetries 1 = no retry inside the Graph helper; this function owns retry/backoff.
+            $Query = New-GraphPOSTRequest -uri 'https://graph.microsoft.com/beta/security/auditLog/queries' -body $Body -tenantid $TenantFilter -AsApp $true -maxRetries 1
+            return [pscustomobject]@{ Id = $Query.id; Status = $Query.status; Outcome = 'Created'; Message = $null; Throttled = $false }
+        } catch {
+            $Raw = $_.Exception.Data['RawErrorBody']
+            if (-not $Raw) { $Raw = $_.ErrorDetails.Message }
+            if (-not $Raw) { $Raw = $_.Exception.Message }
+            $Parsed = $null
+            if ($Raw) { try { $Parsed = ([string]$Raw) | ConvertFrom-Json -ErrorAction Stop } catch {} }
+
+            # AuditingDisabledTenant can be top-level Status or nested as JSON inside error.message.
+            $AuditStatus = $Parsed.Status
+            if (-not $AuditStatus) {
+                $Inner = $Parsed.error.message ?? $Parsed.message
+                if ($Inner -is [string]) { try { $AuditStatus = ($Inner | ConvertFrom-Json -ErrorAction Stop).Status } catch {} }
+            }
+            if ($AuditStatus -eq 'AuditingDisabledTenant') {
+                return [pscustomobject]@{ Id = $null; Status = 'AuditingDisabledTenant'; Outcome = 'AuditingDisabled'; Message = 'Unified auditing is disabled for this tenant.'; Throttled = $false }
+            }
+
+            $Code = $Parsed.error.code ?? $Parsed.code
+            $Msg = $Parsed.error.message ?? $Parsed.message ?? $_.Exception.Message
+            $StatusCode = $null
+            try { $StatusCode = [int]$_.Exception.Response.StatusCode } catch {}
+
+            # 429 = the tenant's ~10 concurrent-search cap is full. Retrying in-process won't clear it,
+            # so return immediately and let the planner defer this + remaining windows to next cycle.
+            if (($Code -eq 'TooManyRequests') -or ($StatusCode -eq 429)) {
+                return [pscustomobject]@{ Id = $null; Status = ([string]($Code ?? 'TooManyRequests')); Outcome = 'Transient'; Message = [string]$Msg; Throttled = $true }
+            }
+
+            # Other transient (UnknownError, 5xx, gateway, timeout): usually a momentary EXO-backend
+            # blip that clears on a quick re-submit. Retry in-process with >1s jitter before giving up.
+            if ($Attempt -lt $MaxAttempts) {
+                Start-Sleep -Seconds (Get-Random -Minimum 1.5 -Maximum 4.0)
+                continue
+            }
+            return [pscustomobject]@{ Id = $null; Status = ([string]($Code ?? 'Error')); Outcome = 'Transient'; Message = [string]$Msg; Throttled = $false }
+        }
+    }
+}

Modules/CIPPCore/Public/Entrypoints/Orchestrator Functions/Start-AuditLogIngestionV2.ps1

@@ -0,0 +1,82 @@
+function Start-AuditLogIngestionV2 {
+    <#
+    .SYNOPSIS
+        V2 audit-log ingestion timer. Drives both download and processing, decoupled so that pending
+        logs are processed even when there is nothing new to download.
+    .DESCRIPTION
+        Runs offset 15 minutes from the creation timer and fans out two kinds of work:
+
+          1. Download tenants - AuditLogCoverage rows in state 'Created' (a search was created and is
+             awaiting download) and due (not in backoff). Each gets a per-tenant orchestrator:
+                 Batch         = AuditLogDownloadV2  (download succeeded searches -> CacheWebhooks)
+                 PostExecution = AuditLogProcessV2   (enqueue processing if any cache rows are pending)
+
+          2. Process-only tenants - tenants that have rows sitting in CacheWebhooks (downloaded but
+             not yet processed, e.g. left behind by a worker crash mid-processing) but no pending
+             download. These get a processing orchestrator fanned out DIRECTLY, skipping the no-op
+             download orchestration.
+
+        This makes processing self-healing: a crashed/partial processing run is retried on the next
+        cycle off the cache contents, not gated behind a fresh download.
+    .FUNCTIONALITY
+        Entrypoint
+    #>
+    [CmdletBinding(SupportsShouldProcess = $true)]
+    param()
+    try {
+        $Ledger = Get-CippTable -TableName 'AuditLogCoverage'
+        $Now = (Get-Date).ToUniversalTime()
+
+        # --- Download tenants: searches awaiting download (State = Created, due) ---
+        $Created = @(Get-CIPPAzDataTableEntity @Ledger -Filter "State eq 'Created'")
+        $DueCreated = $Created | Where-Object { -not $_.NextAttemptUtc -or ([datetimeoffset]$_.NextAttemptUtc).UtcDateTime -le $Now }
+        $DownloadTenants = [System.Collections.Generic.HashSet[string]]::new([System.StringComparer]::OrdinalIgnoreCase)
+        foreach ($Name in @($DueCreated | Group-Object PartitionKey | ForEach-Object { $_.Name })) {
+            if ($Name) { [void]$DownloadTenants.Add([string]$Name) }
+        }
+
+        # --- Process-only tenants: rows pending in the webhook cache (downloaded, not yet processed) ---
+        $CacheTable = Get-CippTable -TableName 'CacheWebhooks'
+        $CacheRows = @(Get-CIPPAzDataTableEntity @CacheTable -Property @('PartitionKey', 'RowKey'))
+        $CacheTenants = [System.Collections.Generic.HashSet[string]]::new([System.StringComparer]::OrdinalIgnoreCase)
+        foreach ($Name in @($CacheRows | Group-Object PartitionKey | ForEach-Object { $_.Name })) {
+            if ($Name) { [void]$CacheTenants.Add([string]$Name) }
+        }
+
+        if ($DownloadTenants.Count -eq 0 -and $CacheTenants.Count -eq 0) {
+            Write-Information 'AuditLogV2: nothing to download or process'
+            return
+        }
+
+        # 1) Download tenants -> download + post-exec processing in one orchestration.
+        foreach ($TenantFilter in $DownloadTenants) {
+            if ($PSCmdlet.ShouldProcess($TenantFilter, 'Download + process audit logs')) {
+                Start-CIPPOrchestrator -InputObject ([PSCustomObject]@{
+                        OrchestratorName = "AuditLogIngestV2-$TenantFilter"
+                        Batch            = @([PSCustomObject]@{ FunctionName = 'AuditLogDownloadV2'; TenantFilter = $TenantFilter })
+                        PostExecution    = @{ FunctionName = 'AuditLogProcessV2'; Parameters = @{ TenantFilter = $TenantFilter } }
+                        SkipLog          = $true
+                    })
+            }
+        }
+
+        # 2) Process-only tenants (pending cache, no pending download) -> process directly.
+        $ProcessOnlyCount = 0
+        foreach ($TenantFilter in $CacheTenants) {
+            if ($DownloadTenants.Contains($TenantFilter)) { continue }
+            $ProcessOnlyCount++
+            if ($PSCmdlet.ShouldProcess($TenantFilter, 'Process pending audit logs')) {
+                Start-CIPPOrchestrator -InputObject ([PSCustomObject]@{
+                        OrchestratorName = "AuditLogProcessV2-$TenantFilter"
+                        QueueFunction    = [PSCustomObject]@{ FunctionName = 'AuditLogProcessingBatchV2'; Parameters = @{ TenantFilter = $TenantFilter } }
+                        SkipLog          = $true
+                    })
+            }
+        }
+
+        Write-Information "AuditLogV2: ingestion fan-out - $($DownloadTenants.Count) download tenant(s), $ProcessOnlyCount process-only tenant(s)"
+    } catch {
+        Write-LogMessage -API 'AuditLogV2' -message 'Error in audit log ingestion orchestrator (V2)' -sev Error -LogData (Get-CippException -Exception $_)
+        Write-Information ('AuditLogV2 ingestion error {0} line {1} - {2}' -f $_.InvocationInfo.ScriptName, $_.InvocationInfo.ScriptLineNumber, $_.Exception.Message)
+    }
+}