Skip to content

Commit

Permalink
chore: add trace level logging to process management (#8822)
Browse files Browse the repository at this point in the history
### Description

Add additional detailed logging to child process management to aid in
finding issues causing #8281

### Testing Instructions

`rustc`
  • Loading branch information
chris-olszewski authored Jul 23, 2024
1 parent 7f3162f commit ddb8014
Show file tree
Hide file tree
Showing 2 changed files with 26 additions and 3 deletions.
21 changes: 18 additions & 3 deletions crates/turborepo-lib/src/process/child.rs
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,7 @@ use tokio::{
process::Command as TokioCommand,
sync::{mpsc, watch, RwLock},
};
use tracing::debug;
use tracing::{debug, trace};

use super::Command;

Expand Down Expand Up @@ -480,8 +480,12 @@ impl Child {

/// Wait for the `Child` to exit, returning the exit code.
pub async fn wait(&mut self) -> Option<ChildExit> {
trace!("watching exit channel of {}", self.label);
// If sending end of exit channel closed, then return last value in the channel
self.exit_channel.changed().await.ok();
match self.exit_channel.changed().await {
Ok(()) => trace!("exit channel was updated"),
Err(_) => trace!("exit channel sender was dropped"),
}
*self.exit_channel.borrow()
}

Expand Down Expand Up @@ -654,7 +658,10 @@ impl Child {
) -> Option<Result<(), io::Error>> {
match stream {
Some(stream) => match stream.read_until(b'\n', buffer).await {
Ok(0) => None,
Ok(0) => {
trace!("reached EOF");
None
}
Ok(_) => Some(Ok(())),
Err(e) => Some(Err(e)),
},
Expand All @@ -669,26 +676,31 @@ impl Child {
loop {
tokio::select! {
Some(result) = next_line(&mut stdout_lines, &mut stdout_buffer) => {
trace!("processing stdout line");
result?;
add_trailing_newline(&mut stdout_buffer);
stdout_pipe.write_all(&stdout_buffer)?;
stdout_buffer.clear();
}
Some(result) = next_line(&mut stderr_lines, &mut stderr_buffer) => {
trace!("processing stderr line");
result?;
add_trailing_newline(&mut stderr_buffer);
stdout_pipe.write_all(&stderr_buffer)?;
stderr_buffer.clear();
}
status = self.wait(), if !is_exited => {
trace!("child process exited: {}", self.label());
is_exited = true;
// We don't abort in the cases of a zero exit code as we could be
// caching this task and should read all the logs it produces.
if status != Some(ChildExit::Finished(Some(0))) {
debug!("child process failed, skipping reading stdout/stderr");
return Ok(status);
}
}
else => {
trace!("flushing child stdout/stderr buffers");
// In the case that both futures read a complete line
// the future not chosen in the select will return None if it's at EOF
// as the number of bytes read will be 0.
Expand Down Expand Up @@ -753,6 +765,7 @@ impl ChildStateManager {
match state {
ChildState::Exited(exit) => {
// ignore the send error, failure means the channel is dropped
trace!("sending child exit");
self.exit_tx.send(Some(exit)).ok();
}
ChildState::Running(_) => {
Expand Down Expand Up @@ -783,6 +796,7 @@ impl ChildStateManager {
}

// ignore the send error, the channel is dropped anyways
trace!("sending child exit");
self.exit_tx.send(Some(child_exit)).ok();
}
}
Expand Down Expand Up @@ -832,6 +846,7 @@ mod test {

#[test_case(false)]
#[test_case(TEST_PTY)]
#[tracing_test::traced_test]
#[tokio::test]
async fn test_wait(use_pty: bool) {
let script = find_script_dir().join_component("hello_world.js");
Expand Down
8 changes: 8 additions & 0 deletions crates/turborepo-lib/src/process/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,7 @@ struct ProcessManagerInner {

impl ProcessManager {
pub fn new(use_pty: bool) -> Self {
debug!("spawning children with pty: {use_pty}");
Self {
state: Arc::new(Mutex::new(ProcessManagerInner {
is_closing: false,
Expand Down Expand Up @@ -75,8 +76,14 @@ impl ProcessManager {
command: Command,
stop_timeout: Duration,
) -> Option<io::Result<child::Child>> {
let label = tracing::enabled!(tracing::Level::TRACE)
.then(|| command.label())
.unwrap_or_default();
trace!("acquiring lock for spawning {label}");
let mut lock = self.state.lock().unwrap();
trace!("acquired lock for spawning {label}");
if lock.is_closing {
debug!("process manager closing");
return None;
}
let child = child::Child::spawn(
Expand All @@ -87,6 +94,7 @@ impl ProcessManager {
if let Ok(child) = &child {
lock.children.push(child.clone());
}
trace!("releasing lock for spawning {label}");
Some(child)
}

Expand Down

0 comments on commit ddb8014

Please sign in to comment.