From 50db87b6816817c3ac47d49395c7276484f942a0 Mon Sep 17 00:00:00 2001 From: Mikey Lombardi Date: Tue, 12 Aug 2025 16:19:35 -0500 Subject: [PATCH] (REPRO) Trace messaging issues repro This change creates a repro resource, tests, and example configuration to enumerate issues with the current model for bubbling up trace messages from resources. The `resources/repro.trace` folder contains the relevant files: - `repro.trace.dsc.resource.json` - resource manifest - `repro.trace.resource.ps1` - resource script - `repro.trace.tests.ps1` - failing tests for behavior - `repro.config.dsc.yaml` - config file with every repro case - `repro.config.result.yaml` - snapshot of output from config The repro covers several test cases to show how DSC behaves when a resource emits trace messages as compressed JSON to stderr: - `simpleMessaging` shows the behavior for emitting a string for a given trace level, like `{"warn":"my warning"}`. - `minimalStruct` shows the behavior for emitting a struct that defines the `level`, `timestamp`, and `fields.message` properties. - `structWithMetadata` also defines the `target` and `lineNumber` properties to bubble up for the resource. - `structWithAdditionalFields` defines fields.`extraString` and `fields`extraInteger` to bubble up related context. - `structWithMetadataAndAdditionalFields` includes defines `target`, `lineNumber`, `fields.extraString`, and `fields.extraInteger`. The resource itself returns the name of the test case and uses the `emittedData` read-only property to return the data that it emitted to stderr for DSC to interpret as a trace message. Findings: - For the structured representation, DSC only retains the trace level and message contents. The `timestamp`, `target`, `lineNumber`, and additional fields are all ignored or dropped. - Regardless of emitted JSON, DSC munges the message to insert the process ID like `PID 1234: `. - For structured representation, DSC bubbles up the message in the `trace_message` field instead of `message`. - For `dsc config get`, DSC doesn't seem to capture the emitted messages in the result object, only emitting them to stderr. This repro shows that we have some unexpected behaviors for resource messaging that may guide a review and update of the implementation. --- build.ps1 | 3 +- resources/repro.trace/copy_files.txt | 1 + resources/repro.trace/repro.config.dsc.yaml | 51 +++ .../repro.trace/repro.config.result.yaml | 89 +++++ .../repro.trace/repro.trace.dsc.resource.json | 45 +++ .../repro.trace/repro.trace.resource.ps1 | 104 ++++++ resources/repro.trace/repro.trace.tests.ps1 | 333 ++++++++++++++++++ 7 files changed, 625 insertions(+), 1 deletion(-) create mode 100644 resources/repro.trace/copy_files.txt create mode 100644 resources/repro.trace/repro.config.dsc.yaml create mode 100644 resources/repro.trace/repro.config.result.yaml create mode 100644 resources/repro.trace/repro.trace.dsc.resource.json create mode 100644 resources/repro.trace/repro.trace.resource.ps1 create mode 100644 resources/repro.trace/repro.trace.tests.ps1 diff --git a/build.ps1 b/build.ps1 index 5cb6b392..d67747c3 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 00000000..cef010c3 --- /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 00000000..67133a30 --- /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 00000000..9b566885 --- /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 00000000..81dd3a46 --- /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 00000000..f3e4d439 --- /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 00000000..ca724269 --- /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