chenchenghao/sglang
1
0
Fork 0
Code Issues Pull Requests Actions 11 Packages Projects Releases Wiki Activity

[model-gateway] Improve logging across core modules (#15497)

Browse Source
This commit is contained in:
Simo Lin
2025-12-19 11:35:28 -10:00
committed by GitHub
parent 6afc5d497b
commit ba72e759ca
19 changed files with 73 additions and 66 deletions
Download Patch File Download Diff File Expand all files Collapse all files

10
sgl-model-gateway/src/app_context.rs
View File

@@ -4,7 +4,7 @@ use std::{
};
use reqwest::Client;
use tracing::info;
use tracing::debug;
use crate::{
config::RouterConfig,
@@ -318,7 +318,7 @@ impl AppContextBuilder {
// Force rustls backend when TLS is configured
if has_tls_config {
client_builder = client_builder.use_rustls_tls();
info!("Using rustls TLS backend for TLS/mTLS connections");
debug!("Using rustls TLS backend for TLS/mTLS connections");
}
// Configure mTLS client identity if provided (certificates already loaded during config creation)
@@ -326,7 +326,7 @@ impl AppContextBuilder {
let identity = reqwest::Identity::from_pem(identity_pem)
.map_err(|e| format!("Failed to create client identity: {}", e))?;
client_builder = client_builder.identity(identity);
info!("mTLS client authentication enabled");
debug!("mTLS client authentication enabled");
}
// Add CA certificates for verifying worker TLS (certificates already loaded during config creation)
@@ -336,7 +336,7 @@ impl AppContextBuilder {
client_builder = client_builder.add_root_certificate(cert);
}
if !config.ca_certificates.is_empty() {
info!(
debug!(
"Added {} CA certificate(s) for worker verification",
config.ca_certificates.len()
);
@@ -495,7 +495,7 @@ impl AppContextBuilder {
let mcp_manager_lock = Arc::new(OnceLock::new());
// Always create with empty config and defaults
info!("Initializing MCP manager with empty config and default settings (5 min TTL, 100 max connections)");
debug!("Initializing MCP manager with empty config and default settings (5 min TTL, 100 max connections)");
let empty_config = crate::mcp::McpConfig {
servers: Vec::new(),

2
sgl-model-gateway/src/middleware.rs
View File

@@ -418,7 +418,7 @@ impl QueueProcessor {
}
pub async fn run(mut self) {
info!("Starting concurrency queue processor");
debug!("Starting concurrency queue processor");
// Process requests in a single task to reduce overhead
while let Some(queued) = self.queue_rx.recv().await {

7
sgl-model-gateway/src/routers/grpc/harmony/builder.rs
View File

@@ -12,7 +12,7 @@ use openai_harmony::{
},
HarmonyEncoding, HarmonyEncodingName,
};
use tracing::debug;
use tracing::{debug, trace};
use super::types::HarmonyBuildOutput;
use crate::protocols::{
@@ -211,13 +211,13 @@ impl HarmonyBuilder {
.tokenizer()
.decode_utf8(&token_ids)
.unwrap_or_else(|_| "<decode error>".to_string());
debug!(
trace!(
token_count = token_ids.len(),
token_preview = ?&token_ids[..token_ids.len().min(20)],
decoded_length = decoded_text.len(),
"Encoded conversation to tokens - decoded text follows:"
);
debug!("DECODED_TEXT_START\n{}\nDECODED_TEXT_END", decoded_text);
trace!("DECODED_TEXT_START\n{}\nDECODED_TEXT_END", decoded_text);
Ok(HarmonyBuildOutput {
input_ids: token_ids,
@@ -230,7 +230,6 @@ impl HarmonyBuilder {
})
}
/// Build system message from ChatCompletionRequest
/// Build system message with common logic
///
/// # Arguments

51
sgl-model-gateway/src/routers/grpc/regular/responses/tool_loop.rs
View File

@@ -16,7 +16,7 @@ use futures_util::StreamExt;
use serde_json::{json, Value};
use tokio::sync::mpsc;
use tokio_stream::wrappers::UnboundedReceiverStream;
use tracing::{debug, error, warn};
use tracing::{error, trace, warn};
use uuid::Uuid;
use super::conversions;
@@ -236,15 +236,17 @@ pub(super) async fn execute_tool_loop(
const MAX_ITERATIONS: usize = 10;
let max_tool_calls = original_request.max_tool_calls.map(|n| n as usize);
debug!(
trace!(
"Starting MCP tool loop: server_label={}, max_tool_calls={:?}, max_iterations={}",
server_label, max_tool_calls, MAX_ITERATIONS
server_label,
max_tool_calls,
MAX_ITERATIONS
);
// Get MCP tools and convert to chat format (do this once before loop)
let mcp_tools = ctx.mcp_manager.list_tools();
let mcp_chat_tools = convert_mcp_tools_to_chat_tools(&mcp_tools);
debug!(
trace!(
"Converted {} MCP tools to chat format",
mcp_chat_tools.len()
);
@@ -287,7 +289,7 @@ pub(super) async fn execute_tool_loop(
// Record tool loop iteration metric
Metrics::record_mcp_tool_iteration(&current_request.model);
debug!(
trace!(
"Tool loop iteration {}: found {} tool call(s)",
state.iteration,
tool_calls.len()
@@ -300,7 +302,7 @@ pub(super) async fn execute_tool_loop(
.into_iter()
.partition(|(_, tool_name, _)| mcp_tool_names.contains(tool_name.as_str()));
debug!(
trace!(
"Separated tool calls: {} MCP, {} function",
mcp_tool_calls.len(),
function_tool_calls.len()
@@ -377,9 +379,11 @@ pub(super) async fn execute_tool_loop(
// Execute all MCP tools
for (call_id, tool_name, args_json_str) in mcp_tool_calls {
debug!(
trace!(
"Calling MCP tool '{}' (call_id: {}) with args: {}",
tool_name, call_id, args_json_str
tool_name,
call_id,
args_json_str
);
let tool_start = Instant::now();
@@ -493,9 +497,10 @@ pub(super) async fn execute_tool_loop(
// Continue to next iteration
} else {
// No more tool calls, we're done
debug!(
trace!(
"Tool loop completed: {} iterations, {} total calls",
state.iteration, state.total_calls
state.iteration,
state.total_calls
);
// Convert final chat response to responses format
@@ -527,7 +532,7 @@ pub(super) async fn execute_tool_loop(
// Append all mcp_call items at the end
responses_response.output.extend(state.mcp_call_items);
debug!(
trace!(
"Injected MCP metadata: 1 mcp_list_tools + {} mcp_call items",
state.total_calls
);
@@ -653,7 +658,7 @@ async fn execute_tool_loop_streaming_internal(
// Get MCP tools and convert to chat format (do this once before loop)
let mcp_tools = ctx.mcp_manager.list_tools();
let mcp_chat_tools = convert_mcp_tools_to_chat_tools(&mcp_tools);
debug!(
trace!(
"Streaming: Converted {} MCP tools to chat format",
mcp_chat_tools.len()
);
@@ -674,7 +679,7 @@ async fn execute_tool_loop_streaming_internal(
));
}
debug!("Streaming MCP tool loop iteration {}", state.iteration);
trace!("Streaming MCP tool loop iteration {}", state.iteration);
// Emit mcp_list_tools as first output item (only once, on first iteration)
if !mcp_list_tools_emitted {
@@ -758,7 +763,7 @@ async fn execute_tool_loop_streaming_internal(
let tool_calls = extract_all_tool_calls_from_chat(&accumulated_response);
if !tool_calls.is_empty() {
debug!(
trace!(
"Tool loop iteration {}: found {} tool call(s)",
state.iteration,
tool_calls.len()
@@ -771,7 +776,7 @@ async fn execute_tool_loop_streaming_internal(
.into_iter()
.partition(|(_, tool_name, _)| mcp_tool_names.contains(tool_name.as_str()));
debug!(
trace!(
"Separated tool calls: {} MCP, {} function",
mcp_tool_calls.len(),
function_tool_calls.len()
@@ -799,9 +804,12 @@ async fn execute_tool_loop_streaming_internal(
for (call_id, tool_name, args_json_str) in mcp_tool_calls {
state.total_calls += 1;
debug!(
trace!(
"Executing tool call {}/{}: {} (call_id: {})",
state.total_calls, state.total_calls, tool_name, call_id
state.total_calls,
state.total_calls,
tool_name,
call_id
);
// Allocate output_index for this mcp_call item
@@ -837,9 +845,10 @@ async fn execute_tool_loop_streaming_internal(
emitter.send_event(&event, &tx)?;
// Execute the MCP tool - manager handles parsing and type coercion
debug!(
trace!(
"Calling MCP tool '{}' with args: {}",
tool_name, args_json_str
tool_name,
args_json_str
);
let tool_start = Instant::now();
let (output_str, success, error) = match ctx
@@ -952,7 +961,7 @@ async fn execute_tool_loop_streaming_internal(
// If there are function tool calls, emit events and exit MCP loop
if !function_tool_calls.is_empty() {
debug!(
trace!(
"Found {} function tool call(s) - emitting events and exiting MCP loop",
function_tool_calls.len()
);
@@ -1067,7 +1076,7 @@ async fn execute_tool_loop_streaming_internal(
}
// No tool calls, this is the final response
debug!("No tool calls found, ending streaming MCP loop");
trace!("No tool calls found, ending streaming MCP loop");
// Check for reasoning content
let reasoning_content = accumulated_response

14
sgl-model-gateway/src/server.rs
View File

@@ -18,7 +18,7 @@ use rustls::crypto::ring;
use serde::Deserialize;
use serde_json::{json, Value};
use tokio::{signal, spawn};
use tracing::{error, info, warn, Level};
use tracing::{debug, error, info, warn, Level};
use crate::{
app_context::AppContext,
@@ -838,7 +838,7 @@ pub async fn startup(config: ServerConfig) -> Result<(), Box<dyn std::error::Err
.workflow_engine
.set(engine)
.expect("WorkflowEngine should only be initialized once");
info!(
debug!(
"Workflow engine initialized with worker and MCP registration workflows (health check timeout: {}s)",
config.router_config.health_check.timeout_secs
);
@@ -881,7 +881,7 @@ pub async fn startup(config: ServerConfig) -> Result<(), Box<dyn std::error::Err
let refresh_interval = Duration::from_secs(600); // 10 minutes
let _refresh_handle =
Arc::clone(mcp_manager).spawn_background_refresh_all(refresh_interval);
info!("Started background refresh for all MCP servers (every 10 minutes)");
debug!("Started background refresh for all MCP servers (every 10 minutes)");
}
let worker_stats = app_context.worker_registry.stats();
@@ -896,14 +896,14 @@ pub async fn startup(config: ServerConfig) -> Result<(), Box<dyn std::error::Err
let _health_checker = app_context
.worker_registry
.start_health_checker(config.router_config.health_check.check_interval_secs);
info!(
debug!(
"Started health checker for workers with {}s interval",
config.router_config.health_check.check_interval_secs
);
if let Some(ref load_monitor) = app_context.load_monitor {
load_monitor.start().await;
info!("Started LoadMonitor for PowerOfTwo policies");
debug!("Started LoadMonitor for PowerOfTwo policies");
}
let (limiter, processor) = middleware::ConcurrencyLimiter::new(
@@ -919,13 +919,13 @@ pub async fn startup(config: ServerConfig) -> Result<(), Box<dyn std::error::Err
match processor {
Some(proc) => {
spawn(proc.run());
info!(
debug!(
"Started request queue (size: {}, timeout: {}s)",
config.router_config.queue_size, config.router_config.queue_timeout_secs
);
}
None => {
info!(
debug!(
"Rate limiting enabled (max_concurrent_requests = {}, queue disabled)",
config.router_config.max_concurrent_requests
);

3
sgl-model-gateway/src/tokenizer/cache/l0.rs vendored
View File

@@ -59,8 +59,7 @@ impl L0Cache {
// Simple eviction: if we're at capacity, remove a random entry
// DashMap doesn't support LRU directly, so we use a simple strategy
if self.map.len() >= self.max_entries {
// Get the key to remove in a separate scope to ensure iterator is dropped
let key_to_remove = { self.map.iter().next().map(|entry| entry.key().clone()) }; // Iterator fully dropped here, all locks released
let key_to_remove = { self.map.iter().next().map(|entry| entry.key().clone()) };
// Now remove it
if let Some(k) = key_to_remove {

6
sgl-model-gateway/src/tokenizer/factory.rs
View File

@@ -1,7 +1,7 @@
use std::{fs::File, io::Read, path::Path, sync::Arc};
use anyhow::{Error, Result};
use tracing::{debug, info};
use tracing::debug;
use super::{huggingface::HuggingFaceTokenizer, tiktoken::TiktokenTokenizer, traits};
use crate::tokenizer::hub::download_tokenizer_from_hf;
@@ -215,10 +215,10 @@ fn resolve_and_log_chat_template(
match (&provided_path, &final_chat_template) {
(Some(provided), _) => {
info!("Using provided chat template: {}", provided);
debug!("Using provided chat template: {}", provided);
}
(None, Some(discovered)) => {
info!(
debug!(
"Auto-discovered chat template in '{}': {}",
discovery_dir.display(),
discovered

4
sgl-model-gateway/src/tool_parser/parsers/deepseek.rs
View File

@@ -153,7 +153,7 @@ impl ToolParser for DeepSeekParser {
match self.parse_tool_call(mat.as_str()) {
Ok(tool) => tools.push(tool),
Err(e) => {
tracing::warn!("Failed to parse tool call: {}", e);
tracing::debug!("Failed to parse tool call: {}", e);
continue;
}
}
@@ -205,7 +205,7 @@ impl ToolParser for DeepSeekParser {
// Validate tool name
if !tool_indices.contains_key(func_name) {
// Invalid tool name - skip this tool, preserve indexing for next tool
tracing::warn!("Invalid tool name '{}' - skipping", func_name);
tracing::debug!("Invalid tool name '{}' - skipping", func_name);
helpers::reset_current_tool_state(
&mut self.buffer,
&mut self.current_tool_name_sent,

4
sgl-model-gateway/src/tool_parser/parsers/glm4_moe.rs
View File

@@ -146,7 +146,7 @@ impl Glm4MoeParser {
Ok(Some(tool)) => tools.push(tool),
Ok(None) => continue,
Err(e) => {
tracing::warn!("Failed to parse tool call: {}", e);
tracing::debug!("Failed to parse tool call: {}", e);
continue;
}
}
@@ -254,7 +254,7 @@ impl ToolParser for Glm4MoeParser {
// Validate tool name
if !tool_indices.contains_key(&tool_call.function.name) {
// Invalid tool name - skip this tool, preserve indexing for next tool
tracing::warn!("Invalid tool name '{}' - skipping", tool_call.function.name);
tracing::debug!("Invalid tool name '{}' - skipping", tool_call.function.name);
helpers::reset_current_tool_state(
&mut self.buffer,
&mut false, // glm4_moe doesn't track name_sent per tool

2
sgl-model-gateway/src/tool_parser/parsers/helpers.rs
View File

@@ -234,7 +234,7 @@ pub fn handle_json_tool_streaming(
if let Some(name) = obj.get("name").and_then(|v| v.as_str()) {
if !tool_indices.contains_key(name) {
// Invalid tool name - skip this tool, preserve indexing for next tool
tracing::warn!("Invalid tool name '{}' - skipping", name);
tracing::debug!("Invalid tool name '{}' - skipping", name);
reset_current_tool_state(
buffer,
current_tool_name_sent,

2
sgl-model-gateway/src/tool_parser/parsers/json.rs
View File

@@ -202,7 +202,7 @@ impl ToolParser for JsonParser {
match parsed {
Ok(tools) => return Ok((normal_text, tools)),
Err(e) => tracing::warn!("parse_complete failed: {:?}", e),
Err(e) => tracing::debug!("parse_complete failed: {:?}", e),
}
}

6
sgl-model-gateway/src/tool_parser/parsers/kimik2.rs
View File

@@ -137,7 +137,7 @@ impl ToolParser for KimiK2Parser {
});
}
Err(e) => {
tracing::warn!(
tracing::debug!(
"Failed to parse JSON arguments for {}: {}",
func_name,
e
@@ -146,7 +146,7 @@ impl ToolParser for KimiK2Parser {
}
}
} else {
tracing::warn!("Failed to parse function ID: {}", function_id);
tracing::debug!("Failed to parse function ID: {}", function_id);
continue;
}
}
@@ -204,7 +204,7 @@ impl ToolParser for KimiK2Parser {
// Validate tool name
if !tool_indices.contains_key(&func_name) {
// Invalid tool name - skip this tool, preserve indexing for next tool
tracing::warn!("Invalid tool name '{}' - skipping", func_name);
tracing::debug!("Invalid tool name '{}' - skipping", func_name);
helpers::reset_current_tool_state(
&mut self.buffer,
&mut self.current_tool_name_sent,

4
sgl-model-gateway/src/tool_parser/parsers/llama.rs
View File

@@ -115,7 +115,7 @@ impl LlamaParser {
}
Err(e) => {
// Skip invalid JSON parts in semicolon-separated list
tracing::warn!("Failed to parse tool call: {}", e);
tracing::debug!("Failed to parse tool call: {}", e);
}
}
}
@@ -157,7 +157,7 @@ impl ToolParser for LlamaParser {
});
parsed.unwrap_or_else(|e| {
tracing::warn!("Failed to parse tool call: {:?}", e);
tracing::debug!("Failed to parse tool call: {:?}", e);
vec![]
})
};

4
sgl-model-gateway/src/tool_parser/parsers/minimax_m2.rs
View File

@@ -181,7 +181,7 @@ impl MinimaxM2Parser {
}
Ok(None) => continue,
Err(e) => {
tracing::warn!("Failed to parse tool call: {}", e);
tracing::debug!("Failed to parse tool call: {}", e);
continue;
}
}
@@ -455,7 +455,7 @@ impl ToolParser for MinimaxM2Parser {
continue;
} else {
// Invalid function name, reset state
tracing::warn!("Invalid function name: {}", function_name);
tracing::debug!("Invalid function name: {}", function_name);
self.in_tool_call = false;
normal_text.push_str(&self.buffer);
self.buffer.clear();

2
sgl-model-gateway/src/tool_parser/parsers/mistral.rs
View File

@@ -189,7 +189,7 @@ impl ToolParser for MistralParser {
Ok(tools) => Ok((normal_text_before, tools)),
Err(e) => {
// If JSON parsing fails, return the original text as normal text
tracing::warn!("Failed to parse tool call: {}", e);
tracing::debug!("Failed to parse tool call: {}", e);
Ok((text.to_string(), vec![]))
}
}

8
sgl-model-gateway/src/tool_parser/parsers/pythonic.rs
View File

@@ -111,8 +111,8 @@ impl ToolParser for PythonicParser {
}
}
Err(e) => {
// Log warning and return entire text as fallback
tracing::warn!("Failed to parse pythonic tool calls: {}", e);
// Log and return entire text as fallback
tracing::debug!("Failed to parse pythonic tool calls: {}", e);
Ok((text.to_string(), vec![]))
}
}
@@ -156,7 +156,7 @@ impl ToolParser for PythonicParser {
.enumerate()
.filter_map(|(idx, tool)| {
if !tool_indices.contains_key(&tool.function.name) {
tracing::warn!(
tracing::debug!(
"Invalid tool name '{}' - skipping",
tool.function.name
);
@@ -177,7 +177,7 @@ impl ToolParser for PythonicParser {
});
}
Err(e) => {
tracing::warn!("Failed to parse pythonic tool call: {}", e);
tracing::debug!("Failed to parse pythonic tool call: {}", e);
// Clear buffer on error
self.buffer.clear();
return Ok(StreamingParseResult::default());

2
sgl-model-gateway/src/tool_parser/parsers/qwen.rs
View File

@@ -133,7 +133,7 @@ impl ToolParser for QwenParser {
Ok(Some(tool)) => tools.push(tool),
Ok(None) => continue,
Err(e) => {
tracing::warn!("Failed to parse tool call: {:?}", e);
tracing::debug!("Failed to parse tool call: {:?}", e);
continue;
}
}

4
sgl-model-gateway/src/tool_parser/parsers/step3.rs
View File

@@ -181,7 +181,7 @@ impl Step3Parser {
});
} else {
// Invalid function name
tracing::warn!("Invalid function name: {}", func_name);
tracing::debug!("Invalid function name: {}", func_name);
self.reset_streaming_state();
return Ok(StreamingParseResult {
normal_text: String::new(),
@@ -433,7 +433,7 @@ impl ToolParser for Step3Parser {
Ok(Some(tool)) => tools.push(tool),
Ok(None) => continue,
Err(e) => {
tracing::warn!("Failed to parse tool call: {}", e);
tracing::debug!("Failed to parse tool call: {}", e);
continue;
}
}

4
sgl-model-gateway/src/wasm/runtime.rs
View File

@@ -12,7 +12,7 @@ use std::{
};
use tokio::sync::oneshot;
use tracing::{debug, error, info};
use tracing::{debug, error};
use wasmtime::{
component::{Component, Linker, ResourceTable},
Config, Engine, Store, StoreLimitsBuilder, UpdateDeadline,
@@ -181,7 +181,7 @@ impl WasmThreadPool {
.max(1);
let num_workers = config.thread_pool_size.clamp(1, max_workers);
info!(
debug!(
target: "sgl_model_gateway::wasm::runtime",
"Initializing WASM runtime with {} workers",
num_workers