diff --git a/dsc/tests/dsc_tracing.tests.ps1 b/dsc/tests/dsc_tracing.tests.ps1 index 322e281dc..e494e32e2 100644 --- a/dsc/tests/dsc_tracing.tests.ps1 +++ b/dsc/tests/dsc_tracing.tests.ps1 @@ -89,13 +89,32 @@ Describe 'tracing tests' { It 'Pass-through tracing should only emit JSON for child processes' { $logPath = "$TestDrive/dsc_trace.log" - $out = dsc -l info -t pass-through config get -f ../examples/groups.dsc.yaml 2> $logPath + $out = dsc -l trace -t pass-through config get -f "$PSScriptRoot/../examples/groups.dsc.yaml" 2> $logPath + $LASTEXITCODE | Should -Be 0 -Because (Get-Content -Path $logPath -Raw) + $foundPID = $false + $foundTarget = $false + $foundLineNumber = $false foreach ($line in (Get-Content $logPath)) { $line | Should -Not -BeNullOrEmpty $json = $line | ConvertFrom-Json - $json.timestamp | Should -Not -BeNullOrEmpty + $json.timestamp | Should -Not -BeNullOrEmpty -Because "Line: $line" $json.level | Should -BeIn 'ERROR', 'WARN', 'INFO', 'DEBUG', 'TRACE' + $json.fields.message | Should -Not -BeNullOrEmpty -Because "Line: $line" + if ($json.fields.pid) { + $json.fields.pid | Should -BeGreaterThan 0 -Because "Line: $line" + $foundPID = $true + } + if ($json.fields.target) { + $foundTarget = $true + } + if ($json.fields.line_number) { + $json.fields.line_number | Should -BeGreaterThan 0 -Because "Line: $line" + $foundLineNumber = $true + } } - $out | Should -BeNullOrEmpty + $foundTarget | Should -BeTrue -Because "No target found in log" + $foundLineNumber | Should -BeTrue -Because "No line number found in log" + $foundPID | Should -BeTrue -Because "No PID found in log" + $out | Should -Not -BeNullOrEmpty } } diff --git a/dsc_lib/src/dscresources/command_resource.rs b/dsc_lib/src/dscresources/command_resource.rs index cf4d57156..54f9ba7cd 100644 --- a/dsc_lib/src/dscresources/command_resource.rs +++ b/dsc_lib/src/dscresources/command_resource.rs @@ -862,57 +862,42 @@ pub fn log_stderr_line<'a>(process_id: &u32, trace_line: &'a str) -> &'a str if !trace_line.is_empty() { if let Ok(trace_object) = serde_json::from_str::(trace_line) { - let mut include_target = trace_object.level == TraceLevel::Debug || trace_object.level == TraceLevel::Trace; - let target = if let Some(t) = trace_object.target.as_deref() { t } else { - include_target = false; - "" - }; - let line_number = if let Some(l) = trace_object.line_number { l } else { - include_target = false; - 0 - }; - let trace_message = if include_target { - format!("PID {process_id}: {target}: {line_number}: {}", trace_object.fields.message) - } else { - format!("PID {process_id}: {}", trace_object.fields.message) - }; match trace_object.level { TraceLevel::Error => { - error!(trace_message); + error!(message = trace_object.fields.message, pid = process_id, target = trace_object.target, line_number = trace_object.line_number); }, TraceLevel::Warn => { - warn!(trace_message); + warn!(message = trace_object.fields.message, pid = process_id, target = trace_object.target, line_number = trace_object.line_number); }, TraceLevel::Info => { - info!(trace_message); + info!(message = trace_object.fields.message, pid = process_id, target = trace_object.target, line_number = trace_object.line_number); }, TraceLevel::Debug => { - debug!(trace_message); + debug!(message = trace_object.fields.message, pid = process_id, target = trace_object.target, line_number = trace_object.line_number); }, TraceLevel::Trace => { - trace!(trace_message); + trace!(message = trace_object.fields.message, pid = process_id, target = trace_object.target, line_number = trace_object.line_number); }, } - } - else if let Ok(json_obj) = serde_json::from_str::(trace_line) { + } else if let Ok(json_obj) = serde_json::from_str::(trace_line) { if let Some(msg) = json_obj.get("error") { - error!("PID {process_id}: {}", msg.as_str().unwrap_or_default()); + error!(message = msg.as_str().unwrap_or_default(), pid = process_id); } else if let Some(msg) = json_obj.get("warn") { - warn!("PID {process_id}: {}", msg.as_str().unwrap_or_default()); + warn!(message = msg.as_str().unwrap_or_default(), pid = process_id); } else if let Some(msg) = json_obj.get("info") { - info!("PID {process_id}: {}", msg.as_str().unwrap_or_default()); + info!(message = msg.as_str().unwrap_or_default(), pid = process_id); } else if let Some(msg) = json_obj.get("debug") { - debug!("PID {process_id}: {}", msg.as_str().unwrap_or_default()); + debug!(message = msg.as_str().unwrap_or_default(), pid = process_id); } else if let Some(msg) = json_obj.get("trace") { - trace!("PID {process_id}: {}", msg.as_str().unwrap_or_default()); + trace!(message = msg.as_str().unwrap_or_default(), pid = process_id); } else { // the line is a valid json, but not one of standard trace lines - return it as filtered stderr_line - trace!("PID {process_id}: {trace_line}"); + trace!(message = trace_line, pid = process_id); return trace_line; } } else { // the line is not a valid json - return it as filtered stderr_line - trace!("PID {process_id}: {}", trace_line); + trace!(message = trace_line, pid = process_id); return trace_line; } } diff --git a/resources/PSScript/psscript.tests.ps1 b/resources/PSScript/psscript.tests.ps1 index 7dbf02c7a..caf625f62 100644 --- a/resources/PSScript/psscript.tests.ps1 +++ b/resources/PSScript/psscript.tests.ps1 @@ -187,8 +187,8 @@ Describe 'Tests for PSScript resource' { $result = dsc resource get -r $resourceType -i $yaml 2> $TestDrive/error.txt | ConvertFrom-Json $LASTEXITCODE | Should -Be 0 -Because (Get-Content $TestDrive/error.txt -Raw | Out-String) $result.actualState.output.Count | Should -Be 0 -Because ($result | ConvertTo-Json | Out-String) - (Get-Content $TestDrive/error.txt -Raw) | Should -BeLike '*WARN*:*This is a warning*' - (Get-Content $TestDrive/error.txt -Raw) | Should -BeLike '*WARN*:*This is second warning*' + (Get-Content $TestDrive/error.txt -Raw) | Should -BeLike '*WARN*This is a warning*' + (Get-Content $TestDrive/error.txt -Raw) | Should -BeLike '*WARN*This is second warning*' } It 'Write-Error shows up as error traces for ' -TestCases $testCases { @@ -292,7 +292,7 @@ Describe 'Tests for PSScript resource' { '@ dsc resource get -r $resourceType -i $yaml 2> $TestDrive/error.txt | ConvertFrom-Json $LASTEXITCODE | Should -Be 2 -Because (Get-Content $TestDrive/error.txt -Raw | Out-String) - (Get-Content $TestDrive/error.txt -Raw) | Should -BeLike '*ERROR*:*Input was provided but script does not have a parameter to accept input.*' + (Get-Content $TestDrive/error.txt -Raw) | Should -BeLike '*ERROR*Input was provided but script does not have a parameter to accept input.*' } It 'Param without input is an error for ' -TestCases $testCases { @@ -305,7 +305,7 @@ Describe 'Tests for PSScript resource' { '@ dsc resource get -r $resourceType -i $yaml 2> $TestDrive/error.txt | ConvertFrom-Json $LASTEXITCODE | Should -Be 2 -Because (Get-Content $TestDrive/error.txt -Raw | Out-String) - (Get-Content $TestDrive/error.txt -Raw) | Should -BeLike "*ERROR*:*Script has a parameter 'inputObj' but no input was provided.*" + (Get-Content $TestDrive/error.txt -Raw) | Should -BeLike "*ERROR*Script has a parameter 'inputObj' but no input was provided.*" } It 'Write-Host results in an info message for ' -TestCases $testCases {