diff --git a/build.ps1 b/build.ps1 index 5cb6b3922..d67747c30 100755 --- a/build.ps1 +++ b/build.ps1 @@ -324,7 +324,8 @@ if (!$SkipBuild) { "sshdconfig", "tools/dsctest", "tools/test_group_resource", - "y2j" + "y2j", + "resources/repro.trace" ) $pedantic_unclean_projects = @() $clippy_unclean_projects = @("tree-sitter-dscexpression", "tree-sitter-ssh-server-config") diff --git a/resources/repro.trace/copy_files.txt b/resources/repro.trace/copy_files.txt new file mode 100644 index 000000000..cef010c39 --- /dev/null +++ b/resources/repro.trace/copy_files.txt @@ -0,0 +1 @@ +./repro.trace.resource.ps1 diff --git a/resources/repro.trace/repro.config.dsc.yaml b/resources/repro.trace/repro.config.dsc.yaml new file mode 100644 index 000000000..67133a304 --- /dev/null +++ b/resources/repro.trace/repro.config.dsc.yaml @@ -0,0 +1,51 @@ +$schema: https://aka.ms/dsc/schemas/v3/bundled/config/document.vscode.json +resources: + - type: Dsc.Repro/Trace + name: Simple messaging + properties: + case: simpleMessage + # emittedData: # Output from repro testing + # warn: Simple message + - type: Dsc.Repro/Trace + name: Minimal struct + properties: + case: minimalStruct + # emittedData: # Output from repro testing + # timestamp: 2024-08-12T15:26:25.4477204-05:00 + # level: WARN + # fields: + # message: structured trace message + - type: Dsc.Repro/Trace + name: Struct with metadata + properties: + case: structWithMetadata + # emittedData: # Output from repro testing + # timestamp: 2024-08-12T15:26:26.1439312-05:00 + # level: WARN + # fields: + # message: structured trace message + # target: C:\code\powershell\working\docs\DSC\bin\debug\repro.trace.resource.ps1 + - type: Dsc.Repro/Trace + name: Sruct with additional fields + properties: + case: structWithAdditionalFields + # emittedData: # Output from repro testing + # timestamp: 2024-08-12T15:26:27.1288515-05:00 + # level: WARN + # fields: + # message: structured trace message + # extraInteger: 10 + # extraString: additional data + - type: Dsc.Repro/Trace + name: Struct with metadata and additional fields + properties: + case: structWithMetadataAndAdditionalFields + # emittedData: # Output from repro testing + # timestamp: 2024-08-12T15:26:27.7689792-05:00 + # level: WARN + # fields: + # message: structured trace message + # extraInteger: 10 + # extraString: additional data + # target: C:\code\powershell\working\docs\DSC\bin\debug\repro.trace.resource.ps1 + # lineNumber: 94 diff --git a/resources/repro.trace/repro.config.result.yaml b/resources/repro.trace/repro.config.result.yaml new file mode 100644 index 000000000..9b5668856 --- /dev/null +++ b/resources/repro.trace/repro.config.result.yaml @@ -0,0 +1,89 @@ +# STDERR messages START +# 2025-08-12T20:26:24.687009Z WARN PID 5020: Simple message +# 2025-08-12T20:26:25.459746Z WARN trace_message="PID 10368: structured trace message" +# 2025-08-12T20:26:26.165380Z WARN trace_message="PID 19292: structured trace message" +# 2025-08-12T20:26:27.156677Z WARN trace_message="PID 25044: structured trace message" +# 2025-08-12T20:26:27.793703Z WARN trace_message="PID 5984: structured trace message" +# STDERR messages END +metadata: + Microsoft.DSC: + version: 3.1.0 + operation: get + executionType: actual + startDatetime: 2025-08-12T15:26:19.134728100-05:00 + endDatetime: 2025-08-12T15:26:27.907077900-05:00 + duration: PT8.7723498S + securityContext: restricted +results: +- metadata: + Microsoft.DSC: + duration: PT1.0954907S + name: Simple messaging + type: Dsc.Repro/Trace + result: + actualState: + case: simpleMessage + emittedData: + warn: Simple message +- metadata: + Microsoft.DSC: + duration: PT0.7814828S + name: Minimal struct + type: Dsc.Repro/Trace + result: + actualState: + case: minimalStruct + emittedData: + timestamp: 2024-08-12T15:26:25.4477204-05:00 + level: WARN + fields: + message: structured trace message +- metadata: + Microsoft.DSC: + duration: PT0.7530085S + name: Struct with metadata + type: Dsc.Repro/Trace + result: + actualState: + case: structWithMetadata + emittedData: + timestamp: 2024-08-12T15:26:26.1439312-05:00 + level: WARN + fields: + message: structured trace message + target: C:\code\powershell\working\docs\DSC\bin\debug\repro.trace.resource.ps1 + lineNumber: 94 +- metadata: + Microsoft.DSC: + duration: PT0.9343058S + name: Sruct with additional fields + type: Dsc.Repro/Trace + result: + actualState: + case: structWithAdditionalFields + emittedData: + timestamp: 2024-08-12T15:26:27.1288515-05:00 + level: WARN + fields: + message: structured trace message + extraInteger: 10 + extraString: additional data +- metadata: + Microsoft.DSC: + duration: PT0.6398828S + name: Struct with metadata and additional fields + type: Dsc.Repro/Trace + result: + actualState: + case: structWithMetadataAndAdditionalFields + emittedData: + timestamp: 2024-08-12T15:26:27.7689792-05:00 + level: WARN + fields: + message: structured trace message + extraInteger: 10 + extraString: additional data + target: C:\code\powershell\working\docs\DSC\bin\debug\repro.trace.resource.ps1 + lineNumber: 94 +messages: [] +hadErrors: false \ No newline at end of file diff --git a/resources/repro.trace/repro.trace.dsc.resource.json b/resources/repro.trace/repro.trace.dsc.resource.json new file mode 100644 index 000000000..81dd3a463 --- /dev/null +++ b/resources/repro.trace/repro.trace.dsc.resource.json @@ -0,0 +1,45 @@ +{ + "$schema": "https://aka.ms/dsc/schemas/v3/bundled/resource/manifest.vscode.json", + "type": "Dsc.Repro/Trace", + "version": "0.1.0", + "description": "Repro resource for trace messaging", + "schema": { + "embedded": { + "$schema": "https://json-schema.org/draft/2020-12/schema", + "type": "object", + "properties": { + "case": { + "title": "Test case", + "description": "Defines which test case to emit messages for", + "type": "string", + "enum": [ + "simpleMessage", + "minimalStruct", + "structWithMetadata", + "structWithAdditionalFields", + "structWithMetadataAndAdditionalFields" + ] + }, + "emittedData":{ + "title": "Emitted data", + "description": "Contains the message data emitted by the resource as compressed JSON to stderr", + "type": "object", + "readOnly": true + } + } + } + }, + "get": { + "executable": "pwsh", + "args": [ + "-NoLogo", + "-NonInteractive", + "-NoProfile", + "-ExecutionPolicy", + "Bypass", + "-Command", + "$Input | ./repro.trace.resource.ps1 Get" + ], + "input": "stdin" + } +} \ No newline at end of file diff --git a/resources/repro.trace/repro.trace.resource.ps1 b/resources/repro.trace/repro.trace.resource.ps1 new file mode 100644 index 000000000..f3e4d439a --- /dev/null +++ b/resources/repro.trace/repro.trace.resource.ps1 @@ -0,0 +1,104 @@ +# Copyright (c) Microsoft Corporation. +# Licensed under the MIT License. +<# + .SYNOPSIS + Repro resource for trace messaging + + .PARAMETER Operation + Operation to perform. Valid operations are: + + - `Get` - return the current state of the instance. + + .PARAMETER JsonInput + Configuration or resource input in JSON format. +#> +[CmdletBinding()] +param( + [Parameter(Mandatory = $true, Position = 0)] + [ValidateSet('Get')] + [string]$Operation, + [Parameter(Mandatory = $false, Position = 1, ValueFromPipeline = $true)] + [string]$jsonInput = '@{}' +) + +begin { + enum TestCase { + SimpleMessage + MinimalStruct + StructWithMetadata + StructWithAdditionalFields + StructWithMetadataAndAdditionalFields + } + + $script:ResourcePath = $MyInvocation.MyCommand.Path + + class TraceTesting { + [TestCase] $Case + [ordered] $EmittedData + + [ordered] TraceData() { + if ($null -ne $this.EmittedData) { + return $this.EmittedData + } + + if ($this.Case -eq [TestCase]::SimpleMessage) { + $this.EmittedData = [ordered]@{ + warn = "Simple message" + } + return $this.EmittedData + } + + $date = Get-Date + $date = $date.AddYears(-1) + $this.EmittedData = [ordered]@{ + timestamp = $date + level = 'WARN' + fields = [ordered]@{ + message = "structured trace message" + } + } + + if ($this.Case -in @([TestCase]::StructWithMetadata, [TestCase]::StructWithMetadataAndAdditionalFields)) { + $this.EmittedData.target = $script:ResourcePath + $this.EmittedData.lineNumber = 94 + } + if ($this.Case -in @([TestCase]::StructWithAdditionalFields, [TestCase]::StructWithMetadataAndAdditionalFields)) { + $this.EmittedData.fields.extraInteger = 10 + $this.EmittedData.fields.extraString = "additional data" + } + + return $this.EmittedData + } + + [string] TraceJson() { + return $this.TraceData() | ConvertTo-Json -Compress + } + [string] ToJson() { + $jsonCase = $this.Case.ToString() + $jsonCase = $jsonCase.Substring(0, 1).ToLowerInvariant() + $jsonCase.Substring(1) + return [ordered] @{ + case = $jsonCase + emittedData = $this.TraceData() + } | ConvertTo-Json -Compress -Depth 99 + } + static [TraceTesting] ParseJson([string]$inputJson) { + $parsed = $inputJson | ConvertFrom-Json + + return [TraceTesting]@{ + Case = $parsed.case + } + } + } +} + +process { + [TraceTesting]$parsedInput = [TraceTesting]::ParseJson($jsonInput) + $host.ui.WriteErrorLine($parsedInput.TraceJson()) + + switch ($Operation) { + 'Get' { + $parsedInput.ToJson() + exit 0 + } + } +} diff --git a/resources/repro.trace/repro.trace.tests.ps1 b/resources/repro.trace/repro.trace.tests.ps1 new file mode 100644 index 000000000..ca724269f --- /dev/null +++ b/resources/repro.trace/repro.trace.tests.ps1 @@ -0,0 +1,333 @@ +BeforeAll { + class ReproResult { + [object]$Result + [object]$Trace + } + + function Invoke-DscRepro { + [CmdletBinding()] + param([hashtable]$instance) + + begin { + $dscArgs = @( + '--trace-format', 'json' + 'resource' + 'get' + '--resource', 'Dsc.Repro/Trace' + '--input', ($instance | ConvertTo-Json -Compress) + ) + } + + process { + $emitted = dsc @dscArgs 2>&1 | ConvertFrom-Json + + [ReproResult]@{ + Result = $emitted[1] + Trace = $emitted[0] + } + } + } +} + +Describe 'Resource trace message behavior' { + describe "simple messaging" { + BeforeAll { + $repro = Invoke-DscRepro -Instance @{ + case = 'simpleMessage' + } + $actualCase = $repro.Result.actualState.case + $emittedData = $repro.Result.actualState.emittedData + $traceTimestamp = $repro.Trace.timestamp -as [datetime] + } + context "actual state" { + it "returns the expected case for actual state" { + $actualCase | Should -BeExactly 'simpleMessage' + } + context "emitted data" { + it "returns 'warn' with the expected message" { + $emittedData.warn | Should -BeExactly 'Simple message' + } + } + } + + context "DSC emitted trace message" { + it "defines the message field" { + $repro.Trace.fields.message | Should -Not -BeNullOrEmpty + } + it "defines the expected message with PID prefix" { + $repro.Trace.fields.message | Should -Match '^PID \d+\:\s+Simple message' + } + it "doesn't define the trace_message field" { + $repro.Trace.fields.trace_message | Should -BeNullOrEmpty + } + it 'bubbles up the expected timestamp' { + $traceTimestamp.Date | Should -be (Get-Date).Date + } + it 'bubbles up the expected level' { + $repro.Trace.level | Should -BeExactly 'WARN' + } + it "doesn't define the target field" { + $repro.Trace.target | Should -BeNullOrEmpty + } + it "doesn't define the line_number field" { + $repro.Trace.line_number | Should -BeNullOrEmpty + } + } + } + describe "Minimal struct" { + BeforeAll { + $repro = Invoke-DscRepro -Instance @{ + case = 'minimalStruct' + } + $actualCase = $repro.Result.actualState.case + $emittedData = $repro.Result.actualState.emittedData + $expectedDate = (Get-Date).AddYears(-1).Date + } + context "actual state" { + it "returns the expected case for actual state" { + $actualCase | Should -Be 'minimalStruct' + } + context "emitted data" { + it "defines 'fields.message'" { + $emittedData.fields.message | Should -BeExactly 'structured trace message' + } + it "defines 'timestamp' for one year ago" { + ($emittedData.timestamp -as [datetime]).Date | Should -Be $expectedDate + } + it "defines 'level' as 'WARN'" { + $emittedData.level | Should -BeExactly 'WARN' + } + } + } + context "DSC emitted trace message" { + it "defines the message field" { + $repro.Trace.fields.message | Should -Not -BeNullOrEmpty + } + it "defines the correct message" { + $repro.Trace.fields.message | Should -match 'structured trace message$' + } + it "doesn't define the trace_message field" { + $repro.Trace.fields.trace_message | Should -BeNullOrEmpty + } + it 'bubbles up the expected timestamp' { + ($repro.Trace.timestamp -as [datetime]).Date | Should -Be $expectedDate + } + it 'bubbles up the expected level' { + $repro.Trace.level | Should -BeExactly 'WARN' + } + it "doesn't define the target field" { + $repro.Trace.target | Should -BeNullOrEmpty + } + it "doesn't define the line_number field" { + $repro.Trace.line_number | Should -BeNullOrEmpty + } + } + } + describe "Struct with metadata" { + BeforeAll { + $repro = Invoke-DscRepro -Instance @{ + case = 'structWithMetadata' + } + $actualCase = $repro.Result.actualState.case + $emittedData = $repro.Result.actualState.emittedData + $expectedDate = (Get-Date).AddYears(-1).Date + $scriptFile = Get-Command repro.trace.resource.ps1 | Select-Object -ExpandProperty Source + } + context "actual state" { + it "returns the expected case for actual state" { + $actualCase | Should -Be 'structWithMetadata' + } + context "emitted data" { + it "defines 'fields.message'" { + $emittedData.fields.message | Should -BeExactly 'structured trace message' + } + it "defines 'timestamp' for one year ago" { + ($emittedData.timestamp -as [datetime]).Date | Should -Be $expectedDate + } + it "defines 'level' as 'WARN'" { + $emittedData.level | Should -BeExactly 'WARN' + } + it "defines 'target' as the path to the script file" { + $emittedData.target | Should -Be $scriptFile + } + it "defines 'lineNumber' as 94" { + $emittedData.lineNumber | Should -be 94 + } + } + } + context "DSC emitted trace message" { + it "defines the message field" { + $repro.Trace.fields.message | Should -Not -BeNullOrEmpty + } + it "defines the correct message" { + $repro.Trace.fields.message | Should -match 'structured trace message$' + } + it "doesn't define the trace_message field" { + $repro.Trace.fields.trace_message | Should -BeNullOrEmpty + } + it 'bubbles up the expected timestamp' { + ($repro.Trace.timestamp -as [datetime]).Date | Should -Be $expectedDate + } + it 'bubbles up the expected level' { + $repro.Trace.level | Should -BeExactly 'WARN' + } + it "defines the target field" { + $repro.Trace.target | Should -Not -BeNullOrEmpty + } + it "bubbles up the target field as expected" { + $repro.Trace.target | Should -Be $scriptFile + } + it "defines the line_number field" { + $repro.Trace.line_number | Should -Not -BeNullOrEmpty + } + it "bubbles up the line number as expected" { + $repro.Trace.line_number | Should -Be 94 + } + } + } + describe "Struct with additional fields" { + BeforeAll { + $repro = Invoke-DscRepro -Instance @{ + case = 'structWithAdditionalFields' + } + $actualCase = $repro.Result.actualState.case + $emittedData = $repro.Result.actualState.emittedData + $expectedDate = (Get-Date).AddYears(-1).Date + } + context "actual state" { + it "returns the expected case for actual state" { + $actualCase | Should -Be 'structWithAdditionalFields' + } + context "emitted data" { + it "defines 'fields.message'" { + $emittedData.fields.message | Should -BeExactly 'structured trace message' + } + it "defines 'fields.extraInteger" { + $emittedData.fields.extraInteger | Should -Be 10 + } + it "defines 'fields.extraString" { + $emittedData.fields.message | Should -BeExactly 'additional data' + } + it "defines 'timestamp' for one year ago" { + ($emittedData.timestamp -as [datetime]).Date | Should -Be $expectedDate + } + it "defines 'level' as 'WARN'" { + $emittedData.level | Should -BeExactly 'WARN' + } + } + } + context "DSC emitted trace message" { + it "defines the 'message' field" { + $repro.Trace.fields.message | Should -Not -BeNullOrEmpty + } + it "bubbles up the correct message" { + $repro.Trace.fields.message | Should -match 'structured trace message$' + } + it "defines the 'extraInteger' field" { + $repro.Trace.fields.extraInteger | Should -Not -BeNullOrEmpty + } + it "bubbles up the correct value for 'extraInteger'" { + $repro.Trace.fields.extraInteger | Should -Be 10 + } + it "defines the 'extraString' field" { + $repro.Trace.fields.extraString | Should -Not -BeNullOrEmpty + } + it "bubbles up the correct value for 'extraString'" { + $repro.Trace.fields.extraString | Should -BeExactly 'additional data' + } + it "doesn't define the trace_message field" { + $repro.Trace.fields.trace_message | Should -BeNullOrEmpty + } + it 'bubbles up the expected timestamp' { + ($repro.Trace.timestamp -as [datetime]).Date | Should -Be $expectedDate + } + it 'bubbles up the expected level' { + $repro.Trace.level | Should -BeExactly 'WARN' + } + it "doesn't define the target field" { + $repro.Trace.target | Should -BeNullOrEmpty + } + it "doesn't define the line_number field" { + $repro.Trace.line_number | Should -BeNullOrEmpty + } + } + } + + describe "Struct with metadata and additional fields" { + BeforeAll { + $repro = Invoke-DscRepro -Instance @{ + case = 'structWithMetadataAndAdditionalFields' + } + $actualCase = $repro.Result.actualState.case + $emittedData = $repro.Result.actualState.emittedData + $expectedDate = (Get-Date).AddYears(-1).Date + $scriptFile = Get-Command repro.trace.resource.ps1 | Select-Object -ExpandProperty Source + } + context "actual state" { + it "returns the expected case for actual state" { + $actualCase | Should -Be 'structWithMetadataAndAdditionalFields' + } + context "emitted data" { + it "defines 'fields.message'" { + $emittedData.fields.message | Should -BeExactly 'structured trace message' + } + it "defines 'fields.extraInteger" { + $emittedData.fields.extraInteger | Should -Be 10 + } + it "defines 'fields.extraString" { + $emittedData.fields.extraString | Should -BeExactly 'additional data' + } + it "defines 'timestamp' for one year ago" { + ($emittedData.timestamp -as [datetime]).Date | Should -Be $expectedDate + } + it "defines 'level' as 'WARN'" { + $emittedData.level | Should -BeExactly 'WARN' + } + it "defines 'target' as the path to the script file" { + $emittedData.target | Should -Be $scriptFile + } + it "defines 'lineNumber' as 94" { + $emittedData.lineNumber | Should -be 94 + } + } + } + context "DSC emitted trace message" { + it "defines the 'message' field" { + $repro.Trace.fields.message | Should -Not -BeNullOrEmpty + } + it "bubbles up the correct message" { + $repro.Trace.fields.message | Should -match 'structured trace message$' + } + it "defines the 'extraInteger' field" { + $repro.Trace.fields.extraInteger | Should -Not -BeNullOrEmpty + } + it "bubbles up the correct value for 'extraInteger'" { + $repro.Trace.fields.extraInteger | Should -Be 10 + } + it "defines the 'extraString' field" { + $repro.Trace.fields.extraString | Should -Not -BeNullOrEmpty + } + it "bubbles up the correct value for 'extraString'" { + $repro.Trace.fields.extraString | Should -BeExactly 'additional data' + } + it "doesn't define the trace_message field" { + $repro.Trace.fields.trace_message | Should -BeNullOrEmpty + } + it 'bubbles up the expected timestamp' { + ($repro.Trace.timestamp -as [datetime]).Date | Should -Be $expectedDate + } + it "defines the target field" { + $repro.Trace.target | Should -Not -BeNullOrEmpty + } + it "bubbles up the target field as expected" { + $repro.Trace.target | Should -Be $scriptFile + } + it "defines the line_number field" { + $repro.Trace.line_number | Should -Not -BeNullOrEmpty + } + it "bubbles up the line number as expected" { + $repro.Trace.line_number | Should -Be 94 + } + } + } +} \ No newline at end of file