Skip to content
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

feat: add more tracing logs #603

Merged
merged 13 commits into from
Jan 15, 2025
3 changes: 3 additions & 0 deletions crates/goose-cli/src/commands/mcp.rs
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,9 @@ use mcp_server::{BoundedService, ByteTransport, Server};
use tokio::io::{stdin, stdout};

pub async fn run_server(name: &str) -> Result<()> {
// Initialize logging
crate::logging::setup_logging(Some(&format!("mcp-{name}")))?;

tracing::info!("Starting MCP server");

let router: Option<Box<dyn BoundedService>> = match name {
Expand Down
21 changes: 15 additions & 6 deletions crates/goose-cli/src/logging.rs
Original file line number Diff line number Diff line change
Expand Up @@ -34,17 +34,21 @@ fn get_log_directory() -> Result<PathBuf> {
/// - File-based logging with JSON formatting (DEBUG level)
/// - Console output for development (INFO level)
/// - Optional Langfuse integration (DEBUG level)
pub fn setup_logging(session_name: Option<&str>) -> Result<()> {
pub fn setup_logging(name: Option<&str>) -> Result<()> {
// Set up file appender for goose module logs
let log_dir = get_log_directory()?;
let timestamp = chrono::Local::now().format("%Y%m%d_%H%M%S").to_string();

// Create log file name by prefixing with timestamp
let log_filename = if name.is_some() {
format!("{}-{}.log", timestamp, name.unwrap())
} else {
format!("{}.log", timestamp)
};

// Create non-rolling file appender for detailed logs
let file_appender = tracing_appender::rolling::RollingFileAppender::new(
Rotation::NEVER,
log_dir,
&format!("{}.log", session_name.unwrap_or(&timestamp)),
);
let file_appender =
tracing_appender::rolling::RollingFileAppender::new(Rotation::NEVER, log_dir, log_filename);

// Create JSON file logging layer with all logs (DEBUG and above)
let file_layer = fmt::layer()
Expand All @@ -68,6 +72,11 @@ pub fn setup_logging(session_name: Option<&str>) -> Result<()> {
let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| {
// Set default levels for different modules
EnvFilter::new("")
// Set mcp-server module to DEBUG
.add_directive("mcp_server=debug".parse().unwrap())
// Set mcp-client to DEBUG
.add_directive("mcp_client=debug".parse().unwrap())
// Set goose module to DEBUG
.add_directive("goose=debug".parse().unwrap())
// Set goose-cli to INFO
.add_directive("goose_cli=info".parse().unwrap())
Expand Down
2 changes: 1 addition & 1 deletion crates/goose-server/src/commands/agent.rs
Original file line number Diff line number Diff line change
Expand Up @@ -6,7 +6,7 @@ use tracing::info;

pub async fn run() -> Result<()> {
// Initialize logging
crate::logging::setup_logging()?;
crate::logging::setup_logging(Some(&"goosed"))?;

// Load configuration
let settings = configuration::Settings::new()?;
Expand Down
4 changes: 3 additions & 1 deletion crates/goose-server/src/commands/mcp.rs
Original file line number Diff line number Diff line change
Expand Up @@ -6,8 +6,10 @@ use mcp_server::{BoundedService, ByteTransport, Server};
use tokio::io::{stdin, stdout};

pub async fn run(name: &str) -> Result<()> {
tracing::info!("Starting MCP server");
// Initialize logging
crate::logging::setup_logging(Some(&format!("mcp-{name}")))?;

tracing::info!("Starting MCP server");
let router: Option<Box<dyn BoundedService>> = match name {
"developer" => Some(Box::new(RouterService(DeveloperRouter::new()))),
"developer2" => Some(Box::new(RouterService(Developer2Router::new()))),
Expand Down
22 changes: 15 additions & 7 deletions crates/goose-server/src/logging.rs
Original file line number Diff line number Diff line change
Expand Up @@ -34,17 +34,21 @@ fn get_log_directory() -> Result<PathBuf> {
/// - File-based logging with JSON formatting (DEBUG level)
/// - Console output for development (INFO level)
/// - Optional Langfuse integration (DEBUG level)
pub fn setup_logging() -> Result<()> {
pub fn setup_logging(name: Option<&str>) -> Result<()> {
// Set up file appender for goose module logs
let log_dir = get_log_directory()?;
let timestamp = chrono::Local::now().format("%Y%m%d_%H%M%S").to_string();

// Create log file name by prefixing with timestamp
let log_filename = if name.is_some() {
format!("{}-{}.log", timestamp, name.unwrap())
} else {
format!("{}.log", timestamp)
};

// Create non-rolling file appender for detailed logs
let file_appender = tracing_appender::rolling::RollingFileAppender::new(
Rotation::NEVER,
log_dir,
&format!("goosed_{}.log", timestamp),
);
let file_appender =
tracing_appender::rolling::RollingFileAppender::new(Rotation::NEVER, log_dir, log_filename);

// Create JSON file logging layer
let file_layer = fmt::layer()
Expand All @@ -67,7 +71,11 @@ pub fn setup_logging() -> Result<()> {
let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| {
// Set default levels for different modules
EnvFilter::new("")
// Set goose module to INFO only
// Set mcp-server module to DEBUG
.add_directive("mcp_server=debug".parse().unwrap())
// Set mcp-client to DEBUG
.add_directive("mcp_client=debug".parse().unwrap())
// Set goose module to DEBUG
.add_directive("goose=debug".parse().unwrap())
// Set goose-server to INFO
.add_directive("goose_server=info".parse().unwrap())
Expand Down
4 changes: 4 additions & 0 deletions crates/goose-server/src/routes/system.rs
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,10 @@ async fn add_system(
if secret_key != state.secret_key {
return Err(StatusCode::UNAUTHORIZED);
}

// TODO: fix when `goosed agent` starts a MCP server, it doesn't write logs to ~/.config/goose/logs
// Instead, the logs get written to the current directory, example: logs/mcp-server.log.2025-01-15
// We would need the system name to write to the correct log file
let mut agent = state.agent.lock().await;
let response = agent.add_system(request).await;

Expand Down
7 changes: 3 additions & 4 deletions crates/mcp-client/src/client.rs
Original file line number Diff line number Diff line change
Expand Up @@ -39,11 +39,10 @@ pub enum Error {
#[error("Error from mcp-server: {0}")]
ServerBoxError(BoxError),

#[error("Call to '{server}' failed for '{method}' with params '{params}'. {source}")]
#[error("Call to '{server}' failed for '{method}'. {source}")]
McpServerError {
method: String,
server: String,
params: Value,
#[source]
source: BoxError,
},
Expand Down Expand Up @@ -146,7 +145,7 @@ where
.map_err(|e| Error::McpServerError {
server: self.server_info.as_ref().unwrap().name.clone(),
method: method.to_string(),
params: params.clone(),
// we don't need include params because it can be really large
source: Box::new(e.into()),
})?;

Expand Down Expand Up @@ -208,7 +207,7 @@ where
.map_err(|e| Error::McpServerError {
server: self.server_info.as_ref().unwrap().name.clone(),
method: method.to_string(),
params: params.clone(),
// we don't need include params because it can be really large
source: Box::new(e.into()),
})?;

Expand Down
15 changes: 11 additions & 4 deletions crates/mcp-client/src/transport/stdio.rs
Original file line number Diff line number Diff line change
Expand Up @@ -38,11 +38,16 @@ impl StdioActor {
loop {
match reader.read_line(&mut line).await {
Ok(0) => {
eprintln!("Child process ended (EOF on stdout)");
tracing::error!("Child process ended (EOF on stdout)");
break;
} // EOF
Ok(_) => {
if let Ok(message) = serde_json::from_str::<JsonRpcMessage>(&line) {
tracing::debug!(
message = ?message,
"Received incoming message"
);

if let JsonRpcMessage::Response(response) = &message {
if let Some(id) = &response.id {
pending_requests.respond(&id.to_string(), Ok(message)).await;
Expand All @@ -52,7 +57,7 @@ impl StdioActor {
line.clear();
}
Err(e) => {
eprintln!("Error reading line: {}", e);
tracing::error!(error = ?e, "Error reading line");
break;
}
}
Expand All @@ -75,6 +80,8 @@ impl StdioActor {
}
};

tracing::debug!(message = ?transport_msg.message, "Sending outgoing message");

if let Some(response_tx) = transport_msg.response_tx {
if let JsonRpcMessage::Request(request) = &transport_msg.message {
if let Some(id) = &request.id {
Expand All @@ -87,13 +94,13 @@ impl StdioActor {
.write_all(format!("{}\n", message_str).as_bytes())
.await
{
eprintln!("write_all failed: {:?}", e);
tracing::error!(error = ?e, "Error writing message to child process");
pending_requests.clear().await;
break;
}

if let Err(e) = stdin.flush().await {
eprintln!("flush failed: {:?}", e);
tracing::error!(error = ?e, "Error flushing message to child process");
pending_requests.clear().await;
break;
}
Expand Down
7 changes: 3 additions & 4 deletions crates/mcp-server/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -55,6 +55,9 @@ where
Ok(s) => s,
Err(e) => return Poll::Ready(Some(Err(TransportError::Utf8(e)))),
};
// Log incoming message here before serde conversion to
// track incomplete chunks which are not valid JSON
tracing::info!(json = %line, "incoming message");

// Parse JSON and validate message format
match serde_json::from_str::<serde_json::Value>(&line) {
Expand All @@ -75,10 +78,6 @@ where
))));
}

tracing::info!(
json = %line,
"incoming message"
);
// Now try to parse as proper message
match serde_json::from_value::<JsonRpcMessage>(value) {
Ok(msg) => Poll::Ready(Some(Ok(msg))),
Expand Down
Loading