Merge pull request #287 from anmenaga/resource_debug_msgs

Support for resource tracing info

Author: Andrew

dsc/tests/dsc_args.tests.ps1

@@ -180,6 +180,13 @@ resources:
         $LASTEXITCODE | Should -Be 0
     }
 
+    It 'resource tracing shows up' {
+        # Assumption here is that DSC/PowerShellGroup provider is visible
+        dsc -l trace resource list 2> $TestDrive/tracing.txt
+        "$TestDrive/tracing.txt" | Should -FileContentMatchExactly 'PSModulePath'
+        $LASTEXITCODE | Should -Be 0
+    }
+
     It 'stdin cannot be empty if neither input or path is provided' {
         '' | dsc resource set -r Microsoft/OSInfo 2> $TestDrive/error.txt
         $err = Get-Content $testdrive/error.txt -Raw

dsc_lib/src/discovery/command_discovery.rs

@@ -5,6 +5,7 @@ use crate::discovery::discovery_trait::ResourceDiscovery;
 use crate::dscresources::dscresource::{Capability, DscResource, ImplementedAs};
 use crate::dscresources::resource_manifest::{import_manifest, Kind, ResourceManifest};
 use crate::dscresources::command_resource::invoke_command;
+use crate::dscresources::command_resource::log_resource_traces;
 use crate::dscerror::DscError;
 use indicatif::ProgressStyle;
 use std::collections::BTreeMap;
@@ -165,6 +166,7 @@ impl CommandDiscovery {
                     continue;
                 },
             };
+            log_resource_traces(&stderr);
 
             if exit_code != 0 {
                 /* In case of "resource list" operation - print failure from adapter as warning

dsc_lib/src/dscresources/command_resource.rs

@@ -7,10 +7,33 @@ use std::{collections::HashMap, env, process::Command, io::{Write, Read}, proces
 use crate::{dscerror::DscError, dscresources::invoke_result::{ResourceGetResponse, ResourceSetResponse, ResourceTestResponse}};
 use crate::configure::config_result::ResourceGetResult;
 use super::{dscresource::get_diff,resource_manifest::{ResourceManifest, InputKind, ReturnKind, SchemaKind}, invoke_result::{GetResult, SetResult, TestResult, ValidateResult, ExportResult}};
-use tracing::{debug, info, trace};
+use tracing::{error, warn, info, debug, trace};
 
 pub const EXIT_PROCESS_TERMINATED: i32 = 0x102;
 
+
+pub fn log_resource_traces(stderr: &str)
+{
+    if !stderr.is_empty()
+    {
+        for trace_line in stderr.lines() {
+            if let Result::Ok(json_obj) = serde_json::from_str::<Value>(trace_line) {
+                if let Some(msg) = json_obj.get("Error") {
+                    error!("{}", msg.as_str().unwrap_or_default());
+                } else if let Some(msg) = json_obj.get("Warning") {
+                    warn!("{}", msg.as_str().unwrap_or_default());
+                } else if let Some(msg) = json_obj.get("Info") {
+                    info!("{}", msg.as_str().unwrap_or_default());
+                } else if let Some(msg) = json_obj.get("Debug") {
+                    debug!("{}", msg.as_str().unwrap_or_default());
+                } else if let Some(msg) = json_obj.get("Trace") {
+                    trace!("{}", msg.as_str().unwrap_or_default());
+                };
+            };
+        }
+    }
+}
+
 /// Invoke the get operation on a resource
 ///
 /// # Arguments
@@ -50,6 +73,7 @@ pub fn invoke_get(resource: &ResourceManifest, cwd: &str, filter: &str) -> Resul
 
     info!("Invoking get {} using {}", &resource.resource_type, &resource.get.executable);
     let (exit_code, stdout, stderr) = invoke_command(&resource.get.executable, get_args, input_filter, Some(cwd), env)?;
+    log_resource_traces(&stderr);
     if exit_code != 0 {
         return Err(DscError::Command(resource.resource_type.clone(), exit_code, stderr));
     }
@@ -150,6 +174,7 @@ pub fn invoke_set(resource: &ResourceManifest, cwd: &str, desired: &str, skip_te
 
     info!("Getting current state for set by invoking get {} using {}", &resource.resource_type, &resource.get.executable);
     let (exit_code, stdout, stderr) = invoke_command(&resource.get.executable, get_args, get_input, Some(cwd), get_env)?;
+    log_resource_traces(&stderr);
     if exit_code != 0 {
         return Err(DscError::Command(resource.resource_type.clone(), exit_code, stderr));
     }
@@ -163,6 +188,7 @@ pub fn invoke_set(resource: &ResourceManifest, cwd: &str, desired: &str, skip_te
 
     info!("Invoking set {} using {}", &resource.resource_type, &set.executable);
     let (exit_code, stdout, stderr) = invoke_command(&set.executable, set.args.clone(), input_desired, Some(cwd), env)?;
+    log_resource_traces(&stderr);
     if exit_code != 0 {
         return Err(DscError::Command(resource.resource_type.clone(), exit_code, stderr));
     }
@@ -262,6 +288,7 @@ pub fn invoke_test(resource: &ResourceManifest, cwd: &str, expected: &str) -> Re
 
     info!("Invoking test {} using {}", &resource.resource_type, &test.executable);
     let (exit_code, stdout, stderr) = invoke_command(&test.executable, args, input_expected, Some(cwd), env)?;
+    log_resource_traces(&stderr);
     if exit_code != 0 {
         return Err(DscError::Command(resource.resource_type.clone(), exit_code, stderr));
     }
@@ -350,6 +377,7 @@ pub fn invoke_validate(resource: &ResourceManifest, cwd: &str, config: &str) ->
     };
 
     let (exit_code, stdout, stderr) = invoke_command(&validate.executable, validate.args.clone(), Some(config), Some(cwd), None)?;
+    log_resource_traces(&stderr);
     if exit_code != 0 {
         return Err(DscError::Command(resource.resource_type.clone(), exit_code, stderr));
     }
@@ -375,6 +403,7 @@ pub fn get_schema(resource: &ResourceManifest, cwd: &str) -> Result<String, DscE
     match schema_kind {
         SchemaKind::Command(ref command) => {
             let (exit_code, stdout, stderr) = invoke_command(&command.executable, command.args.clone(), None, Some(cwd), None)?;
+            log_resource_traces(&stderr);
             if exit_code != 0 {
                 return Err(DscError::Command(resource.resource_type.clone(), exit_code, stderr));
             }
@@ -420,6 +449,7 @@ pub fn invoke_export(resource: &ResourceManifest, cwd: &str, input: Option<&str>
     };
 
     let (exit_code, stdout, stderr) = invoke_command(&export.executable, export.args.clone(), input, Some(cwd), None)?;
+    log_resource_traces(&stderr);
     if exit_code != 0 {
         return Err(DscError::Command(resource.resource_type.clone(), exit_code, stderr));
     }

powershell-adapter/powershell.resource.ps1

@@ -73,13 +73,23 @@ if ($null -eq $DscModule)
 
 Import-Module $DscModule -DisableNameChecking
 
+# Adding some debug info to STDERR
+$m = gmo PSDesiredStateConfiguration
+$trace = @{"Debug"="PSVersion="+$PSVersionTable.PSVersion.ToString()} | ConvertTo-Json -Compress
+$host.ui.WriteErrorLine($trace)
+$trace = @{"Debug"="PSPath="+$PSHome} | ConvertTo-Json -Compress
+$host.ui.WriteErrorLine($trace)
+$trace = @{"Debug"="ModuleVersion="+$m.Version.ToString()} | ConvertTo-Json -Compress
+$host.ui.WriteErrorLine($trace)
+$trace = @{"Debug"="ModulePath="+$m.Path} | ConvertTo-Json -Compress
+$host.ui.WriteErrorLine($trace)
+$trace = @{"Debug"="PSModulePath="+$env:PSModulePath} | ConvertTo-Json -Compress
+$host.ui.WriteErrorLine($trace)
+
 if ($Operation -eq 'List')
 {
     $DscResources= Get-DscResource
-    #TODO: following should be added to debug stream of every operation
-    #$m = gmo PSDesiredStateConfiguration
-    #$r += @{"DebugInfo"=@{"ModuleVersion"=$m.Version.ToString();"ModulePath"=$m.Path;"PSVersion"=$PSVersionTable.PSVersion.ToString();"PSPath"=$PSHome}}
-    #$r[0] | ConvertTo-Json -Compress -Depth 3
+
     foreach ($r in $DscResources)
     {
         if ($r.ImplementedAs -eq "Binary")