feat: add more tracing logs, trim loaded prompt (#603)

This commit is contained in:
Salman Mohammed
2025-01-15 13:44:29 -05:00
committed by GitHub
parent 97fe873823
commit 2cb23d9293
10 changed files with 57 additions and 29 deletions
+3
View File
@@ -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 {
+15 -6
View File
@@ -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()
@@ -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())
+1 -1
View File
@@ -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()?;
+3 -1
View File
@@ -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()))),
+15 -7
View File
@@ -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()
@@ -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())
+1
View File
@@ -23,6 +23,7 @@ async fn add_system(
if secret_key != state.secret_key {
return Err(StatusCode::UNAUTHORIZED);
}
let mut agent = state.agent.lock().await;
let agent = agent.as_mut().ok_or(StatusCode::PRECONDITION_REQUIRED)?;
let response = agent.add_system(request).await;
+3 -3
View File
@@ -11,7 +11,7 @@ pub fn load_prompt<T: Serialize>(template: &str, context_data: &T) -> Result<Str
tera.add_raw_template("inline_template", template)?;
let context = Context::from_serialize(context_data)?;
let rendered = tera.render("inline_template", &context)?;
Ok(rendered)
Ok(rendered.trim().to_string())
}
pub fn load_prompt_file<T: Serialize>(
@@ -75,7 +75,7 @@ mod tests {
let result = load_prompt_file(file_path, &context).unwrap();
assert_eq!(
result,
"This prompt is only used for testing.\n\nHello, Alice! You are 30 years old.\n"
"This prompt is only used for testing.\n\nHello, Alice! You are 30 years old."
);
}
@@ -133,7 +133,7 @@ mod tests {
context.insert("tools".to_string(), tools);
let result = load_prompt(template, &context).unwrap();
let expected = "### Tool Descriptions\n";
let expected = "### Tool Descriptions";
assert_eq!(result, expected);
}
}
+3 -4
View File
@@ -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,
},
@@ -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()),
})?;
@@ -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()),
})?;
+10 -3
View File
@@ -43,6 +43,11 @@ impl StdioActor {
} // 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;
@@ -52,7 +57,7 @@ impl StdioActor {
line.clear();
}
Err(e) => {
eprintln!("Error reading line: {}", e);
tracing::error!(error = ?e, "Error reading line");
break;
}
}
@@ -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 {
@@ -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;
}
+3 -4
View File
@@ -57,6 +57,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) {
@@ -77,10 +80,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))),