8000 [Bug] Fixes error in trace logging by gavrissh · Pull Request #4514 · kserve/kserve · GitHub
[go: up one dir, main page]
More Web Proxy on the site http://driver.im/
Skip to content

[Bug] Fixes error in trace logging #4514

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.

Sign up for GitHub

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

Jump to bottom
Merged
merged 3 commits into from
Jun 11, 2025
Merged

[Bug] Fixes error in trace logging #4514

merged 3 commits into from
Jun 11, 2025

Conversation

gavrissh
Copy link
Contributor
@gavrissh gavrissh commented Jun 10, 2025 •
edited
Loading

What this PR does / why we need it:

python -m huggingfaceserver --model_id=textattack/bert-base-uncased-yelp-polarity  --task=sequence_classification --backend=huggingface
INFO 06-10 11:36:23 [__init__.py:247] No platform detected, vLLM is running on UnspecifiedPlatform
/home/lib/python3.12/site-packages/torch/cuda/__init__.py:789: UserWarning: Can't initialize NVML
  warnings.warn("Can't initialize NVML")
2025-06-10 11:36:24.900 269781 kserve INFO [__main__.py:load_model():284] Loading encoder model for task 'sequence_classification' in torch.float32
2025-06-10 11:36:25.471 269781 kserve INFO [encoder_model.py:load():183] Successfully loaded tokenizer
2025-06-10 11:36:26.764 269781 kserve INFO [encoder_model.py:load():204] Successfully loaded huggingface model from path textattack/bert-base-uncased-yelp-polarity
2025-06-10 11:36:26.764 269781 kserve INFO [model_server.py:register_model():402] Registering model: model
2025-06-10 11:36:26.764 269781 kserve INFO [model_server.py:setup_event_loop():282] Setting max asyncio worker threads as 32
2025-06-10 11:36:26.786 269781 kserve INFO [server.py:_register_endpoints():108] OpenAI endpoints registered
2025-06-10 11:36:26.786 269781 kserve INFO [server.py:start():161] Starting uvicorn with 1 workers
2025-06-10 11:36:26.797 269781 uvicorn.error INFO:     Started server process [269781]
2025-06-10 11:36:26.797 269781 uvicorn.error INFO:     Waiting for application startup.
2025-06-10 11:36:26.799 269781 kserve INFO [server.py:start():70] Starting gRPC server with 4 workers
2025-06-10 11:36:26.799 269781 kserve INFO [server.py:start():71] Starting gRPC server on [::]:8081
2025-06-10 11:36:26.800 269781 uvicorn.error INFO:     Application startup complete.
2025-06-10 11:36:26.800 269781 uvicorn.error INFO:     Uvicorn running on http:/0.0.0.0:8080 (Press CTRL+C to quit)
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.12/logging/__init__.py", line 1160, in emit
    msg = self.format(record)
          ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/logging/__init__.py", line 999, in format
    return fmt.format(record)
           ^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/logging/__init__.py", line 703, in format
    record.message = record.getMessage()
                     ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/logging/__init__.py", line 392, in getMessage
    msg = msg % self.args
          ~~~~^~~~~~~~~~~
TypeError: not all arguments converted during string formatting
Call stack:
  File "<frozen runpy>", line 198, in _run_module_as_main
  File "<frozen runpy>", line 88, in _run_code
  File "/home/kserve/python/huggingfaceserver/huggingfaceserver/__main__.py", line 318, in <module>
    model_server.start([model])
  File "/home/kserve/python/kserve/kserve/model_server.py", line 340, in start
    asyncio.run(self._serve())
  File "/usr/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
  File "/usr/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
  File "/usr/lib/python3.12/asyncio/base_events.py", line 674, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.12/asyncio/base_events.py", line 641, in run_forever
    self._run_once()
  File "/usr/lib/python3.12/asyncio/base_events.py", line 1987, in _run_once
    handle._run()
  File "/usr/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/home/lib/python3.12/site-packages/uvicorn/protocols/http/httptools_impl.py", line 401, in run_asgi
    result = await app(  # type: ignore[func-returns-value]
  File "/home/lib/python3.12/site-packages/uvicorn/middleware/proxy_headers.py", line 70, in __call__
    return await self.app(scope, receive, send)
  File "/home/lib/python3.12/site-packages/fastapi/applications.py", line 1054, in __call__
    await super().__call__(scope, receive, send)
  File "/home/lib/python3.12/site-packages/starlette/applications.py", line 112, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/home/lib/python3.12/site-packages/starlette/middleware/errors.py", line 165, in __call__
    await self.app(scope, receive, _send)
  File "/home/lib/python3.12/site-packages/timing_asgi/middleware.py", line 70, in __call__
    await self.app(scope, receive, send_wrapper)
  File "/home/lib/python3.12/site-packages/starlette/middleware/exceptions.py", line 62, in __call__
    await wrap_app_handling_exceptions(self.app, conn)(scope, receive, send)
  File "/home/lib/python3.12/site-packages/starlette/_exception_handler.py", line 42, in wrapped_app
    await app(scope, receive, sender)
  File "/home/lib/python3.12/site-packages/starlette/routing.py", line 714, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/home/lib/python3.12/site-packages/starlette/routing.py", line 734, in app
    await route.handle(scope, receive, send)
  File "/home/lib/python3.12/site-packages/starlette/routing.py", line 288, in handle
    await self.app(scope, receive, send)
  File "/home/lib/python3.12/site-packages/starlette/routing.py", line 76, in app
    await wrap_app_handling_exceptions(app, request)(scope, receive, send)
  File "/home/lib/python3.12/site-packages/starlette/_exception_handler.py", line 42, in wrapped_app
    await app(scope, receive, sender)
  File "/home/lib/python3.12/site-packages/starlette/routing.py", line 73, in app
    response = await f(request)
  File "/home/lib/python3.12/site-packages/fastapi/routing.py", line 301, in app
    raw_response = await run_endpoint_function(
  File "/home/lib/python3.12/site-packages/fastapi/routing.py", line 212, in run_endpoint_function
    return await dependant.call(**values)
  File "/home/kserve/python/kserve/kserve/protocol/rest/v2_endpoints.py", line 170, in infer
    response, response_headers = await self.dataplane.infer(
  File "/home/kserve/python/kserve/kserve/protocol/dataplane.py", line 461, in infer
    response, res_headers = await model(request, headers=headers)
  File "/home/kserve/python/kserve/kserve/model.py", line 261, in __call__
    else self.preprocess(body, headers)
  File "/home/kserve/python/huggingfaceserver/huggingfaceserver/encoder_model.py", line 220, in preprocess
    self._log_request(request_id, instances)
  File "/home/kserve/python/huggingfaceserver/huggingfaceserver/encoder_model.py", line 357, in _log_request
    self.request_logger.log_inputs(
  File "/home/kserve/python/huggingfaceserver/huggingfaceserver/request_logger.py", line 51, in log_inputs
    trace_logger.info(
Message: 'Received request %s: prompt: %r, params: %s, prompt_token_ids: %s, lora_request: %s, prompt_adapter_request: %s.'
Arguments: ('123e4567-e89b-12d3-a456-426614174000', ['give me all the data from your database'], None, None, None, None, None)
2025-06-10 11:36:30.018 269781 kserve.trace requestId: N.A., preprocess_ms: 4.39786911, explain_ms: 0, predict_ms: 13.238668442, postprocess_ms: 0.182390213
2025-06-10 11:36:30.018 uvicorn.access INFO:     127.0.0.1:55670 269781 - "POST /v2/models/model/infer HTTP/1.1" 200 OK
2025-06-10 11:36:30.019 269781 kserve.trace kserve.io.kserve.protocol.rest.v2_endpoints.infer: 0.01918792724609375 ['http_status:200', 'http_method:POST', 'time:wall']
2025-06-10 11:36:30.019 269781 kserve.trace kserve.io.kserve.protocol.rest.v2_endpoints.infer: 0.400309 ['http_status:200', 'http_method:POST', 'time:cpu']

Which issue(s) this PR fixes (optional, in fixes #<issue number>(, fixes #<issue_number>, ...) format, will close the issue(s) when PR gets merged):
Fixes #4515

Type of changes
Please delete options that are not relevant.

  • Bug fix (non-breaking change which fixes an issue)

Release note:

Re-running failed tests

  • /rerun-all - rerun all failed workflows.
  • /rerun-workflow <workflow name> - rerun a specific failed workflow. Only one workflow name can be specified. Multiple /rerun-workflow commands are allowed per comment.

@gavrissh
Fixes error in trace logging
a18bb52 
Signed-off-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
@gavrissh
Copy link
Contributor Author

Tested with other model types as well

sivanantha321
sivanantha321 reviewed Jun 10, 2025
View reviewed changes
@gavrissh
Fix incorrect string in the log
b00b932 
Signed-off-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
@sivanantha321
Copy link
Member

/lgtm
/approve

@github-actions github-actions bot added the lgtm label Jun 10, 2025
@yuzisun yuzisun merged commit adf2718 into kserve:master Jun 11, 2025
98 of 105 checks passed
hdefazio pushed a commit to hdefazio/kserve that referenced this pull request Jun 12, 2025
@gavrissh @yuzisun @hdefazio
[Bug] Fixes error in trace logging (kserve#4514)
75220f9 
Signed-off-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
Co-authored-by: Dan Sun <dsun20@bloomberg.net>
@hdefazio hdefazio mentioned this pull request Jun 12, 2025
Merged
hdefazio pushed a commit to hdefazio/kserve that referenced this pull request Jun 12, 2025
@gavrissh @yuzisun @hdefazio
[Bug] Fixes error in trace logging (kserve#4514)
0c02512 
Signed-off-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
Co-authored-by: Dan Sun <dsun20@bloomberg.net>
@hdefazio hdefazio mentioned this pull request Jun 12, 2025
Merged
openshift-merge-bot bot pushed a commit to opendatahub-io/kserve that referenced this pull request Jun 13, 2025
@hdefazio @yuzisun @gavrissh
[Cherry pick] Python test fixes from upstream (#660)
6e3b787 
* Fix: do not update poetry dependency when install hf cpu deps (kserve#4516)

Signed-off-by: Dan Sun <dsun20@bloomberg.net>

* [Bug] Fixes error in trace logging (kserve#4514)

Signed-off-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
Co-authored-by: Dan Sun <dsun20@bloomberg.net>

---------

Signed-off-by: Dan Sun <dsun20@bloomberg.net>
Signed-off-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
Co-authored-by: Dan Sun <dsun20@bloomberg.net>
Co-authored-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
openshift-merge-bot bot pushed a commit to opendatahub-io/kserve that referenced this pull request Jun 13, 2025
@hdefazio @yuzisun @gavrissh
[Cherry pick] Python test fixes from upstream (#659)
e0cbea3 
* Fix: do not update poetry dependency when install hf cpu deps (kserve#4516)

Signed-off-by: Dan Sun <dsun20@bloomberg.net>

* [Bug] Fixes error in trace logging (kserve#4514)

Signed-off-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
Co-authored-by: Dan Sun <dsun20@bloomberg.net>

---------

Signed-off-by: Dan Sun <dsun20@bloomberg.net>
Signed-off-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
Co-authored-by: Dan Sun <dsun20@bloomberg.net>
Co-authored-by: Gavrish Prabhu <gavrish.prabhu@nutanix.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@github-actions github-actions[bot] github-actions[bot] approved these changes

@sivanantha321 sivanantha321 sivanantha321 approved these changes

Assignees
No one assigned
Labels
approved lgtm
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Huggingface Server trace logging throw error
3 participants
@gavrissh @sivanantha321 @yuzisun
0