winutil/pester/logging.Tests.ps1

#===========================================================================
# Tests - WinUtil Logging

BeforeAll {
    $script:repoRoot = (Resolve-Path (Join-Path $PSScriptRoot "..")).Path

    . (Join-Path $script:repoRoot "functions\private\Write-WinUtilLog.ps1")
    . (Join-Path $script:repoRoot "functions\private\Measure-WinUtilStep.ps1")
}

Describe "Write-WinUtilLog" {
    BeforeEach {
        $script:testRoot = Join-Path ([System.IO.Path]::GetTempPath()) "winutil-logging-$([guid]::NewGuid())"
        New-Item -Path $script:testRoot -ItemType Directory -Force | Out-Null
        Remove-Variable -Name WinUtilLogPath -Scope Script -ErrorAction SilentlyContinue
    }

    AfterEach {
        Remove-Variable -Name sync -Scope Script -ErrorAction SilentlyContinue
        Remove-Variable -Name WinUtilLogPath -Scope Script -ErrorAction SilentlyContinue
        Remove-Variable -Name WinUtilIsJobWorker -Scope Global -ErrorAction SilentlyContinue
        Remove-Variable -Name WinUtilJobErrorCount -Scope Global -ErrorAction SilentlyContinue
        Remove-Item -Path $script:testRoot -Recurse -Force -ErrorAction SilentlyContinue
    }

    It "writes to the active timestamped session log under logs" {
        $logPath = Join-Path $script:testRoot "logs\winutil_2026-07-01_12-00-00.log"
        $script:sync = [hashtable]::Synchronized(@{
            winutildir = $script:testRoot
            logPath = $logPath
        })

        Write-WinUtilLog -Component "Test" -Message "same session log"

        Test-Path -Path $logPath | Should -BeTrue
        Test-Path -Path (Join-Path $script:testRoot "winutil.log") | Should -BeFalse
        Get-Content -Path $logPath -Raw | Should -Match "\[INFO\] \[Test\] same session log"
    }

    It "writes through the host when the transcript owns the active session log" {
        $logPath = Join-Path $script:testRoot "logs\winutil_2026-07-01_12-00-00.log"
        $script:sync = [hashtable]::Synchronized(@{
            logPath = $logPath
            transcriptPath = $logPath
        })
        Mock Write-Host { }
        Mock Add-Content { }

        Write-WinUtilLog -Component "Test" -Message "transcript entry"

        Should -Invoke Write-Host -Times 1 -Exactly -ParameterFilter {
            $Object -match "\[INFO\] \[Test\] transcript entry"
        }
        Should -Invoke Add-Content -Times 0 -Exactly
    }

    It "writes entries produced concurrently by several threads" {
        $logPath = Join-Path $script:testRoot "logs\winutil_2026-07-01_12-00-00.log"
        $script:sync = [hashtable]::Synchronized(@{
            winutildir = $script:testRoot
            logPath = $logPath
        })

        $logFunction = Get-Content -Path (Join-Path $script:repoRoot "functions\private\Write-WinUtilLog.ps1") -Raw
        $initialSessionState = [System.Management.Automation.Runspaces.InitialSessionState]::CreateDefault()
        $initialSessionState.Variables.Add(
            (New-Object System.Management.Automation.Runspaces.SessionStateVariableEntry -ArgumentList "sync", $script:sync, $null)
        )
        $pool = [runspacefactory]::CreateRunspacePool(1, 4, $initialSessionState, $Host)
        $pool.Open()

        try {
            $handles = foreach ($index in 1..12) {
                $shell = [powershell]::Create()
                $shell.RunspacePool = $pool
                [void]$shell.AddScript($logFunction)
                [void]$shell.AddScript("Write-WinUtilLog -Component 'Test' -Message 'entry $index'")
                [pscustomobject]@{ Shell = $shell; Handle = $shell.BeginInvoke() }
            }

            foreach ($item in $handles) {
                $item.Shell.EndInvoke($item.Handle)
                $item.Shell.Dispose()
            }
        } finally {
            $pool.Close()
            $pool.Dispose()
        }

        $content = Get-Content -Path $logPath
        foreach ($index in 1..12) {
            @($content | Where-Object { $_ -match "\[Test\] entry $index$" }).Count | Should -Be 1
        }
    }

    It "creates one fallback log under logs when only winutildir is available" {
        $script:sync = [hashtable]::Synchronized(@{
            winutildir = $script:testRoot
        })

        Write-WinUtilLog -Component "Test" -Message "first fallback entry"
        Write-WinUtilLog -Component "Test" -Message "second fallback entry"

        $logFiles = @(Get-ChildItem -Path (Join-Path $script:testRoot "logs") -Filter "winutil_*.log")
        $logFiles.Count | Should -Be 1
        Test-Path -Path (Join-Path $script:testRoot "winutil.log") | Should -BeFalse

        $content = Get-Content -Path $logFiles[0].FullName -Raw
        $content | Should -Match "first fallback entry"
        $content | Should -Match "second fallback entry"
    }

    It "falls back to host output when the log file cannot be opened" {
        $logPath = Join-Path $script:testRoot "logs\winutil_2026-07-01_12-00-00.log"
        $script:sync = [hashtable]::Synchronized(@{
            winutildir = $script:testRoot
            logPath = $logPath
        })

        Mock Add-Content { throw [System.IO.IOException]::new("file is locked") } -ParameterFilter {
            $Path -eq $logPath -and $ErrorAction -eq "Stop"
        }
        Mock Write-Host { }
        Mock Write-Warning { }

        Write-WinUtilLog -Component "Test" -Message "locked file fallback"

        Should -Invoke -CommandName Write-Host -Times 1 -Exactly -ParameterFilter {
            $Object -match "\[INFO\] \[Test\] locked file fallback"
        }
        Should -Invoke -CommandName Write-Warning -Times 0 -Exactly
    }

    It "counts headline errors in the logging runspace whether or not it is a job worker" {
        $script:sync = [hashtable]::Synchronized(@{
            winutildir = $script:testRoot
            LoggedErrors = [System.Collections.ArrayList]::Synchronized([System.Collections.ArrayList]::new())
        })
        $global:WinUtilIsJobWorker = $true
        $global:WinUtilJobErrorCount = 0

        Write-WinUtilLog -Level "ERROR" -Component "Test" -Message "job error"
        Write-WinUtilLog -Level "ERROR" -Detail -Component "Test" -Message "error detail"
        $global:WinUtilIsJobWorker = $false
        Write-WinUtilLog -Level "ERROR" -Component "UI" -Message "toggle error"

        $global:WinUtilJobErrorCount | Should -Be 2
        $script:sync.LoggedErrors.Count | Should -Be 2
    }

    It "suppresses debug entries outside a local compile" {
        $logPath = Join-Path $script:testRoot "logs\winutil_2026-07-01_12-00-00.log"
        $script:sync = [hashtable]::Synchronized(@{
            IsLocalCompile = $false
            logPath = $logPath
        })

        Write-WinUtilLog -Level "DEBUG" -Component "UI" -Message "timing detail"

        Test-Path -Path $logPath | Should -BeFalse
    }

    It "writes debug entries from a local compile" {
        $logPath = Join-Path $script:testRoot "logs\winutil_2026-07-01_12-00-00.log"
        $script:sync = [hashtable]::Synchronized(@{
            IsLocalCompile = $true
            logPath = $logPath
        })

        Write-WinUtilLog -Level "DEBUG" -Component "UI" -Message "timing detail"

        Get-Content -Path $logPath -Raw | Should -Match "\[DEBUG\] \[UI\] timing detail"
    }

    It "does not record UI timing steps outside a local compile" {
        $script:sync = [hashtable]::Synchronized(@{
            IsLocalCompile = $false
            StepTimings = [System.Collections.ArrayList]::Synchronized([System.Collections.ArrayList]::new())
        })
        Mock Write-WinUtilLog { }

        $result = Measure-WinUtilStep -Scope "UI" -Name "parse XAML" -ScriptBlock { 42 }

        $result | Should -Be 42
        $script:sync.StepTimings.Count | Should -Be 0
        Should -Invoke Write-WinUtilLog -Times 0 -Exactly
    }

    It "records local UI timing steps as debug entries" {
        $script:sync = [hashtable]::Synchronized(@{
            IsLocalCompile = $true
            StepTimings = [System.Collections.ArrayList]::Synchronized([System.Collections.ArrayList]::new())
        })
        Mock Write-WinUtilLog { }

        Measure-WinUtilStep -Scope "UI" -Name "parse XAML" -ScriptBlock { } | Out-Null

        $script:sync.StepTimings.Count | Should -Be 1
        Should -Invoke Write-WinUtilLog -Times 1 -Exactly -ParameterFilter {
            $Level -eq "DEBUG" -and $Component -eq "UI" -and $Message -like "timing: parse XAML took*"
        }
    }

}