mirror of
https://github.com/aaif-goose/goose.git
synced 2026-06-02 06:14:27 +02:00
feat(observability): trace provider/model at every reply hand-off
- Always populate Message.metadata.inference in reply_internal so the
client has a per-message ground truth even when fetch_model_info()
cannot resolve a canonical model (resolved_model: None is now a
legitimate carried value).
- Add gen_ai.provider and gen_ai.request.model fields to the existing
tracing::instrument on stream_response_from_provider, which wraps
every Provider::stream call. (Instrumenting the trait method
directly is not possible: it has no body for tracing-attributes to
wrap and the in-tree comment at base.rs explicitly forbids it.)
- Add structured tracing::info! at the four reply hand-off points,
tagged with session.id for end-to-end correlation:
* /reply entry, after the session is loaded
(goose-server/src/routes/reply.rs)
* restore_provider_from_session, with provider_source and
model_source = "session" | "config_default"
(goose/src/agents/agent.rs)
* update_provider, with source = "explicit_update"
(goose/src/agents/agent.rs)
* just before provider.stream(...)
(goose/src/agents/reply_parts.rs)
* MessageEvent::Message emit, with the message's inference metadata
(goose-server/src/routes/reply.rs)
- ACP path: add symmetric entry and emit logs in
GooseAcpAgent::on_prompt (goose/src/acp/server.rs). The actual LLM
call site is shared via Agent::reply, so the agent-level changes
cover both /reply and ACP.
Together these allow correlating one log chain per session and
locating where the requested model and the actually-used model
diverge.
Verified: cargo build -p goose -p goose-server, cargo clippy
--all-targets -p goose -p goose-server -- -D warnings, and
cargo test -p goose --lib conversation:: all pass. Pre-existing
sqlx-runtime-feature test failures under cargo test -p goose --lib
are unrelated to this change (confirmed via git stash).
Signed-off-by: Matt Toohey <contact@matttoohey.com>
This commit is contained in:
@@ -283,6 +283,13 @@ pub async fn reply(
|
||||
}
|
||||
};
|
||||
|
||||
tracing::info!(
|
||||
session.id = %session_id,
|
||||
session.provider = ?session.provider_name,
|
||||
session.model = ?session.model_config.as_ref().map(|m| &m.model_name),
|
||||
"reply: incoming request",
|
||||
);
|
||||
|
||||
let session_config = SessionConfig {
|
||||
id: session_id.clone(),
|
||||
schedule_id: session.schedule_id.clone(),
|
||||
@@ -354,6 +361,14 @@ pub async fn reply(
|
||||
|
||||
let token_state = get_token_state(state.session_manager(), &session_id).await;
|
||||
|
||||
tracing::info!(
|
||||
session.id = %session_id,
|
||||
out.provider = ?message.metadata.inference.as_ref().map(|i| &i.provider),
|
||||
out.requested_model = ?message.metadata.inference.as_ref().map(|i| &i.requested_model),
|
||||
out.resolved_model = ?message.metadata.inference.as_ref().and_then(|i| i.resolved_model.as_ref()),
|
||||
"reply: emit message",
|
||||
);
|
||||
|
||||
stream_event(MessageEvent::Message { message, token_state }, &tx, &cancel_token).await;
|
||||
}
|
||||
Ok(Some(Ok(AgentEvent::HistoryReplaced(new_messages)))) => {
|
||||
|
||||
@@ -3059,6 +3059,15 @@ impl GooseAcpAgent {
|
||||
let sid = sid_short(&session_id);
|
||||
let t_start = std::time::Instant::now();
|
||||
|
||||
if let Ok(session) = self.session_manager.get_session(&session_id, false).await {
|
||||
tracing::info!(
|
||||
session.id = %session_id,
|
||||
session.provider = ?session.provider_name,
|
||||
session.model = ?session.model_config.as_ref().map(|m| &m.model_name),
|
||||
"acp on_prompt: incoming request",
|
||||
);
|
||||
}
|
||||
|
||||
let cancel_token = CancellationToken::new();
|
||||
let agent = self
|
||||
.get_session_agent(&session_id, Some(cancel_token.clone()))
|
||||
@@ -3136,6 +3145,13 @@ impl GooseAcpAgent {
|
||||
|
||||
match event {
|
||||
Ok(crate::agents::AgentEvent::Message(message)) => {
|
||||
tracing::info!(
|
||||
session.id = %session_id,
|
||||
out.provider = ?message.metadata.inference.as_ref().map(|i| &i.provider),
|
||||
out.requested_model = ?message.metadata.inference.as_ref().map(|i| &i.requested_model),
|
||||
out.resolved_model = ?message.metadata.inference.as_ref().and_then(|i| i.resolved_model.as_ref()),
|
||||
"acp on_prompt: emit message",
|
||||
);
|
||||
// Agent persists messages via session_manager.add_message() internally.
|
||||
let stored_message_id = message.id.clone();
|
||||
|
||||
|
||||
@@ -1587,15 +1587,15 @@ impl Agent {
|
||||
let provider = self.provider().await?;
|
||||
let provider_name = provider.get_name().to_string();
|
||||
let requested_model = provider.get_model_config().model_name;
|
||||
let inference = provider
|
||||
let resolved_model = provider
|
||||
.fetch_model_info(&requested_model)
|
||||
.await
|
||||
.ok()
|
||||
.and_then(|model_info| model_info.resolved_model)
|
||||
.map(|resolved_model| InferenceMetadata {
|
||||
.and_then(|model_info| model_info.resolved_model);
|
||||
let inference = Some(InferenceMetadata {
|
||||
provider: provider_name,
|
||||
requested_model,
|
||||
resolved_model: Some(resolved_model),
|
||||
resolved_model,
|
||||
});
|
||||
let session_manager = self.config.session_manager.clone();
|
||||
let session_id = session_config.id.clone();
|
||||
@@ -2324,6 +2324,14 @@ impl Agent {
|
||||
let mut current_provider = self.provider.lock().await;
|
||||
*current_provider = Some(provider);
|
||||
|
||||
tracing::info!(
|
||||
session.id = %session_id,
|
||||
provider = %provider_name,
|
||||
model = %model_config.model_name,
|
||||
source = "explicit_update",
|
||||
"agent: provider resolved",
|
||||
);
|
||||
|
||||
self.config
|
||||
.session_manager
|
||||
.clone()
|
||||
@@ -2363,12 +2371,22 @@ impl Agent {
|
||||
pub async fn restore_provider_from_session(&self, session: &Session) -> Result<bool> {
|
||||
let config = Config::global();
|
||||
|
||||
let provider_source = if session.provider_name.is_some() {
|
||||
"session"
|
||||
} else {
|
||||
"config_default"
|
||||
};
|
||||
let provider_name = session
|
||||
.provider_name
|
||||
.clone()
|
||||
.or_else(|| config.get_goose_provider().ok())
|
||||
.ok_or_else(|| anyhow!("Could not configure agent: missing provider"))?;
|
||||
|
||||
let model_source = if session.model_config.is_some() {
|
||||
"session"
|
||||
} else {
|
||||
"config_default"
|
||||
};
|
||||
let model_config = match session.model_config.clone() {
|
||||
Some(saved_config) => saved_config,
|
||||
None => {
|
||||
@@ -2382,6 +2400,15 @@ impl Agent {
|
||||
}
|
||||
};
|
||||
|
||||
tracing::info!(
|
||||
session.id = %session.id,
|
||||
provider = %provider_name,
|
||||
model = %model_config.model_name,
|
||||
provider_source = %provider_source,
|
||||
model_source = %model_source,
|
||||
"agent: restore_provider_from_session resolved",
|
||||
);
|
||||
|
||||
let extensions =
|
||||
EnabledExtensionsState::extensions_or_default(Some(&session.extension_data), config);
|
||||
|
||||
|
||||
@@ -246,7 +246,11 @@ impl Agent {
|
||||
|
||||
#[tracing::instrument(
|
||||
skip(provider, session_id, system_prompt, messages, tools, toolshim_tools),
|
||||
fields(session.id = %session_id)
|
||||
fields(
|
||||
session.id = %session_id,
|
||||
gen_ai.provider = %provider.get_name(),
|
||||
gen_ai.request.model = %provider.get_model_config().model_name,
|
||||
)
|
||||
)]
|
||||
pub(crate) async fn stream_response_from_provider(
|
||||
provider: Arc<dyn Provider>,
|
||||
@@ -280,6 +284,12 @@ impl Agent {
|
||||
// Capture errors during stream creation and return them as part of the stream
|
||||
// so they can be handled by the existing error handling logic in the agent
|
||||
let model_config = provider.get_model_config();
|
||||
tracing::info!(
|
||||
session.id = %session_id,
|
||||
gen_ai.provider = %provider.get_name(),
|
||||
gen_ai.request.model = %model_config.model_name,
|
||||
"llm: stream call",
|
||||
);
|
||||
debug!("WAITING_LLM_STREAM_START");
|
||||
let stream_result = provider
|
||||
.stream(
|
||||
|
||||
Reference in New Issue
Block a user