Fix tracing pass-through structure

[SteveL-MSFT]

PR Summary

This fixes how structured pass-through traces from child processes are correctly structured by DSC. The process id (pid) is now a field instead of being prefixed to the message, this is also true for target and line number if specified.

PR Context

Address part of the issues raised in #1048

[Copilot]

Pull Request Overview

This PR fixes the structure of pass-through traces from child processes by changing how process ID (pid), target, and line number are formatted. Instead of prefixing the PID to the message string, these fields are now structured as separate fields in the trace log.

Key changes:

• Refactored trace logging to use structured fields instead of concatenated strings
• Updated test coverage to verify the new structured format includes pid, target, and line_number fields
• Improved test robustness with better error reporting and validation

Reviewed Changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 1 comment.

File	Description
dsc_lib/src/dscresources/command_resource.rs	Refactored log_stderr_line function to use structured logging fields instead of string formatting
dsc/tests/dsc_tracing.tests.ps1	Enhanced test to validate structured fields (pid, target, line_number) and improved error reporting

---

_{Tip: Customize your code reviews with copilot-instructions.md. Create the file or learn how to get started.}

[michaeltlombardi]

Rebased #1048 on this PR for local testing, and I have some findings with example output after:

1. It doesn't look like the timestamp bubbles up (in the test case I'm intentionally using a timestamp for 2024) when passed from the resource.
2. The target and line number information are captured as fields, but surfaced differently than for native non-passthrough traces (which I only see when specifying --trace-level as debug or trace)
3. The additional structured data (extraInteger and extraString adjacent to message) is still lost when bubbling up the trace.

Updated output examples

• trace level warn, trace format default

  $result = dsc config get --file .\resources\repro.trace\repro.config.dsc.yaml

  2025-08-13T22:09:15.558298Z  WARN Simple message pid=17092
  2025-08-13T22:09:16.245417Z  WARN structured trace message for MinimalStruct pid=13812
  2025-08-13T22:09:16.868091Z  WARN structured trace message for StructWithMetadata pid=25652 target="C:\\code\\dsc\\docs\\bin\\debug\\repro.trace.resource.ps1" line_number=94
  2025-08-13T22:09:17.547376Z  WARN structured trace message for StructWithAdditionalFields pid=11540
  2025-08-13T22:09:18.157590Z  WARN structured trace message for StructWithMetadataAndAdditionalFields pid=704 target="C:\\code\\dsc\\docs\\bin\\debug\\repro.trace.resource.ps1" line_number=94

• trace level debug, trace format default

  $result = dsc --trace-level debug config get --file .\resources\repro.trace\repro.config.dsc.yaml

  2025-08-13T22:12:05.470024Z  WARN dsc_lib::dscresources::command_resource: 886: Simple message pid=27380
  2025-08-13T22:12:06.210666Z  WARN dsc_lib::dscresources::command_resource: 870: structured trace message for MinimalStruct pid=24784
  2025-08-13T22:12:06.842807Z  WARN dsc_lib::dscresources::command_resource: 870: structured trace message for StructWithMetadata pid=20240 target="C:\\code\\dsc\\docs\\bin\\debug\\repro.trace.resource.ps1" line_number=94
  2025-08-13T22:12:07.489946Z  WARN dsc_lib::dscresources::command_resource: 870: structured trace message for StructWithAdditionalFields pid=7120
  2025-08-13T22:12:08.181378Z  WARN dsc_lib::dscresources::command_resource: 870: structured trace message for StructWithMetadataAndAdditionalFields pid=25708 target="C:\\code\\dsc\\docs\\bin\\debug\\repro.trace.resource.ps1" line_number=94

• trace level warn, trace format json

  $result = dsc --trace-format json config get --file .\resources\repro.trace\repro.config.dsc.yaml 2>&1 |
    ConvertFrom-Json
  $result[-2] | ConvertTo-Json

  {
    "timestamp": "2025-08-13T22:15:57.19917Z",
    "level": "WARN",
    "fields": {
      "message": "structured trace message for StructWithMetadataAndAdditionalFields",
      "pid": 24268,
      "target": "C:\\code\\dsc\\docs\\bin\\debug\\repro.trace.resource.ps1",
      "line_number": 94
    }
  }

• trace level debug, trace format json

    $result = dsc --trace-level debug --trace-format json config get --file .\resources\repro.trace\repro.config.dsc.yaml 2>&1 |
      ConvertFrom-Json
    $result[-3] | ConvertTo-Json

  {
    "timestamp": "2025-08-13T22:17:34.44459Z",
    "level": "WARN",
    "fields": {
      "message": "structured trace message for StructWithMetadataAndAdditionalFields",
      "pid": 23248,
      "target": "C:\\code\\dsc\\docs\\bin\\debug\\repro.trace.resource.ps1",
      "line_number": 94
    },
    "target": "dsc_lib::dscresources::command_resource",
    "line_number": 870
  }

[SteveL-MSFT]

@michaeltlombardi per tokio-rs/tracing#2419 those top level properties can't be overwritten at this time

[michaeltlombardi]

With it being a limitation of the library, I think we can defer the problem of bubbling up the timestamp, target, and line_number fields to the top level. Instead, I think this PR should ensure the timestamp (if supplied) also bubbles up to the fields.

I'm not sure how we can bubble up the additional fields at this time - right now I think we're just losing extraInteger and extraString - but without being able to bubble that data up, it's hard to advise resource authors to put in the effort to send the structured trace over the simple trace.

We may also want to provide some namespacing for the nested fields to more clearly differentiate them from the top-level fields - it can be confusing to see two different values for target in the output. We could borrow from the OpenTelemetry Semantic conventions for CLI (command line interface) programs and prefix those values with process., like:

{
  "timestamp": "2025-08-13T22:17:34.44459Z",
  "level": "WARN",
  "fields": {
    "message": "structured trace message for StructWithMetadataAndAdditionalFields",
    "process.pid": 23248,
    "process.target": "C:\\code\\dsc\\docs\\bin\\debug\\repro.trace.resource.ps1",
    "process.line_number": 94,
    "process.timestamp": "2024-08-13T22:17:34.24359Z"
  },
  "target": "dsc_lib::dscresources::command_resource",
  "line_number": 870
}

Regarding the missing data, maybe we can just collect it into a map, like:

{
  "timestamp": "2025-08-13T22:17:34.44459Z",
  "level": "WARN",
  "fields": {
    "message": "structured trace message for StructWithMetadataAndAdditionalFields",
    "process.pid": 23248,
    "process.target": "C:\\code\\dsc\\docs\\bin\\debug\\repro.trace.resource.ps1",
    "process.line_number": 94,
    "process.timestamp": "2024-08-13T22:17:34.24359Z",
    "process.data": {
      "extraInteger": 10,
      "extraString": "additional data"
  },
  "target": "dsc_lib::dscresources::command_resource",
  "line_number": 870
}

[michaeltlombardi]

I spent some time trying to see how we could get data to work properly and unfortunately the only way I see right now is to use the valuable crate, define newtypes for wrapping serde_json::Value and serde_json::Map<String, Value>, and implement the Valuable trait, which seems like a lot of lift.

There are two open (for a while) PRs for handling this:

• Valuable bridge for serde_json::Value tokio-rs/valuable#61 for implementing valuable::Valuable on serde_json::Value in the tracing crate
• Feature valuable serde-rs/json#1256 for implementing valuable::Valuable on serde_json::Value in the serde_json crate.

Either of them being merged would more or less resolve this problem for us nicely, but regardless we would have to add the valuable feature to tracing and tracing-subscriber and enable the tracing_unstable build flag (e.g. RUSTFLAGS="--cfg tracing_unstable" cargo build) because it's an experimental feature for now.

I'm now thinking we may want to defer structured message data until we implement OpenTelemetry, where we can re-examine the model for bubbling up messages from invoked commands.