perf: build debug log messages lazily so disabled debug logs cost nothing (#27834)

GLOBAL_LOG_LEVEL defaults to INFO, so every log.debug(...) in the backend is discarded, but the message is built first: 187 call sites interpolate their payload into an f-string before the logging call runs, so the work happens on every request and the result is thrown away. The worst one sits in process_chat_payload and stringifies the whole request body, full conversation history included, once per chat completion.

That one line with DEBUG disabled, CPython 3.12:

| conversation | payload | before   | after   |
| ------------ | ------- | -------- | ------- |
| 4 messages   | 1.2 kB  | 3.4 us   | 0.07 us |
| 20 messages  | 17 kB   | 24.8 us  | 0.07 us |
| 60 messages  | 123 kB  | 216.6 us | 0.07 us |

The lazy form log.debug('form_data: %s', form_data) hands the payload to record.getMessage(), which the InterceptHandler only reaches once a record has passed the level check. With DEBUG enabled the emitted lines are byte-identical, f'{x=}' sites included: those map to %r. MistralLoader._debug_log callers get the same treatment, since that wrapper already forwards *args.
This commit is contained in:
Classic298
2026-07-31 19:09:01 -05:00
committed by GitHub
parent b67804f2b6
commit 52cfb02c72
40 changed files with 198 additions and 190 deletions
@@ -34,7 +34,7 @@ async def has_access_to_file(
file.user_id == user.id separately before calling this.
"""
file = await Files.get_file_by_id(file_id, db=db)
log.debug(f'Checking if user has {access_type} access to file')
log.debug('Checking if user has %s access to file', access_type)
if not file:
return False
+1 -1
View File
@@ -222,7 +222,7 @@ class AuditLoggingMiddleware:
user = await get_current_user(request, None, None, get_http_authorization_cred(auth_header))
return user
except Exception as e:
logger.debug(f'Failed to get authenticated user: {str(e)}')
logger.debug('Failed to get authenticated user: {}', e)
return None
+2 -2
View File
@@ -667,7 +667,7 @@ async def _check_calendar_alerts(app) -> None:
CalendarEventUpdateForm(meta={'alerted_at': now_ns}),
)
except Exception:
log.debug(f'Failed to mark event {event.id} as alerted', exc_info=True)
log.debug('Failed to mark event %s as alerted', event.id, exc_info=True)
# Send target notification if user has one configured
try:
@@ -687,7 +687,7 @@ async def _check_calendar_alerts(app) -> None:
message=event.title,
)
except Exception:
log.debug(f'Failed to send notification for calendar alert {event.id}', exc_info=True)
log.debug('Failed to send notification for calendar alert %s', event.id, exc_info=True)
async def _record_run(
+3 -3
View File
@@ -115,7 +115,7 @@ async def generate_direct_chat_completion(
else:
yield f'data: {data}\n\n'
except Exception as e:
log.debug(f'Error in event generator: {e}')
log.debug('Error in event generator: %s', e)
pass
# Define a background task to run the event generator
@@ -155,7 +155,7 @@ async def generate_chat_completion(
bypass_filter: bool = False,
bypass_system_prompt: bool = False,
):
log.debug(f'generate_chat_completion: {form_data}')
log.debug('generate_chat_completion: %s', form_data)
if BYPASS_MODEL_ACCESS_CONTROL:
bypass_filter = True
@@ -184,7 +184,7 @@ async def generate_chat_completion(
**dict(request.app.state.MODELS.items()),
request.state.model['id']: request.state.model,
}
log.debug(f'direct connection to model: {request.state.model["id"]}')
log.debug('direct connection to model: %s', request.state.model['id'])
else:
models = request.app.state.MODELS
+1 -1
View File
@@ -186,7 +186,7 @@ async def process_filter_function(
form_data = await run_filter_handler(handler, params)
except Exception as e:
log.debug(f'Error in {filter_type} handler {filter_id}: {e}')
log.debug('Error in %s handler %s: %s', filter_type, filter_id, e)
raise e
return form_data, valves_by_id, skip_files
+3 -3
View File
@@ -17,7 +17,7 @@ default_headers = {'User-Agent': 'Mozilla/5.0'}
async def queue_prompt(prompt, client_id, base_url, api_key):
log.info('queue_prompt')
p = {'prompt': prompt, 'client_id': client_id}
log.debug(f'queue_prompt data: {p}')
log.debug('queue_prompt data: %s', p)
try:
session = await get_session()
async with session.post(
@@ -202,7 +202,7 @@ async def comfyui_create_image(model: str, payload: ComfyUICreateImageForm, clie
) as ws:
log.info('WebSocket connection established.')
log.info('Sending workflow to WebSocket server.')
log.debug(f'Workflow: {workflow}')
log.debug('Workflow: %s', workflow)
images = await _ws_get_images(ws, workflow, client_id, base_url, api_key)
except aiohttp.WSServerHandshakeError as e:
log.exception(f'Failed to connect to WebSocket server: {e}')
@@ -243,7 +243,7 @@ async def comfyui_edit_image(model: str, payload: ComfyUIEditImageForm, client_i
) as ws:
log.info('WebSocket connection established.')
log.info('Sending workflow to WebSocket server.')
log.debug(f'Workflow: {workflow}')
log.debug('Workflow: %s', workflow)
images = await _ws_get_images(ws, workflow, client_id, base_url, api_key)
except aiohttp.WSServerHandshakeError as e:
log.exception(f'Failed to connect to WebSocket server: {e}')
+1 -1
View File
@@ -457,7 +457,7 @@ async def review_memory_after_turn(
try:
done_task.result()
except Exception as e:
log.debug(f'Memory review failed: {e}')
log.debug('Memory review failed: %s', e)
task.add_done_callback(log_failure)
+17 -17
View File
@@ -1210,9 +1210,9 @@ async def chat_completion_tools_handler(
try:
response = await generate_chat_completion(request, form_data=payload, user=user)
log.debug(f'{response=}')
log.debug('response=%r', response)
content = await get_content_from_response(response)
log.debug(f'{content=}')
log.debug('content=%r', content)
if not content:
return body, {}
@@ -1227,7 +1227,7 @@ async def chat_completion_tools_handler(
async def tool_call_handler(tool_call):
nonlocal skip_files
log.debug(f'{tool_call=}')
log.debug('tool_call=%r', tool_call)
tool_function_name = tool_call.get('name', None)
if tool_function_name not in tools:
@@ -1341,13 +1341,13 @@ async def chat_completion_tools_handler(
await tool_call_handler(result)
except Exception as e:
log.debug(f'Error: {e}')
log.debug('Error: %s', e)
content = None
except Exception as e:
log.debug(f'Error: {e}')
log.debug('Error: %s', e)
content = None
log.debug(f'tool_contexts: {sources}')
log.debug('tool_contexts: %s', sources)
if skip_files and 'files' in body.get('metadata', {}):
del body['metadata']['files']
@@ -1912,7 +1912,7 @@ async def chat_completion_files_handler(
except Exception as e:
log.exception(e)
log.debug(f'rag_contexts:sources: {sources}')
log.debug('rag_contexts:sources: %s', sources)
unique_ids = set()
for source in sources or []:
@@ -2028,7 +2028,7 @@ async def convert_url_images_to_base64(form_data, user=None):
else:
new_content.append(item)
except Exception as e:
log.debug(f'Error converting image URL to base64: {e}')
log.debug('Error converting image URL to base64: %s', e)
new_content.append(item)
message['content'] = new_content
@@ -2286,7 +2286,7 @@ async def process_chat_payload(request, form_data, user, metadata, model):
model_system_prompt = (form_data.get('params') or {}).get('system')
form_data = apply_params_to_form_data(form_data, model)
log.debug(f'form_data: {form_data}')
log.debug('form_data: %s', form_data)
# Guided regeneration: extract before it reaches the LLM provider
regeneration_prompt = form_data.pop('regeneration_prompt', None)
@@ -2725,8 +2725,8 @@ async def process_chat_payload(request, form_data, user, metadata, model):
# Client side tools
direct_tool_servers = metadata.get('tool_servers', None)
log.debug(f'{tool_ids=}')
log.debug(f'{direct_tool_servers=}')
log.debug('tool_ids=%r', tool_ids)
log.debug('direct_tool_servers=%r', direct_tool_servers)
tools_dict = {}
@@ -3498,7 +3498,7 @@ async def outlet_filter_handler(ctx):
try:
outlet_data = await process_pipeline_outlet_filter(request, outlet_data, user, models)
except Exception as e:
log.debug(f'Pipeline outlet filter error: {e}')
log.debug('Pipeline outlet filter error: %s', e)
# Function outlet filters
extra_params = {
@@ -3559,7 +3559,7 @@ async def outlet_filter_handler(ctx):
}
)
except Exception as e:
log.debug(f'Error running outlet filters: {e}')
log.debug('Error running outlet filters: %s', e)
async def non_streaming_chat_response_handler(response, ctx):
@@ -3704,7 +3704,7 @@ async def non_streaming_chat_response_handler(response, ctx):
response = build_response_object(response, merge_events_into_response(response_data, events))
except Exception as e:
log.debug(f'Error occurred while processing request: {e}')
log.debug('Error occurred while processing request: %s', e)
chat_id = metadata.get('chat_id')
if getattr(request.state, 'internal', False) is not True and chat_id and is_saved_chat_id(chat_id):
webui_url = await Config.get('webui.url')
@@ -4815,7 +4815,7 @@ async def streaming_chat_response_handler(response, ctx):
if done:
pass
else:
log.debug(f'Error: {e}')
log.debug('Error: %s', e)
continue
await flush_pending_delta_data()
@@ -5336,7 +5336,7 @@ async def streaming_chat_response_handler(response, ctx):
)
retries += 1
log.debug(f'Attempt count: {retries}')
log.debug('Attempt count: %s', retries)
ci_item = output[-1]
ci_output = ''
@@ -5398,7 +5398,7 @@ async def streaming_chat_response_handler(response, ctx):
else:
ci_output = {'stdout': 'Code interpreter engine not configured.'}
log.debug(f'Code interpreter output: {ci_output}')
log.debug('Code interpreter output: %s', ci_output)
# Handle error responses from event_caller
# (e.g. session disconnected, timeout)
+2 -2
View File
@@ -307,7 +307,7 @@ async def get_all_models(request, refresh: bool = False, user: UserModel = None)
try:
await get_function_module_from_cache(request, function_id, function=function)
except Exception as e:
log.debug(f'Failed to load function module for {function_id}: {e}')
log.debug('Failed to load function module for %s: %s', function_id, e)
# Apply global model defaults to all models
# Per-model overrides take precedence over global defaults
@@ -413,7 +413,7 @@ async def get_all_models(request, refresh: bool = False, user: UserModel = None)
filter_items_by_id[filter_id] = items
model['filters'].extend({**item} for item in items)
log.debug(f'get_all_models() returned {len(models)} models')
log.debug('get_all_models() returned %s models', len(models))
models_dict = {model['id']: model for model in models}
if isinstance(request.app.state.MODELS, RedisDict):
+37 -36
View File
@@ -241,7 +241,7 @@ def _normalize_token_expiry(token: dict) -> dict:
if exp is not None:
expires_at = min(expires_at, int(exp))
except Exception as e:
log.debug(f'Could not read exp from id_token: {e}')
log.debug('Could not read exp from id_token: %s', e)
token['expires_at'] = expires_at
return token
@@ -411,7 +411,7 @@ async def get_protected_resource_metadata(server_url: str) -> ProtectedResourceM
)
if match:
resource_metadata_urls = [match.group(1) or match.group(2)]
log.debug(f'Found resource_metadata URL: {resource_metadata_urls[0]}')
log.debug('Found resource_metadata URL: %s', resource_metadata_urls[0])
else:
# Fall back to well-known resource metadata URIs (RFC 9728 §4.2)
parsed, base_url = get_parsed_and_base_url(server_url)
@@ -423,7 +423,7 @@ async def get_protected_resource_metadata(server_url: str) -> ProtectedResourceM
resource_metadata_urls.append(
urllib.parse.urljoin(base_url, '/.well-known/oauth-protected-resource')
)
log.debug(f'No resource_metadata in header, trying well-known URIs: {resource_metadata_urls}')
log.debug('No resource_metadata in header, trying well-known URIs: %s', resource_metadata_urls)
# Fetch Protected Resource metadata from candidate URLs
for resource_metadata_url in resource_metadata_urls:
@@ -436,22 +436,22 @@ async def get_protected_resource_metadata(server_url: str) -> ProtectedResourceM
resource = resource_metadata.get('resource') or None
if resource:
log.debug(f'Discovered resource indicator: {resource}')
log.debug('Discovered resource indicator: %s', resource)
servers = resource_metadata.get('authorization_servers', [])
scopes = resource_metadata.get('scopes_supported', [])
if scopes:
log.debug(f'Discovered resource scopes: {scopes}')
log.debug('Discovered resource scopes: %s', scopes)
if servers:
authorization_servers = servers
log.debug(f'Discovered authorization servers: {servers}')
log.debug('Discovered authorization servers: %s', servers)
break
except Exception as e:
log.debug(f'Failed to fetch resource metadata from {resource_metadata_url}: {e}')
log.debug('Failed to fetch resource metadata from %s: %s', resource_metadata_url, e)
continue
except Exception as e:
log.debug(f'MCP Protected Resource discovery failed: {e}')
log.debug('MCP Protected Resource discovery failed: %s', e)
return ProtectedResourceMetadata(
resource=resource, authorization_servers=authorization_servers, scopes_supported=scopes
@@ -801,7 +801,7 @@ async def recover_static_oauth_client_metadata(connection: dict, oauth_client_in
try:
resource_metadata = await get_protected_resource_metadata(server_url)
except Exception as e:
log.debug(f'Unable to recover static OAuth metadata for {server_url}: {e}')
log.debug('Unable to recover static OAuth metadata for %s: %s', server_url, e)
return oauth_client_info
recovered = {**oauth_client_info}
@@ -946,9 +946,7 @@ class OAuthClientManager:
if not authorization_url:
return True
except Exception as e:
log.debug(
f'Skipping OAuth preflight for client {client_info.client_id}: {e}',
)
log.debug('Skipping OAuth preflight for client %s: %s', client_info.client_id, e)
return True
try:
@@ -994,7 +992,7 @@ class OAuthClientManager:
return False
except Exception as e:
log.debug(f'Skipping OAuth preflight network check for client {client_info.client_id}: {e}')
log.debug('Skipping OAuth preflight network check for client %s: %s', client_info.client_id, e)
return True
@@ -1043,7 +1041,7 @@ class OAuthClientManager:
or session.expires_at is None
or datetime.now() + timedelta(minutes=5) >= datetime.fromtimestamp(session.expires_at)
):
log.debug(f'Token refresh needed for user {user_id}, client_id {session.provider}')
log.debug('Token refresh needed for user %s, client_id %s', user_id, session.provider)
refreshed_token = await self._refresh_token(session)
if refreshed_token:
return refreshed_token
@@ -1160,7 +1158,7 @@ class OAuthClientManager:
_normalize_token_expiry(new_token_data)
log.debug(f'Token refresh successful for client_id {client_id}')
log.debug('Token refresh successful for client_id %s', client_id)
return new_token_data
else:
error_text = await r.text()
@@ -1326,8 +1324,9 @@ class OAuthManager:
# the session (#24618).
if (session.provider or '').startswith('mcp:'):
log.debug(
f'Skipping MCP session {session.id} (provider={session.provider}) '
f'in SSO OAuthManager — handled by oauth_client_manager'
'Skipping MCP session %s (provider=%s) in SSO OAuthManager — handled by oauth_client_manager',
session.id,
session.provider,
)
return None
@@ -1336,7 +1335,7 @@ class OAuthManager:
or session.expires_at is None
or datetime.now() + timedelta(minutes=5) >= datetime.fromtimestamp(session.expires_at)
):
log.debug(f'Token refresh needed for user {user_id}, provider {session.provider}')
log.debug('Token refresh needed for user %s, provider %s', user_id, session.provider)
refreshed_token = await self._refresh_token(session)
if refreshed_token:
return refreshed_token
@@ -1452,7 +1451,7 @@ class OAuthManager:
_normalize_token_expiry(new_token_data)
log.debug(f'Token refresh successful for provider {provider}')
log.debug('Token refresh successful for provider %s', provider)
return new_token_data
else:
error_text = await r.text()
@@ -1511,10 +1510,10 @@ class OAuthManager:
elif isinstance(claim_data, int):
oauth_roles = [str(claim_data)]
log.debug(f'Oauth Roles claim: {oauth_claim}')
log.debug(f'User roles from oauth: {oauth_roles}')
log.debug(f'Accepted user roles: {oauth_allowed_roles}')
log.debug(f'Accepted admin roles: {oauth_admin_roles}')
log.debug('Oauth Roles claim: %s', oauth_claim)
log.debug('User roles from oauth: %s', oauth_roles)
log.debug('Accepted user roles: %s', oauth_allowed_roles)
log.debug('Accepted admin roles: %s', oauth_admin_roles)
# If roles are present in the token, they must match; otherwise deny access
if oauth_roles:
@@ -1591,7 +1590,7 @@ class OAuthManager:
# Determine creator ID: Prefer admin, fallback to current user if no admin exists
admin_user = await Users.get_super_admin_user()
creator_id = admin_user.id if admin_user else user.id
log.debug(f'Using creator ID {creator_id} for potential group creation.')
log.debug('Using creator ID %s for potential group creation.', creator_id)
for group_name in user_oauth_groups:
if group_name not in all_group_names:
@@ -1622,10 +1621,10 @@ class OAuthManager:
all_available_groups = await Groups.get_all_groups(db=db)
log.debug('Refreshed list of all available groups after creation.')
log.debug(f'Oauth Groups claim: {oauth_claim}')
log.debug(f'User oauth groups: {user_oauth_groups}')
log.debug(f"User's current groups: {[g.name for g in user_current_groups]}")
log.debug(f'All groups available in OpenWebUI: {[g.name for g in all_available_groups]}')
log.debug('Oauth Groups claim: %s', oauth_claim)
log.debug('User oauth groups: %s', user_oauth_groups)
log.debug("User's current groups: %s", [g.name for g in user_current_groups])
log.debug('All groups available in OpenWebUI: %s', [g.name for g in all_available_groups])
# Remove groups that user is no longer a part of
for group_model in user_current_groups:
@@ -1635,7 +1634,7 @@ class OAuthManager:
and not is_in_blocked_groups(group_model.name, blocked_groups)
):
# Remove group from user
log.debug(f'Removing user from group {group_model.name} as it is no longer in their oauth groups')
log.debug('Removing user from group %s as it is no longer in their oauth groups', group_model.name)
await Groups.remove_users_from_group(group_model.id, [user.id], db=db)
# In case a group is created, but perms are never assigned to the group by hitting "save"
@@ -1663,7 +1662,7 @@ class OAuthManager:
and not is_in_blocked_groups(group_model.name, blocked_groups)
):
# Add user to group
log.debug(f'Adding user to group {group_model.name} as it was found in their oauth groups')
log.debug('Adding user to group %s as it was found in their oauth groups', group_model.name)
await Groups.add_users_to_group(group_model.id, [user.id], db=db)
@@ -1916,7 +1915,7 @@ class OAuthManager:
if new_name and new_name != user.name:
await Users.update_user_by_id(user.id, {'name': new_name}, db=db)
user.name = new_name
log.debug(f'Updated name for user {user.email}')
log.debug('Updated name for user %s', user.email)
if auth_config.OAUTH_UPDATE_EMAIL_ON_LOGIN:
email_claim = auth_config.OAUTH_EMAIL_CLAIM
@@ -1931,7 +1930,7 @@ class OAuthManager:
else:
await Auths.update_email_by_id(user.id, new_email.lower(), db=db)
user.email = new_email.lower()
log.debug(f'Updated email for user {user.id}')
log.debug('Updated email for user %s', user.id)
# Update profile picture if enabled and different from current
if auth_config.OAUTH_UPDATE_PICTURE_ON_LOGIN:
@@ -1946,7 +1945,7 @@ class OAuthManager:
)
if processed_picture_url != user.profile_image_url:
await Users.update_user_profile_image_url_by_id(user.id, processed_picture_url, db=db)
log.debug(f'Updated profile picture for user {user.email}')
log.debug('Updated profile picture for user %s', user.email)
else:
# If the user does not exist, check if signups are enabled
if auth_config.ENABLE_OAUTH_SIGNUP:
@@ -2172,7 +2171,7 @@ class OAuthManager:
matched_issuer = provider_issuer
break
except Exception as e:
log.debug(f'Back-channel logout: error checking provider {provider_name}: {e}')
log.debug('Back-channel logout: error checking provider %s: %s', provider_name, e)
continue
if not matched_provider or not matched_client_id or not matched_jwks_uri:
@@ -2249,10 +2248,12 @@ class OAuthManager:
users_to_logout.append(user)
if not users_to_logout and sid:
log.debug(f'Back-channel logout: no user found by sub, sid-based lookup not yet supported (sid={sid})')
log.debug('Back-channel logout: no user found by sub, sid-based lookup not yet supported (sid=%s)', sid)
if not users_to_logout:
log.debug(f'Back-channel logout: no matching user for provider={matched_provider}, sub={sub}, sid={sid}')
log.debug(
'Back-channel logout: no matching user for provider=%s, sub=%s, sid=%s', matched_provider, sub, sid
)
return JSONResponse(status_code=200, content={})
# 9. Revoke tokens and delete sessions
+3 -3
View File
@@ -1187,7 +1187,7 @@ async def get_terminal_cwd(
data = await resp.json()
return data.get('cwd')
except Exception as e:
log.debug(f'Failed to fetch terminal CWD: {e}')
log.debug('Failed to fetch terminal CWD: %s', e)
return None
@@ -1226,7 +1226,7 @@ async def get_terminal_system_prompt(
data = await resp.json()
return data.get('prompt')
except Exception as e:
log.debug(f'Failed to fetch terminal system prompt: {e}')
log.debug('Failed to fetch terminal system prompt: %s', e)
return None
@@ -1447,7 +1447,7 @@ async def get_tool_server_data(url: str, headers: dict | None) -> dict[str, Any]
error = str(err)
raise Exception(error)
log.debug(f'Fetched data: {res}')
log.debug('Fetched data: %s', res)
return res
+3 -3
View File
@@ -29,7 +29,7 @@ def _event_text(message: str, description: str | None = None, event_data: dict |
async def post_webhook(name: str, url: str, message: str, event_data: dict, description: str | None = None) -> bool:
try:
log.debug(f'post_webhook: {url}, {message}, {event_data}')
log.debug('post_webhook: %s, %s, %s', url, message, event_data)
# Block private-IP / loopback / cloud-metadata targets — the URL is
# caller-controlled (user notification settings under
# ENABLE_USER_WEBHOOKS, automation notification triggers).
@@ -83,7 +83,7 @@ async def post_webhook(name: str, url: str, message: str, event_data: dict, desc
else:
payload = event_data
log.debug(f'payload: {payload}')
log.debug('payload: %s', payload)
async with get_ssrf_safe_session() as session:
async with session.post(
url,
@@ -93,7 +93,7 @@ async def post_webhook(name: str, url: str, message: str, event_data: dict, desc
) as r:
r_text = await r.text()
r.raise_for_status()
log.debug(f'r.text: {r_text}')
log.debug('r.text: %s', r_text)
return True
except Exception as e: