Fix progress display when using JSON, add None option; exhance progress schema #644

SteveL-MSFT · 2025-02-18T01:16:10Z

PR Summary

Based on discussion with WinGet team, they needed more information in the progress JSON. Changes:

Moved all progress code into a single file
Created ProgressBar struct that is used to provide progress instead of calling the crate APIs directly
Added None option to --progress-format
Fixed so that when json option is used, no progress is written even when interactive
Fixed use of writing progress so when undetermined number of items, set to 1 and also ensure it gets incremented so that progress is shown
Rename some methods and fields to be more clear
Enhanced Progress struct to have a unique id which is only useful for JSON representation, but since nested progress is allowed, enables tool consuming the progress to know which one is being updated
Added resourceName, resourceType, and result optional members to Progress so consuming tool can present it to user
Added failed member to Progress which is mutually exclusive to result if the resource failed

Example:

$config_yaml contains:

$schema: https://raw.githubusercontent.com/PowerShell/DSC/main/schemas/2024/04/config/document.json
resources:
- name: Echo 1
  type: Microsoft.DSC.Debug/Echo
  properties:
    output: hello
- name: ErrorTest
  type: Test/ExitCode
  properties:
    exitCode: 8

PS> dsc -p json config get -i $config_yaml
{"id":"427c7d5f-0440-4b6a-afb2-01827be21506","activity":"Searching for resources","totalItems":1,"completedItems":0}
{"id":"427c7d5f-0440-4b6a-afb2-01827be21506","activity":"Searching for resources","totalItems":1,"completedItems":1}
{"id":"25aeebd7-a1fd-44c4-847c-d123767cd4db","activity":"Get 'Echo 1'","totalItems":2,"completedItems":0,"resourceName":"Echo 1","resourceType":"Microsoft.DSC.Debug/Echo"}
{"id":"25aeebd7-a1fd-44c4-847c-d123767cd4db","activity":"Get 'Echo 1'","totalItems":2,"completedItems":1,"resourceName":"Echo 1","resourceType":"Microsoft.DSC.Debug/Echo","result":{"actualState":{"output":"hello"}}}
{"id":"25aeebd7-a1fd-44c4-847c-d123767cd4db","activity":"Get 'ErrorTest'","totalItems":2,"completedItems":1,"resourceName":"ErrorTest","resourceType":"Test/ExitCode"}
{"id":"25aeebd7-a1fd-44c4-847c-d123767cd4db","activity":"Get 'ErrorTest'","totalItems":2,"completedItems":2,"resourceName":"ErrorTest","resourceType":"Test/ExitCode","failure":{"message":"Placeholder from manifest for exit code 8","exitCode":8}}
2025-02-20T21:55:07.627550Z ERROR Command: Resource 'dsctest' [exit code 8] manifest description: Placeholder from manifest for exit code 8

Copilot reviewed 8 out of 18 changed files in this pull request and generated no comments.

Files not reviewed (10)

dsc/tests/dsc_args.tests.ps1: Language not supported
dsc/tests/dsc_config_get.tests.ps1: Language not supported
dsc/tests/dsc_resource_list.tests.ps1: Language not supported
dsc_lib/src/discovery/discovery_trait.rs: Evaluated as low risk
dsc/src/args.rs: Evaluated as low risk
dsc/src/subcommand.rs: Evaluated as low risk
dsc_lib/src/discovery/mod.rs: Evaluated as low risk
dsc_lib/src/util.rs: Evaluated as low risk
dsc/src/main.rs: Evaluated as low risk
dsc_lib/locales/en-us.toml: Evaluated as low risk

Comments suppressed due to low confidence (1)

dsc_lib/src/configure/mod.rs:250

The set_resource method is used to set the resource details, but it is not always followed by an increment call. Ensure that the progress is incremented consistently after setting the resource details.

progress.set_resource(&resource.name, &resource.resource_type, None);

dsc_lib/src/progress.rs

…ss schema

…mments to pub functions

JohnMcPMS · 2025-02-18T23:21:24Z

Building tree-sitter-dscexpression ... for current
Error when generating parser

Caused by:
    Failed to load grammar.js -- Failed to run `node` -- program not found
Exception: D:\dsc\tree-sitter-dscexpression\build.ps1:11
Line |
  11 |          throw "Command $cmd failed with exit code $LASTEXITCODE"
     |          ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
     | Command tree-sitter generate --build failed with exit code 1

tree-sitter-dscexpression appears to be dependent on node, but some of us don't have it already. Is there a specific version requirement or can I just install latest?

SteveL-MSFT · 2025-02-19T00:19:16Z

Looks like the tree-sitter-cli still has a dependency on node when building

JohnMcPMS · 2025-02-19T00:46:23Z

Rather than try and muddle through figuring out where the issue is in the code, I will present a test case:

--- dscv3-testreg.yaml ---

$schema: https://raw.githubusercontent.com/PowerShell/DSC/main/schemas/2023/08/config/document.json
metadata:
  winget:
    processor: dscv3
resources:
  - name: RegVal
    type: Microsoft.Windows/Registry
    properties:
      keyPath: HKEY_CURRENT_USER\Software\Microsoft\WinGet
      valueName: TestVal
      valueData:
        String: Value!
  - name: RegVal2
    type: Microsoft.Windows/Registry
    properties:
      keyPath: HKEY_CURRENT_USER\Software\Microsoft\WinGet
      valueName: TestVal2
      valueData:
        String: Value2!

--- progress output ---

{"id":"9d7ee3db-7cda-4726-b5a8-22cf7f5179f2","activity":"Searching for resources","percentComplete":0}
{"id":"9d7ee3db-7cda-4726-b5a8-22cf7f5179f2","activity":"Searching for resources","percentComplete":100}
{"id":"80e488c0-9ca0-49ae-a2d8-47e6c9c6dc5b","activity":"Test 'RegVal'","percentComplete":0}
{"id":"80e488c0-9ca0-49ae-a2d8-47e6c9c6dc5b","activity":"Test 'RegVal'","percentComplete":50,"resourceName":"RegVal","resourceType":"Microsoft.Windows/Registry","result":{"keyPath":"HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet","valueName":"TestVal","valueData":{"String":"Value!"}}}
{"id":"80e488c0-9ca0-49ae-a2d8-47e6c9c6dc5b","activity":"Test 'RegVal2'","percentComplete":50,"resourceName":"RegVal","resourceType":"Microsoft.Windows/Registry","result":{"keyPath":"HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet","valueName":"TestVal","valueData":{"String":"Value!"}}}
{"id":"80e488c0-9ca0-49ae-a2d8-47e6c9c6dc5b","activity":"Test 'RegVal2'","percentComplete":100,"resourceName":"RegVal2","resourceType":"Microsoft.Windows/Registry","result":{"keyPath":"HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet","valueName":"TestVal2","valueData":{"String":"Value2!"}}}

The first progress report for "activity":"Test 'RegVal2'" should be indicating that this instance is starting, but it appears to have retained the RegVal instance result information (pretty-printed with comments added):

{
    "id": "80e488c0-9ca0-49ae-a2d8-47e6c9c6dc5b",
    "activity": "Test 'RegVal2'",
    "percentComplete": 50,
    "resourceName": "RegVal",  // Resource name should be RegVal2
    "resourceType": "Microsoft.Windows/Registry",  // Ensure that this is also being update as this case was two of the same resources
    "result": {  // We shouldn't have a result yet as this is the "starting" progress line
        "keyPath": "HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet",
        "valueName": "TestVal",
        "valueData": { "String": "Value!" }
    }
}

SteveL-MSFT · 2025-02-19T00:58:54Z

Thanks! Looks like where it's setting the resource and result isn't not happening correctly per resource, will check.

JohnMcPMS · 2025-02-19T01:01:50Z

The results in the progress lines do not have the full fidelity information that the overall result has. For test I'm not actually sure what the progress result indicates. While I have not attempted to induce an error, hopefully the individual instance results would indicate that as well. Generally, I would like for the progress result object to be identical to the overall result object.

--- progress result ---

{
    "id": "a85d6c05-961b-4003-9dad-da6158782eaf",
    "activity": "Test 'RegVal'",
    "percentComplete": 50,
    "resourceName": "RegVal",
    "resourceType": "Microsoft.Windows/Registry",
    "result": {  // This object
        "keyPath": "HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet",
        "valueName": "TestVal",
        "valueData": { "String": "Value!" }
    }
}

--- overall result object ---

{
    "metadata": { "Microsoft.DSC": { "duration": "PT1.1595442S" } },
    "name": "RegVal",
    "type": "Microsoft.Windows/Registry",
    "result": {  // Should equal this object
        "desiredState": {
            "keyPath": "HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet",
            "valueName": "TestVal",
            "valueData": { "String": "Value!" }
        },
        "actualState": {
            "keyPath": "HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet",
            "valueName": "TestVal",
            "valueData": { "String": "Value!" }
        },
        "inDesiredState": true,
        "differingProperties": []
    }
}

SteveL-MSFT · 2025-02-19T01:38:46Z

The results in the progress lines do not have the full fidelity information that the overall result has. For test I'm not actually sure what the progress result indicates. While I have not attempted to induce an error, hopefully the individual instance results would indicate that as well. Generally, I would like for the progress result object to be identical to the overall result object.

The current result is what the resource outputs and not what the engine outputs. I can switch that if that is what you need.

SteveL-MSFT · 2025-02-19T04:39:21Z

@JohnMcPMS fetch my changes and try again, the order of setting the progress content and writing it was incorrect and now fixed. Here's what the json looks like now:

{"id":"ab122824-87b1-4f67-b7fb-479172dba0ce","activity":"Searching for resources","percentComplete":0}
{"id":"ab122824-87b1-4f67-b7fb-479172dba0ce","activity":"Searching for resources","percentComplete":100}
{"id":"2a714b94-d45a-42fb-8f36-a63db27eecb4","activity":"Get 'Echo 1'","percentComplete":0,"resourceName":"Echo 1","resourceType":"Microsoft.DSC.Debug/Echo"}
{"id":"2a714b94-d45a-42fb-8f36-a63db27eecb4","activity":"Get 'Echo 1'","percentComplete":50,"resourceName":"Echo 1","resourceType":"Microsoft.DSC.Debug/Echo","result":{"actualState":{"output":"hello"}}}
{"id":"2a714b94-d45a-42fb-8f36-a63db27eecb4","activity":"Get 'Echo 2'","percentComplete":50,"resourceName":"Echo 2","resourceType":"Microsoft.DSC.Debug/Echo"}
{"id":"2a714b94-d45a-42fb-8f36-a63db27eecb4","activity":"Get 'Echo 2'","percentComplete":100,"resourceName":"Echo 2","resourceType":"Microsoft.DSC.Debug/Echo","result":{"actualState":{"output":"world"}}}

with this result

metadata:
  Microsoft.DSC:
    version: 3.0.0
    operation: Get
    executionType: Actual
    startDatetime: 2025-02-18T20:38:15.928505-08:00
    endDatetime: 2025-02-18T20:38:15.979178-08:00
    duration: PT0.050673S
    securityContext: Restricted
results:
- metadata:
    Microsoft.DSC:
      duration: PT0.023614S
  name: Echo 1
  type: Microsoft.DSC.Debug/Echo
  result:
    actualState:
      output: hello
- metadata:
    Microsoft.DSC:
      duration: PT0.005786S
  name: Echo 2
  type: Microsoft.DSC.Debug/Echo
  result:
    actualState:
      output: world
messages: []
hadErrors: false

dsc_lib/src/progress.rs

JohnMcPMS · 2025-02-19T17:57:56Z

I'm seeing both changes. 👍

This is somewhat tangential, but the error handling strategy seems to be difficult to work against. I changed my registry test to have the second instance target HKLM and ran from an unelevated console. It fails as expected, but the results are not as easy to consume programmatically. There is no output, only error:

{"id":"4c021301-6ceb-47d2-91b5-064464c4ae55","activity":"Searching for resources","percentComplete":0}
{"id":"4c021301-6ceb-47d2-91b5-064464c4ae55","activity":"Searching for resources","percentComplete":100}
{"id":"7eccc602-0df7-4d38-8ac2-bdf5e9b2828e","activity":"Set 'RegVal'","percentComplete":0,"resourceName":"RegVal","resourceType":"Microsoft.Windows/Registry"}
{"id":"7eccc602-0df7-4d38-8ac2-bdf5e9b2828e","activity":"Set 'RegVal'","percentComplete":50,"resourceName":"RegVal","resourceType":"Microsoft.Windows/Registry","result":{"beforeState":{"keyPath":"HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet","valueName":"TestVal","valueData":{"String":"Value!"}},"afterState":{"keyPath":"HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet","valueName":"TestVal","valueData":{"String":"Value!"}},"changedProperties":null}}
{"id":"7eccc602-0df7-4d38-8ac2-bdf5e9b2828e","activity":"Set 'RegVal2'","percentComplete":50,"resourceName":"RegVal2","resourceType":"Microsoft.Windows/Registry"}
2025-02-19T17:22:42.920012Z ERROR trace_message="PID 3140: Registry key: Permission denied for given path: \"Software\\\\Microsoft\""
2025-02-19T17:22:42.922877Z ERROR Error: Command: Resource 'registry' [exit code 3] manifest description: Registry error

In a simple example I can assume serial execution and place the error messages with the resource that was last reported as starting (via a progress line with a new identity no result). However, I just have some strings and no easy way to extract a specific error result.

My thoughts:

If I request JSON progress, it would be best if the entire error stream was JSON lines. I don't have a problem with trace messages being interleaved with progress, but if they were structured it would make things much easier to handle downstream. Even better if they are appropriately associated with a resource instance.

{
    "id":"7eccc602-0df7-4d38-8ac2-bdf5e9b2828e",  // Required for full instance identity
    "resourceName": "RegVal2",
    "resourceType": "Microsoft.Windows/Registry",
    "timestamp": "2025-02-19T17:22:42.922877Z",
    "messageLevel": "ERROR",
    "message": "Error: Command: Resource 'registry' [exit code 3] manifest description: Registry error"
}

Also with JSON progress, it would be great if the error was appropriately rolled up and a completion progress event was sent. I'm not sure what the schema is for errors, or maybe there isn't one currently. But using the same pattern of the progress line having the full result object would hold here.

{
    "id": "7eccc602-0df7-4d38-8ac2-bdf5e9b2828e",
    "activity": "Set 'RegVal2'",
    "percentComplete": 100,
    "resourceName": "RegVal2",
    "resourceType": "Microsoft.Windows/Registry",
    "result": {
        "beforeState": {
            "keyPath": "HKEY_CURRENT_USER\\Software\\Microsoft\\WinGet",
            "valueName": "TestVal",
            "valueData": { "String": "Value!" }
        },
        "errorCode": 3,
        "errorDescription": "Registry error"
    }
}

In the event of an error, why is no overall result generated? The success case presents a hadErrors property, but it seems like it might be impossible currently to see it be true.
This is a larger discussion on error handling strategy generally, but since I'm already here... Winget currently uses a best effort approach, attempting to apply as much configuration as possible. An error in a resource instance only prevents other instances from running if they have a dependency. The goal was to make as much progress as possible, given that resources should be idempotent. If we are unattended, achieving as much as we can now means less time during any subsequent attempt. Even if this is not the default behavior, I would propose it as an option.

Co-authored-by: Tess Gauthier <[email protected]>

SteveL-MSFT · 2025-02-19T20:42:31Z

@JohnMcPMS for traces, you need to specify the trace format:

dsc --progress-format json --trace-format json config get -f ./dsc/examples/osinfo_parameters.dsc.yaml

SteveL-MSFT · 2025-02-19T20:47:41Z

@tgauth the set_percent_complete() is only relevant for writing JSON, so I'm removing that helper and moving that directly into write_json()

…needed there

JohnMcPMS · 2025-02-19T22:25:53Z

Filed #654 to help with discoverability.

Would you consider adding the identifying fields to traces as part of this PR, or should I open an issue to request it?

Are you planning on adding a closing progress event for a resource error (my thought 2), or should I roll that into a larger issue along with thoughts 3 and 4?

SteveL-MSFT · 2025-02-19T23:37:44Z

Filed #654 to help with discoverability.

Would you consider adding the identifying fields to traces as part of this PR, or should I open an issue to request it?

Are you planning on adding a closing progress event for a resource error (my thought 2), or should I roll that into a larger issue along with thoughts 3 and 4?

Any additions to traces should be a separate new issue. Do you need a closing progress event or can you just key off percentComplete = 100?

JohnMcPMS · 2025-02-19T23:48:03Z

I don't need a closing progress event for the entire configuration, but I was hoping that there would be one for the currently running resource instance when an error occurs. But that might roll into the larger error handling issue that it looks like I will have to file.

SteveL-MSFT · 2025-02-20T00:49:37Z

I don't need a closing progress event for the entire configuration, but I was hoping that there would be one for the currently running resource instance when an error occurs. But that might roll into the larger error handling issue that it looks like I will have to file.

Ok, I see so to know a resource is complete when it errors and not just success. Let me think about that one.

…failed property to progress

SteveL-MSFT · 2025-02-20T05:26:57Z

@JohnMcPMS due to the fact that tracing happens async and there can be multiple error traces written, there isn't a way to get the error message from the resource to put into the progress record. Instead, I added a failed boolean so you either get a result or failed when a resource completes. You can probably in most cases use the last error trace to be the message that came from the resource (assuming it emitted it).

I also removed the calculation of percent complete since that seems to be the role of the presentation layer and instead progress record includes the totalItems and completedItems you can use to calculate % complete.

JohnMcPMS · 2025-02-20T18:44:16Z

This is workable. I would prefer to also have some amount of detail on the failure be included in the progress report, but I can live without it for now. For example, I suspect you have the exit code (or how would know it failed) and could include the resource defined message (a caller can also find that with sufficient effort, but it is probably at your fingertips). In my example, the trace message with that data actually comes after the progress containing the failed property, making it harder to include in any forwarded progress.

SteveL-MSFT · 2025-02-20T18:55:15Z

@JohnMcPMS yes, do have the exit code so I could change it for now from failed to exitCode. The async nature of traces means you can't guarantee correlation as it could come out before or after the event. Let me make the change to include the exit code.

SteveL-MSFT · 2025-02-20T22:06:02Z

@JohnMcPMS so latest change has a failure property that is an object that contains message and exitCode properties. message is a mapping in the resource manifest of the exit code to an error message that is defined by the author otherwise it'll be some generic failure message (if not found in the manifest)

SteveL-MSFT added this to the 3.0-Approved milestone Feb 18, 2025

SteveL-MSFT requested review from adityapatwardhan, tgauth and Copilot February 18, 2025 01:16

Copilot AI reviewed Feb 18, 2025

View reviewed changes

SteveL-MSFT mentioned this pull request Feb 18, 2025

Breaking Change: Standardize casing for property names and enumerated values in JSON #642

Open

tgauth reviewed Feb 18, 2025

View reviewed changes

dsc_lib/src/progress.rs Outdated Show resolved Hide resolved

tgauth reviewed Feb 18, 2025

View reviewed changes

dsc_lib/src/progress.rs Outdated Show resolved Hide resolved

SteveL-MSFT added 3 commits February 18, 2025 14:33

Fix progress display when using JSON, add None option; exhance progre…

fa666b8

…ss schema

fix tests

0731204

address Tess' feedback moving common code to a function and adding co…

93e52da

…mments to pub functions

SteveL-MSFT force-pushed the progress-json branch from 65d8629 to 93e52da Compare February 18, 2025 22:33

SteveL-MSFT closed this Feb 18, 2025

SteveL-MSFT reopened this Feb 18, 2025

Fix ordering of setting progress data and writing it

a087de5

tgauth reviewed Feb 19, 2025

View reviewed changes

dsc_lib/src/progress.rs Outdated Show resolved Hide resolved

Update dsc_lib/src/progress.rs

c99d806

Co-authored-by: Tess Gauthier <[email protected]>

encapsulate set_percent_complete() into write_json() since it's only …

646878c

…needed there

Removed percentComplete and added totalItems and completedItems, add …

88acfd2

…failed property to progress

fix test

6d033fd

SteveL-MSFT added 2 commits February 20, 2025 13:57

change to a failure object that contains exitCode and message

769a421

fix clippy

3165520

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix progress display when using JSON, add None option; exhance progress schema #644

Fix progress display when using JSON, add None option; exhance progress schema #644

SteveL-MSFT commented Feb 18, 2025 •

edited

Loading

JohnMcPMS commented Feb 18, 2025

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 19, 2025 •

edited

Loading

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 19, 2025 •

edited

Loading

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 20, 2025

SteveL-MSFT commented Feb 20, 2025

JohnMcPMS commented Feb 20, 2025

SteveL-MSFT commented Feb 20, 2025

SteveL-MSFT commented Feb 20, 2025

Fix progress display when using JSON, add None option; exhance progress schema #644

Are you sure you want to change the base?

Fix progress display when using JSON, add None option; exhance progress schema #644

Conversation

SteveL-MSFT commented Feb 18, 2025 • edited Loading

PR Summary

Choose a reason for hiding this comment

JohnMcPMS commented Feb 18, 2025

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 19, 2025 • edited Loading

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 19, 2025 • edited Loading

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 19, 2025

JohnMcPMS commented Feb 19, 2025

SteveL-MSFT commented Feb 20, 2025

SteveL-MSFT commented Feb 20, 2025

JohnMcPMS commented Feb 20, 2025

SteveL-MSFT commented Feb 20, 2025

SteveL-MSFT commented Feb 20, 2025

SteveL-MSFT commented Feb 18, 2025 •

edited

Loading

SteveL-MSFT commented Feb 19, 2025 •

edited

Loading

SteveL-MSFT commented Feb 19, 2025 •

edited

Loading