【Hackathon 9th No.88】Phase B: model_executor print→logger + per-request INFO→DEBUG + f-string→%s

- model_executor/: 14 print() calls → logger.debug/warning/info (6 files)
  - graph_optimization/utils.py: memory info → debug
  - ops/gpu/__init__.py: sm_version → debug, module error → warning
  - models/adapters.py: load failure → warning
  - layers/attention/mla_attention_backend.py: flash attn detect → info
  - ops/triton_ops/triton_utils.py: kernel cache/compile → debug
  - ops/triton_ops/triton_utils_v2.py: kernel cache/compile → debug
- entrypoints/: per-request INFO → DEBUG with lazy %s (12 files)
  - engine_client.py: objgraph debug, max_tokens, control methods
  - serving_chat.py: create/release/stream per-request calls
  - serving_completion.py: init/preprocess/response per-request calls
  - v1/serving_chat.py, v1/serving_completion.py: stream/response
  - run_batch.py: startup/progress f-string → %s (keep INFO)
  - llm.py, chat_utils.py, serving_reward.py, utils.py, v1/serving_base.py
- scheduler/splitwise_scheduler.py: per-request → DEBUG, startup → INFO %s

Acceptance criteria met:
- Core module print() = 0 (excl subprocess string, .print() methods)
- Per-request INFO = 0 in serving paths (all downgraded to DEBUG)
- All hot-path logger calls use %s lazy formatting

Author: cloudforge1

fastdeploy/entrypoints/chat_utils.py

@@ -122,7 +122,7 @@ def http_get_with_retry(self, url, max_retries=3, retry_delay=1, backoff_factor=
                 if retry_cnt >= max_retries:
                     api_server_logger.error(f"HTTP GET failed: {e}. Max retries reached")
                     raise
-                api_server_logger.info(f"HTTP GET failed: {e}. Start retry {retry_cnt}")
+                api_server_logger.info("HTTP GET failed: %s. Start retry %s", e, retry_cnt)
                 time.sleep(delay)
                 delay *= backoff_factor
 

fastdeploy/entrypoints/engine_client.py

@@ -311,7 +311,7 @@ async def add_requests(self, task):
                 )
             else:
                 request_id = task.get("request_id", "unknown")
-                obj_logger.info(f"\n{'='*60} OBJGRAPH DEBUG [request_id={request_id}] {'='*60}")
+                obj_logger.debug("\n%s OBJGRAPH DEBUG [request_id=%s] %s", '='*60, request_id, '='*60)
                 # 打印内存占用
                 if not _has_psutil:
                     obj_logger.warning(
@@ -320,18 +320,18 @@ async def add_requests(self, task):
                 else:
                     process = psutil.Process()
                     rss_memory = process.memory_info().rss / 1024**3
-                    obj_logger.info(f"Process Memory (RSS): {rss_memory:.2f} GB")
+                    obj_logger.debug("Process Memory (RSS): %.2f GB", rss_memory)
                 obj_logger.info("Object growth statistics:")
                 growth_data = objgraph.growth(limit=20)
                 for item in growth_data:
                     if len(item) == 3:
                         obj_type, current_count, growth = item
-                        obj_logger.info(f"  {obj_type:30s} {current_count:8d} +{growth}")
+                        obj_logger.debug("  %-30s %8d +%s", obj_type, current_count, growth)
                     elif len(item) == 2:
                         obj_type, count = item
-                        obj_logger.info(f"  {obj_type:30s} +{count}")
+                        obj_logger.debug("  %-30s +%s", obj_type, count)
                     else:
-                        obj_logger.info(f"  {item}")
+                        obj_logger.debug("  %s", item)
 
         task["metrics"]["preprocess_start_time"] = time.time()
         request_id = task.get("request_id").split("_")[0]
@@ -354,7 +354,7 @@ async def add_requests(self, task):
             min_tokens = task.get("min_tokens", 1)
             if "messages" in task:
                 task["messages"] = None
-            api_server_logger.info(f"task['max_tokens']:{task['max_tokens']}")
+            api_server_logger.debug("task['max_tokens']:%s", task['max_tokens'])
             main_process_metrics.request_params_max_tokens.observe(task["max_tokens"])
             main_process_metrics.prompt_tokens_total.inc(input_ids_len)
             main_process_metrics.request_prompt_tokens.observe(input_ids_len)
@@ -581,7 +581,7 @@ def check_health(self, time_interval_threashold=30):
         return True, ""
 
     async def run_control_method(self, request: ControlRequest):
-        api_server_logger.info(f"Start Run Control Method: {request}")
+        api_server_logger.debug("Start Run Control Method: %s", request)
         self.zmq_client.send_json(request.to_dict())
         request_id = request.request_id
         dealer, response_queue = await self.connection_manager.get_connection(request_id)
@@ -590,7 +590,7 @@ async def run_control_method(self, request: ControlRequest):
             # todo: support user specified timeout. default 600s is enough for most control cases
             response = await asyncio.wait_for(response_queue.get(), timeout=600)
             response = ControlResponse.from_dict(response[0])
-            api_server_logger.info(f"End Run Control Method: {response}")
+            api_server_logger.debug("End Run Control Method: %s", response)
             return response
         except asyncio.TimeoutError:
             error_response = ControlResponse(request_id, 500, "Timeout waiting for control method response")
@@ -816,7 +816,7 @@ async def rearrange_experts(self, request_dict: dict):
             return content, status_code
 
         action = request_dict.get("action", "")
-        api_server_logger.info(f"redundant_expert: rearrange_experts recv request, action {action}")
+        api_server_logger.debug("redundant_expert: rearrange_experts recv request, action %s", action)
         if action == "":
             # action: start rearrange experts
             # params: {'user': 'xxx', 'passwd': 'xxx', 'ips': ['10.54.99.77:8000', '10.54.99.77:8300']}
@@ -984,7 +984,7 @@ async def check_redundant(self, request_dict: dict):
 
     async def abort(self, request_id, n=1) -> None:
         if envs.FD_ENABLE_REQUEST_DISCONNECT_STOP_INFERENCE:
-            api_server_logger.info(f"abort request_id:{request_id}")
+            api_server_logger.info("abort request_id:%s", request_id)
             if n <= 0:
                 api_server_logger.warning("Abort function called with non-positive n: %d. No requests aborted.", n)
                 return

fastdeploy/entrypoints/llm.py

@@ -406,7 +406,7 @@ def _build_sample_logprobs(self, logprobs_lists: LogprobsLists, topk_logprobs: i
             list[dict[int, Logprob]]: One dict per request, mapping token ID to Logprob.
         """
         try:
-            llm_logger.info(f"filter logprobs, topk_logprobs: {topk_logprobs}")
+            llm_logger.debug("filter logprobs, topk_logprobs: %s", topk_logprobs)
             if not logprobs_lists.logprob_token_ids:
                 llm_logger.warning("Empty logprob_token_ids in LogprobsLists")
                 return None

fastdeploy/entrypoints/openai/run_batch.py

@@ -114,7 +114,7 @@ def init_engine(args: argparse.Namespace):
     if llm_engine is not None:
         return llm_engine
 
-    api_server_logger.info(f"FastDeploy LLM API server starting... {os.getpid()}")
+    api_server_logger.info("FastDeploy LLM API server starting... %s", os.getpid())
     engine_args = EngineArgs.from_cli_args(args)
     engine = LLMEngine.from_engine_args(engine_args)
     if not engine.start(api_server_pid=os.getpid()):
@@ -144,7 +144,7 @@ def completed(self):
         if self._total > 0:
             log_interval = min(100, max(self._total // 10, 1))
             if self._completed - self._last_log_count >= log_interval:
-                console_logger.info(f"Progress: {self._completed}/{self._total} requests completed")
+                console_logger.info("Progress: %s/%s requests completed", self._completed, self._total)
                 self._last_log_count = self._completed
 
     def pbar(self) -> tqdm:
@@ -398,7 +398,7 @@ async def setup_engine_and_handlers(args: Namespace) -> Tuple[EngineClient, Open
         args.tokenizer = args.model
 
     pid = determine_process_id()
-    console_logger.info(f"Process ID: {pid}")
+    console_logger.info("Process ID: %s", pid)
 
     model_paths = create_model_paths(args)
     chat_template = load_chat_template(args.chat_template, args.model)
@@ -429,7 +429,7 @@ async def run_batch(
     max_concurrency = (concurrency + workers - 1) // workers
     semaphore = asyncio.Semaphore(max_concurrency)
 
-    console_logger.info(f"concurrency: {concurrency}, workers: {workers}, max_concurrency: {max_concurrency}")
+    console_logger.info("concurrency: %s, workers: %s, max_concurrency: %s", concurrency, workers, max_concurrency)
 
     tracker = BatchProgressTracker()
     console_logger.info("Reading batch from %s...", args.input_file)
@@ -474,7 +474,7 @@ async def run_batch(
 
     success_count = sum(1 for r in responses if r.error is None)
     error_count = len(responses) - success_count
-    console_logger.info(f"Batch processing completed: {success_count} success, {error_count} errors")
+    console_logger.info("Batch processing completed: %s success, %s errors", success_count, error_count)
 
     await write_file(args.output_file, responses, args.output_tmp_dir)
     console_logger.info("Results written to output file")
@@ -485,7 +485,7 @@ async def main(args: argparse.Namespace):
     try:
         if args.workers is None:
             args.workers = max(min(int(args.max_num_seqs // 32), 8), 1)
-        console_logger.info(f"Workers: {args.workers}")
+        console_logger.info("Workers: %s", args.workers)
         args.model = retrive_model_from_server(args.model, args.revision)
 
         if args.tool_parser_plugin:

fastdeploy/entrypoints/openai/serving_chat.py

@@ -98,7 +98,7 @@ def __init__(
         else:
             self.master_ip = "0.0.0.0"
             self.is_master_ip = True
-        api_server_logger.info(f"master ip: {self.master_ip}")
+        api_server_logger.info("master ip: %s", self.master_ip)
 
     def _check_master(self):
         return self.engine_client.is_master or self.is_master_ip
@@ -129,7 +129,7 @@ async def create_chat_completion(self, request: ChatCompletionRequest):
                 await self.engine_client.semaphore.acquire()
             else:
                 await asyncio.wait_for(self.engine_client.semaphore.acquire(), timeout=self.max_waiting_time)
-            api_server_logger.info(f"current {self.engine_client.semaphore.status()}")
+            api_server_logger.debug("current %s", self.engine_client.semaphore.status())
 
             if request.request_id is not None:
                 request_id = request.request_id
@@ -141,7 +141,7 @@ async def create_chat_completion(self, request: ChatCompletionRequest):
                 request_id = f"chatcmpl-{uuid.uuid4()}"
             tracing.trace_req_start(rid=request_id, trace_content=request.trace_context, role="FastDeploy")
             del request.trace_context
-            api_server_logger.info(f"create chat completion request: {request_id}")
+            api_server_logger.debug("create chat completion request: %s", request_id)
             prompt_tokens = None
             max_tokens = None
             try:
@@ -252,7 +252,7 @@ async def chat_completion_stream_generator(
             choices=[],
             model=model_name,
         )
-        api_server_logger.info(f"create chat completion request: {request_id}")
+        api_server_logger.debug("create chat completion request: %s", request_id)
 
         try:
             dealer, response_queue = await self.engine_client.connection_manager.get_connection(
@@ -370,7 +370,7 @@ async def chat_completion_stream_generator(
                                     completion_tokens_details=CompletionTokenUsageInfo(reasoning_tokens=0),
                                 )
                             yield f"data: {chunk.model_dump_json(exclude_unset=True)} \n\n"
-                            api_server_logger.info(f"Chat Streaming response send_idx 0: {chunk.model_dump_json()}")
+                            api_server_logger.debug("Chat Streaming response send_idx 0: %s", chunk.model_dump_json())
                         first_iteration = False
 
                     output = res["outputs"]
@@ -489,7 +489,7 @@ async def chat_completion_stream_generator(
                         chunk.choices = choices
                         yield f"data: {chunk.model_dump_json(exclude_unset=True)}\n\n"
                         if res["finished"]:
-                            api_server_logger.info(f"Chat Streaming response last send: {chunk.model_dump_json()}")
+                            api_server_logger.debug("Chat Streaming response last send: %s", chunk.model_dump_json())
                         choices = []
 
             if include_usage:
@@ -528,7 +528,7 @@ async def chat_completion_stream_generator(
             tracing.trace_req_finish(request_id)
             await self.engine_client.connection_manager.cleanup_request(request_id)
             self.engine_client.semaphore.release()
-            api_server_logger.info(f"release {request_id} {self.engine_client.semaphore.status()}")
+            api_server_logger.debug("release %s %s", request_id, self.engine_client.semaphore.status())
             yield "data: [DONE]\n\n"
 
     async def chat_completion_full_generator(
@@ -695,7 +695,7 @@ async def chat_completion_full_generator(
             tracing.trace_req_finish(request_id)
             await self.engine_client.connection_manager.cleanup_request(request_id)
             self.engine_client.semaphore.release()
-            api_server_logger.info(f"release {self.engine_client.semaphore.status()}")
+            api_server_logger.debug("release %s", self.engine_client.semaphore.status())
 
         num_prompt_tokens = len(prompt_token_ids)
         num_generated_tokens = sum(previous_num_tokens)
@@ -722,7 +722,7 @@ async def chat_completion_full_generator(
             choices=choices,
             usage=usage,
         )
-        api_server_logger.info(f"Chat response: {res.model_dump_json()}")
+        api_server_logger.debug("Chat response: %s", res.model_dump_json())
         return res
 
     async def _create_chat_completion_choice(

fastdeploy/entrypoints/openai/serving_completion.py

@@ -77,7 +77,7 @@ def __init__(self, engine_client, models, pid, ips, max_waiting_time):
             self.master_ip = "0.0.0.0"
             self.is_master_ip = True
         self._is_process_response_dict_async = None
-        api_server_logger.info(f"master ip: {self.master_ip}")
+        api_server_logger.info("master ip: %s", self.master_ip)
 
     def _check_master(self):
         return self.engine_client.is_master or self.is_master_ip
@@ -110,7 +110,7 @@ async def create_completion(self, request: CompletionRequest):
             request_id = f"cmpl-{request.user}-{uuid.uuid4()}"
         else:
             request_id = f"cmpl-{uuid.uuid4()}"
-        api_server_logger.info(f"Initialize request {request_id}: {request}")
+        api_server_logger.debug("Initialize request %s: %s", request_id, request)
         tracing.trace_req_start(rid=request_id, trace_content=request.trace_context, role="FastDeploy")
         del request.trace_context
         request_prompt_ids = None
@@ -155,7 +155,7 @@ async def create_completion(self, request: CompletionRequest):
             request_prompts = request_prompt_ids
 
         num_choices = len(request_prompts) * (1 if request.n is None else request.n)
-        api_server_logger.info(f"Start preprocessing request: req_id={request_id}), num_choices={num_choices}")
+        api_server_logger.debug("Start preprocessing request: req_id=%s, num_choices=%s", request_id, num_choices)
         prompt_batched_token_ids = []
         prompt_tokens_list = []
         max_tokens_list = []
@@ -370,7 +370,7 @@ async def completion_full_generator(
                 prompt_tokens_list=prompt_tokens_list,
                 max_tokens_list=max_tokens_list,
             )
-            api_server_logger.info(f"Completion response: {res.model_dump_json()}")
+            api_server_logger.debug("Completion response: %s", res.model_dump_json())
             return res
         except Exception as e:
             api_server_logger.error(f"Error in completion_full_generator: {e}", exc_info=True)
@@ -642,7 +642,7 @@ async def completion_stream_generator(
                                 metrics=res["metrics"] if request.collect_metrics else None,
                             )
                             yield f"data: {usage_chunk.model_dump_json(exclude_unset=True)}\n\n"
-                        api_server_logger.info(f"Completion Streaming response last send: {chunk.model_dump_json()}")
+                        api_server_logger.debug("Completion Streaming response last send: %s", chunk.model_dump_json())
 
         except asyncio.CancelledError as e:
             await self.engine_client.abort(f"{request_id}_0", num_choices)

fastdeploy/entrypoints/openai/serving_reward.py

@@ -104,7 +104,7 @@ async def create_reward(self, request: ChatRewardRequest):
     @override
     def _build_response(self, ctx: ServeContext, request_output: dict):
         """Generate final reward response"""
-        api_server_logger.info(f"[{ctx.request_id}] Reward RequestOutput received:{request_output}")
+        api_server_logger.debug("[%s] Reward RequestOutput received:%s", ctx.request_id, request_output)
 
         base = PoolingRequestOutput.from_dict(request_output)
         reward_res = RewardRequestOutput.from_base(base)

fastdeploy/entrypoints/openai/utils.py

@@ -97,7 +97,7 @@ async def initialize(self):
         self.running = True
         for index in range(self.max_connections):
             await self._add_connection(index)
-        api_server_logger.info(f"Started {self.max_connections} connections, pid {self.pid}")
+        api_server_logger.info("Started %s connections, pid %s", self.max_connections, self.pid)
 
     async def _add_connection(self, index):
         """create a new connection and start listening task"""

fastdeploy/entrypoints/openai/v1/serving_base.py

@@ -76,7 +76,7 @@ def __init__(
             self.master_ip = "0.0.0.0"
             self.is_master_ip = True
         self.eoi_token_id = 101032
-        api_server_logger.info(f"master ip: {self.master_ip}")
+        api_server_logger.info("master ip: %s", self.master_ip)
 
     @override
     def _check_master(self) -> bool:

fastdeploy/entrypoints/openai/v1/serving_chat.py

@@ -302,7 +302,7 @@ async def _build_stream_response(
             max_tokens = request.max_completion_tokens or request.max_tokens
             choice_completion_tokens = response_ctx.choice_completion_tokens_dict[output.index]
             choice.finish_reason = self._calc_finish_reason(request_output, max_tokens, choice_completion_tokens)
-            api_server_logger.info(f"Chat Streaming response last send: {chunk.model_dump_json()}")
+            api_server_logger.debug("Chat Streaming response last send: %s", chunk.model_dump_json())
 
         yield f"data: {chunk.model_dump_json(exclude_unset=True)}\n\n"
         if request_output.finished and response_ctx.remain_choices == 0:
@@ -339,7 +339,7 @@ async def _build_full_response(
         res = ChatCompletionResponse(
             id=ctx.request_id, model=request.model, choices=choices, created=ctx.created_time, usage=response_ctx.usage
         )
-        api_server_logger.info(f"Chat response: {res.model_dump_json()}")
+        api_server_logger.debug("Chat response: %s", res.model_dump_json())
         return res
 
     async def _create_chat_completion_choice(