diff --git a/CHANGELOG.md b/CHANGELOG.md index 4f98af6..8844044 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,12 @@ +## Logging and timer audit fixes (unreleased) + +- Treat redaction replacement text literally, preventing regex substitutions from reinserting secrets. +- Serialize buffer snapshot/write/removal; retain entries after failed writes and preserve appended entries. +- Resolve default log paths from the calling script, with current-directory fallback for interactive calls. +- Reject conflicting buffered severity switches while retaining individual compatibility switches. +- Require a non-null stopwatch in every Get-ElapsedTime parameter set. +- Add regression tests and concurrent-process file-write coverage. + ## String utilities restoration (unreleased) - Restore character conversion, string checksums and SHA-256 hashing. diff --git a/Private/ConvertTo-NewLogEntryRedactedMessage.ps1 b/Private/ConvertTo-NewLogEntryRedactedMessage.ps1 index e0426f1..9838c4a 100644 --- a/Private/ConvertTo-NewLogEntryRedactedMessage.ps1 +++ b/Private/ConvertTo-NewLogEntryRedactedMessage.ps1 @@ -18,7 +18,8 @@ function ConvertTo-NewLogEntryRedactedMessage continue } - $redactedMessage = [regex]::Replace($redactedMessage, $item, $Replacement) + # Escape dollar signs so replacement syntax cannot reinsert matched secrets. + $redactedMessage = [regex]::Replace($redactedMessage, $item, $Replacement.Replace('$', '$$')) } return $redactedMessage diff --git a/Private/Flush-NewLogEntryBuffer.ps1 b/Private/Flush-NewLogEntryBuffer.ps1 new file mode 100644 index 0000000..705d582 --- /dev/null +++ b/Private/Flush-NewLogEntryBuffer.ps1 @@ -0,0 +1,38 @@ +function Flush-NewLogEntryBuffer +{ + param( + [string]$Path, + [ValidateRange(1, 86400)] + [int]$LockTimeoutSeconds = 30 + ) + + Initialize-NewLogEntryState + + # Serialize snapshot, write, and removal with other operations on this buffer. + # A failed write leaves entries available for a later retry. + [System.Threading.Monitor]::Enter($script:NewLogEntryBufferLock) + try + { + $lines = $script:NewLogEntryBuffer.ToArray() + if ($lines.Count -eq 0) + { + return + } + + Write-NewLogEntryLines -Lines $lines -Path $Path -LockTimeoutSeconds $LockTimeoutSeconds + + # Remove only the written prefix, preserving any reentrant append during writing. + $script:NewLogEntryBuffer.RemoveRange(0, $lines.Count) + $script:messageBuffer = $script:NewLogEntryBuffer -join [Environment]::NewLine + if ($script:messageBuffer.Length -gt 0) + { + $script:messageBuffer += [Environment]::NewLine + } + } + finally + { + [System.Threading.Monitor]::Exit($script:NewLogEntryBufferLock) + } + + return $lines +} diff --git a/Private/Resolve-NewLogEntryPath.ps1 b/Private/Resolve-NewLogEntryPath.ps1 index cad8e7e..df27c19 100644 --- a/Private/Resolve-NewLogEntryPath.ps1 +++ b/Private/Resolve-NewLogEntryPath.ps1 @@ -1,19 +1,15 @@ function Resolve-NewLogEntryPath { - param([string]$Path) + param([string]$Path, [string]$CallerScriptPath) if (-not [string]::IsNullOrWhiteSpace($Path)) { return $ExecutionContext.SessionState.Path.GetUnresolvedProviderPathFromPSPath($Path) } - $basePath = if (-not [string]::IsNullOrWhiteSpace($script:PSCommandPath)) + $basePath = if (-not [string]::IsNullOrWhiteSpace($CallerScriptPath)) { - $script:PSCommandPath - } - elseif (-not [string]::IsNullOrWhiteSpace($PSCommandPath)) - { - $PSCommandPath + $CallerScriptPath } else { diff --git a/Public/Get-ElapsedTime.ps1 b/Public/Get-ElapsedTime.ps1 index e70128b..6c010c3 100644 --- a/Public/Get-ElapsedTime.ps1 +++ b/Public/Get-ElapsedTime.ps1 @@ -65,17 +65,8 @@ function Get-ElapsedTime [OutputType([timespan])] param ( - [Parameter(ParameterSetName = 'FullOutput', - Mandatory = $true)] - [Parameter(ParameterSetName = 'Days')] - [Parameter(ParameterSetName = 'Hours')] - [Parameter(ParameterSetName = 'Minutes')] - [Parameter(ParameterSetName = 'Seconds')] - [Parameter(ParameterSetName = 'TotalDays')] - [Parameter(ParameterSetName = 'TotalHours')] - [Parameter(ParameterSetName = 'TotalMilliseconds')] - [Parameter(ParameterSetName = 'TotalMinutes')] - [Parameter(ParameterSetName = 'TotalSeconds')] + [Parameter(Mandatory = $true)] + [ValidateNotNull()] [System.Diagnostics.Stopwatch] $ElapsedTime, [Parameter(ParameterSetName = 'Days')] diff --git a/Public/New-LogEntry.ps1 b/Public/New-LogEntry.ps1 index af2cf27..916621b 100644 --- a/Public/New-LogEntry.ps1 +++ b/Public/New-LogEntry.ps1 @@ -49,7 +49,9 @@ function New-LogEntry Returns buffered log entries without clearing them. .PARAMETER FlushBuffer - Writes buffered entries to the log file and clears the buffer after a successful write. + Writes buffered entries to the log file and removes the written entries after a successful write. + A failed file write retains the buffer for retry. A partial filesystem write can leave + content on disk, so a retry after an I/O failure can duplicate that content. .PARAMETER ClearBuffer Clears buffered entries without writing them. @@ -72,7 +74,7 @@ function New-LogEntry Additional regular expression patterns to redact before formatting or writing the message. .PARAMETER RedactionText - Replacement text used for redacted content. Defaults to [REDACTED]. + Literal replacement text used for redacted content (regex substitutions are not expanded). Defaults to [REDACTED]. .PARAMETER NoTag Omits the severity tag from the formatted entry. @@ -170,6 +172,7 @@ function New-LogEntry begin { + $callerScriptPath = $MyInvocation.ScriptName $pendingEntries = [System.Collections.Generic.List[string]]::new() $activeRedactPatterns = [System.Collections.Generic.List[string]]::new() @@ -178,6 +181,12 @@ function New-LogEntry throw 'Use either -IsWarningMessage or -IsErrorMessage, not both.' } + $bufferSeverityCount = [int]$BufferOnlyInfo.IsPresent + [int]$BufferOnlyWarning.IsPresent + [int]$BufferOnlyError.IsPresent + if ($bufferSeverityCount -gt 1) + { + throw 'Use only one of -BufferOnlyInfo, -BufferOnlyWarning, or -BufferOnlyError.' + } + if ($PSBoundParameters.ContainsKey('Level') -and ($IsWarningMessage -or $IsErrorMessage -or $BufferOnlyWarning -or $BufferOnlyError -or $BufferOnlyInfo)) { throw 'Use either -Level or a compatibility severity switch, not both.' @@ -234,15 +243,14 @@ function New-LogEntry 'FlushBuffer' { - $bufferedLines = Get-NewLogEntryBuffer + $resolvedLogPath = Resolve-NewLogEntryPath -Path $LogFilePath -CallerScriptPath $callerScriptPath + $bufferedLines = @(Flush-NewLogEntryBuffer -Path $resolvedLogPath -LockTimeoutSeconds $LockTimeoutSeconds) if ($bufferedLines.Count -eq 0) { return } - Write-NewLogEntryLines -Lines $bufferedLines -Path $LogFilePath -LockTimeoutSeconds $LockTimeoutSeconds - if (-not $NoConsole) { foreach ($line in $bufferedLines) @@ -251,8 +259,6 @@ function New-LogEntry } } - Clear-NewLogEntryBuffer - if ($PassThru) { $bufferedLines @@ -294,7 +300,8 @@ function New-LogEntry return } - Write-NewLogEntryLines -Lines $entries -Path $LogFilePath -LockTimeoutSeconds $LockTimeoutSeconds + $resolvedLogPath = Resolve-NewLogEntryPath -Path $LogFilePath -CallerScriptPath $callerScriptPath + Write-NewLogEntryLines -Lines $entries -Path $resolvedLogPath -LockTimeoutSeconds $LockTimeoutSeconds if (-not $NoConsole) { diff --git a/README.md b/README.md index e6b5489..1c6e040 100644 --- a/README.md +++ b/README.md @@ -42,7 +42,16 @@ Stop-Timer -Timer $timer Logging output only enters the success pipeline when requested with `-PassThru`. Use `New-LogEntry -GetBuffer`, `-FlushBuffer` and `-ClearBuffer` rather than accessing -module variables. Redaction is opt-in and does not guarantee detection of every secret. +module variables. A successful flush removes only the written entries; a failed file write +retains the buffer for retry. Buffer operations are serialized during a flush. +A partially completed filesystem write may still leave content on disk, so retrying after +an I/O failure does not provide an exactly-once delivery guarantee. + +Without `-LogFilePath`, logs are created beside the calling script, or in the current +directory for interactive calls. Specify a path to select a stable log filename. +`-RedactionText` is literal text, including dollar signs. Specify only one buffered +severity switch, or use `-BufferOnly -Level WARNING` / `ERROR`. +Redaction is opt-in and does not guarantee detection of every secret. ## Migration from v2 @@ -66,11 +75,12 @@ Invoke-Pester ./Tests CI runs syntax validation, isolated import and Pester on Windows, Linux and macOS using each hosted runner's installed PowerShell. It does not test every PowerShell -release. The inherited ten logger tests now exercise the command through module import. -Concurrency stress tests and Windows/AD integration tests are future work. +release. Logger tests exercise module import, redaction, failed-write retention, default paths, +and simultaneous direct/buffered file writes from three processes. Windows/AD +integration tests are future work. The logger is adopted from `PowerShell-Functions/New-LogEntry` at commit `d5a9edd`. -The source and helper implementations are unchanged; integration tests import this module. +The integrated logger includes the maintenance fixes described in CHANGELOG.md. See [CHANGELOG.md](./CHANGELOG.md) for history. Released under the [MIT License](./LICENSE). diff --git a/Tests/Module.Tests.ps1 b/Tests/Module.Tests.ps1 index e258425..2469d4a 100644 --- a/Tests/Module.Tests.ps1 +++ b/Tests/Module.Tests.ps1 @@ -42,3 +42,24 @@ Describe 'Timers' { Get-TimerStatus -Timer $timer | Should -BeFalse } } + + +Describe 'Elapsed-time input validation' { + It 'requires a non-null stopwatch in every parameter set' { + $command = Get-Command Get-ElapsedTime -Module IT-ToolBox + foreach ($set in $command.ParameterSets) { + ($set.Parameters | Where-Object Name -eq ElapsedTime).IsMandatory | Should -BeTrue + } + { Get-ElapsedTime -ElapsedTime $null -Seconds } | Should -Throw + } + + It 'returns the requested elapsed-time component: ' -ForEach @( + @{ Component = 'Days' }; @{ Component = 'Hours' }; @{ Component = 'Minutes' } + @{ Component = 'Seconds' }; @{ Component = 'TotalDays' }; @{ Component = 'TotalHours' } + @{ Component = 'TotalMinutes' }; @{ Component = 'TotalSeconds' }; @{ Component = 'TotalMilliseconds' } + ) { + $timer = [System.Diagnostics.Stopwatch]::new() + $selector = @{ $Component = $true } + Get-ElapsedTime -ElapsedTime $timer @selector | Should -Be $timer.Elapsed.$Component + } +} diff --git a/Tests/New-LogEntry.Tests.ps1 b/Tests/New-LogEntry.Tests.ps1 index 3e3ace0..da70f88 100644 --- a/Tests/New-LogEntry.Tests.ps1 +++ b/Tests/New-LogEntry.Tests.ps1 @@ -126,3 +126,191 @@ Describe 'New-LogEntry' { $buffer[0] | Should -Not -Match 'abc123' } } + + +Describe 'New-LogEntry audit regressions' { + BeforeEach { + New-LogEntry -ClearBuffer + } + + It 'treats regex replacement expressions as literal text: ' -ForEach @( + @{ Replacement = '$0' } + @{ Replacement = '$1' } + @{ Replacement = '$&' } + @{ Replacement = '$$' } + @{ Replacement = '${secret}' } + ) { + $path = Join-Path $TestDrive ([guid]::NewGuid().ToString() + '.log') + $line = New-LogEntry -LogMessage 'token=do-not-disclose' -RedactSecrets -RedactionText $Replacement -LogFilePath $path -NoConsole -PassThru + $line | Should -Not -Match 'do-not-disclose' + $line.EndsWith($Replacement) | Should -BeTrue + (Get-Content -LiteralPath $path) | Should -Be $line + New-LogEntry -LogMessage 'token=do-not-disclose' -BufferOnly -RedactPattern '(?token=\S+)' -RedactionText $Replacement + (New-LogEntry -GetBuffer).EndsWith($Replacement) | Should -BeTrue + } + + It 'rejects conflicting buffered severity switches: and ' -ForEach @( + @{ First = 'BufferOnlyInfo'; Second = 'BufferOnlyWarning' } + @{ First = 'BufferOnlyInfo'; Second = 'BufferOnlyError' } + @{ First = 'BufferOnlyWarning'; Second = 'BufferOnlyError' } + ) { + $flags = @{ $First = $true; $Second = $true } + { New-LogEntry -LogMessage 'conflict' @flags } | Should -Throw '*Use only one*' + @(New-LogEntry -GetBuffer).Count | Should -Be 0 + } + + It 'still accepts individual buffered severity switches: ' -ForEach @( + @{ Flag = 'BufferOnlyInfo'; Tag = 'INFO' } + @{ Flag = 'BufferOnlyWarning'; Tag = 'WARNING' } + @{ Flag = 'BufferOnlyError'; Tag = 'ERROR' } + ) { + $flags = @{ $Flag = $true } + New-LogEntry -LogMessage 'message' -BufferOnly @flags + (New-LogEntry -GetBuffer) | Should -Match "\[$Tag\]: message$" + } + + It 'preserves an entry appended while the snapshot is being written' { + InModuleScope IT-ToolBox { + Mock Write-NewLogEntryLines { + [System.Threading.Monitor]::IsEntered($script:NewLogEntryBufferLock) | Should -BeTrue + Add-NewLogEntryBuffer -Lines 'arrived-during-flush' + } + New-LogEntry -LogMessage 'original' -BufferOnly + $flushed = @(New-LogEntry -FlushBuffer -LogFilePath 'unused.log' -NoConsole -PassThru) + $flushed.Count | Should -Be 1 + $flushed[0] | Should -Match ': original$' + @(New-LogEntry -GetBuffer).Count | Should -Be 1 + (New-LogEntry -GetBuffer) | Should -Be 'arrived-during-flush' + $script:messageBuffer | Should -Be ("arrived-during-flush" + [Environment]::NewLine) + } + } + + It 'retains all entries when writing fails and releases the buffer lock' { + InModuleScope IT-ToolBox { + Mock Write-NewLogEntryLines { throw 'write failed' } + New-LogEntry -LogMessage 'retry-me' -BufferOnly + { New-LogEntry -FlushBuffer -LogFilePath 'unused.log' -NoConsole } | Should -Throw '*write failed*' + (New-LogEntry -GetBuffer) | Should -Match ': retry-me$' + [System.Threading.Monitor]::IsEntered($script:NewLogEntryBufferLock) | Should -BeFalse + New-LogEntry -LogMessage 'next' -BufferOnly + @(New-LogEntry -GetBuffer).Count | Should -Be 2 + } + } + + It 'writes buffered entries exactly once across successive flushes' { + $path = Join-Path $TestDrive 'once.log' + New-LogEntry -LogMessage 'once' -BufferOnly + New-LogEntry -FlushBuffer -LogFilePath $path -NoConsole + New-LogEntry -FlushBuffer -LogFilePath $path -NoConsole + @(Get-Content -LiteralPath $path).Count | Should -Be 1 + @(New-LogEntry -GetBuffer).Count | Should -Be 0 + } + + It 'resolves interactive defaults in the current directory' { + InModuleScope IT-ToolBox -Parameters @{ Directory = $TestDrive } { + param($Directory) + Push-Location $Directory + try { + $path = Resolve-NewLogEntryPath + (Split-Path $path -Parent) | Should -Be $Directory + (Split-Path $path -Leaf) | Should -Match '^PowerShell-LogFile-\d{8}-\d{6}\.log$' + } + finally { Pop-Location } + } + } + + It 'writes default logs beside a calling script, including buffer flushes' { + $scriptDirectory = Join-Path $TestDrive 'caller' + New-Item -ItemType Directory $scriptDirectory | Out-Null + $caller = Join-Path $scriptDirectory 'automation.ps1' + @' +New-LogEntry -LogMessage 'direct-default' -NoConsole +New-LogEntry -LogMessage 'buffer-default' -BufferOnly +New-LogEntry -FlushBuffer -NoConsole +'@ | Set-Content -LiteralPath $caller + & $caller + $logs = @(Get-ChildItem $scriptDirectory -Filter 'automation.ps1-LogFile-*.log') + $logs.Count | Should -BeGreaterThan 0 + $lines = @(Get-Content -LiteralPath $logs.FullName) + $lines.Count | Should -Be 2 + $lines[0] | Should -Match ': direct-default$' + $lines[1] | Should -Match ': buffer-default$' + } +} + + +Describe 'New-LogEntry file-write integration' { + BeforeEach { New-LogEntry -ClearBuffer } + + It 'can retry buffered entries after a real filesystem failure' { + New-LogEntry -LogMessage 'retained-after-failure' -BufferOnly + { New-LogEntry -FlushBuffer -LogFilePath $TestDrive -NoConsole -ErrorAction Stop } | Should -Throw + $before = @(New-LogEntry -GetBuffer) + $before.Count | Should -Be 1 + $path = Join-Path $TestDrive 'retried.log' + $written = @(New-LogEntry -FlushBuffer -LogFilePath $path -NoConsole -PassThru) + $written[0] | Should -Be $before[0] + (Get-Content -LiteralPath $path) | Should -Be $before[0] + @(New-LogEntry -GetBuffer).Count | Should -Be 0 + } + + It 'preserves every direct and buffered line from concurrent processes' { + $path = Join-Path $TestDrive 'concurrent.log' + $manifest = [System.IO.Path]::ChangeExtension((Get-Module IT-ToolBox).Path, '.psd1') + $jobs = @() + try { + $jobs = @(1..3 | ForEach-Object { + Start-Job -ArgumentList $manifest, $path, $_ -ScriptBlock { + param($Manifest, $Path, $Worker) + Import-Module $Manifest -ErrorAction Stop + foreach ($i in 1..20) { + New-LogEntry -LogMessage "worker-$Worker-direct-$i" -LogFilePath $Path -NoConsole -ErrorAction Stop + New-LogEntry -LogMessage "worker-$Worker-buffer-$i" -BufferOnly -ErrorAction Stop + } + New-LogEntry -FlushBuffer -LogFilePath $Path -NoConsole -ErrorAction Stop + } + }) + $jobs | Receive-Job -Wait -ErrorAction Stop + foreach ($job in $jobs) { $job.State | Should -Be 'Completed' } + $lines = @(Get-Content -LiteralPath $path) + $lines.Count | Should -Be 120 + $messages = @($lines | ForEach-Object { $_ -replace '^.*\[INFO\]: ', '' }) + @($messages | Select-Object -Unique).Count | Should -Be 120 + foreach ($worker in 1..3) { + foreach ($i in 1..20) { + $messages | Should -Contain "worker-$worker-direct-$i" + $messages | Should -Contain "worker-$worker-buffer-$i" + } + } + } + finally { + if ($jobs.Count -gt 0) { $jobs | Remove-Job -Force } + } + } +} + + +Describe 'Interactive default log path' { + It 'writes in the current directory when called without a script file' { + $manifest = [System.IO.Path]::ChangeExtension((Get-Module IT-ToolBox).Path, '.psd1') + $job = Start-Job -ArgumentList $manifest, $TestDrive -ScriptBlock { + param($Manifest, $Directory) + Import-Module $Manifest -ErrorAction Stop + Set-Location $Directory + New-LogEntry -LogMessage 'interactive-default' -NoConsole -ErrorAction Stop + New-LogEntry -LogMessage 'interactive-buffer' -BufferOnly + New-LogEntry -FlushBuffer -NoConsole -ErrorAction Stop + } + try { + $job | Receive-Job -Wait -ErrorAction Stop + $job.State | Should -Be 'Completed' + $logs = @(Get-ChildItem $TestDrive -Filter 'PowerShell-LogFile-*.log') + $logs.Count | Should -BeGreaterThan 0 + $lines = @(Get-Content -LiteralPath $logs.FullName) + $lines.Count | Should -Be 2 + $lines[0] | Should -Match ': interactive-default$' + $lines[1] | Should -Match ': interactive-buffer$' + } + finally { $job | Remove-Job -Force } + } +}