mirror of
https://github.com/Skyvern-AI/skyvern.git
synced 2026-07-09 16:09:13 +00:00
log: drop log_level= from uvicorn.run() so ws spam stays silenced (#6046)
This commit is contained in:
parent
5083112f22
commit
a38df7ebc4
8 changed files with 112 additions and 6 deletions
|
|
@ -128,7 +128,9 @@ def run_server() -> None:
|
|||
"skyvern.forge.api_app:create_api_app",
|
||||
host=_default_host(),
|
||||
port=port,
|
||||
log_level="info",
|
||||
# Omit log_level= so uvicorn.Config.configure_logging() doesn't reset setup_logger()'s uvicorn.error WARNING.
|
||||
access_log=False,
|
||||
log_config={"version": 1, "disable_existing_loggers": False},
|
||||
factory=True,
|
||||
ws="websockets-sansio",
|
||||
)
|
||||
|
|
|
|||
|
|
@ -82,12 +82,8 @@ if __name__ == "__main__":
|
|||
"skyvern.forge.api_app:create_api_app",
|
||||
host="0.0.0.0",
|
||||
port=port,
|
||||
log_level="info",
|
||||
# Omit log_level= so uvicorn.Config.configure_logging() doesn't reset setup_logger()'s uvicorn.error WARNING.
|
||||
access_log=False,
|
||||
# uvicorn's default LOGGING_CONFIG runs dictConfig() which resets the
|
||||
# uvicorn.error / uvicorn.access levels we set in setup_logger() back to
|
||||
# INFO, leaking WebSocket "connection open" / "WebSocket [accepted]" spam
|
||||
# to stderr. Pass a no-op dict so structlog stays in charge.
|
||||
log_config={"version": 1, "disable_existing_loggers": False},
|
||||
reload=reload,
|
||||
reload_excludes=reload_excludes,
|
||||
|
|
|
|||
|
|
@ -373,6 +373,10 @@ class BaseRunResponse(BaseModel):
|
|||
default=None,
|
||||
description="Total number of steps executed in this run",
|
||||
)
|
||||
total_cost: float | None = Field(
|
||||
default=None,
|
||||
description="Estimated cost of this run",
|
||||
)
|
||||
|
||||
|
||||
class TaskRunResponse(BaseRunResponse):
|
||||
|
|
|
|||
|
|
@ -42,6 +42,13 @@ async def get_run_response(run_id: str, organization_id: str | None = None) -> R
|
|||
elif run.task_run_type == RunType.ui_tars:
|
||||
run_engine = RunEngine.ui_tars
|
||||
|
||||
task_total_cost: float | None = None
|
||||
if run.organization_id and task_v1_response.step_count:
|
||||
_, completed_step_count = await app.DATABASE.tasks.get_step_counts_by_task_ids(
|
||||
task_ids=[run.run_id], organization_id=run.organization_id
|
||||
)
|
||||
task_total_cost = 0.05 * completed_step_count
|
||||
|
||||
return TaskRunResponse(
|
||||
run_id=run.run_id,
|
||||
run_type=run.task_run_type,
|
||||
|
|
@ -72,6 +79,7 @@ async def get_run_response(run_id: str, organization_id: str | None = None) -> R
|
|||
),
|
||||
errors=task_v1_response.errors,
|
||||
step_count=task_v1_response.step_count,
|
||||
total_cost=task_total_cost,
|
||||
)
|
||||
elif run.task_run_type == RunType.task_v2:
|
||||
task_v2 = await app.DATABASE.observer.get_task_v2(run.run_id, organization_id=organization_id)
|
||||
|
|
|
|||
|
|
@ -2058,6 +2058,7 @@ async def build_task_v2_run_response(task_v2: TaskV2) -> TaskRunResponse:
|
|||
),
|
||||
errors=workflow_run_resp.errors if workflow_run_resp else None,
|
||||
step_count=workflow_run_resp.step_count if workflow_run_resp else None,
|
||||
total_cost=workflow_run_resp.total_cost if workflow_run_resp else None,
|
||||
)
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -133,6 +133,7 @@ async def get_workflow_run_response(
|
|||
workflow_run_id=workflow_run.workflow_run_id,
|
||||
organization_id=organization_id,
|
||||
include_step_count=True,
|
||||
include_cost=True,
|
||||
)
|
||||
app_url = f"{settings.SKYVERN_APP_URL.rstrip('/')}/runs/{workflow_run.workflow_run_id}"
|
||||
return WorkflowRunResponse(
|
||||
|
|
@ -171,4 +172,5 @@ async def get_workflow_run_response(
|
|||
),
|
||||
errors=workflow_run_resp.errors,
|
||||
step_count=workflow_run_resp.total_steps,
|
||||
total_cost=workflow_run_resp.total_cost,
|
||||
)
|
||||
|
|
|
|||
|
|
@ -47,6 +47,7 @@ async def test_get_workflow_run_response_passes_through_all_fields() -> None:
|
|||
parameters={},
|
||||
errors=None,
|
||||
total_steps=4,
|
||||
total_cost=0.2,
|
||||
)
|
||||
|
||||
with (
|
||||
|
|
@ -71,5 +72,6 @@ async def test_get_workflow_run_response_passes_through_all_fields() -> None:
|
|||
assert resp.run_with == "code"
|
||||
assert resp.status == RunStatus.completed
|
||||
assert resp.step_count == 4
|
||||
assert resp.total_cost == 0.2
|
||||
assert resp.run_request is not None
|
||||
assert resp.run_request.browser_session_id == "pbs_123"
|
||||
|
|
|
|||
91
tests/unit/test_forge_log_uvicorn_levels.py
Normal file
91
tests/unit/test_forge_log_uvicorn_levels.py
Normal file
|
|
@ -0,0 +1,91 @@
|
|||
"""Regression tests for the uvicorn.error log-level suppression.
|
||||
|
||||
Both "connection open" and the "WebSocket /v1/stream/..." [accepted] access
|
||||
line are emitted via logging.getLogger("uvicorn.error") — uvicorn explicitly
|
||||
passes its own logger into websockets' ServerProtocol (see
|
||||
uvicorn/protocols/websockets/websockets_sansio_impl.py). Suppressing them
|
||||
requires two cooperating pieces:
|
||||
|
||||
1. setup_logger() must setLevel(WARNING) on uvicorn.error and CRITICAL on
|
||||
uvicorn.access.
|
||||
2. Every uvicorn.run() entry point must NOT pass log_level=, otherwise
|
||||
uvicorn.Config.configure_logging() calls setLevel(log_level) on
|
||||
uvicorn.error/access/asgi and undoes (1).
|
||||
"""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import ast
|
||||
import importlib
|
||||
import inspect
|
||||
import logging
|
||||
from collections.abc import Iterator
|
||||
from types import ModuleType
|
||||
|
||||
import pytest
|
||||
|
||||
from skyvern.forge.sdk.forge_log import setup_logger
|
||||
|
||||
_TOUCHED_LOGGERS = (
|
||||
"uvicorn.error",
|
||||
"uvicorn.access",
|
||||
"uvicorn.asgi",
|
||||
"websockets",
|
||||
"websockets.server",
|
||||
"websockets.client",
|
||||
"websockets.legacy",
|
||||
"websockets.legacy.server",
|
||||
)
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def _restore_logger_levels() -> Iterator[None]:
|
||||
saved = {name: logging.getLogger(name).level for name in _TOUCHED_LOGGERS}
|
||||
yield
|
||||
for name, level in saved.items():
|
||||
logging.getLogger(name).setLevel(level)
|
||||
|
||||
|
||||
def test_setup_logger_silences_uvicorn_and_websockets(_restore_logger_levels: None) -> None:
|
||||
setup_logger()
|
||||
assert logging.getLogger("uvicorn.error").level == logging.WARNING
|
||||
assert logging.getLogger("uvicorn.access").level == logging.CRITICAL
|
||||
assert logging.getLogger("websockets").level == logging.WARNING
|
||||
assert logging.getLogger("websockets.server").level == logging.WARNING
|
||||
assert logging.getLogger("websockets.client").level == logging.WARNING
|
||||
assert logging.getLogger("websockets.legacy").level == logging.WARNING
|
||||
assert logging.getLogger("websockets.legacy.server").level == logging.WARNING
|
||||
|
||||
|
||||
@pytest.mark.parametrize(
|
||||
"module_path",
|
||||
[
|
||||
"skyvern.forge.__main__",
|
||||
"skyvern.cli.run_commands",
|
||||
],
|
||||
)
|
||||
def test_no_log_level_kwarg_on_uvicorn_run(module_path: str) -> None:
|
||||
module: ModuleType = importlib.import_module(module_path)
|
||||
tree = ast.parse(inspect.getsource(module))
|
||||
|
||||
found_call = False
|
||||
for node in ast.walk(tree):
|
||||
if not isinstance(node, ast.Call):
|
||||
continue
|
||||
func = node.func
|
||||
if not (
|
||||
isinstance(func, ast.Attribute)
|
||||
and func.attr == "run"
|
||||
and isinstance(func.value, ast.Name)
|
||||
and func.value.id == "uvicorn"
|
||||
):
|
||||
continue
|
||||
found_call = True
|
||||
for kw in node.keywords:
|
||||
assert kw.arg != "log_level", (
|
||||
f"{module_path} must not pass log_level= to uvicorn.run(); it triggers "
|
||||
"Config.configure_logging() to setLevel(log_level) on "
|
||||
"uvicorn.error/access/asgi and re-leaks WebSocket INFO spam."
|
||||
)
|
||||
|
||||
assert found_call, f"expected a uvicorn.run() call in {module_path}"
|
||||
Loading…
Add table
Add a link
Reference in a new issue