command.tests.ps1

Describe "Trace-Command" -tags "Feature" {
    
    Context "Listener options" {
        BeforeAll {
            $logFile = setup -f traceCommandLog.txt -pass
            $actualLogFile = setup -f actualTraceCommandLog.txt -pass
        }

        AfterEach {
            if ( test-path $logfile ) { Remove-Item $logFile }
            if ( test-path $actualLogFile ) { Remove-Item $actualLogFile }
        }
        
        It "LogicalOperationStack works" -pending:($IsCoreCLR) {
            $keyword = "Trace_Command_ListenerOption_LogicalOperationStack_Foo"
            $stack = [System.Diagnostics.Trace]::CorrelationManager.LogicalOperationStack
            $stack.Push($keyword)

            Trace-Command -Name * -Expression {write-output Foo} -ListenerOption LogicalOperationStack -FilePath $logfile

            $log = Get-Content $logfile | Where-Object {$_ -like "*LogicalOperationStack=$keyword*"}            
            $log.Count | Should BeGreaterThan 0
        } 

        It "Callstack works" -pending:($IsCoreCLR) {
            Trace-Command -Name * -Expression {write-output Foo} -ListenerOption Callstack -FilePath $logfile
            $log = Get-Content $logfile | Where-Object {$_ -like "*Callstack=   * System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)*"}
            $log.Count | Should BeGreaterThan 0
        }

        It "Datetime works" {
            $expectedDate = Trace-Command -Name * -Expression {Get-Date} -ListenerOption DateTime -FilePath $logfile
            $log = Get-Content $logfile | Where-Object {$_ -like "*DateTime=*"}
            $results = $log | ForEach-Object {[DateTime]::Parse($_.Split("=")[1])}

            ## allow a gap of 6 seconds. All traces should be finished within 6 seconds.
            $allowedGap = [timespan](60 * 1000 * 1000)
            $results | ForEach-Object { 
                    $actualGap = $_ - $expectedDate; 
                    if ($expectedDate -gt $_) 
                    { 
                        $actualGap = $expectedDate - $_;
                    }

                    $allowedGap | Should BeGreaterThan $actualGap
                }
        }

        It "None options has no effect" {            
            Trace-Command -Name * -Expression {write-output Foo} -ListenerOption None -FilePath $actualLogfile
            Trace-Command -name * -Expression {write-output Foo} -FilePath $logfile

            Compare-Object (Get-Content $actualLogfile) (Get-Content $logfile) | Should BeNullOrEmpty
        }

        It "ThreadID works" {
            Trace-Command -Name * -Expression {write-output Foo} -ListenerOption ThreadId -FilePath $logfile
            $log = Get-Content $logfile | Where-Object {$_ -like "*ThreadID=*"}
            $results = $log | ForEach-Object {$_.Split("=")[1]}

            $results | % { $_ | Should Be ([threading.thread]::CurrentThread.ManagedThreadId) }
        }

        It "Timestamp creates logs in ascending order" {
            Trace-Command -Name * -Expression {write-output Foo} -ListenerOption Timestamp -FilePath $logfile
            $log = Get-Content $logfile | Where-Object {$_ -like "*Timestamp=*"}
            $results = $log | ForEach-Object {$_.Split("=")[1]}
            $sortedResults = $results | Sort-Object
            $sortedResults | Should Be $results 
        }

        It "ProcessId logs current process Id" {
            Trace-Command -Name * -Expression {write-output Foo} -ListenerOption ProcessId -FilePath $logfile
            $log = Get-Content $logfile | Where-Object {$_ -like "*ProcessID=*"}
            $results = $log | ForEach-Object {$_.Split("=")[1]}

            $results | ForEach-Object { $_ | Should Be $pid }
        }
    }        
}