Skip to content

Fix tracing pass-through structure #1052

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 2 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
25 changes: 22 additions & 3 deletions dsc/tests/dsc_tracing.tests.ps1
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
}
41 changes: 13 additions & 28 deletions dsc_lib/src/dscresources/command_resource.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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>(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::<Value>(trace_line) {
} else if let Ok(json_obj) = serde_json::from_str::<Value>(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;
}
}
Expand Down
8 changes: 4 additions & 4 deletions resources/PSScript/psscript.tests.ps1
Original file line number Diff line number Diff line change
Expand Up @@ -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 <resourceType>' -TestCases $testCases {
Expand Down Expand Up @@ -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 <resourceType>' -TestCases $testCases {
Expand All @@ -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 <resourceType>' -TestCases $testCases {
Expand Down
Loading