Modules/Private/Main/Write-AZTIRunLog.ps1
|
<# .Synopsis Per-run diagnostic log for Azure Scout. .DESCRIPTION Every run writes a detailed, timestamped log into its own run folder, with no extra parameter required from the operator (AB#5634 / AB#5635). Before this existed, a failed run left nothing behind but a single red line on the console. Working out what a run actually did - which subscriptions it reached, which phase it was in, how long each phase took, where it died - meant running the whole tool again with -Debug and watching the screen. That is not a diagnostic story, and it is why a data-dependent crash (AB#5633) took a full reproduction cycle to locate. Two files are written into the run folder: scout-run.log structured phase log - metadata header, phase boundaries with elapsed time, per-phase counts, warnings, and the full error record (message, script, line, script stack trace) when a run fails. scout-console.log best-effort PowerShell transcript of everything printed to the console, including warnings. Skipped silently on hosts that do not support transcription. Logging must never be the reason a run fails, so every function here swallows its own errors. A broken log is a lost diagnostic, not a lost report. .COMPONENT This PowerShell Module is part of Azure Scout (AZSC). #> $script:AZSCRunLogPath = $null $script:AZSCTranscriptPath = $null $script:AZSCRunLogStart = $null function Start-AZSCRunLog { [CmdletBinding()] Param( [Parameter(Mandatory)] [string]$DefaultPath, [hashtable]$Metadata, [switch]$NoTranscript ) try { if (-not (Test-Path -Path $DefaultPath)) { # -ErrorAction Stop: a bad path raises a NON-terminating error by default, which # would sail straight past this try/catch and out to the console as red text. $null = New-Item -Path $DefaultPath -ItemType Directory -Force -ErrorAction Stop } $script:AZSCRunLogPath = Join-Path $DefaultPath 'scout-run.log' $script:AZSCRunLogStart = Get-Date $Header = @() $Header += '================================================================' $Header += ' Azure Scout run log' $Header += '================================================================' $Header += (' Started : ' + $script:AZSCRunLogStart.ToString('yyyy-MM-dd HH:mm:ss.fff zzz')) if ($Metadata) { foreach ($Key in ($Metadata.Keys | Sort-Object)) { $Value = $Metadata[$Key] if ($Value -is [System.Collections.IEnumerable] -and $Value -isnot [string]) { $Value = (@($Value) -join ', ') } $Header += (' {0,-12} : {1}' -f $Key, $Value) } } $Header += '================================================================' $Header += '' Set-Content -Path $script:AZSCRunLogPath -Value $Header -Encoding UTF8 -ErrorAction Stop } catch { # A run folder we cannot write to is worth one warning, not a failed run. Write-Warning "[AzureScout] Could not start the run log: $($_.Exception.Message)" $script:AZSCRunLogPath = $null return } if ($NoTranscript.IsPresent) { return } try { $script:AZSCTranscriptPath = Join-Path $DefaultPath 'scout-console.log' Start-Transcript -Path $script:AZSCTranscriptPath -Force -ErrorAction Stop | Out-Null } catch { # Transcription is unavailable in some hosts (and in Azure Automation). The # structured log above is the part that matters; carry on without it. $script:AZSCTranscriptPath = $null } } function Write-AZSCLog { [CmdletBinding()] Param( [Parameter(Mandatory, Position = 0)] [AllowEmptyString()] [string]$Message, [ValidateSet('INFO', 'PHASE', 'WARN', 'ERROR', 'DEBUG')] [string]$Level = 'INFO' ) if (-not $script:AZSCRunLogPath) { return } try { $Stamp = (Get-Date).ToString('yyyy-MM-dd HH:mm:ss.fff') $Line = '[{0}] [{1,-5}] {2}' -f $Stamp, $Level, $Message Add-Content -Path $script:AZSCRunLogPath -Value $Line -Encoding UTF8 -ErrorAction Stop } catch { # Deliberately silent: a failed log write must not derail the run. } } function Write-AZSCLogPhase { [CmdletBinding()] Param( [Parameter(Mandatory, Position = 0)] [string]$Name, [string]$Elapsed, [hashtable]$Detail ) if (-not $script:AZSCRunLogPath) { return } $Text = $Name if ($Elapsed) { $Text = "$Text (elapsed $Elapsed)" } Write-AZSCLog -Message $Text -Level 'PHASE' if ($Detail) { foreach ($Key in ($Detail.Keys | Sort-Object)) { $Value = $Detail[$Key] if ($null -eq $Value) { $Value = '<none>' } elseif ($Value -is [System.Collections.IEnumerable] -and $Value -isnot [string]) { $Value = (@($Value) -join ', ') } Write-AZSCLog -Message (' {0,-22} : {1}' -f $Key, $Value) -Level 'INFO' } } } function Write-AZSCLogError { [CmdletBinding()] Param( [Parameter(Mandatory, Position = 0)] [System.Management.Automation.ErrorRecord]$ErrorRecord ) if (-not $script:AZSCRunLogPath) { return } try { Write-AZSCLog -Message '---------------- RUN FAILED ----------------' -Level 'ERROR' Write-AZSCLog -Message ('Message : ' + $ErrorRecord.Exception.Message) -Level 'ERROR' Write-AZSCLog -Message ('Type : ' + $ErrorRecord.Exception.GetType().FullName) -Level 'ERROR' Write-AZSCLog -Message ('Category : ' + $ErrorRecord.CategoryInfo.ToString()) -Level 'ERROR' Write-AZSCLog -Message ('FullyQualifiedErrorId : ' + $ErrorRecord.FullyQualifiedErrorId) -Level 'ERROR' if ($ErrorRecord.InvocationInfo) { Write-AZSCLog -Message ('Script : ' + $ErrorRecord.InvocationInfo.ScriptName) -Level 'ERROR' Write-AZSCLog -Message ('Line : ' + $ErrorRecord.InvocationInfo.ScriptLineNumber) -Level 'ERROR' if ($ErrorRecord.InvocationInfo.Line) { Write-AZSCLog -Message ('Statement : ' + $ErrorRecord.InvocationInfo.Line.Trim()) -Level 'ERROR' } } Write-AZSCLog -Message 'ScriptStackTrace :' -Level 'ERROR' foreach ($Frame in (($ErrorRecord.ScriptStackTrace -split "`r?`n") | Where-Object { $_ })) { Write-AZSCLog -Message (' ' + $Frame) -Level 'ERROR' } $Inner = $ErrorRecord.Exception.InnerException $Depth = 0 while ($Inner -and $Depth -lt 5) { Write-AZSCLog -Message ("InnerException[$Depth] : " + $Inner.Message) -Level 'ERROR' $Inner = $Inner.InnerException $Depth++ } } catch { # Never let error logging raise a second error on top of the first. } } function Stop-AZSCRunLog { [CmdletBinding()] Param( [ValidateSet('COMPLETED', 'FAILED')] [string]$Status = 'COMPLETED', [switch]$Quiet ) $Path = $script:AZSCRunLogPath if ($Path) { try { $Elapsed = if ($script:AZSCRunLogStart) { ((Get-Date) - $script:AZSCRunLogStart).ToString('dd\:hh\:mm\:ss\:fff') } else { 'unknown' } Write-AZSCLog -Message '' -Level 'INFO' Write-AZSCLog -Message ("Run $Status after $Elapsed") -Level 'PHASE' } catch { # nothing useful left to do here } } if ($script:AZSCTranscriptPath) { try { Stop-Transcript -ErrorAction Stop | Out-Null } catch { } $script:AZSCTranscriptPath = $null } if ($Path -and -not $Quiet.IsPresent) { Write-Host ' Run log : ' -NoNewline -ForegroundColor DarkGray Write-Host $Path -ForegroundColor Cyan } $script:AZSCRunLogPath = $null $script:AZSCRunLogStart = $null return $Path } function Get-AZSCRunLogPath { [CmdletBinding()] Param() return $script:AZSCRunLogPath } |