refactor: convert f-string logging to lazy %-style format (G004)
Sweep all 1676 G004 violations across 112 files, converting
`logger.<level>(f"…{x}…")` to `logger.<level>("…%s…", x)`.
Why: ruff rule G004 was added to pyproject.toml to enforce lazy
%-style logging — defers formatting until the log level is enabled
and lets structured log tooling match the unformatted template.
Conversion preserves rendered output byte-for-byte:
- `{x}` → `%s` + `x`
- `{x!r}` / `{x!s}` / `{x!a}` → `%r` / `%s` / `%a`
- Format specs (`{x:.2f}`, `{x:>10}`) → `%s` + `format(x, 'spec')`
(printf-style specs aren't 1:1 with Python format specs, so we
delegate to `format()` to keep identical output)
- Literal `%` → `%%`
- Concatenated f-strings (`f"a {x} " "b"`) flattened
- Trailing kwargs (`exc_info=True`) preserved
Verified:
- `uv run ruff check --select G004` → 0 violations
- `uv run ty check -- nextcloud_mcp_server` → passes
- `uv run pytest tests/unit/` → 1010 passed
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
co-authored by
Claude Opus 4.7
parent
a4e6125d28
commit
665cb9b1eb
@@ -61,8 +61,8 @@ def get_database_url() -> str:
|
||||
db_path = Path(get_token_db_path())
|
||||
url = f"sqlite+aiosqlite:///{db_path}"
|
||||
logger.warning(
|
||||
f"No database URL configured, using default: {url}. "
|
||||
"Set sqlalchemy.url in alembic.ini or pass -x database_url=..."
|
||||
"No database URL configured, using default: %s. Set sqlalchemy.url in alembic.ini or pass -x database_url=...",
|
||||
url,
|
||||
)
|
||||
|
||||
return url
|
||||
|
||||
@@ -137,7 +137,7 @@ def _sanitize_error_for_client(error: Exception, context: str = "") -> str:
|
||||
Generic error message safe for client consumption
|
||||
"""
|
||||
# Log detailed error for debugging
|
||||
logger.error(f"Error in {context}: {error}", exc_info=True)
|
||||
logger.error("Error in %s: %s", context, error, exc_info=True)
|
||||
|
||||
# Return generic message
|
||||
return "An internal error occurred. Please contact your administrator."
|
||||
@@ -307,7 +307,7 @@ async def get_vector_sync_status(request: Request) -> JSONResponse:
|
||||
indexed_count = count_result.count
|
||||
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to query Qdrant for indexed count: {e}")
|
||||
logger.warning("Failed to query Qdrant for indexed count: %s", e)
|
||||
# Continue with indexed_count = 0
|
||||
|
||||
# Determine status
|
||||
@@ -355,7 +355,7 @@ async def get_user_session(request: Request) -> JSONResponse:
|
||||
# Verify token user matches requested user
|
||||
if token_user_id != path_user_id:
|
||||
logger.warning(
|
||||
f"User {token_user_id} attempted to access session for {path_user_id}"
|
||||
"User %s attempted to access session for %s", token_user_id, path_user_id
|
||||
)
|
||||
return JSONResponse(
|
||||
{
|
||||
@@ -442,7 +442,7 @@ async def revoke_user_access(request: Request) -> JSONResponse:
|
||||
# Validate OAuth token and extract user
|
||||
token_user_id, validated = await validate_token_and_get_user(request)
|
||||
except Exception as e:
|
||||
logger.warning(f"Unauthorized access to /api/v1/users/{{user_id}}/revoke: {e}")
|
||||
logger.warning("Unauthorized access to /api/v1/users/{{user_id}}/revoke: %s", e)
|
||||
return JSONResponse(
|
||||
{
|
||||
"error": "Unauthorized",
|
||||
@@ -457,7 +457,7 @@ async def revoke_user_access(request: Request) -> JSONResponse:
|
||||
# Verify token user matches requested user
|
||||
if token_user_id != path_user_id:
|
||||
logger.warning(
|
||||
f"User {token_user_id} attempted to revoke access for {path_user_id}"
|
||||
"User %s attempted to revoke access for %s", token_user_id, path_user_id
|
||||
)
|
||||
return JSONResponse(
|
||||
{
|
||||
@@ -492,7 +492,8 @@ async def revoke_user_access(request: Request) -> JSONResponse:
|
||||
await token_broker.cache.invalidate(token_user_id)
|
||||
|
||||
logger.info(
|
||||
f"Revoked background access for user {token_user_id} (cache and storage cleared)"
|
||||
"Revoked background access for user %s (cache and storage cleared)",
|
||||
token_user_id,
|
||||
)
|
||||
|
||||
return JSONResponse(
|
||||
|
||||
@@ -143,7 +143,7 @@ def _extract_basic_auth(
|
||||
# Verify username matches path user_id
|
||||
if username != path_user_id:
|
||||
logger.warning(
|
||||
f"Username mismatch in app password operation for path user {path_user_id}"
|
||||
"Username mismatch in app password operation for path user %s", path_user_id
|
||||
)
|
||||
return (
|
||||
"",
|
||||
@@ -211,7 +211,7 @@ async def provision_app_password(request: Request) -> JSONResponse:
|
||||
is_allowed, retry_after = _check_rate_limit(path_user_id)
|
||||
if not is_allowed:
|
||||
logger.warning(
|
||||
f"Rate limit exceeded for app password provisioning: {path_user_id}"
|
||||
"Rate limit exceeded for app password provisioning: %s", path_user_id
|
||||
)
|
||||
return JSONResponse(
|
||||
{
|
||||
@@ -263,7 +263,8 @@ async def provision_app_password(request: Request) -> JSONResponse:
|
||||
|
||||
if response.status_code != 200:
|
||||
logger.warning(
|
||||
f"App password validation failed for user: HTTP {response.status_code}"
|
||||
"App password validation failed for user: HTTP %s",
|
||||
response.status_code,
|
||||
)
|
||||
_record_rate_limit_attempt(path_user_id, success=False)
|
||||
return JSONResponse(
|
||||
@@ -283,7 +284,7 @@ async def provision_app_password(request: Request) -> JSONResponse:
|
||||
)
|
||||
|
||||
except httpx.RequestError as e:
|
||||
logger.error(f"Failed to validate app password: {e}")
|
||||
logger.error("Failed to validate app password: %s", e)
|
||||
return JSONResponse(
|
||||
{"success": False, "error": "Failed to validate credentials"},
|
||||
status_code=500,
|
||||
@@ -309,7 +310,7 @@ async def provision_app_password(request: Request) -> JSONResponse:
|
||||
invalidate_scope_cache(username)
|
||||
|
||||
_record_rate_limit_attempt(path_user_id, success=True)
|
||||
logger.info(f"Provisioned app password for user: {username}")
|
||||
logger.info("Provisioned app password for user: %s", username)
|
||||
|
||||
return JSONResponse(
|
||||
{
|
||||
@@ -409,7 +410,7 @@ async def delete_app_password(request: Request) -> JSONResponse:
|
||||
status_code=401,
|
||||
)
|
||||
except httpx.RequestError as e:
|
||||
logger.error(f"Failed to validate credentials: {e}")
|
||||
logger.error("Failed to validate credentials: %s", e)
|
||||
return JSONResponse(
|
||||
{"success": False, "error": "Failed to validate credentials"},
|
||||
status_code=500,
|
||||
@@ -420,7 +421,7 @@ async def delete_app_password(request: Request) -> JSONResponse:
|
||||
deleted = await storage.delete_app_password(username)
|
||||
|
||||
if deleted:
|
||||
logger.info(f"Deleted app password for user: {username}")
|
||||
logger.info("Deleted app password for user: %s", username)
|
||||
return JSONResponse(
|
||||
{
|
||||
"success": True,
|
||||
|
||||
@@ -90,7 +90,7 @@ async def unified_search(request: Request) -> JSONResponse:
|
||||
try:
|
||||
user_id, _validated = await validate_token_and_get_user(request)
|
||||
except Exception as e:
|
||||
logger.warning(f"Unauthorized access to /api/v1/search: {e}")
|
||||
logger.warning("Unauthorized access to /api/v1/search: %s", e)
|
||||
return JSONResponse(
|
||||
{
|
||||
"error": "Unauthorized",
|
||||
@@ -268,12 +268,12 @@ async def unified_search(request: Request) -> JSONResponse:
|
||||
)
|
||||
response_data["pca_data"] = pca_data
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to compute PCA for unified search: {e}")
|
||||
logger.warning("Failed to compute PCA for unified search: %s", e)
|
||||
|
||||
return JSONResponse(response_data)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error in unified search: {e}")
|
||||
logger.error("Error in unified search: %s", e)
|
||||
return JSONResponse(
|
||||
{
|
||||
"error": "Internal error",
|
||||
@@ -311,7 +311,7 @@ async def vector_search(request: Request) -> JSONResponse:
|
||||
try:
|
||||
user_id, _validated = await validate_token_and_get_user(request)
|
||||
except Exception as e:
|
||||
logger.warning(f"Unauthorized access to /api/v1/vector-viz/search: {e}")
|
||||
logger.warning("Unauthorized access to /api/v1/vector-viz/search: %s", e)
|
||||
return JSONResponse(
|
||||
{
|
||||
"error": "Unauthorized",
|
||||
@@ -428,7 +428,7 @@ async def vector_search(request: Request) -> JSONResponse:
|
||||
if "pca_variance" in pca_data:
|
||||
response_data["pca_variance"] = pca_data["pca_variance"]
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to compute PCA coordinates: {e}")
|
||||
logger.warning("Failed to compute PCA coordinates: %s", e)
|
||||
response_data["coordinates_3d"] = []
|
||||
response_data["query_coords"] = []
|
||||
elif include_pca:
|
||||
@@ -465,7 +465,7 @@ async def get_chunk_context(request: Request) -> JSONResponse:
|
||||
# Validate OAuth token and extract user
|
||||
user_id, validated = await validate_token_and_get_user(request)
|
||||
except Exception as e:
|
||||
logger.warning(f"Unauthorized access to /api/v1/chunk-context: {e}")
|
||||
logger.warning("Unauthorized access to /api/v1/chunk-context: %s", e)
|
||||
return JSONResponse(
|
||||
{
|
||||
"error": "Unauthorized",
|
||||
@@ -661,14 +661,16 @@ async def get_pdf_preview(request: Request) -> JSONResponse:
|
||||
# Log incoming request
|
||||
file_path_param = request.query_params.get("file_path", "<not provided>")
|
||||
page_param = request.query_params.get("page", "1")
|
||||
logger.info(f"PDF preview request: file_path={file_path_param}, page={page_param}")
|
||||
logger.info(
|
||||
"PDF preview request: file_path=%s, page=%s", file_path_param, page_param
|
||||
)
|
||||
|
||||
try:
|
||||
# Validate OAuth token and extract user
|
||||
user_id, validated = await validate_token_and_get_user(request)
|
||||
logger.info(f"PDF preview authenticated for user: {user_id}")
|
||||
logger.info("PDF preview authenticated for user: %s", user_id)
|
||||
except Exception as e:
|
||||
logger.warning(f"Unauthorized access to /api/v1/pdf-preview: {e}")
|
||||
logger.warning("Unauthorized access to /api/v1/pdf-preview: %s", e)
|
||||
return JSONResponse(
|
||||
{
|
||||
"success": False,
|
||||
@@ -763,8 +765,11 @@ async def get_pdf_preview(request: Request) -> JSONResponse:
|
||||
image_b64 = base64.b64encode(png_bytes).decode("ascii")
|
||||
|
||||
logger.info(
|
||||
f"Rendered PDF preview: {file_path} page {page_num}/{total_pages}, "
|
||||
f"{len(png_bytes):,} bytes"
|
||||
"Rendered PDF preview: %s page %s/%s, %s bytes",
|
||||
file_path,
|
||||
page_num,
|
||||
total_pages,
|
||||
format(len(png_bytes), ","),
|
||||
)
|
||||
|
||||
return JSONResponse(
|
||||
@@ -777,19 +782,19 @@ async def get_pdf_preview(request: Request) -> JSONResponse:
|
||||
)
|
||||
|
||||
except FileNotFoundError:
|
||||
logger.warning(f"PDF file not found: {file_path_param}")
|
||||
logger.warning("PDF file not found: %s", file_path_param)
|
||||
return JSONResponse(
|
||||
{"success": False, "error": "PDF file not found"},
|
||||
status_code=404,
|
||||
)
|
||||
except (pymupdf.FileDataError, pymupdf.EmptyFileError):
|
||||
logger.warning(f"Invalid or corrupted PDF file: {file_path_param}")
|
||||
logger.warning("Invalid or corrupted PDF file: %s", file_path_param)
|
||||
return JSONResponse(
|
||||
{"success": False, "error": "Invalid or corrupted PDF file"},
|
||||
status_code=400,
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"PDF preview error: {e}", exc_info=True)
|
||||
logger.error("PDF preview error: %s", e, exc_info=True)
|
||||
error_msg = _sanitize_error_for_client(e, "get_pdf_preview")
|
||||
return JSONResponse(
|
||||
{"success": False, "error": error_msg},
|
||||
|
||||
+112
-85
@@ -169,10 +169,10 @@ def initialize_document_processors():
|
||||
progress_interval=unst_config.get("progress_interval", 10),
|
||||
)
|
||||
registry.register(processor, priority=10)
|
||||
logger.info(f"Registered Unstructured processor: {unst_config['api_url']}")
|
||||
logger.info("Registered Unstructured processor: %s", unst_config["api_url"])
|
||||
registered_count += 1
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to register Unstructured processor: {e}")
|
||||
logger.warning("Failed to register Unstructured processor: %s", e)
|
||||
|
||||
# Register Tesseract processor
|
||||
if "tesseract" in config["processors"]:
|
||||
@@ -187,10 +187,10 @@ def initialize_document_processors():
|
||||
default_lang=tess_config["lang"],
|
||||
)
|
||||
registry.register(processor, priority=5)
|
||||
logger.info(f"Registered Tesseract processor: lang={tess_config['lang']}")
|
||||
logger.info("Registered Tesseract processor: lang=%s", tess_config["lang"])
|
||||
registered_count += 1
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to register Tesseract processor: {e}")
|
||||
logger.warning("Failed to register Tesseract processor: %s", e)
|
||||
|
||||
# Register PyMuPDF processor (high priority, local, no API required)
|
||||
if "pymupdf" in config["processors"]:
|
||||
@@ -206,11 +206,12 @@ def initialize_document_processors():
|
||||
)
|
||||
registry.register(processor, priority=15) # Higher than unstructured
|
||||
logger.info(
|
||||
f"Registered PyMuPDF processor: extract_images={pymupdf_config.get('extract_images', True)}"
|
||||
"Registered PyMuPDF processor: extract_images=%s",
|
||||
pymupdf_config.get("extract_images", True),
|
||||
)
|
||||
registered_count += 1
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to register PyMuPDF processor: {e}")
|
||||
logger.warning("Failed to register PyMuPDF processor: %s", e)
|
||||
|
||||
# Register custom processor
|
||||
if "custom" in config["processors"]:
|
||||
@@ -229,16 +230,19 @@ def initialize_document_processors():
|
||||
)
|
||||
registry.register(processor, priority=1)
|
||||
logger.info(
|
||||
f"Registered Custom processor '{custom_config['name']}': {custom_config['api_url']}"
|
||||
"Registered Custom processor '%s': %s",
|
||||
custom_config["name"],
|
||||
custom_config["api_url"],
|
||||
)
|
||||
registered_count += 1
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to register Custom processor: {e}")
|
||||
logger.warning("Failed to register Custom processor: %s", e)
|
||||
|
||||
if registered_count > 0:
|
||||
logger.info(
|
||||
f"Document processing initialized with {registered_count} processor(s): "
|
||||
f"{', '.join(registry.list_processors())}"
|
||||
"Document processing initialized with %s processor(s): %s",
|
||||
registered_count,
|
||||
", ".join(registry.list_processors()),
|
||||
)
|
||||
else:
|
||||
logger.warning("Document processing enabled but no processors registered")
|
||||
@@ -409,10 +413,10 @@ class BasicAuthMiddleware:
|
||||
"password": password,
|
||||
}
|
||||
logger.debug(
|
||||
f"BasicAuth credentials extracted for user: {username}"
|
||||
"BasicAuth credentials extracted for user: %s", username
|
||||
)
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to extract BasicAuth credentials: {e}")
|
||||
logger.warning("Failed to extract BasicAuth credentials: %s", e)
|
||||
|
||||
await self.app(scope, receive, send)
|
||||
|
||||
@@ -451,7 +455,7 @@ async def load_oauth_client_credentials(
|
||||
client_data = await storage.get_oauth_client()
|
||||
if client_data:
|
||||
logger.info(
|
||||
f"Loaded OAuth client from SQLite: {client_data['client_id'][:16]}..."
|
||||
"Loaded OAuth client from SQLite: %s...", client_data["client_id"][:16]
|
||||
)
|
||||
return (client_data["client_id"], client_data["client_secret"])
|
||||
except ValueError:
|
||||
@@ -496,7 +500,7 @@ async def load_oauth_client_credentials(
|
||||
dcr_scopes = f"{dcr_scopes} offline_access"
|
||||
logger.info("✓ offline_access scope enabled for refresh tokens")
|
||||
|
||||
logger.info(f"MCP server DCR scopes (resource server): {dcr_scopes}")
|
||||
logger.info("MCP server DCR scopes (resource server): %s", dcr_scopes)
|
||||
|
||||
# Get token type from environment (Bearer or jwt)
|
||||
# Note: Must be lowercase "jwt" to match OIDC app's check
|
||||
@@ -504,7 +508,7 @@ async def load_oauth_client_credentials(
|
||||
# Special case: "bearer" should remain capitalized for compatibility
|
||||
if token_type != "jwt":
|
||||
token_type = "Bearer"
|
||||
logger.info(f"Requesting token type: {token_type}")
|
||||
logger.info("Requesting token type: %s", token_type)
|
||||
|
||||
# Ensure OAuth client in SQLite storage
|
||||
storage = RefreshTokenStorage.from_env()
|
||||
@@ -525,7 +529,7 @@ async def load_oauth_client_credentials(
|
||||
resource_url=resource_url, # RFC 9728 Protected Resource URL
|
||||
)
|
||||
|
||||
logger.info(f"OAuth client ready: {client_info.client_id[:16]}...")
|
||||
logger.info("OAuth client ready: %s...", client_info.client_id[:16])
|
||||
return (client_info.client_id, client_info.client_secret)
|
||||
|
||||
# No credentials available
|
||||
@@ -555,7 +559,8 @@ async def app_lifespan_basic(server: FastMCP) -> AsyncIterator[AppContext]:
|
||||
is_multi_user = settings.enable_multi_user_basic_auth
|
||||
|
||||
logger.info(
|
||||
f"Starting MCP session in {'multi-user' if is_multi_user else 'single-user'} BasicAuth mode"
|
||||
"Starting MCP session in %s BasicAuth mode",
|
||||
"multi-user" if is_multi_user else "single-user",
|
||||
)
|
||||
|
||||
# Only create shared client for single-user mode
|
||||
@@ -633,7 +638,7 @@ async def setup_oauth_config():
|
||||
discovery_url = os.getenv(
|
||||
"OIDC_DISCOVERY_URL", f"{nextcloud_host}/.well-known/openid-configuration"
|
||||
)
|
||||
logger.info(f"Performing OIDC discovery: {discovery_url}")
|
||||
logger.info("Performing OIDC discovery: %s", discovery_url)
|
||||
|
||||
# Perform OIDC discovery
|
||||
async with nextcloud_httpx_client(follow_redirects=True) as client:
|
||||
@@ -654,12 +659,12 @@ async def setup_oauth_config():
|
||||
registration_endpoint = discovery.get("registration_endpoint")
|
||||
|
||||
logger.info("OIDC endpoints discovered:")
|
||||
logger.info(f" Issuer: {issuer}")
|
||||
logger.info(f" Userinfo: {userinfo_uri}")
|
||||
logger.info(" Issuer: %s", issuer)
|
||||
logger.info(" Userinfo: %s", userinfo_uri)
|
||||
if jwks_uri:
|
||||
logger.info(f" JWKS: {jwks_uri}")
|
||||
logger.info(" JWKS: %s", jwks_uri)
|
||||
if introspection_uri:
|
||||
logger.info(f" Introspection: {introspection_uri}")
|
||||
logger.info(" Introspection: %s", introspection_uri)
|
||||
|
||||
# Auto-detect provider mode based on issuer
|
||||
# External IdP mode: issuer doesn't match Nextcloud host
|
||||
@@ -685,7 +690,9 @@ async def setup_oauth_config():
|
||||
if is_external_idp:
|
||||
oauth_provider = "external" # Could be Keycloak, Auth0, Okta, etc.
|
||||
logger.info(
|
||||
f"✓ Detected external IdP mode (issuer: {issuer} != Nextcloud: {nextcloud_host})"
|
||||
"✓ Detected external IdP mode (issuer: %s != Nextcloud: %s)",
|
||||
issuer,
|
||||
nextcloud_host,
|
||||
)
|
||||
logger.info(" Tokens will be validated via Nextcloud user_oidc app")
|
||||
else:
|
||||
@@ -716,7 +723,7 @@ async def setup_oauth_config():
|
||||
"✓ Refresh token storage initialized (offline_access enabled)"
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to initialize refresh token storage: {e}")
|
||||
logger.error("Failed to initialize refresh token storage: %s", e)
|
||||
logger.warning(
|
||||
"Continuing without refresh token storage - users will need to re-authenticate after token expiration"
|
||||
)
|
||||
@@ -726,7 +733,7 @@ async def setup_oauth_config():
|
||||
client_secret = os.getenv("NEXTCLOUD_OIDC_CLIENT_SECRET")
|
||||
|
||||
if client_id and client_secret:
|
||||
logger.info(f"Using static OIDC client credentials: {client_id}")
|
||||
logger.info("Using static OIDC client credentials: %s", client_id)
|
||||
elif registration_endpoint:
|
||||
logger.info(
|
||||
"NEXTCLOUD_OIDC_CLIENT_ID not set, attempting Dynamic Client Registration"
|
||||
@@ -753,13 +760,13 @@ async def setup_oauth_config():
|
||||
# Warn if resource URIs are not configured (required for ADR-005 compliance)
|
||||
if not os.getenv("NEXTCLOUD_MCP_SERVER_URL"):
|
||||
logger.warning(
|
||||
f"NEXTCLOUD_MCP_SERVER_URL not set, defaulting to: {mcp_server_url}. "
|
||||
"This should be set explicitly for proper audience validation."
|
||||
"NEXTCLOUD_MCP_SERVER_URL not set, defaulting to: %s. This should be set explicitly for proper audience validation.",
|
||||
mcp_server_url,
|
||||
)
|
||||
if not os.getenv("NEXTCLOUD_RESOURCE_URI"):
|
||||
logger.warning(
|
||||
f"NEXTCLOUD_RESOURCE_URI not set, defaulting to: {nextcloud_resource_uri}. "
|
||||
"This should be set explicitly for proper audience validation."
|
||||
"NEXTCLOUD_RESOURCE_URI not set, defaulting to: %s. This should be set explicitly for proper audience validation.",
|
||||
nextcloud_resource_uri,
|
||||
)
|
||||
|
||||
# Create settings for UnifiedTokenVerifier (use same settings instance from start of function)
|
||||
@@ -790,8 +797,8 @@ async def setup_oauth_config():
|
||||
logger.info(
|
||||
"✓ Multi-audience mode enabled (ADR-005) - tokens must contain both MCP and Nextcloud audiences"
|
||||
)
|
||||
logger.info(f" Required MCP audience: {client_id} or {mcp_server_url}")
|
||||
logger.info(f" Required Nextcloud audience: {nextcloud_resource_uri}")
|
||||
logger.info(" Required MCP audience: %s or %s", client_id, mcp_server_url)
|
||||
logger.info(" Required Nextcloud audience: %s", nextcloud_resource_uri)
|
||||
|
||||
if introspection_uri:
|
||||
logger.info("✓ Opaque token introspection enabled (RFC 7662)")
|
||||
@@ -881,7 +888,8 @@ async def setup_oauth_config_for_multi_user_basic(
|
||||
f"{nextcloud_host}/.well-known/openid-configuration",
|
||||
)
|
||||
logger.info(
|
||||
f"Performing OIDC discovery for multi-user BasicAuth hybrid mode: {discovery_url}"
|
||||
"Performing OIDC discovery for multi-user BasicAuth hybrid mode: %s",
|
||||
discovery_url,
|
||||
)
|
||||
|
||||
# Perform OIDC discovery
|
||||
@@ -894,20 +902,22 @@ async def setup_oauth_config_for_multi_user_basic(
|
||||
discovery = response.json()
|
||||
except httpx.HTTPStatusError as e:
|
||||
logger.error(
|
||||
f"OIDC discovery failed: HTTP {e.response.status_code} from {discovery_url}"
|
||||
"OIDC discovery failed: HTTP %s from %s",
|
||||
e.response.status_code,
|
||||
discovery_url,
|
||||
)
|
||||
raise ValueError(
|
||||
f"OIDC discovery failed: HTTP {e.response.status_code} from {discovery_url}. "
|
||||
"Ensure Nextcloud OIDC (user_oidc app) is installed and configured."
|
||||
) from e
|
||||
except httpx.RequestError as e:
|
||||
logger.error(f"OIDC discovery failed: {e}")
|
||||
logger.error("OIDC discovery failed: %s", e)
|
||||
raise ValueError(
|
||||
f"OIDC discovery failed: Cannot connect to {discovery_url}. Error: {e}"
|
||||
) from e
|
||||
except (KeyError, ValueError) as e:
|
||||
logger.error(
|
||||
f"OIDC discovery failed: Invalid response from {discovery_url}: {e}"
|
||||
"OIDC discovery failed: Invalid response from %s: %s", discovery_url, e
|
||||
)
|
||||
raise ValueError(
|
||||
f"OIDC discovery failed: Invalid response from {discovery_url}. "
|
||||
@@ -923,10 +933,10 @@ async def setup_oauth_config_for_multi_user_basic(
|
||||
introspection_uri = discovery.get("introspection_endpoint")
|
||||
|
||||
logger.info("OIDC endpoints configured for management API:")
|
||||
logger.info(f" Issuer: {issuer}")
|
||||
logger.info(f" Userinfo: {userinfo_uri}")
|
||||
logger.info(f" JWKS: {jwks_uri}")
|
||||
logger.info(f" Introspection: {introspection_uri}")
|
||||
logger.info(" Issuer: %s", issuer)
|
||||
logger.info(" Userinfo: %s", userinfo_uri)
|
||||
logger.info(" JWKS: %s", jwks_uri)
|
||||
logger.info(" Introspection: %s", introspection_uri)
|
||||
|
||||
# Get MCP server URL for audience validation
|
||||
mcp_server_url = os.getenv("NEXTCLOUD_MCP_SERVER_URL", "http://localhost:8000")
|
||||
@@ -982,8 +992,8 @@ async def setup_oauth_config_for_multi_user_basic(
|
||||
"✓ Refresh token storage initialized for background operations (hybrid mode)"
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to initialize refresh token storage: {e}")
|
||||
logger.debug(f"Full traceback:\n{traceback.format_exc()}")
|
||||
logger.error("Failed to initialize refresh token storage: %s", e)
|
||||
logger.debug("Full traceback:\\n%s", traceback.format_exc())
|
||||
logger.warning(
|
||||
"Continuing without refresh token storage - webhook management may be limited"
|
||||
)
|
||||
@@ -1012,8 +1022,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
logger.error(error_msg)
|
||||
raise ValueError(error_msg)
|
||||
|
||||
logger.info(f"✅ Configuration validated successfully for {mode.value} mode")
|
||||
logger.debug(f"Mode details:\n{get_mode_summary(mode)}")
|
||||
logger.info("✅ Configuration validated successfully for %s mode", mode.value)
|
||||
logger.debug("Mode details:\\n%s", get_mode_summary(mode))
|
||||
|
||||
# Derive helper variables for backward compatibility with existing code.
|
||||
# `oauth_enabled` is True for the LOGIN_FLOW (formerly OAUTH_SINGLE_AUDIENCE)
|
||||
@@ -1033,7 +1043,7 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
if settings.metrics_enabled:
|
||||
setup_metrics(port=settings.metrics_port)
|
||||
logger.info(
|
||||
f"Prometheus metrics enabled on dedicated port {settings.metrics_port}"
|
||||
"Prometheus metrics enabled on dedicated port %s", settings.metrics_port
|
||||
)
|
||||
|
||||
# Setup OpenTelemetry tracing (optional)
|
||||
@@ -1045,7 +1055,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
sampling_rate=settings.otel_traces_sampler_arg,
|
||||
)
|
||||
logger.info(
|
||||
f"OpenTelemetry tracing enabled (endpoint: {settings.otel_exporter_otlp_endpoint})"
|
||||
"OpenTelemetry tracing enabled (endpoint: %s)",
|
||||
settings.otel_exporter_otlp_endpoint,
|
||||
)
|
||||
else:
|
||||
logger.info(
|
||||
@@ -1093,7 +1104,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
# This avoids relying on discovery doc which may use public URLs unreachable from containers
|
||||
registration_endpoint = f"{settings.nextcloud_host}/apps/oidc/register"
|
||||
logger.info(
|
||||
f"Attempting Dynamic Client Registration at: {registration_endpoint}"
|
||||
"Attempting Dynamic Client Registration at: %s",
|
||||
registration_endpoint,
|
||||
)
|
||||
|
||||
# Perform DCR
|
||||
@@ -1108,13 +1120,13 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
registration_endpoint=registration_endpoint,
|
||||
)
|
||||
logger.info(
|
||||
f"✓ Dynamic Client Registration successful for background operations "
|
||||
f"(client_id: {client_id[:16]}...)"
|
||||
"✓ Dynamic Client Registration successful for background operations (client_id: %s...)",
|
||||
client_id[:16],
|
||||
)
|
||||
return (client_id, client_secret)
|
||||
except Exception as e:
|
||||
logger.error(f"Dynamic Client Registration failed: {e}")
|
||||
logger.debug(f"Full traceback:\n{traceback.format_exc()}")
|
||||
logger.error("Dynamic Client Registration failed: %s", e)
|
||||
logger.debug("Full traceback:\\n%s", traceback.format_exc())
|
||||
logger.warning("Background vector sync will be disabled.")
|
||||
return None
|
||||
|
||||
@@ -1151,8 +1163,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
# - httpx.HTTPError: Network issues, OIDC discovery failures
|
||||
# - ValueError: Missing required configuration (NEXTCLOUD_HOST)
|
||||
# - KeyError: Missing required fields in OIDC discovery response
|
||||
logger.error(f"Failed to setup OAuth infrastructure: {e}")
|
||||
logger.debug(f"Full traceback:\n{traceback.format_exc()}")
|
||||
logger.error("Failed to setup OAuth infrastructure: %s", e)
|
||||
logger.debug("Full traceback:\\n%s", traceback.format_exc())
|
||||
logger.warning(
|
||||
"Management API will be unavailable. "
|
||||
"Webhook management from Astrolabe admin UI will not work."
|
||||
@@ -1163,8 +1175,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
except Exception as e:
|
||||
# Unexpected error - this is a programming error, re-raise it
|
||||
logger.error(
|
||||
f"Unexpected error during OAuth infrastructure setup: {e}. "
|
||||
"This is likely a programming error that should be fixed."
|
||||
"Unexpected error during OAuth infrastructure setup: %s. This is likely a programming error that should be fixed.",
|
||||
e,
|
||||
)
|
||||
raise
|
||||
|
||||
@@ -1191,7 +1203,7 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
Lifespan context for OAuth mode - captures OAuth configuration from outer scope.
|
||||
"""
|
||||
logger.info("Starting MCP server in OAuth mode")
|
||||
logger.info(f"Using OAuth provider: {oauth_provider}")
|
||||
logger.info("Using OAuth provider: %s", oauth_provider)
|
||||
if refresh_token_storage:
|
||||
logger.info("Refresh token storage is available")
|
||||
if oauth_client:
|
||||
@@ -1223,7 +1235,7 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
try:
|
||||
await oauth_client.close()
|
||||
except Exception as e:
|
||||
logger.warning(f"Error closing OAuth client: {e}")
|
||||
logger.warning("Error closing OAuth client: %s", e)
|
||||
logger.info("MCP server shutdown complete")
|
||||
|
||||
mcp = FastMCP(
|
||||
@@ -1239,7 +1251,7 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
)
|
||||
else:
|
||||
# BasicAuth modes (single-user or multi-user)
|
||||
logger.info(f"Configuring MCP server for {mode.value} mode")
|
||||
logger.info("Configuring MCP server for %s mode", mode.value)
|
||||
mcp = FastMCP(
|
||||
"Nextcloud MCP",
|
||||
lifespan=app_lifespan_basic,
|
||||
@@ -1264,11 +1276,13 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
# Configure only the enabled apps
|
||||
for app_name in enabled_apps:
|
||||
if app_name in AVAILABLE_APPS:
|
||||
logger.info(f"Configuring {app_name} tools")
|
||||
logger.info("Configuring %s tools", app_name)
|
||||
AVAILABLE_APPS[app_name](mcp)
|
||||
else:
|
||||
logger.warning(
|
||||
f"Unknown app: {app_name}. Available apps: {list(AVAILABLE_APPS.keys())}"
|
||||
"Unknown app: %s. Available apps: %s",
|
||||
app_name,
|
||||
list(AVAILABLE_APPS.keys()),
|
||||
)
|
||||
|
||||
# Register semantic search tools (cross-app feature)
|
||||
@@ -1304,8 +1318,9 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
user_scopes = get_access_token_scopes()
|
||||
is_jwt = is_jwt_token()
|
||||
logger.info(
|
||||
f"🔍 list_tools called - Token type: {'JWT' if is_jwt else 'opaque/none'}, "
|
||||
f"User scopes: {user_scopes}"
|
||||
"🔍 list_tools called - Token type: %s, User scopes: %s",
|
||||
"JWT" if is_jwt else "opaque/none",
|
||||
user_scopes,
|
||||
)
|
||||
|
||||
# Get all tools
|
||||
@@ -1323,14 +1338,17 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
]
|
||||
token_type = "JWT" if is_jwt else "Bearer"
|
||||
logger.info(
|
||||
f"✂️ {token_type} scope filtering: {len(allowed_tools)}/{len(all_tools)} tools "
|
||||
f"available for scopes: {user_scopes}"
|
||||
"✂️ %s scope filtering: %s/%s tools available for scopes: %s",
|
||||
token_type,
|
||||
len(allowed_tools),
|
||||
len(all_tools),
|
||||
user_scopes,
|
||||
)
|
||||
else:
|
||||
# BasicAuth mode or no token - show all tools
|
||||
allowed_tools = all_tools
|
||||
logger.info(
|
||||
f"📋 Showing all {len(all_tools)} tools (no token/BasicAuth)"
|
||||
"📋 Showing all %s tools (no token/BasicAuth)", len(all_tools)
|
||||
)
|
||||
|
||||
# Return the Tool objects directly (they're already in the correct format)
|
||||
@@ -1457,7 +1475,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
break
|
||||
|
||||
logger.info(
|
||||
f"OAuth context initialized for login routes (client_id={client_id[:16]}...)"
|
||||
"OAuth context initialized for login routes (client_id=%s...)",
|
||||
client_id[:16],
|
||||
)
|
||||
else:
|
||||
# BasicAuth mode - initialize storage for webhook management
|
||||
@@ -1505,7 +1524,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
}
|
||||
app.state.oauth_context = oauth_context_dict
|
||||
logger.info(
|
||||
f"✓ OAuth context initialized for management APIs (hybrid mode, client_id={sync_client_id[:16]}...)"
|
||||
"✓ OAuth context initialized for management APIs (hybrid mode, client_id=%s...)",
|
||||
sync_client_id[:16],
|
||||
)
|
||||
elif multi_user_basic_oauth_creds and multi_user_token_verifier is None:
|
||||
logger.warning(
|
||||
@@ -1573,7 +1593,7 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
await get_qdrant_client() # Triggers collection creation if needed
|
||||
logger.info("Qdrant collection ready")
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to initialize Qdrant collection: {e}")
|
||||
logger.error("Failed to initialize Qdrant collection: %s", e)
|
||||
raise RuntimeError(
|
||||
f"Cannot start vector sync - Qdrant initialization failed: {e}"
|
||||
) from e
|
||||
@@ -1639,8 +1659,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
_vector_sync_state.eviction_task_group = tg
|
||||
|
||||
logger.info(
|
||||
f"Background sync tasks started: 1 scanner + "
|
||||
f"{settings.vector_sync_processor_workers} processors"
|
||||
"Background sync tasks started: 1 scanner + %s processors",
|
||||
settings.vector_sync_processor_workers,
|
||||
)
|
||||
|
||||
# Run MCP session manager and yield
|
||||
@@ -1664,7 +1684,7 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
# OAuth mode with background operations - multi-user sync
|
||||
# Also used for multi-user BasicAuth mode (client auth is BasicAuth, background sync uses app passwords or OAuth)
|
||||
mode_desc = "OAuth mode" if oauth_enabled else "Multi-user BasicAuth mode"
|
||||
logger.info(f"Starting background vector sync tasks for {mode_desc}")
|
||||
logger.info("Starting background vector sync tasks for %s", mode_desc)
|
||||
|
||||
# Get nextcloud_host (from settings - already validated)
|
||||
nextcloud_host_for_sync = settings.nextcloud_host
|
||||
@@ -1735,7 +1755,7 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
await get_qdrant_client() # Triggers collection creation if needed
|
||||
logger.info("Qdrant collection ready")
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to initialize Qdrant collection: {e}")
|
||||
logger.error("Failed to initialize Qdrant collection: %s", e)
|
||||
raise RuntimeError(
|
||||
f"Cannot start vector sync - Qdrant initialization failed: {e}"
|
||||
) from e
|
||||
@@ -1748,10 +1768,12 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
)
|
||||
if removed:
|
||||
logger.info(
|
||||
f"Cleaned up {len(removed)} stale app password(s): {removed}"
|
||||
"Cleaned up %s stale app password(s): %s",
|
||||
len(removed),
|
||||
removed,
|
||||
)
|
||||
except Exception as e:
|
||||
logger.warning(f"App password cleanup failed (non-fatal): {e}")
|
||||
logger.warning("App password cleanup failed (non-fatal): %s", e)
|
||||
|
||||
# Initialize shared state
|
||||
send_stream, receive_stream = anyio.create_memory_object_stream(
|
||||
@@ -1829,8 +1851,8 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
_vector_sync_state.eviction_task_group = tg
|
||||
|
||||
logger.info(
|
||||
f"Background sync tasks started: 1 user manager + "
|
||||
f"{settings.vector_sync_processor_workers} processors"
|
||||
"Background sync tasks started: 1 user manager + %s processors",
|
||||
settings.vector_sync_processor_workers,
|
||||
)
|
||||
|
||||
# Run MCP session manager and yield
|
||||
@@ -2137,8 +2159,10 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
|
||||
if oauth_provisioning_available:
|
||||
logger.info(
|
||||
f"OAuth provisioning routes enabled for mode: {mode.value} "
|
||||
f"(oauth_enabled={oauth_enabled}, hybrid_mode={not oauth_enabled})"
|
||||
"OAuth provisioning routes enabled for mode: %s (oauth_enabled=%s, hybrid_mode=%s)",
|
||||
mode.value,
|
||||
oauth_enabled,
|
||||
not oauth_enabled,
|
||||
)
|
||||
|
||||
def oauth_protected_resource_metadata(request):
|
||||
@@ -2330,7 +2354,7 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
browser_routes.append(
|
||||
Mount("/static", StaticFiles(directory=static_dir), name="static")
|
||||
)
|
||||
logger.info(f"Mounted static files from {static_dir}")
|
||||
logger.info("Mounted static files from %s", static_dir)
|
||||
|
||||
browser_app = Starlette(routes=browser_routes)
|
||||
browser_app.add_middleware(
|
||||
@@ -2381,13 +2405,14 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
token_preview = (
|
||||
auth_header[:50] + "..." if len(auth_header) > 50 else auth_header
|
||||
)
|
||||
logger.info(f"🔑 /mcp request with Authorization: {token_preview}")
|
||||
logger.info("🔑 /mcp request with Authorization: %s", token_preview)
|
||||
else:
|
||||
# Only warn about missing Authorization in OAuth mode
|
||||
# In BasicAuth mode, /mcp requests without Authorization are expected
|
||||
if oauth_enabled:
|
||||
logger.warning(
|
||||
f"⚠️ /mcp request WITHOUT Authorization header from {request.client}"
|
||||
"⚠️ /mcp request WITHOUT Authorization header from %s",
|
||||
request.client,
|
||||
)
|
||||
|
||||
# Log client capabilities on initialize request
|
||||
@@ -2404,8 +2429,9 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
client_info = params.get("clientInfo", {})
|
||||
|
||||
logger.info(
|
||||
f"🔌 MCP client connected: {client_info.get('name', 'unknown')} "
|
||||
f"v{client_info.get('version', 'unknown')}"
|
||||
"🔌 MCP client connected: %s v%s",
|
||||
client_info.get("name", "unknown"),
|
||||
client_info.get("version", "unknown"),
|
||||
)
|
||||
|
||||
# Log capabilities in a structured way
|
||||
@@ -2421,16 +2447,17 @@ def get_app(transport: str = "streamable-http", enabled_apps: list[str] | None =
|
||||
)
|
||||
|
||||
logger.info(
|
||||
f"📋 Client capabilities: {', '.join(cap_summary) if cap_summary else 'none'}"
|
||||
"📋 Client capabilities: %s",
|
||||
", ".join(cap_summary) if cap_summary else "none",
|
||||
)
|
||||
# Log full capabilities at INFO level to diagnose capability issues
|
||||
logger.info(
|
||||
f"Full capabilities JSON: {json.dumps(capabilities)}"
|
||||
"Full capabilities JSON: %s", json.dumps(capabilities)
|
||||
)
|
||||
except Exception as e:
|
||||
# Don't fail the request if logging fails
|
||||
logger.debug(
|
||||
f"Failed to parse MCP request for capability logging: {e}"
|
||||
"Failed to parse MCP request for capability logging: %s", e
|
||||
)
|
||||
|
||||
response = await call_next(request)
|
||||
|
||||
@@ -61,12 +61,12 @@ class AstrolabeClient:
|
||||
discovery_url = f"{self.nextcloud_host}/.well-known/openid-configuration"
|
||||
|
||||
async with nextcloud_httpx_client() as client:
|
||||
logger.debug(f"Discovering token endpoint from {discovery_url}")
|
||||
logger.debug("Discovering token endpoint from %s", discovery_url)
|
||||
discovery_resp = await client.get(discovery_url)
|
||||
discovery_resp.raise_for_status()
|
||||
token_endpoint = discovery_resp.json()["token_endpoint"]
|
||||
|
||||
logger.debug(f"Requesting client credentials token from {token_endpoint}")
|
||||
logger.debug("Requesting client credentials token from %s", token_endpoint)
|
||||
|
||||
# Request token using client credentials grant
|
||||
token_resp = await client.post(
|
||||
@@ -88,7 +88,7 @@ class AstrolabeClient:
|
||||
"expires_at": time.time() + expires_in - 60,
|
||||
}
|
||||
|
||||
logger.info(f"Obtained Astrolabe API token (expires in {expires_in}s)")
|
||||
logger.info("Obtained Astrolabe API token (expires in %ss)", expires_in)
|
||||
return data["access_token"]
|
||||
|
||||
async def get_user_app_password(self, user_id: str) -> Optional[str]:
|
||||
@@ -108,7 +108,7 @@ class AstrolabeClient:
|
||||
url = f"{self.nextcloud_host}/apps/astrolabe/api/v1/background-sync/credentials/{user_id}"
|
||||
|
||||
async with nextcloud_httpx_client() as client:
|
||||
logger.debug(f"Retrieving app password for user: {user_id}")
|
||||
logger.debug("Retrieving app password for user: %s", user_id)
|
||||
|
||||
response = await client.get(
|
||||
url,
|
||||
@@ -117,14 +117,16 @@ class AstrolabeClient:
|
||||
)
|
||||
|
||||
if response.status_code == 404:
|
||||
logger.debug(f"No app password configured for user: {user_id}")
|
||||
logger.debug("No app password configured for user: %s", user_id)
|
||||
return None
|
||||
|
||||
response.raise_for_status()
|
||||
data = response.json()
|
||||
|
||||
logger.info(
|
||||
f"Retrieved app password for user: {user_id} (type: {data.get('credential_type')})"
|
||||
"Retrieved app password for user: %s (type: %s)",
|
||||
user_id,
|
||||
data.get("credential_type"),
|
||||
)
|
||||
return data.get("app_password")
|
||||
|
||||
|
||||
@@ -133,8 +133,8 @@ async def register_client(
|
||||
if resource_url:
|
||||
client_metadata["resource_url"] = resource_url
|
||||
|
||||
logger.info(f"Registering OAuth client with Nextcloud: {client_name}")
|
||||
logger.debug(f"Registration endpoint: {registration_endpoint}")
|
||||
logger.info("Registering OAuth client with Nextcloud: %s", client_name)
|
||||
logger.debug("Registration endpoint: %s", registration_endpoint)
|
||||
|
||||
async with nextcloud_httpx_client(timeout=30.0) as client:
|
||||
for attempt in range(max_retries):
|
||||
@@ -151,14 +151,17 @@ async def register_client(
|
||||
retry_after = int(response.headers.get("Retry-After", 2))
|
||||
wait_time = min(retry_after, 2**attempt)
|
||||
logger.warning(
|
||||
f"Rate limited (429) registering client, "
|
||||
f"retrying in {wait_time}s (attempt {attempt + 1}/{max_retries})"
|
||||
"Rate limited (429) registering client, retrying in %ss (attempt %s/%s)",
|
||||
wait_time,
|
||||
attempt + 1,
|
||||
max_retries,
|
||||
)
|
||||
await anyio.sleep(wait_time)
|
||||
continue
|
||||
else:
|
||||
logger.error(
|
||||
f"Failed to register client after {max_retries} attempts: Rate limited (429)"
|
||||
"Failed to register client after %s attempts: Rate limited (429)",
|
||||
max_retries,
|
||||
)
|
||||
response.raise_for_status()
|
||||
|
||||
@@ -166,14 +169,15 @@ async def register_client(
|
||||
|
||||
client_info = response.json()
|
||||
logger.info(
|
||||
f"Successfully registered client: {client_info.get('client_id')}"
|
||||
"Successfully registered client: %s", client_info.get("client_id")
|
||||
)
|
||||
expires_at = dt.datetime.fromtimestamp(
|
||||
client_info.get("client_secret_expires_at")
|
||||
)
|
||||
logger.info(
|
||||
f"Client expires at: {expires_at} "
|
||||
f"(in {client_info.get('client_secret_expires_at', 0) - int(time.time())} seconds)"
|
||||
"Client expires at: %s (in %s seconds)",
|
||||
expires_at,
|
||||
client_info.get("client_secret_expires_at", 0) - int(time.time()),
|
||||
)
|
||||
|
||||
# Log if RFC 7592 fields are present
|
||||
@@ -206,13 +210,13 @@ async def register_client(
|
||||
|
||||
except httpx.HTTPStatusError as e:
|
||||
logger.error(
|
||||
f"Failed to register client: HTTP {e.response.status_code}"
|
||||
"Failed to register client: HTTP %s", e.response.status_code
|
||||
)
|
||||
logger.error(f"Response: {e.response.text}")
|
||||
logger.error("Response: %s", e.response.text)
|
||||
raise
|
||||
except KeyError as e:
|
||||
logger.error(
|
||||
f"Invalid response from registration endpoint: missing {e}"
|
||||
"Invalid response from registration endpoint: missing %s", e
|
||||
)
|
||||
raise ValueError(f"Invalid registration response: missing {e}")
|
||||
|
||||
@@ -264,8 +268,8 @@ async def delete_client(
|
||||
else:
|
||||
deletion_endpoint = f"{nextcloud_url}/apps/oidc/register/{client_id}"
|
||||
|
||||
logger.info(f"Deleting OAuth client: {client_id[:16]}...")
|
||||
logger.debug(f"Deletion endpoint: {deletion_endpoint}")
|
||||
logger.info("Deleting OAuth client: %s...", client_id[:16])
|
||||
logger.debug("Deletion endpoint: %s", deletion_endpoint)
|
||||
|
||||
async with nextcloud_httpx_client(timeout=30.0) as http_client:
|
||||
for attempt in range(max_retries):
|
||||
@@ -296,7 +300,7 @@ async def delete_client(
|
||||
# RFC 7592: Successful deletion returns 204 No Content
|
||||
if response.status_code == 204:
|
||||
logger.info(
|
||||
f"Successfully deleted OAuth client: {client_id[:16]}..."
|
||||
"Successfully deleted OAuth client: %s...", client_id[:16]
|
||||
)
|
||||
return True
|
||||
elif response.status_code == 429:
|
||||
@@ -307,42 +311,53 @@ async def delete_client(
|
||||
retry_after, 2**attempt
|
||||
) # Exponential backoff, max from header
|
||||
logger.warning(
|
||||
f"Rate limited (429) deleting client {client_id[:16]}..., "
|
||||
f"retrying in {wait_time}s (attempt {attempt + 1}/{max_retries})"
|
||||
"Rate limited (429) deleting client %s..., retrying in %ss (attempt %s/%s)",
|
||||
client_id[:16],
|
||||
wait_time,
|
||||
attempt + 1,
|
||||
max_retries,
|
||||
)
|
||||
await anyio.sleep(wait_time)
|
||||
continue
|
||||
else:
|
||||
logger.error(
|
||||
f"Failed to delete client {client_id[:16]}... after {max_retries} attempts: Rate limited (429)"
|
||||
"Failed to delete client %s... after %s attempts: Rate limited (429)",
|
||||
client_id[:16],
|
||||
max_retries,
|
||||
)
|
||||
return False
|
||||
elif response.status_code == 401:
|
||||
logger.error(
|
||||
f"Failed to delete client {client_id[:16]}...: Authentication failed (invalid credentials)"
|
||||
"Failed to delete client %s...: Authentication failed (invalid credentials)",
|
||||
client_id[:16],
|
||||
)
|
||||
return False
|
||||
elif response.status_code == 403:
|
||||
logger.error(
|
||||
f"Failed to delete client {client_id[:16]}...: Not authorized (not a DCR client or wrong client)"
|
||||
"Failed to delete client %s...: Not authorized (not a DCR client or wrong client)",
|
||||
client_id[:16],
|
||||
)
|
||||
return False
|
||||
else:
|
||||
logger.error(
|
||||
f"Failed to delete client {client_id[:16]}...: HTTP {response.status_code}"
|
||||
"Failed to delete client %s...: HTTP %s",
|
||||
client_id[:16],
|
||||
response.status_code,
|
||||
)
|
||||
logger.debug(f"Response: {response.text}")
|
||||
logger.debug("Response: %s", response.text)
|
||||
return False
|
||||
|
||||
except httpx.HTTPStatusError as e:
|
||||
logger.error(
|
||||
f"HTTP error deleting client {client_id[:16]}...: {e.response.status_code}"
|
||||
"HTTP error deleting client %s...: %s",
|
||||
client_id[:16],
|
||||
e.response.status_code,
|
||||
)
|
||||
logger.debug(f"Response: {e.response.text}")
|
||||
logger.debug("Response: %s", e.response.text)
|
||||
return False
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Unexpected error deleting client {client_id[:16]}...: {e}"
|
||||
"Unexpected error deleting client %s...: %s", client_id[:16], e
|
||||
)
|
||||
return False
|
||||
|
||||
@@ -390,14 +405,14 @@ async def ensure_oauth_client(
|
||||
client_data = await storage.get_oauth_client()
|
||||
if client_data:
|
||||
logger.info(
|
||||
f"Loaded OAuth client from SQLite: {client_data['client_id'][:16]}..."
|
||||
"Loaded OAuth client from SQLite: %s...", client_data["client_id"][:16]
|
||||
)
|
||||
return ClientInfo.from_dict(client_data)
|
||||
|
||||
# Register new client
|
||||
logger.info("Registering new OAuth client...")
|
||||
if resource_url:
|
||||
logger.info(f" with resource_url: {resource_url}")
|
||||
logger.info(" with resource_url: %s", resource_url)
|
||||
client_info = await register_client(
|
||||
nextcloud_url=nextcloud_url,
|
||||
registration_endpoint=registration_endpoint,
|
||||
|
||||
@@ -89,7 +89,7 @@ class ClientRegistry:
|
||||
|
||||
if not cid or not redirect:
|
||||
logger.warning(
|
||||
f"Skipping malformed ALLOWED_MCP_CLIENTS entry: {entry!r}"
|
||||
"Skipping malformed ALLOWED_MCP_CLIENTS entry: %r", entry
|
||||
)
|
||||
continue
|
||||
|
||||
@@ -97,8 +97,9 @@ class ClientRegistry:
|
||||
hostname = parsed.hostname
|
||||
if hostname is None:
|
||||
logger.warning(
|
||||
f"Skipping client {cid!r}: cannot parse hostname "
|
||||
f"from {redirect!r}"
|
||||
"Skipping client %r: cannot parse hostname from %r",
|
||||
cid,
|
||||
redirect,
|
||||
)
|
||||
continue
|
||||
is_loopback = hostname in ("localhost", "127.0.0.1", "::1")
|
||||
@@ -108,8 +109,9 @@ class ClientRegistry:
|
||||
or (parsed.scheme == "http" and is_loopback)
|
||||
):
|
||||
logger.warning(
|
||||
f"Rejecting client {cid!r}: HTTP redirect URIs are only "
|
||||
f"allowed for localhost, got {redirect!r}"
|
||||
"Rejecting client %r: HTTP redirect URIs are only allowed for localhost, got %r",
|
||||
cid,
|
||||
redirect,
|
||||
)
|
||||
continue
|
||||
|
||||
@@ -120,7 +122,7 @@ class ClientRegistry:
|
||||
allowed_scopes=["*"],
|
||||
is_public=True,
|
||||
)
|
||||
logger.info(f"Registered static client: {cid}")
|
||||
logger.info("Registered static client: %s", cid)
|
||||
else:
|
||||
self._clients[entry] = MCPClientInfo(
|
||||
client_id=entry,
|
||||
@@ -129,7 +131,7 @@ class ClientRegistry:
|
||||
allowed_scopes=["*"],
|
||||
is_public=True,
|
||||
)
|
||||
logger.info(f"Registered static client: {entry}")
|
||||
logger.info("Registered static client: %s", entry)
|
||||
|
||||
if not self._clients:
|
||||
logger.warning(
|
||||
@@ -170,7 +172,7 @@ class ClientRegistry:
|
||||
if not client:
|
||||
if self.allow_dynamic_registration:
|
||||
# In production, would attempt DCR here
|
||||
logger.info(f"Unknown client {client_id}, would attempt DCR")
|
||||
logger.info("Unknown client %s, would attempt DCR", client_id)
|
||||
return True, None
|
||||
else:
|
||||
return False, f"Unknown client_id: {client_id}"
|
||||
@@ -229,15 +231,15 @@ class ClientRegistry:
|
||||
True if registered successfully
|
||||
"""
|
||||
if not self.allow_dynamic_registration:
|
||||
logger.warning(f"DCR disabled, cannot register {client_info.client_id}")
|
||||
logger.warning("DCR disabled, cannot register %s", client_info.client_id)
|
||||
return False
|
||||
|
||||
if client_info.client_id in self._clients:
|
||||
logger.warning(f"Client {client_info.client_id} already registered")
|
||||
logger.warning("Client %s already registered", client_info.client_id)
|
||||
return False
|
||||
|
||||
self._clients[client_info.client_id] = client_info
|
||||
logger.info(f"Dynamically registered client: {client_info.client_id}")
|
||||
logger.info("Dynamically registered client: %s", client_info.client_id)
|
||||
|
||||
# In production, would persist to database
|
||||
return True
|
||||
@@ -263,7 +265,7 @@ class ClientRegistry:
|
||||
allowed_scopes=["*"], # Nextcloud enforces actual scopes
|
||||
is_public=True,
|
||||
)
|
||||
logger.info(f"Registered proxy client: {client_id}")
|
||||
logger.info("Registered proxy client: %s", client_id)
|
||||
|
||||
def get_client(self, client_id: str) -> Optional[MCPClientInfo]:
|
||||
"""
|
||||
|
||||
@@ -54,8 +54,8 @@ def get_client_from_context(ctx: Context, base_url: str) -> NextcloudClient:
|
||||
raise ValueError("Username not available in OAuth token context")
|
||||
|
||||
logger.debug(
|
||||
f"Creating NextcloudClient for user {username} with multi-audience token "
|
||||
f"(no exchange needed)"
|
||||
"Creating NextcloudClient for user %s with multi-audience token (no exchange needed)",
|
||||
username,
|
||||
)
|
||||
|
||||
# Token was validated to have MCP audience
|
||||
@@ -65,6 +65,6 @@ def get_client_from_context(ctx: Context, base_url: str) -> NextcloudClient:
|
||||
)
|
||||
|
||||
except AttributeError as e:
|
||||
logger.error(f"Failed to extract OAuth context: {e}")
|
||||
logger.error("Failed to extract OAuth context: %s", e)
|
||||
logger.error("This may indicate the server is not running in OAuth mode")
|
||||
raise
|
||||
|
||||
@@ -129,7 +129,7 @@ class LoginFlowV2Client:
|
||||
f"Malformed Login Flow v2 initiate response from Nextcloud (missing key: {e})"
|
||||
) from e
|
||||
|
||||
logger.info(f"Login Flow v2 initiated: login_url={result.login_url[:60]}...")
|
||||
logger.info("Login Flow v2 initiated: login_url=%s...", result.login_url[:60])
|
||||
return result
|
||||
|
||||
def _rewrite_to_nextcloud_host(self, url: str) -> str:
|
||||
@@ -142,7 +142,7 @@ class LoginFlowV2Client:
|
||||
"""
|
||||
result = rewrite_url_origin(url, self.nextcloud_host)
|
||||
if result != url:
|
||||
logger.debug(f"Rewrote Login Flow v2 URL: {url} → {result}")
|
||||
logger.debug("Rewrote Login Flow v2 URL: %s → %s", url, result)
|
||||
return result
|
||||
|
||||
async def poll(self, poll_endpoint: str, poll_token: str) -> LoginFlowPollResult:
|
||||
@@ -172,8 +172,9 @@ class LoginFlowV2Client:
|
||||
if response.status_code == 200:
|
||||
data = response.json()
|
||||
logger.info(
|
||||
f"Login Flow v2 completed: server={data.get('server')}, "
|
||||
f"loginName={data.get('loginName')}"
|
||||
"Login Flow v2 completed: server=%s, loginName=%s",
|
||||
data.get("server"),
|
||||
data.get("loginName"),
|
||||
)
|
||||
try:
|
||||
return LoginFlowPollResult(
|
||||
@@ -193,6 +194,6 @@ class LoginFlowV2Client:
|
||||
|
||||
# Any other status indicates the flow has expired or is invalid
|
||||
logger.warning(
|
||||
f"Login Flow v2 poll returned unexpected status: {response.status_code}"
|
||||
"Login Flow v2 poll returned unexpected status: %s", response.status_code
|
||||
)
|
||||
return LoginFlowPollResult(status="expired")
|
||||
|
||||
@@ -359,7 +359,8 @@ async def oauth_authorize(request: Request) -> RedirectResponse | JSONResponse:
|
||||
if auth_parsed.query:
|
||||
authorization_endpoint += f"?{auth_parsed.query}"
|
||||
logger.info(
|
||||
f"Rewrote authorization endpoint for browser access: {authorization_endpoint}"
|
||||
"Rewrote authorization endpoint for browser access: %s",
|
||||
authorization_endpoint,
|
||||
)
|
||||
|
||||
# Prefix resource scopes with the resource server identifier if configured.
|
||||
@@ -952,7 +953,7 @@ async def _oauth_callback_as_proxy(
|
||||
|
||||
if response.status_code != 200:
|
||||
logger.error(
|
||||
f"AS proxy token exchange failed: {response.status_code} {response.text}"
|
||||
"AS proxy token exchange failed: %s %s", response.status_code, response.text
|
||||
)
|
||||
params = urlencode(
|
||||
{
|
||||
@@ -968,8 +969,8 @@ async def _oauth_callback_as_proxy(
|
||||
nc_token_response = response.json()
|
||||
|
||||
logger.info(
|
||||
"AS proxy: Successfully exchanged code for Nextcloud token "
|
||||
f"(token_type={nc_token_response.get('token_type')})"
|
||||
"AS proxy: Successfully exchanged code for Nextcloud token (token_type=%s)",
|
||||
nc_token_response.get("token_type"),
|
||||
)
|
||||
|
||||
# Verify the ID token signature + claims before caching the response
|
||||
@@ -1017,7 +1018,8 @@ async def _oauth_callback_as_proxy(
|
||||
redirect_url = f"{session.client_redirect_uri}?{redirect_params}"
|
||||
|
||||
logger.info(
|
||||
f"AS proxy: Redirecting to client with proxy_code (client_id={session.client_id})"
|
||||
"AS proxy: Redirecting to client with proxy_code (client_id=%s)",
|
||||
session.client_id,
|
||||
)
|
||||
return RedirectResponse(redirect_url, status_code=302)
|
||||
|
||||
@@ -1294,7 +1296,7 @@ async def _token_refresh(request: Request, form) -> JSONResponse:
|
||||
|
||||
if response.status_code != 200:
|
||||
logger.error(
|
||||
f"AS proxy token refresh failed: {response.status_code} {response.text}"
|
||||
"AS proxy token refresh failed: %s %s", response.status_code, response.text
|
||||
)
|
||||
return JSONResponse(
|
||||
{
|
||||
@@ -1396,7 +1398,9 @@ async def oauth_register_proxy(request: Request) -> JSONResponse:
|
||||
|
||||
if response.status_code not in (200, 201):
|
||||
logger.error(
|
||||
f"DCR proxy: Upstream registration failed: {response.status_code} {response.text}"
|
||||
"DCR proxy: Upstream registration failed: %s %s",
|
||||
response.status_code,
|
||||
response.text,
|
||||
)
|
||||
return JSONResponse(
|
||||
response.json()
|
||||
|
||||
@@ -44,11 +44,14 @@ async def is_nextcloud_admin(request: Request, http_client: AsyncClient) -> bool
|
||||
# Check if user is in the admin group
|
||||
is_admin = "admin" in user_groups
|
||||
logger.debug(
|
||||
f"Admin check for user '{username}': {is_admin} (groups: {user_groups})"
|
||||
"Admin check for user '%s': %s (groups: %s)",
|
||||
username,
|
||||
is_admin,
|
||||
user_groups,
|
||||
)
|
||||
|
||||
return is_admin
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error checking admin permissions: {e}", exc_info=True)
|
||||
logger.error("Error checking admin permissions: %s", e, exc_info=True)
|
||||
return False
|
||||
|
||||
@@ -90,7 +90,7 @@ async def _poll_and_store(provision_id: str) -> None:
|
||||
result = await flow_client.poll(poll_endpoint, poll_token)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Login Flow v2 poll error for provision {provision_id}: {e}"
|
||||
"Login Flow v2 poll error for provision %s: %s", provision_id, e
|
||||
)
|
||||
await anyio.sleep(2)
|
||||
continue
|
||||
@@ -106,7 +106,8 @@ async def _poll_and_store(provision_id: str) -> None:
|
||||
if session:
|
||||
session["status"] = "error"
|
||||
logger.error(
|
||||
f"Login Flow v2 completed but no app_password (provision_id={provision_id})"
|
||||
"Login Flow v2 completed but no app_password (provision_id=%s)",
|
||||
provision_id,
|
||||
)
|
||||
return
|
||||
await storage.store_app_password_with_scopes(
|
||||
@@ -121,8 +122,9 @@ async def _poll_and_store(provision_id: str) -> None:
|
||||
session["status"] = "completed"
|
||||
session["username"] = result.login_name
|
||||
logger.info(
|
||||
f"Login Flow v2 web provision completed for user {effective_user_id} "
|
||||
f"(provision_id={provision_id})"
|
||||
"Login Flow v2 web provision completed for user %s (provision_id=%s)",
|
||||
effective_user_id,
|
||||
provision_id,
|
||||
)
|
||||
return
|
||||
|
||||
@@ -131,7 +133,7 @@ async def _poll_and_store(provision_id: str) -> None:
|
||||
if session:
|
||||
session["status"] = "expired"
|
||||
logger.warning(
|
||||
f"Login Flow v2 web provision expired (provision_id={provision_id})"
|
||||
"Login Flow v2 web provision expired (provision_id=%s)", provision_id
|
||||
)
|
||||
return
|
||||
|
||||
@@ -142,7 +144,7 @@ async def _poll_and_store(provision_id: str) -> None:
|
||||
if session:
|
||||
session["status"] = "expired"
|
||||
logger.warning(
|
||||
f"Login Flow v2 web provision timed out (provision_id={provision_id})"
|
||||
"Login Flow v2 web provision timed out (provision_id=%s)", provision_id
|
||||
)
|
||||
|
||||
|
||||
@@ -166,7 +168,7 @@ async def provision_page(
|
||||
try:
|
||||
user_id, _token_data = await validate_token_and_get_user(request)
|
||||
except (ValueError, KeyError, AttributeError) as e:
|
||||
logger.warning(f"Provision request rejected: {e}")
|
||||
logger.warning("Provision request rejected: %s", e)
|
||||
return JSONResponse({"error": "Authentication required"}, status_code=401)
|
||||
|
||||
_cleanup_expired_sessions()
|
||||
@@ -180,14 +182,14 @@ async def provision_page(
|
||||
)
|
||||
|
||||
if urlparse(redirect_uri).scheme == "http":
|
||||
logger.warning(f"Provision redirect_uri uses insecure HTTP: {redirect_uri}")
|
||||
logger.warning("Provision redirect_uri uses insecure HTTP: %s", redirect_uri)
|
||||
|
||||
# Check if user already has an app password — skip straight to redirect
|
||||
if user_id:
|
||||
storage = await get_shared_storage()
|
||||
existing = await storage.get_app_password_with_scopes(user_id)
|
||||
if existing:
|
||||
logger.info(f"User {user_id} already has app password, skipping provision")
|
||||
logger.info("User %s already has app password, skipping provision", user_id)
|
||||
return RedirectResponse(redirect_uri)
|
||||
|
||||
# Initiate Login Flow v2
|
||||
@@ -206,7 +208,7 @@ async def provision_page(
|
||||
)
|
||||
init_response = await flow_client.initiate()
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to initiate Login Flow v2 for web provision: {e}")
|
||||
logger.error("Failed to initiate Login Flow v2 for web provision: %s", e)
|
||||
return HTMLResponse(
|
||||
content=_render_error(
|
||||
"Failed to start login flow. Please try again later."
|
||||
@@ -241,8 +243,9 @@ async def provision_page(
|
||||
poll_tg.start_soon(_poll_and_store, provision_id)
|
||||
|
||||
logger.info(
|
||||
f"Login Flow v2 web provision initiated (provision_id={provision_id}, "
|
||||
f"user_id={user_id or 'unknown'}), redirecting to NC login"
|
||||
"Login Flow v2 web provision initiated (provision_id=%s, user_id=%s), redirecting to NC login",
|
||||
provision_id,
|
||||
user_id or "unknown",
|
||||
)
|
||||
|
||||
# Redirect to Nextcloud's Login Flow v2 login page.
|
||||
@@ -277,7 +280,7 @@ async def provision_status(request: Request) -> JSONResponse:
|
||||
try:
|
||||
_user_id, _token_data = await validate_token_and_get_user(request)
|
||||
except (ValueError, KeyError, AttributeError) as e:
|
||||
logger.warning(f"Provision status request rejected: {e}")
|
||||
logger.warning("Provision status request rejected: %s", e)
|
||||
return JSONResponse({"error": "Authentication required"}, status_code=401)
|
||||
|
||||
provision_id = request.query_params.get("id", "")
|
||||
|
||||
@@ -89,7 +89,7 @@ def require_provisioning(func: Callable) -> Callable:
|
||||
if not refresh_data:
|
||||
# User has not completed Flow 2 - provide helpful error
|
||||
logger.info(
|
||||
f"User {user_id} attempted to use Nextcloud tool without provisioning"
|
||||
"User %s attempted to use Nextcloud tool without provisioning", user_id
|
||||
)
|
||||
raise McpError(
|
||||
ErrorData(
|
||||
@@ -104,7 +104,7 @@ def require_provisioning(func: Callable) -> Callable:
|
||||
)
|
||||
|
||||
logger.debug(
|
||||
f"User {user_id} has provisioned access - proceeding with tool execution"
|
||||
"User %s has provisioned access - proceeding with tool execution", user_id
|
||||
)
|
||||
|
||||
# User has provisioned - allow access
|
||||
@@ -156,15 +156,14 @@ def require_provisioning_or_suggest(func: Callable) -> Callable:
|
||||
|
||||
if not refresh_data:
|
||||
logger.info(
|
||||
f"User {user_id} has not provisioned Nextcloud access. "
|
||||
"Some features may not work. Consider running "
|
||||
"'provision_nextcloud_access' tool."
|
||||
"User %s has not provisioned Nextcloud access. Some features may not work. Consider running 'provision_nextcloud_access' tool.",
|
||||
user_id,
|
||||
)
|
||||
else:
|
||||
logger.debug(f"User {user_id} has provisioned access")
|
||||
logger.debug("User %s has provisioned access", user_id)
|
||||
|
||||
except Exception as e:
|
||||
logger.debug(f"Could not check provisioning status: {e}")
|
||||
logger.debug("Could not check provisioning status: %s", e)
|
||||
|
||||
# Always proceed with the function
|
||||
return await func(*args, **kwargs)
|
||||
|
||||
@@ -119,7 +119,7 @@ def require_scopes(*required_scopes: str):
|
||||
# No context parameter found - likely BasicAuth mode
|
||||
# In BasicAuth mode, all operations are allowed
|
||||
logger.debug(
|
||||
f"No context parameter for {func_name} - allowing (BasicAuth mode)"
|
||||
"No context parameter for %s - allowing (BasicAuth mode)", func_name
|
||||
)
|
||||
return await func(*args, **kwargs)
|
||||
|
||||
@@ -131,7 +131,7 @@ def require_scopes(*required_scopes: str):
|
||||
if access_token is None:
|
||||
# No OAuth token — BasicAuth mode bypasses scope checks
|
||||
logger.debug(
|
||||
f"No access token for {func_name} - allowing (BasicAuth mode)"
|
||||
"No access token for %s - allowing (BasicAuth mode)", func_name
|
||||
)
|
||||
return await func(*args, **kwargs)
|
||||
|
||||
@@ -210,7 +210,8 @@ def require_scopes(*required_scopes: str):
|
||||
if stored_scopes == "all":
|
||||
# NULL scopes in DB = legacy app password = all allowed
|
||||
logger.debug(
|
||||
f"Stored app password scope check passed for {func_name}: all scopes"
|
||||
"Stored app password scope check passed for %s: all scopes",
|
||||
func_name,
|
||||
)
|
||||
return await func(*args, **kwargs)
|
||||
|
||||
@@ -227,7 +228,7 @@ def require_scopes(*required_scopes: str):
|
||||
raise InsufficientScopeError(list(missing), error_msg)
|
||||
|
||||
logger.debug(
|
||||
f"Stored app password scope check passed for {func_name}"
|
||||
"Stored app password scope check passed for %s", func_name
|
||||
)
|
||||
return await func(*args, **kwargs)
|
||||
|
||||
@@ -303,7 +304,7 @@ def require_scopes(*required_scopes: str):
|
||||
|
||||
# All required scopes present - allow execution
|
||||
logger.debug(
|
||||
f"Scope authorization passed for {func_name}: {required_scopes}"
|
||||
"Scope authorization passed for %s: %s", func_name, required_scopes
|
||||
)
|
||||
return await func(*args, **kwargs)
|
||||
|
||||
@@ -366,7 +367,7 @@ def get_access_token_scopes(ctx: Context | None = None) -> set[str]:
|
||||
|
||||
scopes = set(access_token.scopes or [])
|
||||
scopes = _strip_resource_prefix(scopes)
|
||||
logger.info(f"✅ Extracted scopes from access token: {scopes}")
|
||||
logger.info("✅ Extracted scopes from access token: %s", scopes)
|
||||
return scopes
|
||||
|
||||
|
||||
@@ -446,7 +447,7 @@ def is_jwt_token() -> bool:
|
||||
token_string = access_token.token
|
||||
is_jwt = "." in token_string and token_string.count(".") == 2
|
||||
|
||||
logger.debug(f"Token format check: is_jwt={is_jwt}")
|
||||
logger.debug("Token format check: is_jwt=%s", is_jwt)
|
||||
return is_jwt
|
||||
|
||||
|
||||
|
||||
@@ -184,12 +184,12 @@ class RefreshTokenStorage:
|
||||
|
||||
if has_schema:
|
||||
logger.info(
|
||||
f"Detected pre-Alembic database at {self.db_path}, "
|
||||
"stamping with initial revision"
|
||||
"Detected pre-Alembic database at %s, stamping with initial revision",
|
||||
self.db_path,
|
||||
)
|
||||
else:
|
||||
logger.info(
|
||||
f"Initializing new database at {self.db_path} with migrations"
|
||||
"Initializing new database at %s with migrations", self.db_path
|
||||
)
|
||||
|
||||
# Run migrations in a worker thread using anyio.to_thread
|
||||
@@ -215,7 +215,7 @@ class RefreshTokenStorage:
|
||||
os.chmod(self.db_path, 0o600)
|
||||
|
||||
self._initialized = True
|
||||
logger.info(f"Initialized refresh token storage at {self.db_path}")
|
||||
logger.info("Initialized refresh token storage at %s", self.db_path)
|
||||
|
||||
async def store_refresh_token(
|
||||
self,
|
||||
@@ -333,7 +333,7 @@ class RefreshTokenStorage:
|
||||
)
|
||||
await db.commit()
|
||||
|
||||
logger.debug(f"Cached user profile for {user_id}")
|
||||
logger.debug("Cached user profile for %s", user_id)
|
||||
|
||||
async def get_user_profile(self, user_id: str) -> dict[str, Any] | None:
|
||||
"""
|
||||
@@ -419,7 +419,7 @@ class RefreshTokenStorage:
|
||||
row = await cursor.fetchone()
|
||||
|
||||
if not row:
|
||||
logger.debug(f"No refresh token found for user {user_id}")
|
||||
logger.debug("No refresh token found for user %s", user_id)
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "select", duration, "success")
|
||||
return None
|
||||
@@ -437,7 +437,9 @@ class RefreshTokenStorage:
|
||||
# Check expiration
|
||||
if expires_at is not None and expires_at < time.time():
|
||||
logger.warning(
|
||||
f"Refresh token for user {user_id} has expired (expired at {expires_at})"
|
||||
"Refresh token for user %s has expired (expired at %s)",
|
||||
user_id,
|
||||
expires_at,
|
||||
)
|
||||
await self.delete_refresh_token(user_id)
|
||||
duration = time.time() - start_time
|
||||
@@ -448,7 +450,9 @@ class RefreshTokenStorage:
|
||||
scopes = json.loads(scopes_json) if scopes_json else None
|
||||
|
||||
logger.debug(
|
||||
f"Retrieved refresh token for user {user_id} (flow_type: {flow_type})"
|
||||
"Retrieved refresh token for user %s (flow_type: %s)",
|
||||
user_id,
|
||||
flow_type,
|
||||
)
|
||||
|
||||
duration = time.time() - start_time
|
||||
@@ -467,7 +471,7 @@ class RefreshTokenStorage:
|
||||
except Exception as e:
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "select", duration, "error")
|
||||
logger.error(f"Failed to decrypt refresh token for user {user_id}: {e}")
|
||||
logger.error("Failed to decrypt refresh token for user %s: %s", user_id, e)
|
||||
return None
|
||||
|
||||
async def get_refresh_token_by_provisioning_client_id(
|
||||
@@ -511,7 +515,8 @@ class RefreshTokenStorage:
|
||||
|
||||
if not row:
|
||||
logger.debug(
|
||||
f"No refresh token found for provisioning_client_id {provisioning_client_id[:16]}..."
|
||||
"No refresh token found for provisioning_client_id %s...",
|
||||
provisioning_client_id[:16],
|
||||
)
|
||||
return None
|
||||
|
||||
@@ -529,7 +534,8 @@ class RefreshTokenStorage:
|
||||
# Check expiration
|
||||
if expires_at is not None and expires_at < time.time():
|
||||
logger.warning(
|
||||
f"Refresh token for provisioning_client_id {provisioning_client_id[:16]}... has expired"
|
||||
"Refresh token for provisioning_client_id %s... has expired",
|
||||
provisioning_client_id[:16],
|
||||
)
|
||||
return None
|
||||
|
||||
@@ -538,7 +544,9 @@ class RefreshTokenStorage:
|
||||
scopes = json.loads(scopes_json) if scopes_json else None
|
||||
|
||||
logger.debug(
|
||||
f"Retrieved refresh token for provisioning_client_id {provisioning_client_id[:16]}... (user_id: {user_id})"
|
||||
"Retrieved refresh token for provisioning_client_id %s... (user_id: %s)",
|
||||
provisioning_client_id[:16],
|
||||
user_id,
|
||||
)
|
||||
|
||||
return {
|
||||
@@ -553,7 +561,9 @@ class RefreshTokenStorage:
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Failed to decrypt refresh token for provisioning_client_id {provisioning_client_id[:16]}...: {e}"
|
||||
"Failed to decrypt refresh token for provisioning_client_id %s...: %s",
|
||||
provisioning_client_id[:16],
|
||||
e,
|
||||
)
|
||||
return None
|
||||
|
||||
@@ -584,14 +594,14 @@ class RefreshTokenStorage:
|
||||
record_db_operation("sqlite", "delete", duration, "success")
|
||||
|
||||
if deleted:
|
||||
logger.info(f"Deleted refresh token for user {user_id}")
|
||||
logger.info("Deleted refresh token for user %s", user_id)
|
||||
await self._audit_log(
|
||||
event="delete_refresh_token",
|
||||
user_id=user_id,
|
||||
auth_method="offline_access",
|
||||
)
|
||||
else:
|
||||
logger.debug(f"No refresh token to delete for user {user_id}")
|
||||
logger.debug("No refresh token to delete for user %s", user_id)
|
||||
|
||||
return deleted
|
||||
except Exception:
|
||||
@@ -616,7 +626,7 @@ class RefreshTokenStorage:
|
||||
rows = await cursor.fetchall()
|
||||
|
||||
user_ids = [row[0] for row in rows]
|
||||
logger.debug(f"Found {len(user_ids)} users with refresh tokens")
|
||||
logger.debug("Found %s users with refresh tokens", len(user_ids))
|
||||
return user_ids
|
||||
|
||||
async def cleanup_expired_tokens(self) -> int:
|
||||
@@ -640,7 +650,7 @@ class RefreshTokenStorage:
|
||||
deleted = cursor.rowcount
|
||||
|
||||
if deleted > 0:
|
||||
logger.info(f"Cleaned up {deleted} expired refresh token(s)")
|
||||
logger.info("Cleaned up %s expired refresh token(s)", deleted)
|
||||
|
||||
return deleted
|
||||
|
||||
@@ -718,8 +728,9 @@ class RefreshTokenStorage:
|
||||
await db.commit()
|
||||
|
||||
logger.info(
|
||||
f"Stored OAuth client credentials (client_id: {client_id[:16]}..., "
|
||||
f"expires at {client_secret_expires_at})"
|
||||
"Stored OAuth client credentials (client_id: %s..., expires at %s)",
|
||||
client_id[:16],
|
||||
client_secret_expires_at,
|
||||
)
|
||||
|
||||
# Audit log
|
||||
@@ -785,7 +796,7 @@ class RefreshTokenStorage:
|
||||
# Check expiration
|
||||
if expires_at < time.time():
|
||||
logger.warning(
|
||||
f"OAuth client has expired (expired at {expires_at}), deleting"
|
||||
"OAuth client has expired (expired at %s), deleting", expires_at
|
||||
)
|
||||
await self.delete_oauth_client()
|
||||
return None
|
||||
@@ -803,7 +814,7 @@ class RefreshTokenStorage:
|
||||
redirect_uris = json.loads(redirect_uris_json)
|
||||
|
||||
logger.debug(
|
||||
f"Retrieved OAuth client credentials (client_id: {client_id[:16]}...)"
|
||||
"Retrieved OAuth client credentials (client_id: %s...)", client_id[:16]
|
||||
)
|
||||
|
||||
return {
|
||||
@@ -817,7 +828,7 @@ class RefreshTokenStorage:
|
||||
}
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to decrypt OAuth client credentials: {e}")
|
||||
logger.error("Failed to decrypt OAuth client credentials: %s", e)
|
||||
return None
|
||||
|
||||
async def delete_oauth_client(self) -> bool:
|
||||
@@ -1017,7 +1028,9 @@ class RefreshTokenStorage:
|
||||
)
|
||||
await db.commit()
|
||||
|
||||
logger.debug(f"Stored OAuth session {session_id} (expires in {ttl_seconds}s)")
|
||||
logger.debug(
|
||||
"Stored OAuth session %s (expires in %ss)", session_id, ttl_seconds
|
||||
)
|
||||
|
||||
async def get_oauth_session(self, session_id: str) -> dict | None:
|
||||
"""
|
||||
@@ -1043,7 +1056,7 @@ class RefreshTokenStorage:
|
||||
|
||||
# Check expiration
|
||||
if session["expires_at"] < time.time():
|
||||
logger.debug(f"OAuth session {session_id} has expired")
|
||||
logger.debug("OAuth session %s has expired", session_id)
|
||||
await self.delete_oauth_session(session_id)
|
||||
return None
|
||||
|
||||
@@ -1077,7 +1090,8 @@ class RefreshTokenStorage:
|
||||
# Check expiration
|
||||
if session["expires_at"] < time.time():
|
||||
logger.debug(
|
||||
f"OAuth session with MCP code {mcp_authorization_code[:16]}... has expired"
|
||||
"OAuth session with MCP code %s... has expired",
|
||||
mcp_authorization_code[:16],
|
||||
)
|
||||
await self.delete_oauth_session(session["session_id"])
|
||||
return None
|
||||
@@ -1133,7 +1147,7 @@ class RefreshTokenStorage:
|
||||
updated = cursor.rowcount > 0
|
||||
|
||||
if updated:
|
||||
logger.debug(f"Updated OAuth session {session_id}")
|
||||
logger.debug("Updated OAuth session %s", session_id)
|
||||
|
||||
return updated
|
||||
|
||||
@@ -1155,7 +1169,7 @@ class RefreshTokenStorage:
|
||||
deleted = cursor.rowcount > 0
|
||||
|
||||
if deleted:
|
||||
logger.debug(f"Deleted OAuth session {session_id}")
|
||||
logger.debug("Deleted OAuth session %s", session_id)
|
||||
|
||||
return deleted
|
||||
|
||||
@@ -1179,7 +1193,7 @@ class RefreshTokenStorage:
|
||||
deleted = cursor.rowcount
|
||||
|
||||
if deleted > 0:
|
||||
logger.info(f"Cleaned up {deleted} expired OAuth session(s)")
|
||||
logger.info("Cleaned up %s expired OAuth session(s)", deleted)
|
||||
|
||||
return deleted
|
||||
|
||||
@@ -1339,7 +1353,7 @@ class RefreshTokenStorage:
|
||||
)
|
||||
await db.commit()
|
||||
|
||||
logger.debug(f"Stored webhook {webhook_id} for preset '{preset_id}'")
|
||||
logger.debug("Stored webhook %s for preset '%s'", webhook_id, preset_id)
|
||||
|
||||
async def get_webhooks_by_preset(self, preset_id: str) -> list[int]:
|
||||
"""
|
||||
@@ -1384,7 +1398,7 @@ class RefreshTokenStorage:
|
||||
deleted = cursor.rowcount > 0
|
||||
|
||||
if deleted:
|
||||
logger.debug(f"Deleted webhook {webhook_id} from tracking")
|
||||
logger.debug("Deleted webhook %s from tracking", webhook_id)
|
||||
|
||||
return deleted
|
||||
|
||||
@@ -1430,7 +1444,7 @@ class RefreshTokenStorage:
|
||||
deleted = cursor.rowcount
|
||||
|
||||
if deleted > 0:
|
||||
logger.debug(f"Cleared {deleted} webhook(s) for preset '{preset_id}'")
|
||||
logger.debug("Cleared %s webhook(s) for preset '%s'", deleted, preset_id)
|
||||
|
||||
return deleted
|
||||
|
||||
@@ -1482,7 +1496,7 @@ class RefreshTokenStorage:
|
||||
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "insert", duration, "success")
|
||||
logger.info(f"Stored app password for user {user_id}")
|
||||
logger.info("Stored app password for user %s", user_id)
|
||||
|
||||
except Exception:
|
||||
duration = time.time() - start_time
|
||||
@@ -1525,7 +1539,7 @@ class RefreshTokenStorage:
|
||||
row = await cursor.fetchone()
|
||||
|
||||
if not row:
|
||||
logger.debug(f"No app password found for user {user_id}")
|
||||
logger.debug("No app password found for user %s", user_id)
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "select", duration, "success")
|
||||
return None
|
||||
@@ -1535,14 +1549,14 @@ class RefreshTokenStorage:
|
||||
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "select", duration, "success")
|
||||
logger.debug(f"Retrieved app password for user {user_id}")
|
||||
logger.debug("Retrieved app password for user %s", user_id)
|
||||
|
||||
return decrypted_password
|
||||
|
||||
except Exception as e:
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "select", duration, "error")
|
||||
logger.error(f"Failed to decrypt app password for user {user_id}: {e}")
|
||||
logger.error("Failed to decrypt app password for user %s: %s", user_id, e)
|
||||
return None
|
||||
|
||||
async def delete_app_password(self, user_id: str) -> bool:
|
||||
@@ -1572,14 +1586,14 @@ class RefreshTokenStorage:
|
||||
record_db_operation("sqlite", "delete", duration, "success")
|
||||
|
||||
if deleted:
|
||||
logger.info(f"Deleted app password for user {user_id}")
|
||||
logger.info("Deleted app password for user %s", user_id)
|
||||
await self._audit_log(
|
||||
event="delete_app_password",
|
||||
user_id=user_id,
|
||||
auth_method="app_password",
|
||||
)
|
||||
else:
|
||||
logger.debug(f"No app password to delete for user {user_id}")
|
||||
logger.debug("No app password to delete for user %s", user_id)
|
||||
|
||||
return deleted
|
||||
|
||||
@@ -1605,7 +1619,7 @@ class RefreshTokenStorage:
|
||||
rows = await cursor.fetchall()
|
||||
|
||||
user_ids = [row[0] for row in rows]
|
||||
logger.debug(f"Found {len(user_ids)} users with app passwords")
|
||||
logger.debug("Found %s users with app passwords", len(user_ids))
|
||||
return user_ids
|
||||
|
||||
async def cleanup_invalid_app_passwords(self, nextcloud_host: str) -> list[str]:
|
||||
@@ -1651,19 +1665,21 @@ class RefreshTokenStorage:
|
||||
|
||||
if response.status_code in (401, 403):
|
||||
logger.info(
|
||||
f"App password for {user_id} is invalid "
|
||||
f"(HTTP {response.status_code}), removing"
|
||||
"App password for %s is invalid (HTTP %s), removing",
|
||||
user_id,
|
||||
response.status_code,
|
||||
)
|
||||
await self.delete_app_password(user_id)
|
||||
removed.append(user_id)
|
||||
else:
|
||||
logger.debug(
|
||||
f"App password for {user_id} validated "
|
||||
f"(HTTP {response.status_code})"
|
||||
"App password for %s validated (HTTP %s)",
|
||||
user_id,
|
||||
response.status_code,
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.warning(f"Could not validate app password for {user_id}: {e}")
|
||||
logger.warning("Could not validate app password for %s: %s", user_id, e)
|
||||
|
||||
async with anyio.create_task_group() as tg:
|
||||
for user_id in user_ids:
|
||||
@@ -1745,9 +1761,10 @@ class RefreshTokenStorage:
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "insert", duration, "success")
|
||||
logger.info(
|
||||
f"Stored scoped app password for user {user_id} "
|
||||
f"(scopes={'all' if scopes is None else len(scopes)}, "
|
||||
f"username={username or 'N/A'})"
|
||||
"Stored scoped app password for user %s (scopes=%s, username=%s)",
|
||||
user_id,
|
||||
"all" if scopes is None else len(scopes),
|
||||
username or "N/A",
|
||||
)
|
||||
|
||||
except Exception:
|
||||
@@ -1793,7 +1810,7 @@ class RefreshTokenStorage:
|
||||
row = await cursor.fetchone()
|
||||
|
||||
if not row:
|
||||
logger.debug(f"No app password found for user {user_id}")
|
||||
logger.debug("No app password found for user %s", user_id)
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "select", duration, "success")
|
||||
return None
|
||||
@@ -1917,7 +1934,7 @@ class RefreshTokenStorage:
|
||||
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "insert", duration, "success")
|
||||
logger.info(f"Stored login flow session for user {user_id}")
|
||||
logger.info("Stored login flow session for user %s", user_id)
|
||||
|
||||
except Exception:
|
||||
duration = time.time() - start_time
|
||||
@@ -1984,7 +2001,7 @@ class RefreshTokenStorage:
|
||||
duration = time.time() - start_time
|
||||
record_db_operation("sqlite", "select", duration, "error")
|
||||
logger.error(
|
||||
f"Failed to retrieve login flow session for user {user_id}: {e}"
|
||||
"Failed to retrieve login flow session for user %s: %s", user_id, e
|
||||
)
|
||||
raise
|
||||
|
||||
@@ -2014,7 +2031,7 @@ class RefreshTokenStorage:
|
||||
record_db_operation("sqlite", "delete", duration, "success")
|
||||
|
||||
if deleted:
|
||||
logger.info(f"Deleted login flow session for user {user_id}")
|
||||
logger.info("Deleted login flow session for user %s", user_id)
|
||||
await self._audit_log(
|
||||
event="delete_login_flow_session",
|
||||
user_id=user_id,
|
||||
@@ -2052,7 +2069,7 @@ class RefreshTokenStorage:
|
||||
record_db_operation("sqlite", "delete", duration, "success")
|
||||
|
||||
if count > 0:
|
||||
logger.info(f"Cleaned up {count} expired login flow sessions")
|
||||
logger.info("Cleaned up %s expired login flow sessions", count)
|
||||
await self._audit_log(
|
||||
event="delete_expired_login_flow_sessions",
|
||||
user_id="system",
|
||||
|
||||
@@ -56,15 +56,15 @@ class TokenCache:
|
||||
# Check if token has expired
|
||||
if now >= expiry:
|
||||
del self._cache[user_id]
|
||||
logger.debug(f"Cached token expired for user {user_id}")
|
||||
logger.debug("Cached token expired for user %s", user_id)
|
||||
return None
|
||||
|
||||
# Check if token will expire soon (refresh early)
|
||||
if now >= expiry - self._early_refresh:
|
||||
logger.debug(f"Cached token expiring soon for user {user_id}")
|
||||
logger.debug("Cached token expiring soon for user %s", user_id)
|
||||
return None
|
||||
|
||||
logger.debug(f"Using cached token for user {user_id}")
|
||||
logger.debug("Using cached token for user %s", user_id)
|
||||
return token
|
||||
|
||||
async def set(self, user_id: str, token: str, expires_in: int | None = None):
|
||||
@@ -77,14 +77,14 @@ class TokenCache:
|
||||
expiry = datetime.now(timezone.utc) + self._ttl
|
||||
|
||||
self._cache[user_id] = (token, expiry)
|
||||
logger.debug(f"Cached token for user {user_id} until {expiry}")
|
||||
logger.debug("Cached token for user %s until %s", user_id, expiry)
|
||||
|
||||
async def invalidate(self, user_id: str):
|
||||
"""Remove token from cache."""
|
||||
async with self._lock:
|
||||
if user_id in self._cache:
|
||||
del self._cache[user_id]
|
||||
logger.debug(f"Invalidated cached token for user {user_id}")
|
||||
logger.debug("Invalidated cached token for user %s", user_id)
|
||||
|
||||
|
||||
class TokenBrokerService:
|
||||
@@ -214,7 +214,7 @@ class TokenBrokerService:
|
||||
# Get stored refresh token
|
||||
refresh_data = await self.storage.get_refresh_token(user_id)
|
||||
if not refresh_data:
|
||||
logger.info(f"No refresh token found for user {user_id}")
|
||||
logger.info("No refresh token found for user %s", user_id)
|
||||
return None
|
||||
|
||||
try:
|
||||
@@ -230,7 +230,7 @@ class TokenBrokerService:
|
||||
return access_token
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to get Nextcloud token for user {user_id}: {e}")
|
||||
logger.error("Failed to get Nextcloud token for user %s: %s", user_id, e)
|
||||
# Invalidate cache on error
|
||||
await self.cache.invalidate(user_id)
|
||||
return None
|
||||
@@ -273,19 +273,21 @@ class TokenBrokerService:
|
||||
cached_token = await self.cache.get(cache_key)
|
||||
if cached_token:
|
||||
logger.debug(
|
||||
f"Token found in cache after lock acquisition for user {user_id}"
|
||||
"Token found in cache after lock acquisition for user %s", user_id
|
||||
)
|
||||
return cached_token
|
||||
|
||||
# Check if another thread is currently refreshing
|
||||
if await self.cache.get(refresh_in_progress_key):
|
||||
logger.debug(f"Refresh in progress for user {user_id}, waiting briefly")
|
||||
logger.debug(
|
||||
"Refresh in progress for user %s, waiting briefly", user_id
|
||||
)
|
||||
await anyio.sleep(0.1) # Brief wait for in-progress refresh
|
||||
# Check cache one more time after wait
|
||||
cached_token = await self.cache.get(cache_key)
|
||||
if cached_token:
|
||||
logger.debug(
|
||||
f"Token refreshed by another thread for user {user_id}"
|
||||
"Token refreshed by another thread for user %s", user_id
|
||||
)
|
||||
return cached_token
|
||||
|
||||
@@ -296,7 +298,7 @@ class TokenBrokerService:
|
||||
# Get stored refresh token
|
||||
refresh_data = await self.storage.get_refresh_token(user_id)
|
||||
if not refresh_data:
|
||||
logger.info(f"No refresh token found for user {user_id}")
|
||||
logger.info("No refresh token found for user %s", user_id)
|
||||
return None
|
||||
|
||||
# storage.get_refresh_token() returns already-decrypted token
|
||||
@@ -312,14 +314,18 @@ class TokenBrokerService:
|
||||
await self.cache.set(cache_key, access_token, expires_in)
|
||||
|
||||
logger.info(
|
||||
f"Generated background token for user {user_id} with scopes: {required_scopes}"
|
||||
"Generated background token for user %s with scopes: %s",
|
||||
user_id,
|
||||
required_scopes,
|
||||
)
|
||||
|
||||
return access_token
|
||||
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Failed to get background token for user {user_id}: {e}",
|
||||
"Failed to get background token for user %s: %s",
|
||||
user_id,
|
||||
e,
|
||||
exc_info=True,
|
||||
)
|
||||
await self.cache.invalidate(cache_key)
|
||||
@@ -375,7 +381,7 @@ class TokenBrokerService:
|
||||
|
||||
if response.status_code != 200:
|
||||
logger.error(
|
||||
f"Token refresh failed: {response.status_code} - {response.text}"
|
||||
"Token refresh failed: %s - %s", response.status_code, response.text
|
||||
)
|
||||
raise Exception(f"Token refresh failed: {response.status_code}")
|
||||
|
||||
@@ -395,11 +401,11 @@ class TokenBrokerService:
|
||||
refresh_token=new_refresh_token,
|
||||
expires_at=expires_at,
|
||||
)
|
||||
logger.info(f"Stored rotated refresh token for user {user_id}")
|
||||
logger.info("Stored rotated refresh token for user %s", user_id)
|
||||
|
||||
# Note: Nextcloud validates token audience on API calls - no need to pre-validate here
|
||||
|
||||
logger.info(f"Refreshed access token (expires in {expires_in}s)")
|
||||
logger.info("Refreshed access token (expires in %ss)", expires_in)
|
||||
return access_token, expires_in
|
||||
|
||||
async def _refresh_access_token_with_scopes(
|
||||
@@ -446,7 +452,9 @@ class TokenBrokerService:
|
||||
}
|
||||
|
||||
logger.info(
|
||||
f"Token refresh request to {token_endpoint} with client_id={self.client_id[:16]}..."
|
||||
"Token refresh request to %s with client_id=%s...",
|
||||
token_endpoint,
|
||||
self.client_id[:16],
|
||||
)
|
||||
|
||||
response = await client.post(
|
||||
@@ -457,9 +465,11 @@ class TokenBrokerService:
|
||||
|
||||
if response.status_code != 200:
|
||||
logger.error(
|
||||
f"Token refresh with scopes failed: {response.status_code} - {response.text}"
|
||||
"Token refresh with scopes failed: %s - %s",
|
||||
response.status_code,
|
||||
response.text,
|
||||
)
|
||||
logger.error(f" client_id used: {self.client_id[:16]}...")
|
||||
logger.error(" client_id used: %s...", self.client_id[:16])
|
||||
raise Exception(f"Token refresh failed: {response.status_code}")
|
||||
|
||||
token_data = response.json()
|
||||
@@ -479,12 +489,12 @@ class TokenBrokerService:
|
||||
refresh_token=new_refresh_token,
|
||||
expires_at=expires_at,
|
||||
)
|
||||
logger.info(f"Stored rotated refresh token for user {user_id}")
|
||||
logger.info("Stored rotated refresh token for user %s", user_id)
|
||||
|
||||
# Note: Nextcloud validates token audience on API calls - no need to pre-validate here
|
||||
|
||||
logger.info(
|
||||
f"Refreshed access token with scopes {scopes} (expires in {expires_in}s)"
|
||||
"Refreshed access token with scopes %s (expires in %ss)", scopes, expires_in
|
||||
)
|
||||
return access_token, expires_in
|
||||
|
||||
@@ -503,7 +513,7 @@ class TokenBrokerService:
|
||||
"""
|
||||
refresh_data = await self.storage.get_refresh_token(user_id)
|
||||
if not refresh_data:
|
||||
logger.warning(f"No refresh token to rotate for user {user_id}")
|
||||
logger.warning("No refresh token to rotate for user %s", user_id)
|
||||
return False
|
||||
|
||||
try:
|
||||
@@ -538,7 +548,7 @@ class TokenBrokerService:
|
||||
)
|
||||
|
||||
if response.status_code != 200:
|
||||
logger.error(f"Master token refresh failed: {response.status_code}")
|
||||
logger.error("Master token refresh failed: %s", response.status_code)
|
||||
return False
|
||||
|
||||
token_data = response.json()
|
||||
@@ -555,7 +565,7 @@ class TokenBrokerService:
|
||||
refresh_token=new_refresh_token,
|
||||
expires_at=expires_at,
|
||||
)
|
||||
logger.info(f"Rotated master refresh token for user {user_id}")
|
||||
logger.info("Rotated master refresh token for user %s", user_id)
|
||||
|
||||
# Invalidate cached access token
|
||||
await self.cache.invalidate(user_id)
|
||||
@@ -564,7 +574,7 @@ class TokenBrokerService:
|
||||
return True
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to refresh master token for user {user_id}: {e}")
|
||||
logger.error("Failed to refresh master token for user %s: %s", user_id, e)
|
||||
return False
|
||||
|
||||
async def has_nextcloud_provisioning(self, user_id: str) -> bool:
|
||||
@@ -601,7 +611,7 @@ class TokenBrokerService:
|
||||
refresh_token = refresh_data["refresh_token"]
|
||||
await self._revoke_token_at_idp(refresh_token)
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to revoke at IdP: {e}")
|
||||
logger.warning("Failed to revoke at IdP: %s", e)
|
||||
|
||||
# Remove from storage
|
||||
await self.storage.delete_refresh_token(user_id)
|
||||
@@ -609,11 +619,11 @@ class TokenBrokerService:
|
||||
# Clear cache
|
||||
await self.cache.invalidate(user_id)
|
||||
|
||||
logger.info(f"Revoked Nextcloud access for user {user_id}")
|
||||
logger.info("Revoked Nextcloud access for user %s", user_id)
|
||||
return True
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to revoke access for user {user_id}: {e}")
|
||||
logger.error("Failed to revoke access for user %s: %s", user_id, e)
|
||||
return False
|
||||
|
||||
async def _revoke_token_at_idp(self, token: str):
|
||||
@@ -638,7 +648,7 @@ class TokenBrokerService:
|
||||
if response.status_code == 200:
|
||||
logger.info("Token revoked at IdP")
|
||||
else:
|
||||
logger.warning(f"Token revocation returned {response.status_code}")
|
||||
logger.warning("Token revocation returned %s", response.status_code)
|
||||
|
||||
async def close(self):
|
||||
"""Clean up resources."""
|
||||
|
||||
@@ -69,7 +69,7 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
# JWT verification support
|
||||
self.jwks_client: PyJWKClient | None = None
|
||||
if hasattr(settings, "jwks_uri") and settings.jwks_uri:
|
||||
logger.info(f"JWT verification enabled with JWKS URI: {settings.jwks_uri}")
|
||||
logger.info("JWT verification enabled with JWKS URI: %s", settings.jwks_uri)
|
||||
self.jwks_client = PyJWKClient(settings.jwks_uri, cache_keys=True)
|
||||
|
||||
# Introspection support (for opaque tokens)
|
||||
@@ -81,7 +81,7 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
and settings.oidc_client_secret
|
||||
):
|
||||
self.introspection_uri = settings.introspection_uri
|
||||
logger.info(f"Token introspection enabled: {self.introspection_uri}")
|
||||
logger.info("Token introspection enabled: %s", self.introspection_uri)
|
||||
|
||||
# Build list of valid issuers (internal + public may differ in Docker)
|
||||
# AS proxy obtains tokens via internal URL (e.g. http://app:80), while
|
||||
@@ -114,14 +114,16 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
)
|
||||
else:
|
||||
logger.info(
|
||||
f"Management API allowlist: {sorted(self._allowed_mgmt_clients)}"
|
||||
"Management API allowlist: %s", sorted(self._allowed_mgmt_clients)
|
||||
)
|
||||
|
||||
logger.info(
|
||||
f"UnifiedTokenVerifier initialized in {self.mode} mode. "
|
||||
f"MCP audience: {settings.oidc_client_id} or {settings.nextcloud_mcp_server_url}, "
|
||||
f"Nextcloud resource URI: {settings.nextcloud_resource_uri}, "
|
||||
f"Valid issuers: {self.valid_issuers}"
|
||||
"UnifiedTokenVerifier initialized in %s mode. MCP audience: %s or %s, Nextcloud resource URI: %s, Valid issuers: %s",
|
||||
self.mode,
|
||||
settings.oidc_client_id,
|
||||
settings.nextcloud_mcp_server_url,
|
||||
settings.nextcloud_resource_uri,
|
||||
self.valid_issuers,
|
||||
)
|
||||
|
||||
async def verify_token(self, token: str) -> AccessToken | None:
|
||||
@@ -281,9 +283,10 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
if not self._has_mcp_audience(payload):
|
||||
audiences = payload.get("aud", [])
|
||||
logger.error(
|
||||
f"Token rejected: Missing MCP audience. "
|
||||
f"Got {audiences}, need MCP ({self.settings.oidc_client_id} or "
|
||||
f"{self.settings.nextcloud_mcp_server_url})"
|
||||
"Token rejected: Missing MCP audience. Got %s, need MCP (%s or %s)",
|
||||
audiences,
|
||||
self.settings.oidc_client_id,
|
||||
self.settings.nextcloud_mcp_server_url,
|
||||
)
|
||||
# Record as invalid due to audience mismatch
|
||||
record_oauth_token_validation(validation_method, "invalid")
|
||||
@@ -303,7 +306,7 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
return self._create_access_token(token, payload)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Token verification failed: {e}")
|
||||
logger.error("Token verification failed: %s", e)
|
||||
record_oauth_token_validation(validation_method, "error")
|
||||
return None
|
||||
|
||||
@@ -368,14 +371,15 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
|
||||
# Skip audience validation - any valid Nextcloud token is accepted
|
||||
logger.debug(
|
||||
f"Management API token validated (no audience check) for user: {payload.get('sub')}"
|
||||
"Management API token validated (no audience check) for user: %s",
|
||||
payload.get("sub"),
|
||||
)
|
||||
|
||||
# Cache and return the token
|
||||
return self._create_access_token_with_cache_key(token, payload, cache_key)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Management API token verification failed: {e}")
|
||||
logger.error("Management API token verification failed: %s", e)
|
||||
record_oauth_token_validation(validation_method, "error")
|
||||
return None
|
||||
|
||||
@@ -478,20 +482,20 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
f"expected one of: {self.valid_issuers}"
|
||||
)
|
||||
|
||||
logger.debug(f"JWT signature verified for user: {payload.get('sub')}")
|
||||
logger.debug("JWT signature verified for user: %s", payload.get("sub"))
|
||||
return payload
|
||||
|
||||
except jwt.ExpiredSignatureError:
|
||||
logger.info("JWT token has expired")
|
||||
return None
|
||||
except jwt.InvalidIssuerError as e:
|
||||
logger.warning(f"JWT issuer validation failed: {e}")
|
||||
logger.warning("JWT issuer validation failed: %s", e)
|
||||
return None
|
||||
except jwt.InvalidTokenError as e:
|
||||
logger.warning(f"JWT validation failed: {e}")
|
||||
logger.warning("JWT validation failed: %s", e)
|
||||
return None
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error during JWT verification: {e}")
|
||||
logger.error("Unexpected error during JWT verification: %s", e)
|
||||
return None
|
||||
|
||||
async def _introspect_token(self, token: str) -> dict[str, Any] | None:
|
||||
@@ -528,20 +532,23 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
return None
|
||||
|
||||
logger.debug(
|
||||
f"Token introspected successfully for user: {introspection_data.get('sub')}"
|
||||
"Token introspected successfully for user: %s",
|
||||
introspection_data.get("sub"),
|
||||
)
|
||||
return introspection_data
|
||||
|
||||
elif response.status_code in (400, 401, 403):
|
||||
logger.warning(
|
||||
f"Token introspection failed: HTTP {response.status_code}. "
|
||||
f"Response: {response.text[:200] if response.text else 'empty'}"
|
||||
"Token introspection failed: HTTP %s. Response: %s",
|
||||
response.status_code,
|
||||
response.text[:200] if response.text else "empty",
|
||||
)
|
||||
return None
|
||||
else:
|
||||
logger.warning(
|
||||
f"Unexpected response from introspection: {response.status_code}. "
|
||||
f"Response: {response.text[:200] if response.text else 'empty'}"
|
||||
"Unexpected response from introspection: %s. Response: %s",
|
||||
response.status_code,
|
||||
response.text[:200] if response.text else "empty",
|
||||
)
|
||||
return None
|
||||
|
||||
@@ -549,10 +556,10 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
logger.error("Timeout while introspecting token")
|
||||
return None
|
||||
except httpx.RequestError as e:
|
||||
logger.error(f"Network error while introspecting token: {e}")
|
||||
logger.error("Network error while introspecting token: %s", e)
|
||||
return None
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error during token introspection: {e}")
|
||||
logger.error("Unexpected error during token introspection: %s", e)
|
||||
return None
|
||||
|
||||
def _create_access_token(
|
||||
@@ -598,7 +605,9 @@ class UnifiedTokenVerifier(TokenVerifier):
|
||||
scope_string = payload.get("scope", "")
|
||||
scopes = scope_string.split() if scope_string else []
|
||||
logger.debug(
|
||||
f"Extracted scopes from token - scope claim: '{scope_string}' -> scopes list: {scopes}"
|
||||
"Extracted scopes from token - scope claim: '%s' -> scopes list: %s",
|
||||
scope_string,
|
||||
scopes,
|
||||
)
|
||||
|
||||
# Extract expiration
|
||||
|
||||
@@ -143,7 +143,7 @@ async def _get_processing_status(request: Request) -> dict[str, Any] | None:
|
||||
indexed_count = count_result.count
|
||||
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to query Qdrant for indexed count: {e}")
|
||||
logger.warning("Failed to query Qdrant for indexed count: %s", e)
|
||||
# Continue with indexed_count = 0
|
||||
|
||||
# Determine status
|
||||
@@ -156,7 +156,7 @@ async def _get_processing_status(request: Request) -> dict[str, Any] | None:
|
||||
}
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error getting processing status: {e}")
|
||||
logger.error("Error getting processing status: %s", e)
|
||||
return None
|
||||
|
||||
|
||||
@@ -243,11 +243,11 @@ async def _get_userinfo_endpoint(oauth_ctx: dict[str, Any]) -> str | None:
|
||||
try:
|
||||
await oauth_client.discover()
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to discover IdP endpoints: {e}")
|
||||
logger.error("Failed to discover IdP endpoints: %s", e)
|
||||
return None
|
||||
|
||||
logger.debug(
|
||||
f"Using external IdP userinfo endpoint: {oauth_client.userinfo_endpoint}"
|
||||
"Using external IdP userinfo endpoint: %s", oauth_client.userinfo_endpoint
|
||||
)
|
||||
return oauth_client.userinfo_endpoint
|
||||
|
||||
@@ -269,7 +269,8 @@ async def _get_userinfo_endpoint(oauth_ctx: dict[str, Any]) -> str | None:
|
||||
|
||||
if userinfo_endpoint:
|
||||
logger.debug(
|
||||
f"Using Nextcloud userinfo endpoint from discovery: {userinfo_endpoint}"
|
||||
"Using Nextcloud userinfo endpoint from discovery: %s",
|
||||
userinfo_endpoint,
|
||||
)
|
||||
return userinfo_endpoint
|
||||
|
||||
@@ -277,7 +278,7 @@ async def _get_userinfo_endpoint(oauth_ctx: dict[str, Any]) -> str | None:
|
||||
return None
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to query discovery document for userinfo endpoint: {e}")
|
||||
logger.error("Failed to query discovery document for userinfo endpoint: %s", e)
|
||||
return None
|
||||
|
||||
|
||||
@@ -302,7 +303,7 @@ async def _query_idp_userinfo(
|
||||
response.raise_for_status()
|
||||
return response.json()
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to query IdP userinfo endpoint: {e}")
|
||||
logger.warning("Failed to query IdP userinfo endpoint: %s", e)
|
||||
return None
|
||||
|
||||
|
||||
@@ -379,9 +380,9 @@ async def _get_user_info(request: Request) -> dict[str, Any]:
|
||||
# Include cached profile if available
|
||||
if profile_data:
|
||||
user_context["idp_profile"] = profile_data
|
||||
logger.debug(f"Loaded cached profile for {session_id[:16]}...")
|
||||
logger.debug("Loaded cached profile for %s...", session_id[:16])
|
||||
else:
|
||||
logger.warning(f"No cached profile found for {session_id[:16]}...")
|
||||
logger.warning("No cached profile found for %s...", session_id[:16])
|
||||
user_context["idp_profile_error"] = (
|
||||
"Profile not cached. Try logging out and back in."
|
||||
)
|
||||
@@ -389,8 +390,8 @@ async def _get_user_info(request: Request) -> dict[str, Any]:
|
||||
return user_context
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error retrieving user info: {e}")
|
||||
logger.error(f"Traceback: {traceback.format_exc()}")
|
||||
logger.error("Error retrieving user info: %s", e)
|
||||
logger.error("Traceback: %s", traceback.format_exc())
|
||||
return {
|
||||
"error": f"Failed to retrieve user info: {e}",
|
||||
"username": username,
|
||||
@@ -439,7 +440,7 @@ async def user_info_html(request: Request) -> HTMLResponse:
|
||||
is_admin = await is_nextcloud_admin(request, nc_client._client)
|
||||
await nc_client.close()
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to check admin status: {e}")
|
||||
logger.warning("Failed to check admin status: %s", e)
|
||||
# Default to not admin if check fails
|
||||
|
||||
# Check for error
|
||||
@@ -697,9 +698,9 @@ async def revoke_session(request: Request) -> HTMLResponse:
|
||||
|
||||
try:
|
||||
# Delete the refresh token
|
||||
logger.info(f"Revoking background access for session {session_id[:16]}...")
|
||||
logger.info("Revoking background access for session %s...", session_id[:16])
|
||||
await storage.delete_refresh_token(session_id)
|
||||
logger.info(f"✓ Background access revoked for session {session_id[:16]}...")
|
||||
logger.info("✓ Background access revoked for session %s...", session_id[:16])
|
||||
|
||||
# Redirect back to user page
|
||||
user_page_url = str(request.url_for("user_info_html"))
|
||||
@@ -718,7 +719,7 @@ async def revoke_session(request: Request) -> HTMLResponse:
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to revoke background access: {e}")
|
||||
logger.error("Failed to revoke background access: %s", e)
|
||||
template = _jinja_env.get_template("error.html")
|
||||
return HTMLResponse(
|
||||
content=template.render(
|
||||
|
||||
@@ -140,8 +140,13 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
doc_types = doc_types_param.split(",") if doc_types_param else None
|
||||
|
||||
logger.info(
|
||||
f"Viz search: user={username}, query='{query}', "
|
||||
f"algorithm={algorithm}, fusion={fusion}, limit={limit}, doc_types={doc_types}"
|
||||
"Viz search: user=%s, query='%s', algorithm=%s, fusion=%s, limit=%s, doc_types=%s",
|
||||
username,
|
||||
query,
|
||||
algorithm,
|
||||
fusion,
|
||||
limit,
|
||||
doc_types,
|
||||
)
|
||||
|
||||
try:
|
||||
@@ -230,8 +235,9 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
score_range = max_score - min_score if max_score > min_score else 1.0
|
||||
|
||||
logger.info(
|
||||
f"Normalizing scores for viz: original range [{min_score:.3f}, {max_score:.3f}] "
|
||||
f"→ [0.0, 1.0]"
|
||||
"Normalizing scores for viz: original range [%s, %s] → [0.0, 1.0]",
|
||||
format(min_score, ".3f"),
|
||||
format(max_score, ".3f"),
|
||||
)
|
||||
|
||||
# Store original score and rescale to 0-1 for visualization
|
||||
@@ -338,7 +344,7 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
status_code=500,
|
||||
)
|
||||
|
||||
logger.info(f"Detected embedding dimension: {embedding_dim}")
|
||||
logger.info("Detected embedding dimension: %s", embedding_dim)
|
||||
|
||||
# Build chunk vectors array in search_results order (1:1 mapping)
|
||||
chunk_vectors = []
|
||||
@@ -349,7 +355,8 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
else:
|
||||
# Chunk not found in vectors (shouldn't happen)
|
||||
logger.warning(
|
||||
f"Chunk {chunk_key} not found in fetched vectors, using zero vector"
|
||||
"Chunk %s not found in fetched vectors, using zero vector",
|
||||
chunk_key,
|
||||
)
|
||||
# Use zero vector as fallback
|
||||
chunk_vectors.append(np.zeros(embedding_dim))
|
||||
@@ -361,14 +368,16 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
if search_algo.query_embedding is not None:
|
||||
query_embedding = search_algo.query_embedding
|
||||
logger.info(
|
||||
f"Reusing query embedding from search algorithm "
|
||||
f"(dimension={len(query_embedding)})"
|
||||
"Reusing query embedding from search algorithm (dimension=%s)",
|
||||
len(query_embedding),
|
||||
)
|
||||
else:
|
||||
# Fallback: generate embedding if not available from search
|
||||
embedding_service = get_embedding_service()
|
||||
query_embedding = await embedding_service.embed(query)
|
||||
logger.info(f"Generated query embedding (dimension={len(query_embedding)})")
|
||||
logger.info(
|
||||
"Generated query embedding (dimension=%s)", len(query_embedding)
|
||||
)
|
||||
query_embed_duration = time.perf_counter() - query_embed_start
|
||||
|
||||
# Combine query vector with chunk vectors for PCA
|
||||
@@ -387,16 +396,19 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
if zero_norm_mask.any():
|
||||
zero_indices = np.where(zero_norm_mask)[0]
|
||||
logger.warning(
|
||||
f"Found {zero_norm_mask.sum()} zero-norm vectors at indices {zero_indices.tolist()}. "
|
||||
"Replacing with small epsilon to avoid division by zero."
|
||||
"Found %s zero-norm vectors at indices %s. Replacing with small epsilon to avoid division by zero.",
|
||||
zero_norm_mask.sum(),
|
||||
zero_indices.tolist(),
|
||||
)
|
||||
# Replace zero norms with small epsilon to avoid NaN
|
||||
norms[zero_norm_mask] = 1e-10
|
||||
|
||||
all_vectors_normalized = all_vectors / norms
|
||||
logger.info(
|
||||
f"Normalized vectors: query_norm={norms[-1][0]:.3f}, "
|
||||
f"doc_norm_range=[{norms[:-1].min():.3f}, {norms[:-1].max():.3f}]"
|
||||
"Normalized vectors: query_norm=%s, doc_norm_range=[%s, %s]",
|
||||
format(norms[-1][0], ".3f"),
|
||||
format(norms[:-1].min(), ".3f"),
|
||||
format(norms[:-1].max(), ".3f"),
|
||||
)
|
||||
|
||||
# Apply PCA dimensionality reduction (768-dim → 3D) on normalized vectors
|
||||
@@ -428,8 +440,9 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
if nan_mask.any():
|
||||
nan_rows = np.where(nan_mask.any(axis=1))[0]
|
||||
logger.error(
|
||||
f"Found NaN values in PCA output at {len(nan_rows)} points: {nan_rows.tolist()[:10]}. "
|
||||
"Replacing NaN with 0.0 to prevent JSON serialization error."
|
||||
"Found NaN values in PCA output at %s points: %s. Replacing NaN with 0.0 to prevent JSON serialization error.",
|
||||
len(nan_rows),
|
||||
nan_rows.tolist()[:10],
|
||||
)
|
||||
# Replace NaN with 0 to allow JSON serialization
|
||||
coords_3d = np.nan_to_num(coords_3d, nan=0.0)
|
||||
@@ -442,13 +455,16 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
chunk_coords_3d = coords_3d[:-1] # All but last are chunks
|
||||
|
||||
logger.info(
|
||||
f"PCA explained variance: PC1={pca.explained_variance_ratio_[0]:.3f}, "
|
||||
f"PC2={pca.explained_variance_ratio_[1]:.3f}, "
|
||||
f"PC3={pca.explained_variance_ratio_[2]:.3f}"
|
||||
"PCA explained variance: PC1=%s, PC2=%s, PC3=%s",
|
||||
format(pca.explained_variance_ratio_[0], ".3f"),
|
||||
format(pca.explained_variance_ratio_[1], ".3f"),
|
||||
format(pca.explained_variance_ratio_[2], ".3f"),
|
||||
)
|
||||
logger.info(
|
||||
f"Embedding stats: chunks={len(chunk_vectors)}, "
|
||||
f"query_dim={len(query_embedding)}, chunk_vector_dim={chunk_vectors.shape[1] if chunk_vectors.size > 0 else 0}"
|
||||
"Embedding stats: chunks=%s, query_dim=%s, chunk_vector_dim=%s",
|
||||
len(chunk_vectors),
|
||||
len(query_embedding),
|
||||
chunk_vectors.shape[1] if chunk_vectors.size > 0 else 0,
|
||||
)
|
||||
|
||||
# Coordinates already match search_results order (1:1 mapping)
|
||||
@@ -479,12 +495,18 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
|
||||
# Log comprehensive timing metrics
|
||||
logger.info(
|
||||
f"Viz search timing: total={total_duration * 1000:.1f}ms, "
|
||||
f"search={search_duration * 1000:.1f}ms ({search_duration / total_duration * 100:.1f}%), "
|
||||
f"vector_fetch={vector_fetch_duration * 1000:.1f}ms ({vector_fetch_duration / total_duration * 100:.1f}%), "
|
||||
f"query_embed={query_embed_duration * 1000:.1f}ms ({query_embed_duration / total_duration * 100:.1f}%), "
|
||||
f"pca={pca_duration * 1000:.1f}ms ({pca_duration / total_duration * 100:.1f}%), "
|
||||
f"results={len(search_results)}, chunk_vectors={len(chunk_vectors)}"
|
||||
"Viz search timing: total=%sms, search=%sms (%s%%), vector_fetch=%sms (%s%%), query_embed=%sms (%s%%), pca=%sms (%s%%), results=%s, chunk_vectors=%s",
|
||||
format(total_duration * 1000, ".1f"),
|
||||
format(search_duration * 1000, ".1f"),
|
||||
format(search_duration / total_duration * 100, ".1f"),
|
||||
format(vector_fetch_duration * 1000, ".1f"),
|
||||
format(vector_fetch_duration / total_duration * 100, ".1f"),
|
||||
format(query_embed_duration * 1000, ".1f"),
|
||||
format(query_embed_duration / total_duration * 100, ".1f"),
|
||||
format(pca_duration * 1000, ".1f"),
|
||||
format(pca_duration / total_duration * 100, ".1f"),
|
||||
len(search_results),
|
||||
len(chunk_vectors),
|
||||
)
|
||||
|
||||
return JSONResponse(
|
||||
@@ -511,7 +533,7 @@ async def vector_visualization_search(request: Request) -> JSONResponse:
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Viz search error: {e}", exc_info=True)
|
||||
logger.error("Viz search error: %s", e, exc_info=True)
|
||||
return JSONResponse(
|
||||
{"success": False, "error": str(e)},
|
||||
status_code=500,
|
||||
@@ -637,10 +659,12 @@ async def chunk_context_endpoint(request: Request) -> JSONResponse:
|
||||
)
|
||||
|
||||
logger.info(
|
||||
f"Fetched chunk context for {doc_type}_{doc_id}: "
|
||||
f"chunk_len={len(chunk_context.chunk_text)}, "
|
||||
f"before_len={len(chunk_context.before_context)}, "
|
||||
f"after_len={len(chunk_context.after_context)}"
|
||||
"Fetched chunk context for %s_%s: chunk_len=%s, before_len=%s, after_len=%s",
|
||||
doc_type,
|
||||
doc_id,
|
||||
len(chunk_context.chunk_text),
|
||||
len(chunk_context.before_context),
|
||||
len(chunk_context.after_context),
|
||||
)
|
||||
|
||||
# For PDF files, also fetch the chunk bbox from Qdrant so the client
|
||||
@@ -688,7 +712,7 @@ async def chunk_context_endpoint(request: Request) -> JSONResponse:
|
||||
status_code=400,
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"Chunk context error: {e}", exc_info=True)
|
||||
logger.error("Chunk context error: %s", e, exc_info=True)
|
||||
return JSONResponse(
|
||||
{"success": False, "error": str(e)},
|
||||
status_code=500,
|
||||
|
||||
@@ -167,7 +167,7 @@ class NextcloudClient:
|
||||
"""
|
||||
from ..auth import BearerAuth # noqa: PLC0415
|
||||
|
||||
logger.info(f"Creating NC Client for user '{username}' using OAuth token")
|
||||
logger.info("Creating NC Client for user '%s' using OAuth token", username)
|
||||
return cls(
|
||||
base_url=base_url,
|
||||
username=username,
|
||||
|
||||
@@ -43,7 +43,8 @@ def retry_on_429(func):
|
||||
# error we wait a couple of seconds and do a retry
|
||||
if e.response.status_code == codes.TOO_MANY_REQUESTS:
|
||||
logger.warning(
|
||||
f"429 Client Error: Too Many Requests, Number of attempts: {retries}"
|
||||
"429 Client Error: Too Many Requests, Number of attempts: %s",
|
||||
retries,
|
||||
)
|
||||
# Record retry metric (extract app name from args if available)
|
||||
if len(args) > 0 and hasattr(args[0], "app_name"):
|
||||
@@ -53,17 +54,26 @@ def retry_on_429(func):
|
||||
# 404 errors are often expected (e.g., checking if attachments exist)
|
||||
# Log as debug instead of warning
|
||||
logger.debug(
|
||||
f"HTTPStatusError {e.response.status_code}: {e}, Number of attempts: {retries}"
|
||||
"HTTPStatusError %s: %s, Number of attempts: %s",
|
||||
e.response.status_code,
|
||||
e,
|
||||
retries,
|
||||
)
|
||||
raise
|
||||
else:
|
||||
logger.warning(
|
||||
f"HTTPStatusError {e.response.status_code}: {e}, Number of attempts: {retries}"
|
||||
"HTTPStatusError %s: %s, Number of attempts: %s",
|
||||
e.response.status_code,
|
||||
e,
|
||||
retries,
|
||||
)
|
||||
raise
|
||||
except RequestError as e:
|
||||
logger.warning(
|
||||
f"RequestError {e.request.url}: {e}, Number of attempts: {retries}"
|
||||
"RequestError %s: %s, Number of attempts: %s",
|
||||
e.request.url,
|
||||
e,
|
||||
retries,
|
||||
)
|
||||
raise
|
||||
|
||||
@@ -127,7 +137,7 @@ class BaseNextcloudClient(ABC):
|
||||
Response object
|
||||
"""
|
||||
url = self._resolve_url(url)
|
||||
logger.debug(f"Making {method} request to {url}")
|
||||
logger.debug("Making %s request to %s", method, url)
|
||||
|
||||
# Start timer for metrics
|
||||
start_time = time.time()
|
||||
|
||||
@@ -131,23 +131,32 @@ class CalendarClient:
|
||||
max_attempts: Maximum polling attempts (default: 40)
|
||||
initial_delay_ms: Initial delay between attempts in ms (default: 100ms)
|
||||
"""
|
||||
logger.info(f"Waiting for calendar '{calendar_name}' to propagate...")
|
||||
logger.info("Waiting for calendar '%s' to propagate...", calendar_name)
|
||||
delay_ms = initial_delay_ms
|
||||
|
||||
for attempt in range(max_attempts):
|
||||
try:
|
||||
logger.debug(
|
||||
f"Attempt {attempt + 1}/{max_attempts} to find calendar '{calendar_name}'..."
|
||||
"Attempt %s/%s to find calendar '%s'...",
|
||||
attempt + 1,
|
||||
max_attempts,
|
||||
calendar_name,
|
||||
)
|
||||
calendars = await self.list_calendars()
|
||||
if any(cal["name"] == calendar_name for cal in calendars):
|
||||
logger.info(
|
||||
f"Calendar '{calendar_name}' became available after {attempt + 1} attempts"
|
||||
"Calendar '%s' became available after %s attempts",
|
||||
calendar_name,
|
||||
attempt + 1,
|
||||
)
|
||||
return
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Attempt {attempt + 1}/{max_attempts} to verify calendar '{calendar_name}' failed: {e}"
|
||||
"Attempt %s/%s to verify calendar '%s' failed: %s",
|
||||
attempt + 1,
|
||||
max_attempts,
|
||||
calendar_name,
|
||||
e,
|
||||
)
|
||||
|
||||
if attempt < max_attempts - 1:
|
||||
@@ -156,7 +165,9 @@ class CalendarClient:
|
||||
delay_ms = min(delay_ms * 2, 2000)
|
||||
|
||||
logger.error(
|
||||
f"Calendar '{calendar_name}' did not become available after {max_attempts} attempts."
|
||||
"Calendar '%s' did not become available after %s attempts.",
|
||||
calendar_name,
|
||||
max_attempts,
|
||||
)
|
||||
|
||||
# ============= Calendar Operations =============
|
||||
@@ -243,7 +254,7 @@ class CalendarClient:
|
||||
}
|
||||
)
|
||||
|
||||
logger.debug(f"Found {len(result)} calendars")
|
||||
logger.debug("Found %s calendars", len(result))
|
||||
return result
|
||||
|
||||
async def create_calendar(
|
||||
@@ -285,7 +296,7 @@ class CalendarClient:
|
||||
f"Failed to create calendar '{calendar_name}': HTTP {response.status}"
|
||||
)
|
||||
|
||||
logger.debug(f"Created calendar: {calendar_name}")
|
||||
logger.debug("Created calendar: %s", calendar_name)
|
||||
|
||||
# Wait for calendar to be queryable (Nextcloud eventual consistency)
|
||||
await self._wait_for_calendar_propagation(calendar_name)
|
||||
@@ -306,7 +317,7 @@ class CalendarClient:
|
||||
)
|
||||
await self._dav_client.delete(calendar_url)
|
||||
|
||||
logger.debug(f"Deleted calendar: {calendar_name}")
|
||||
logger.debug("Deleted calendar: %s", calendar_name)
|
||||
return {"status_code": 204}
|
||||
|
||||
# ============= Event Operations =============
|
||||
@@ -467,7 +478,7 @@ class CalendarClient:
|
||||
# caldav v3's _async_put raises PutError on HTTP failure
|
||||
event = await calendar.save_event(ical=ical_content) # type: ignore[misc] # dual-mode
|
||||
|
||||
logger.debug(f"Created event {event_uid}")
|
||||
logger.debug("Created event %s", event_uid)
|
||||
|
||||
return {
|
||||
"uid": event_uid,
|
||||
@@ -498,7 +509,7 @@ class CalendarClient:
|
||||
|
||||
await _maybe_await(event.save())
|
||||
|
||||
logger.debug(f"Updated event {event_uid}")
|
||||
logger.debug("Updated event %s", event_uid)
|
||||
return {
|
||||
"uid": event_uid,
|
||||
"href": str(event.url),
|
||||
@@ -515,10 +526,10 @@ class CalendarClient:
|
||||
calendar, event_uid, cdav.CompFilter("VEVENT")
|
||||
)
|
||||
await _maybe_await(event.delete())
|
||||
logger.debug(f"Deleted event {event_uid}")
|
||||
logger.debug("Deleted event %s", event_uid)
|
||||
return {"status_code": 204}
|
||||
except caldav_error.NotFoundError as e:
|
||||
logger.debug(f"Event {event_uid} not found: {e}")
|
||||
logger.debug("Event %s not found: %s", event_uid, e)
|
||||
return {"status_code": 404}
|
||||
|
||||
async def get_event(
|
||||
@@ -539,7 +550,7 @@ class CalendarClient:
|
||||
event_data["href"] = str(event.url)
|
||||
event_data["etag"] = ""
|
||||
|
||||
logger.debug(f"Retrieved event {event_uid}")
|
||||
logger.debug("Retrieved event %s", event_uid)
|
||||
return event_data, ""
|
||||
|
||||
async def search_events_across_calendars(
|
||||
@@ -573,14 +584,14 @@ class CalendarClient:
|
||||
all_events.extend(events)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Error getting events from calendar {calendar['name']}: {e}"
|
||||
"Error getting events from calendar %s: %s", calendar["name"], e
|
||||
)
|
||||
continue
|
||||
|
||||
return all_events
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error searching events across calendars: {e}")
|
||||
logger.error("Error searching events across calendars: %s", e)
|
||||
raise
|
||||
|
||||
# ============= Todo/Task Operations (NEW) =============
|
||||
@@ -611,7 +622,7 @@ class CalendarClient:
|
||||
if not filters or self._todo_matches_filters(todo_dict, filters):
|
||||
result.append(todo_dict)
|
||||
|
||||
logger.debug(f"Found {len(result)} todos")
|
||||
logger.debug("Found %s todos", len(result))
|
||||
return result
|
||||
|
||||
async def create_todo(
|
||||
@@ -626,7 +637,7 @@ class CalendarClient:
|
||||
# caldav v3's _async_put raises PutError on HTTP failure
|
||||
todo = await calendar.save_todo(ical=ical_content) # type: ignore[misc] # dual-mode
|
||||
|
||||
logger.debug(f"Created todo {todo_uid}")
|
||||
logger.debug("Created todo %s", todo_uid)
|
||||
|
||||
return {
|
||||
"uid": todo_uid,
|
||||
@@ -653,7 +664,7 @@ class CalendarClient:
|
||||
await _maybe_await(todo.load(only_if_unloaded=True))
|
||||
|
||||
logger.debug(
|
||||
f"Loaded todo {todo_uid}, current data length: {len(todo.data)}" # type: ignore
|
||||
"Loaded todo %s, current data length: %s", todo_uid, len(todo.data)
|
||||
)
|
||||
|
||||
# Merge updates into existing iCal data
|
||||
@@ -662,14 +673,14 @@ class CalendarClient:
|
||||
todo_data,
|
||||
todo_uid,
|
||||
)
|
||||
logger.debug(f"Merged iCal data length: {len(updated_ical)}")
|
||||
logger.debug(f"Updated iCal content:\n{updated_ical}")
|
||||
logger.debug("Merged iCal data length: %s", len(updated_ical))
|
||||
logger.debug("Updated iCal content:\\n%s", updated_ical)
|
||||
|
||||
todo.data = updated_ical
|
||||
|
||||
await _maybe_await(todo.save())
|
||||
|
||||
logger.debug(f"Updated todo {todo_uid}")
|
||||
logger.debug("Updated todo %s", todo_uid)
|
||||
return {
|
||||
"uid": todo_uid,
|
||||
"href": str(todo.url),
|
||||
@@ -677,7 +688,7 @@ class CalendarClient:
|
||||
"status_code": 200,
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Error updating todo {todo_uid}: {e}", exc_info=True)
|
||||
logger.error("Error updating todo %s: %s", todo_uid, e, exc_info=True)
|
||||
raise
|
||||
|
||||
async def delete_todo(self, calendar_name: str, todo_uid: str) -> dict[str, Any]:
|
||||
@@ -689,10 +700,10 @@ class CalendarClient:
|
||||
calendar, todo_uid, cdav.CompFilter("VTODO")
|
||||
)
|
||||
await _maybe_await(todo.delete())
|
||||
logger.debug(f"Deleted todo {todo_uid}")
|
||||
logger.debug("Deleted todo %s", todo_uid)
|
||||
return {"status_code": 204}
|
||||
except caldav_error.NotFoundError as e:
|
||||
logger.debug(f"Todo {todo_uid} not found: {e}")
|
||||
logger.debug("Todo %s not found: %s", todo_uid, e)
|
||||
return {"status_code": 404}
|
||||
|
||||
async def search_todos_across_calendars(
|
||||
@@ -717,14 +728,14 @@ class CalendarClient:
|
||||
all_todos.extend(todos)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Error getting todos from calendar {calendar['name']}: {e}"
|
||||
"Error getting todos from calendar %s: %s", calendar["name"], e
|
||||
)
|
||||
continue
|
||||
|
||||
return all_todos
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error searching todos across calendars: {e}")
|
||||
logger.error("Error searching todos across calendars: %s", e)
|
||||
raise
|
||||
|
||||
# ============= Helper Methods - Event iCalendar =============
|
||||
@@ -935,7 +946,7 @@ class CalendarClient:
|
||||
return self._extract_vevent_data(component)
|
||||
return None
|
||||
except Exception as e:
|
||||
logger.error(f"Error parsing iCalendar event: {e}")
|
||||
logger.error("Error parsing iCalendar event: %s", e)
|
||||
return None
|
||||
|
||||
def _merge_ical_properties(
|
||||
@@ -1060,7 +1071,7 @@ class CalendarClient:
|
||||
return cal.to_ical().decode("utf-8")
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error merging iCal properties: {e}")
|
||||
logger.error("Error merging iCal properties: %s", e)
|
||||
return self._create_ical_event(event_data, event_uid)
|
||||
|
||||
# ============= Helper Methods - Todo iCalendar =============
|
||||
@@ -1184,7 +1195,7 @@ class CalendarClient:
|
||||
return None
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error parsing iCalendar todo: {e}")
|
||||
logger.error("Error parsing iCalendar todo: %s", e)
|
||||
return None
|
||||
|
||||
def _merge_ical_todo_properties(
|
||||
@@ -1193,7 +1204,7 @@ class CalendarClient:
|
||||
"""Merge new todo data into existing raw iCal while preserving all properties."""
|
||||
try:
|
||||
logger.debug(
|
||||
f"Merging todo properties for {todo_uid}: {list(todo_data.keys())}"
|
||||
"Merging todo properties for %s: %s", todo_uid, list(todo_data.keys())
|
||||
)
|
||||
cal = Calendar.from_ical(raw_ical)
|
||||
|
||||
@@ -1207,13 +1218,13 @@ class CalendarClient:
|
||||
if "status" in todo_data:
|
||||
status_value = todo_data["status"].upper()
|
||||
component["STATUS"] = status_value
|
||||
logger.debug(f"Set STATUS to {status_value}")
|
||||
logger.debug("Set STATUS to %s", status_value)
|
||||
if "priority" in todo_data:
|
||||
component["PRIORITY"] = todo_data["priority"]
|
||||
if "percent_complete" in todo_data:
|
||||
percent_value = todo_data["percent_complete"]
|
||||
component["PERCENT-COMPLETE"] = percent_value
|
||||
logger.debug(f"Set PERCENT-COMPLETE to {percent_value}")
|
||||
logger.debug("Set PERCENT-COMPLETE to %s", percent_value)
|
||||
|
||||
# Handle due date
|
||||
if "due" in todo_data:
|
||||
@@ -1221,7 +1232,7 @@ class CalendarClient:
|
||||
if due_str:
|
||||
due_dt = self._ensure_timezone_aware(due_str)
|
||||
component["DUE"] = vDDDTypes(due_dt)
|
||||
logger.debug(f"Set DUE to {due_dt}")
|
||||
logger.debug("Set DUE to %s", due_dt)
|
||||
|
||||
# Handle start date
|
||||
if "dtstart" in todo_data:
|
||||
@@ -1229,7 +1240,7 @@ class CalendarClient:
|
||||
if dtstart_str:
|
||||
dtstart_dt = self._ensure_timezone_aware(dtstart_str)
|
||||
component["DTSTART"] = vDDDTypes(dtstart_dt)
|
||||
logger.debug(f"Set DTSTART to {dtstart_dt}")
|
||||
logger.debug("Set DTSTART to %s", dtstart_dt)
|
||||
|
||||
# Handle completed date
|
||||
if "completed" in todo_data:
|
||||
@@ -1237,7 +1248,7 @@ class CalendarClient:
|
||||
if completed_str:
|
||||
completed_dt = self._ensure_timezone_aware(completed_str)
|
||||
component["COMPLETED"] = vDDDTypes(completed_dt)
|
||||
logger.debug(f"Set COMPLETED to {completed_dt}")
|
||||
logger.debug("Set COMPLETED to %s", completed_dt)
|
||||
|
||||
# Handle categories
|
||||
if "categories" in todo_data:
|
||||
@@ -1246,7 +1257,7 @@ class CalendarClient:
|
||||
component["CATEGORIES"] = [
|
||||
c.strip() for c in categories_str.split(",")
|
||||
]
|
||||
logger.debug(f"Set CATEGORIES to {categories_str}")
|
||||
logger.debug("Set CATEGORIES to %s", categories_str)
|
||||
|
||||
# Update timestamps
|
||||
now = dt.datetime.now(dt.UTC)
|
||||
@@ -1258,7 +1269,7 @@ class CalendarClient:
|
||||
return cal.to_ical().decode("utf-8")
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error merging iCal todo properties: {e}", exc_info=True)
|
||||
logger.error("Error merging iCal todo properties: %s", e, exc_info=True)
|
||||
return self._create_ical_todo(todo_data, todo_uid)
|
||||
|
||||
# ============= Helper Methods - Filtering =============
|
||||
@@ -1290,7 +1301,7 @@ class CalendarClient:
|
||||
return categories_obj.to_ical().decode("utf-8")
|
||||
return str(categories_obj)
|
||||
except Exception as e:
|
||||
logger.warning(f"Error extracting categories: {e}")
|
||||
logger.warning("Error extracting categories: %s", e)
|
||||
return str(categories_obj)
|
||||
|
||||
def _apply_event_filters(
|
||||
@@ -1437,7 +1448,7 @@ class CalendarClient:
|
||||
}
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error in bulk update: {e}")
|
||||
logger.error("Error in bulk update: %s", e)
|
||||
raise
|
||||
|
||||
async def find_availability(
|
||||
|
||||
@@ -89,7 +89,7 @@ class ContactsClient(BaseNextcloudClient):
|
||||
}
|
||||
)
|
||||
|
||||
logger.debug(f"Found {len(addressbooks)} addressbooks")
|
||||
logger.debug("Found %s addressbooks", len(addressbooks))
|
||||
return addressbooks
|
||||
|
||||
async def create_addressbook(self, *, name: str, display_name: str):
|
||||
@@ -166,7 +166,7 @@ class ContactsClient(BaseNextcloudClient):
|
||||
except Exception:
|
||||
# Fall back to creating new vCard if we can't get existing
|
||||
logger.warning(
|
||||
f"Could not fetch existing vCard for {uid}, creating new"
|
||||
"Could not fetch existing vCard for %s, creating new", uid
|
||||
)
|
||||
raw_vcard_content = ""
|
||||
|
||||
@@ -283,7 +283,7 @@ class ContactsClient(BaseNextcloudClient):
|
||||
}
|
||||
)
|
||||
|
||||
logger.debug(f"Found {len(contacts)} contacts")
|
||||
logger.debug("Found %s contacts", len(contacts))
|
||||
return contacts
|
||||
|
||||
async def _get_raw_vcard(self, addressbook: str, uid: str) -> tuple[str, str]:
|
||||
@@ -296,7 +296,7 @@ class ContactsClient(BaseNextcloudClient):
|
||||
etag = response.headers.get("etag", "")
|
||||
return response.text, etag
|
||||
except Exception as e:
|
||||
logger.error(f"Error getting raw vCard for {uid}: {e}")
|
||||
logger.error("Error getting raw vCard for %s: %s", uid, e)
|
||||
raise
|
||||
|
||||
def _merge_vcard_properties(
|
||||
@@ -428,7 +428,7 @@ class ContactsClient(BaseNextcloudClient):
|
||||
return "\n".join(updated_lines)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error merging vCard properties: {e}")
|
||||
logger.error("Error merging vCard properties: %s", e)
|
||||
# Fallback to creating basic vCard matching Nextcloud format
|
||||
basic_vcard = f"""BEGIN:VCARD
|
||||
VERSION:3.0
|
||||
|
||||
@@ -130,7 +130,7 @@ class CookbookClient(BaseNextcloudClient):
|
||||
Returns:
|
||||
Full imported recipe data
|
||||
"""
|
||||
logger.info(f"Importing recipe from URL: {url}")
|
||||
logger.info("Importing recipe from URL: %s", url)
|
||||
response = await self._make_request(
|
||||
"POST",
|
||||
"/apps/cookbook/api/v1/import",
|
||||
|
||||
@@ -67,7 +67,7 @@ class GroupsClient(BaseNextcloudClient):
|
||||
headers={"OCS-APIRequest": "true", "Accept": "application/json"},
|
||||
)
|
||||
response.raise_for_status()
|
||||
logger.info(f"Created group: {groupid}")
|
||||
logger.info("Created group: %s", groupid)
|
||||
|
||||
@retry_on_429
|
||||
async def delete_group(self, groupid: str) -> None:
|
||||
@@ -85,7 +85,7 @@ class GroupsClient(BaseNextcloudClient):
|
||||
headers={"OCS-APIRequest": "true", "Accept": "application/json"},
|
||||
)
|
||||
response.raise_for_status()
|
||||
logger.info(f"Deleted group: {groupid}")
|
||||
logger.info("Deleted group: %s", groupid)
|
||||
|
||||
@retry_on_429
|
||||
async def get_group_members(self, groupid: str) -> List[str]:
|
||||
@@ -150,4 +150,4 @@ class GroupsClient(BaseNextcloudClient):
|
||||
headers={"OCS-APIRequest": "true", "Accept": "application/json"},
|
||||
)
|
||||
response.raise_for_status()
|
||||
logger.info(f"Updated group {groupid} displayname to: {displayname}")
|
||||
logger.info("Updated group %s displayname to: %s", groupid, displayname)
|
||||
|
||||
@@ -93,13 +93,14 @@ class NotesClient(BaseNextcloudClient):
|
||||
for note in response_data:
|
||||
note_id = note.get("id")
|
||||
if note_id is None:
|
||||
logger.warning(f"Skipping note without ID: {note}")
|
||||
logger.warning("Skipping note without ID: %s", note)
|
||||
continue
|
||||
|
||||
# Skip duplicates (API returns all IDs in last chunk for deletion detection)
|
||||
if note_id in seen_ids:
|
||||
logger.debug(
|
||||
f"Skipping duplicate note {note_id} (pruned version in last chunk)"
|
||||
"Skipping duplicate note %s (pruned version in last chunk)",
|
||||
note_id,
|
||||
)
|
||||
continue
|
||||
|
||||
@@ -152,10 +153,10 @@ class NotesClient(BaseNextcloudClient):
|
||||
if category is not None:
|
||||
old_note = await self.get_note(note_id)
|
||||
old_category = old_note.get("category", "")
|
||||
logger.info(f"Current category for note {note_id}: '{old_category}'")
|
||||
logger.info("Current category for note %s: '%s'", note_id, old_category)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Could not fetch current note {note_id} details before update: {e}"
|
||||
"Could not fetch current note %s details before update: %s", note_id, e
|
||||
)
|
||||
old_note = None
|
||||
|
||||
@@ -169,7 +170,7 @@ class NotesClient(BaseNextcloudClient):
|
||||
body["category"] = category
|
||||
|
||||
logger.info(
|
||||
f"Attempting to update note {note_id} with etag {etag}. Body: {body}"
|
||||
"Attempting to update note %s with etag %s. Body: %s", note_id, etag, body
|
||||
)
|
||||
|
||||
response = await self._make_request(
|
||||
@@ -180,7 +181,7 @@ class NotesClient(BaseNextcloudClient):
|
||||
)
|
||||
|
||||
logger.info(
|
||||
f"Update response for note {note_id}: Status {response.status_code}"
|
||||
"Update response for note %s: Status %s", note_id, response.status_code
|
||||
)
|
||||
updated_note = _expect_note_object(response.json(), operation="update_note")
|
||||
|
||||
@@ -191,7 +192,9 @@ class NotesClient(BaseNextcloudClient):
|
||||
and old_note.get("category", "") != category
|
||||
):
|
||||
logger.info(
|
||||
f"Category changed from '{old_note.get('category', '')}' to '{category}' - cleaning up old attachment directory"
|
||||
"Category changed from '%s' to '%s' - cleaning up old attachment directory",
|
||||
old_note.get("category", ""),
|
||||
category,
|
||||
)
|
||||
try:
|
||||
webdav_client = WebDAVClient(self._client, self.username)
|
||||
@@ -200,7 +203,9 @@ class NotesClient(BaseNextcloudClient):
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Error cleaning up old attachment directory for note {note_id}: {e}"
|
||||
"Error cleaning up old attachment directory for note %s: %s",
|
||||
note_id,
|
||||
e,
|
||||
)
|
||||
|
||||
return updated_note
|
||||
@@ -220,20 +225,23 @@ class NotesClient(BaseNextcloudClient):
|
||||
potential_categories.append("") # Empty category
|
||||
|
||||
logger.info(
|
||||
f"Note {note_id} has category: '{category}', will check attachment directories in: {potential_categories}"
|
||||
"Note %s has category: '%s', will check attachment directories in: %s",
|
||||
note_id,
|
||||
category,
|
||||
potential_categories,
|
||||
)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Could not fetch note {note_id} details before deletion: {e}"
|
||||
"Could not fetch note %s details before deletion: %s", note_id, e
|
||||
)
|
||||
potential_categories = ["", "Unknown"] # Try common categories
|
||||
|
||||
# Delete the note via API
|
||||
logger.info(f"Deleting note {note_id} via API")
|
||||
logger.info("Deleting note %s via API", note_id)
|
||||
response = await self._make_request(
|
||||
"DELETE", f"/apps/notes/api/v1/notes/{note_id}"
|
||||
)
|
||||
logger.info(f"Note {note_id} deleted successfully via API")
|
||||
logger.info("Note %s deleted successfully via API", note_id)
|
||||
json_response = response.json()
|
||||
|
||||
# Clean up attachment directories
|
||||
@@ -245,16 +253,16 @@ class NotesClient(BaseNextcloudClient):
|
||||
await webdav_client.cleanup_note_attachments(note_id, cat)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Failed to cleanup attachments for category '{cat}': {e}"
|
||||
"Failed to cleanup attachments for category '%s': %s", cat, e
|
||||
)
|
||||
except Exception as e:
|
||||
logger.warning(f"Error during attachment cleanup: {e}")
|
||||
logger.warning("Error during attachment cleanup: %s", e)
|
||||
|
||||
return json_response
|
||||
|
||||
async def append_content(self, note_id: int, content: str) -> Dict[str, Any]:
|
||||
"""Append content to an existing note with a separator."""
|
||||
logger.info(f"Appending content to note {note_id}")
|
||||
logger.info("Appending content to note %s", note_id)
|
||||
|
||||
# Get current note
|
||||
current_note = await self.get_note(note_id)
|
||||
@@ -270,7 +278,9 @@ class NotesClient(BaseNextcloudClient):
|
||||
new_content = content # No separator needed for empty notes
|
||||
|
||||
logger.info(
|
||||
f"Combining existing content ({len(existing_content)} chars) with new content ({len(content)} chars)"
|
||||
"Combining existing content (%s chars) with new content (%s chars)",
|
||||
len(existing_content),
|
||||
len(content),
|
||||
)
|
||||
|
||||
# Update with combined content
|
||||
|
||||
@@ -72,8 +72,12 @@ class SharingClient(BaseNextcloudClient):
|
||||
)
|
||||
|
||||
logger.info(
|
||||
f"Created share {share_data['id']}: {path} -> {share_with} "
|
||||
f"(type={share_type}, permissions={permissions})"
|
||||
"Created share %s: %s -> %s (type=%s, permissions=%s)",
|
||||
share_data["id"],
|
||||
path,
|
||||
share_with,
|
||||
share_type,
|
||||
permissions,
|
||||
)
|
||||
return share_data
|
||||
|
||||
@@ -99,7 +103,7 @@ class SharingClient(BaseNextcloudClient):
|
||||
f"OCS API error: {data['ocs']['meta'].get('message', 'Unknown error')}"
|
||||
)
|
||||
|
||||
logger.info(f"Deleted share {share_id}")
|
||||
logger.info("Deleted share %s", share_id)
|
||||
|
||||
@retry_on_429
|
||||
async def get_share(self, share_id: int) -> dict[str, Any]:
|
||||
@@ -206,5 +210,5 @@ class SharingClient(BaseNextcloudClient):
|
||||
f"OCS API error: {result['ocs']['meta'].get('message', 'Unknown error')}"
|
||||
)
|
||||
|
||||
logger.info(f"Updated share {share_id}")
|
||||
logger.info("Updated share %s", share_id)
|
||||
return result["ocs"]["data"]
|
||||
|
||||
@@ -28,7 +28,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
path_with_slash = path
|
||||
|
||||
webdav_path = f"{self._get_webdav_base_path()}/{path_with_slash.lstrip('/')}"
|
||||
logger.debug(f"Deleting WebDAV resource: {webdav_path}")
|
||||
logger.debug("Deleting WebDAV resource: %s", webdav_path)
|
||||
|
||||
headers = {"OCS-APIRequest": "true"}
|
||||
try:
|
||||
@@ -39,28 +39,30 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
"PROPFIND", webdav_path, headers=propfind_headers
|
||||
)
|
||||
logger.debug(
|
||||
f"Resource exists check status: {propfind_resp.status_code}"
|
||||
"Resource exists check status: %s", propfind_resp.status_code
|
||||
)
|
||||
except HTTPStatusError as e:
|
||||
if e.response.status_code == 404:
|
||||
logger.debug(f"Resource '{path}' doesn't exist, no deletion needed")
|
||||
logger.debug(
|
||||
"Resource '%s' doesn't exist, no deletion needed", path
|
||||
)
|
||||
return {"status_code": 404}
|
||||
# For other errors, continue with deletion attempt
|
||||
|
||||
# Proceed with deletion
|
||||
response = await self._make_request("DELETE", webdav_path, headers=headers)
|
||||
logger.debug(f"Successfully deleted WebDAV resource '{path}'")
|
||||
logger.debug("Successfully deleted WebDAV resource '%s'", path)
|
||||
return {"status_code": response.status_code}
|
||||
|
||||
except HTTPStatusError as e:
|
||||
if e.response.status_code == 404:
|
||||
logger.debug(f"Resource '{path}' not found, no deletion needed")
|
||||
logger.debug("Resource '%s' not found, no deletion needed", path)
|
||||
return {"status_code": 404}
|
||||
else:
|
||||
logger.error(f"HTTP error deleting WebDAV resource '{path}': {e}")
|
||||
logger.error("HTTP error deleting WebDAV resource '%s': %s", path, e)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error deleting WebDAV resource '{path}': {e}")
|
||||
logger.error("Unexpected error deleting WebDAV resource '%s': %s", path, e)
|
||||
raise e
|
||||
|
||||
async def cleanup_old_attachment_directory(
|
||||
@@ -72,13 +74,15 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
f"Notes/{old_category_path_part}.attachments.{note_id}/"
|
||||
)
|
||||
|
||||
logger.debug(f"Cleaning up old attachment directory: {old_attachment_dir_path}")
|
||||
logger.debug(
|
||||
"Cleaning up old attachment directory: %s", old_attachment_dir_path
|
||||
)
|
||||
try:
|
||||
delete_result = await self.delete_resource(path=old_attachment_dir_path)
|
||||
logger.debug(f"Cleanup result: {delete_result}")
|
||||
logger.debug("Cleanup result: %s", delete_result)
|
||||
return delete_result
|
||||
except Exception as e:
|
||||
logger.error(f"Error during cleanup of old attachment directory: {e}")
|
||||
logger.error("Error during cleanup of old attachment directory: %s", e)
|
||||
raise e
|
||||
|
||||
async def cleanup_note_attachments(
|
||||
@@ -89,14 +93,14 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
attachment_dir_path = f"Notes/{cat_path_part}.attachments.{note_id}/"
|
||||
|
||||
logger.debug(
|
||||
f"Cleaning up attachments for note {note_id} in category '{category}'"
|
||||
"Cleaning up attachments for note %s in category '%s'", note_id, category
|
||||
)
|
||||
try:
|
||||
delete_result = await self.delete_resource(path=attachment_dir_path)
|
||||
logger.debug(f"Cleanup result for note {note_id}: {delete_result}")
|
||||
logger.debug("Cleanup result for note %s: %s", note_id, delete_result)
|
||||
return delete_result
|
||||
except Exception as e:
|
||||
logger.error(f"Failed cleaning up attachments for note {note_id}: {e}")
|
||||
logger.error("Failed cleaning up attachments for note %s: %s", note_id, e)
|
||||
raise e
|
||||
|
||||
async def add_note_attachment(
|
||||
@@ -118,7 +122,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
parent_dir_path = f"{webdav_base}/{parent_dir_webdav_rel_path}"
|
||||
attachment_path = f"{parent_dir_path}/{filename}"
|
||||
|
||||
logger.debug(f"Uploading attachment '{filename}' for note {note_id}")
|
||||
logger.debug("Uploading attachment '%s' for note %s", filename, note_id)
|
||||
|
||||
if not mime_type:
|
||||
mime_type, _ = mimetypes.guess_type(filename)
|
||||
@@ -143,7 +147,8 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
)
|
||||
elif notes_dir_response.status_code >= 400:
|
||||
logger.error(
|
||||
f"Error accessing WebDAV Notes directory: {notes_dir_response.status_code}"
|
||||
"Error accessing WebDAV Notes directory: %s",
|
||||
notes_dir_response.status_code,
|
||||
)
|
||||
notes_dir_response.raise_for_status()
|
||||
|
||||
@@ -156,7 +161,8 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
# MKCOL should return 201 Created or 405 Method Not Allowed (if directory already exists)
|
||||
if mkcol_response.status_code not in [201, 405]:
|
||||
logger.error(
|
||||
f"Unexpected status code {mkcol_response.status_code} when creating attachments directory"
|
||||
"Unexpected status code %s when creating attachments directory",
|
||||
mkcol_response.status_code,
|
||||
)
|
||||
mkcol_response.raise_for_status()
|
||||
|
||||
@@ -166,18 +172,24 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
)
|
||||
response.raise_for_status()
|
||||
logger.debug(
|
||||
f"Successfully uploaded attachment '{filename}' to note {note_id}"
|
||||
"Successfully uploaded attachment '%s' to note %s", filename, note_id
|
||||
)
|
||||
return {"status_code": response.status_code}
|
||||
|
||||
except HTTPStatusError as e:
|
||||
logger.error(
|
||||
f"HTTP error uploading attachment '{filename}' to note {note_id}: {e}"
|
||||
"HTTP error uploading attachment '%s' to note %s: %s",
|
||||
filename,
|
||||
note_id,
|
||||
e,
|
||||
)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Unexpected error uploading attachment '{filename}' to note {note_id}: {e}"
|
||||
"Unexpected error uploading attachment '%s' to note %s: %s",
|
||||
filename,
|
||||
note_id,
|
||||
e,
|
||||
)
|
||||
raise e
|
||||
|
||||
@@ -190,7 +202,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
attachment_dir_segment = f".attachments.{note_id}"
|
||||
attachment_path = f"{webdav_base}/Notes/{category_path_part}{attachment_dir_segment}/{filename}"
|
||||
|
||||
logger.debug(f"Fetching attachment '{filename}' for note {note_id}")
|
||||
logger.debug("Fetching attachment '%s' for note %s", filename, note_id)
|
||||
|
||||
try:
|
||||
response = await self._make_request("GET", attachment_path)
|
||||
@@ -200,21 +212,29 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
mime_type = response.headers.get("content-type", "application/octet-stream")
|
||||
|
||||
logger.debug(
|
||||
f"Successfully fetched attachment '{filename}' ({len(content)} bytes)"
|
||||
"Successfully fetched attachment '%s' (%s bytes)",
|
||||
filename,
|
||||
len(content),
|
||||
)
|
||||
return content, mime_type
|
||||
|
||||
except HTTPStatusError as e:
|
||||
if e.response.status_code == 404:
|
||||
logger.debug(f"Attachment '{filename}' not found for note {note_id}")
|
||||
logger.debug("Attachment '%s' not found for note %s", filename, note_id)
|
||||
else:
|
||||
logger.error(
|
||||
f"HTTP error fetching attachment '{filename}' for note {note_id}: {e}"
|
||||
"HTTP error fetching attachment '%s' for note %s: %s",
|
||||
filename,
|
||||
note_id,
|
||||
e,
|
||||
)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Unexpected error fetching attachment '{filename}' for note {note_id}: {e}"
|
||||
"Unexpected error fetching attachment '%s' for note %s: %s",
|
||||
filename,
|
||||
note_id,
|
||||
e,
|
||||
)
|
||||
raise e
|
||||
|
||||
@@ -224,7 +244,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
if not webdav_path.endswith("/"):
|
||||
webdav_path += "/"
|
||||
|
||||
logger.debug(f"Listing directory: {path}")
|
||||
logger.debug("Listing directory: %s", path)
|
||||
|
||||
propfind_body = """<?xml version="1.0"?>
|
||||
<d:propfind xmlns:d="DAV:">
|
||||
@@ -308,21 +328,21 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
}
|
||||
)
|
||||
|
||||
logger.debug(f"Found {len(items)} items in directory: {path}")
|
||||
logger.debug("Found %s items in directory: %s", len(items), path)
|
||||
return items
|
||||
|
||||
except HTTPStatusError as e:
|
||||
logger.error(f"HTTP error listing directory '{webdav_path}': {e}")
|
||||
logger.error("HTTP error listing directory '%s': %s", webdav_path, e)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error listing directory '{webdav_path}': {e}")
|
||||
logger.error("Unexpected error listing directory '%s': %s", webdav_path, e)
|
||||
raise e
|
||||
|
||||
async def read_file(self, path: str) -> Tuple[bytes, str]:
|
||||
"""Read a file's content via WebDAV GET."""
|
||||
webdav_path = f"{self._get_webdav_base_path()}/{path.lstrip('/')}"
|
||||
|
||||
logger.debug(f"Reading file: {path}")
|
||||
logger.debug("Reading file: %s", path)
|
||||
|
||||
try:
|
||||
response = await self._make_request("GET", webdav_path)
|
||||
@@ -333,14 +353,14 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
"content-type", "application/octet-stream"
|
||||
)
|
||||
|
||||
logger.debug(f"Successfully read file '{path}' ({len(content)} bytes)")
|
||||
logger.debug("Successfully read file '%s' (%s bytes)", path, len(content))
|
||||
return content, content_type
|
||||
|
||||
except HTTPStatusError as e:
|
||||
logger.error(f"HTTP error reading file '{path}': {e}")
|
||||
logger.error("HTTP error reading file '%s': %s", path, e)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error reading file '{path}': {e}")
|
||||
logger.error("Unexpected error reading file '%s': %s", path, e)
|
||||
raise e
|
||||
|
||||
async def write_file(
|
||||
@@ -349,7 +369,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
"""Write content to a file via WebDAV PUT."""
|
||||
webdav_path = f"{self._get_webdav_base_path()}/{path.lstrip('/')}"
|
||||
|
||||
logger.debug(f"Writing file: {path}")
|
||||
logger.debug("Writing file: %s", path)
|
||||
|
||||
if not content_type:
|
||||
content_type, _ = mimetypes.guess_type(path)
|
||||
@@ -364,14 +384,14 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
)
|
||||
response.raise_for_status()
|
||||
|
||||
logger.debug(f"Successfully wrote file '{path}'")
|
||||
logger.debug("Successfully wrote file '%s'", path)
|
||||
return {"status_code": response.status_code}
|
||||
|
||||
except HTTPStatusError as e:
|
||||
logger.error(f"HTTP error writing file '{path}': {e}")
|
||||
logger.error("HTTP error writing file '%s': %s", path, e)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error writing file '{path}': {e}")
|
||||
logger.error("Unexpected error writing file '%s': %s", path, e)
|
||||
raise e
|
||||
|
||||
async def create_directory(
|
||||
@@ -382,7 +402,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
if not webdav_path.endswith("/"):
|
||||
webdav_path += "/"
|
||||
|
||||
logger.debug(f"Creating directory: {path}")
|
||||
logger.debug("Creating directory: %s", path)
|
||||
|
||||
headers = {"OCS-APIRequest": "true"}
|
||||
|
||||
@@ -390,13 +410,13 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
response = await self._make_request("MKCOL", webdav_path, headers=headers)
|
||||
response.raise_for_status()
|
||||
|
||||
logger.debug(f"Successfully created directory '{path}'")
|
||||
logger.debug("Successfully created directory '%s'", path)
|
||||
return {"status_code": response.status_code}
|
||||
|
||||
except HTTPStatusError as e:
|
||||
# Method Not Allowed - directory already exists
|
||||
if e.response.status_code == 405:
|
||||
logger.debug(f"Directory '{path}' already exists")
|
||||
logger.debug("Directory '%s' already exists", path)
|
||||
return {"status_code": 405, "message": "Directory already exists"}
|
||||
|
||||
# File Conflict - parent directory does not exist
|
||||
@@ -406,20 +426,21 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
if len(path_parts) > 1:
|
||||
parent_dir = "/".join(path_parts[:-1])
|
||||
logger.debug(
|
||||
f"Parent directory '{parent_dir}' doesn't exist, creating recursively"
|
||||
"Parent directory '%s' doesn't exist, creating recursively",
|
||||
parent_dir,
|
||||
)
|
||||
await self.create_directory(parent_dir, recursive)
|
||||
# Now try to create the original directory again
|
||||
return await self.create_directory(path, recursive)
|
||||
else:
|
||||
# This shouldn't happen for single-level directories under root
|
||||
logger.error(f"409 conflict for single-level directory '{path}'")
|
||||
logger.error("409 conflict for single-level directory '%s'", path)
|
||||
raise e
|
||||
|
||||
logger.error(f"HTTP error creating directory '{path}': {e}")
|
||||
logger.error("HTTP error creating directory '%s': %s", path, e)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error creating directory '{path}': {e}")
|
||||
logger.error("Unexpected error creating directory '%s': %s", path, e)
|
||||
raise e
|
||||
|
||||
async def move_resource(
|
||||
@@ -446,7 +467,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
elif not source_path.endswith("/") and destination_path.endswith("/"):
|
||||
source_webdav_path += "/"
|
||||
|
||||
logger.debug(f"Moving resource from '{source_path}' to '{destination_path}'")
|
||||
logger.debug("Moving resource from '%s' to '%s'", source_path, destination_path)
|
||||
|
||||
headers = {
|
||||
"OCS-APIRequest": "true",
|
||||
@@ -461,17 +482,20 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
response.raise_for_status()
|
||||
|
||||
logger.debug(
|
||||
f"Successfully moved resource from '{source_path}' to '{destination_path}'"
|
||||
"Successfully moved resource from '%s' to '%s'",
|
||||
source_path,
|
||||
destination_path,
|
||||
)
|
||||
return {"status_code": response.status_code}
|
||||
|
||||
except HTTPStatusError as e:
|
||||
if e.response.status_code == 404:
|
||||
logger.debug(f"Source resource '{source_path}' not found")
|
||||
logger.debug("Source resource '%s' not found", source_path)
|
||||
return {"status_code": 404, "message": "Source resource not found"}
|
||||
elif e.response.status_code == 412:
|
||||
logger.debug(
|
||||
f"Destination '{destination_path}' already exists and overwrite is false"
|
||||
"Destination '%s' already exists and overwrite is false",
|
||||
destination_path,
|
||||
)
|
||||
return {
|
||||
"status_code": 412,
|
||||
@@ -479,7 +503,8 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
}
|
||||
elif e.response.status_code == 409:
|
||||
logger.debug(
|
||||
f"Parent directory of destination '{destination_path}' doesn't exist"
|
||||
"Parent directory of destination '%s' doesn't exist",
|
||||
destination_path,
|
||||
)
|
||||
return {
|
||||
"status_code": 409,
|
||||
@@ -487,12 +512,18 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
}
|
||||
else:
|
||||
logger.error(
|
||||
f"HTTP error moving resource from '{source_path}' to '{destination_path}': {e}"
|
||||
"HTTP error moving resource from '%s' to '%s': %s",
|
||||
source_path,
|
||||
destination_path,
|
||||
e,
|
||||
)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Unexpected error moving resource from '{source_path}' to '{destination_path}': {e}"
|
||||
"Unexpected error moving resource from '%s' to '%s': %s",
|
||||
source_path,
|
||||
destination_path,
|
||||
e,
|
||||
)
|
||||
raise e
|
||||
|
||||
@@ -520,7 +551,9 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
elif not source_path.endswith("/") and destination_path.endswith("/"):
|
||||
source_webdav_path += "/"
|
||||
|
||||
logger.debug(f"Copying resource from '{source_path}' to '{destination_path}'")
|
||||
logger.debug(
|
||||
"Copying resource from '%s' to '%s'", source_path, destination_path
|
||||
)
|
||||
|
||||
headers = {
|
||||
"OCS-APIRequest": "true",
|
||||
@@ -535,17 +568,20 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
response.raise_for_status()
|
||||
|
||||
logger.debug(
|
||||
f"Successfully copied resource from '{source_path}' to '{destination_path}'"
|
||||
"Successfully copied resource from '%s' to '%s'",
|
||||
source_path,
|
||||
destination_path,
|
||||
)
|
||||
return {"status_code": response.status_code}
|
||||
|
||||
except HTTPStatusError as e:
|
||||
if e.response.status_code == 404:
|
||||
logger.debug(f"Source resource '{source_path}' not found")
|
||||
logger.debug("Source resource '%s' not found", source_path)
|
||||
return {"status_code": 404, "message": "Source resource not found"}
|
||||
elif e.response.status_code == 412:
|
||||
logger.debug(
|
||||
f"Destination '{destination_path}' already exists and overwrite is false"
|
||||
"Destination '%s' already exists and overwrite is false",
|
||||
destination_path,
|
||||
)
|
||||
return {
|
||||
"status_code": 412,
|
||||
@@ -553,7 +589,8 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
}
|
||||
elif e.response.status_code == 409:
|
||||
logger.debug(
|
||||
f"Parent directory of destination '{destination_path}' doesn't exist"
|
||||
"Parent directory of destination '%s' doesn't exist",
|
||||
destination_path,
|
||||
)
|
||||
return {
|
||||
"status_code": 409,
|
||||
@@ -561,12 +598,18 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
}
|
||||
else:
|
||||
logger.error(
|
||||
f"HTTP error copying resource from '{source_path}' to '{destination_path}': {e}"
|
||||
"HTTP error copying resource from '%s' to '%s': %s",
|
||||
source_path,
|
||||
destination_path,
|
||||
e,
|
||||
)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Unexpected error copying resource from '{source_path}' to '{destination_path}': {e}"
|
||||
"Unexpected error copying resource from '%s' to '%s': %s",
|
||||
source_path,
|
||||
destination_path,
|
||||
e,
|
||||
)
|
||||
raise e
|
||||
|
||||
@@ -615,7 +658,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
|
||||
headers = {"Content-Type": "text/xml", "OCS-APIRequest": "true"}
|
||||
|
||||
logger.debug(f"Searching files in scope: {scope}")
|
||||
logger.debug("Searching files in scope: %s", scope)
|
||||
|
||||
try:
|
||||
response = await self._make_request(
|
||||
@@ -626,14 +669,14 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
# Parse the XML response
|
||||
results = self._parse_search_response(response.content, scope)
|
||||
|
||||
logger.debug(f"Search returned {len(results)} results")
|
||||
logger.debug("Search returned %s results", len(results))
|
||||
return results
|
||||
|
||||
except HTTPStatusError as e:
|
||||
logger.error(f"HTTP error during search: {e}")
|
||||
logger.error("HTTP error during search: %s", e)
|
||||
raise e
|
||||
except Exception as e:
|
||||
logger.error(f"Unexpected error during search: {e}")
|
||||
logger.error("Unexpected error during search: %s", e)
|
||||
raise e
|
||||
|
||||
def _build_search_xml(
|
||||
@@ -1129,7 +1172,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
"file_id": file_id,
|
||||
}
|
||||
|
||||
logger.debug(f"Retrieved file info for ID {file_id}: {name}")
|
||||
logger.debug("Retrieved file info for ID %s: %s", file_id, name)
|
||||
return file_info
|
||||
|
||||
async def get_tag_by_name(self, tag_name: str) -> dict[str, Any] | None:
|
||||
@@ -1449,7 +1492,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
"is_directory": is_directory,
|
||||
}
|
||||
|
||||
logger.debug(f"Got file info for '{path}': id={file_info['id']}")
|
||||
logger.debug("Got file info for '%s': id=%s", path, file_info["id"])
|
||||
return file_info
|
||||
|
||||
async def create_tag(
|
||||
@@ -1500,7 +1543,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
"userAssignable": user_assignable,
|
||||
}
|
||||
|
||||
logger.info(f"Created tag '{name}' with ID {tag_info['id']}")
|
||||
logger.info("Created tag '%s' with ID %s", name, tag_info["id"])
|
||||
return tag_info
|
||||
|
||||
async def get_or_create_tag(
|
||||
@@ -1522,7 +1565,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
# First try to get existing tag
|
||||
existing_tag = await self.get_tag_by_name(name)
|
||||
if existing_tag:
|
||||
logger.debug(f"Tag '{name}' already exists with ID {existing_tag['id']}")
|
||||
logger.debug("Tag '%s' already exists with ID %s", name, existing_tag["id"])
|
||||
return existing_tag
|
||||
|
||||
# Create new tag
|
||||
@@ -1558,7 +1601,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
|
||||
# 201 = Created (new assignment), 409 = Conflict (already assigned)
|
||||
if response.status_code in (201, 409):
|
||||
logger.info(f"Tagged file {file_id} with tag {tag_id}")
|
||||
logger.info("Tagged file %s with tag %s", file_id, tag_id)
|
||||
return True
|
||||
|
||||
response.raise_for_status()
|
||||
@@ -1584,7 +1627,7 @@ class WebDAVClient(BaseNextcloudClient):
|
||||
|
||||
# 204 = No Content (removed), 404 = Not Found (wasn't assigned)
|
||||
if response.status_code in (204, 404):
|
||||
logger.info(f"Removed tag {tag_id} from file {file_id}")
|
||||
logger.info("Removed tag %s from file %s", tag_id, file_id)
|
||||
return True
|
||||
|
||||
response.raise_for_status()
|
||||
|
||||
@@ -603,8 +603,8 @@ class Settings:
|
||||
|
||||
if self.document_chunk_size < 512:
|
||||
logger.warning(
|
||||
f"DOCUMENT_CHUNK_SIZE is set to {self.document_chunk_size} characters, which is quite small. "
|
||||
f"Smaller chunks may lose context. Consider using at least 1024 characters."
|
||||
"DOCUMENT_CHUNK_SIZE is set to %s characters, which is quite small. Smaller chunks may lose context. Consider using at least 1024 characters.",
|
||||
self.document_chunk_size,
|
||||
)
|
||||
|
||||
# --- ADR-022 follow-up: deployment mode is the single source of truth ---
|
||||
|
||||
@@ -216,7 +216,7 @@ def detect_auth_mode(settings: Settings) -> AuthMode:
|
||||
)
|
||||
|
||||
explicit_mode = mode_map[mode_str]
|
||||
logger.info(f"Using explicit deployment mode: {explicit_mode.value}")
|
||||
logger.info("Using explicit deployment mode: %s", explicit_mode.value)
|
||||
return explicit_mode
|
||||
|
||||
# Auto-detection (no explicit deployment_mode).
|
||||
@@ -247,7 +247,7 @@ def validate_configuration(settings: Settings) -> tuple[AuthMode, list[str]]:
|
||||
requirements = MODE_REQUIREMENTS[mode]
|
||||
errors: list[str] = []
|
||||
|
||||
logger.debug(f"Validating configuration for mode: {mode.value}")
|
||||
logger.debug("Validating configuration for mode: %s", mode.value)
|
||||
|
||||
# Check required variables
|
||||
for var in requirements.required:
|
||||
@@ -333,8 +333,8 @@ def validate_configuration(settings: Settings) -> tuple[AuthMode, list[str]]:
|
||||
# (This is a runtime check, not a config check, so we just warn)
|
||||
if not settings.oidc_client_id or not settings.oidc_client_secret:
|
||||
logger.info(
|
||||
f"[{mode.value}] OAuth credentials not configured. "
|
||||
"Will attempt Dynamic Client Registration (DCR) at startup."
|
||||
"[%s] OAuth credentials not configured. Will attempt Dynamic Client Registration (DCR) at startup.",
|
||||
mode.value,
|
||||
)
|
||||
|
||||
if mode == AuthMode.MULTI_USER_BASIC:
|
||||
@@ -343,9 +343,8 @@ def validate_configuration(settings: Settings) -> tuple[AuthMode, list[str]]:
|
||||
if settings.enable_offline_access:
|
||||
if not settings.oidc_client_id or not settings.oidc_client_secret:
|
||||
logger.info(
|
||||
f"[{mode.value}] OAuth credentials not configured. "
|
||||
"Will attempt Dynamic Client Registration (DCR) at startup "
|
||||
"(required for app password retrieval via Astrolabe)."
|
||||
"[%s] OAuth credentials not configured. Will attempt Dynamic Client Registration (DCR) at startup (required for app password retrieval via Astrolabe).",
|
||||
mode.value,
|
||||
)
|
||||
|
||||
# Note: Vector sync no longer requires explicit ENABLE_OFFLINE_ACCESS setting
|
||||
|
||||
@@ -139,7 +139,9 @@ def _get_client_from_basic_auth(ctx: Context) -> NextcloudClient:
|
||||
raise ValueError("Invalid BasicAuth credentials - missing username or password")
|
||||
|
||||
logger.debug(
|
||||
f"Creating multi-user BasicAuth client for {settings.nextcloud_host} as {username}"
|
||||
"Creating multi-user BasicAuth client for %s as %s",
|
||||
settings.nextcloud_host,
|
||||
username,
|
||||
)
|
||||
|
||||
# Create client that passes BasicAuth credentials through to Nextcloud
|
||||
@@ -191,7 +193,7 @@ async def _get_client_from_login_flow(
|
||||
|
||||
username = app_data.get("username") or user_id
|
||||
|
||||
logger.debug(f"Creating Login Flow v2 client for {nextcloud_host} as {username}")
|
||||
logger.debug("Creating Login Flow v2 client for %s as %s", nextcloud_host, username)
|
||||
|
||||
return NextcloudClient(
|
||||
base_url=nextcloud_host,
|
||||
|
||||
@@ -55,7 +55,7 @@ class CustomHTTPProcessor(DocumentProcessor):
|
||||
self._name = name
|
||||
self._supported_types = supported_types or set()
|
||||
|
||||
logger.info(f"Initialized CustomHTTPProcessor: {name} -> {api_url}")
|
||||
logger.info("Initialized CustomHTTPProcessor: %s -> %s", name, api_url)
|
||||
|
||||
@property
|
||||
def name(self) -> str:
|
||||
@@ -114,7 +114,9 @@ class CustomHTTPProcessor(DocumentProcessor):
|
||||
metadata = result.get("metadata", {})
|
||||
|
||||
logger.debug(
|
||||
f"Custom processor '{self.name}' extracted {len(text)} characters"
|
||||
"Custom processor '%s' extracted %s characters",
|
||||
self.name,
|
||||
len(text),
|
||||
)
|
||||
|
||||
return ProcessingResult(
|
||||
@@ -125,10 +127,10 @@ class CustomHTTPProcessor(DocumentProcessor):
|
||||
)
|
||||
|
||||
except httpx.HTTPError as e:
|
||||
logger.error(f"Custom processor '{self.name}' HTTP error: {e}")
|
||||
logger.error("Custom processor '%s' HTTP error: %s", self.name, e)
|
||||
raise ProcessorError(f"API call failed: {str(e)}") from e
|
||||
except Exception as e:
|
||||
logger.error(f"Custom processor '{self.name}' failed: {e}")
|
||||
logger.error("Custom processor '%s' failed: %s", self.name, e)
|
||||
raise ProcessorError(f"Processing failed: {str(e)}") from e
|
||||
|
||||
async def health_check(self) -> bool:
|
||||
@@ -146,5 +148,7 @@ class CustomHTTPProcessor(DocumentProcessor):
|
||||
)
|
||||
return response.status_code < 500
|
||||
except Exception as e:
|
||||
logger.warning(f"Custom processor '{self.name}' health check failed: {e}")
|
||||
logger.warning(
|
||||
"Custom processor '%s' health check failed: %s", self.name, e
|
||||
)
|
||||
return False
|
||||
|
||||
@@ -59,7 +59,8 @@ class PyMuPDFProcessor(DocumentProcessor):
|
||||
if self.extract_images:
|
||||
self.image_dir.mkdir(exist_ok=True, parents=True)
|
||||
logger.info(
|
||||
f"Initialized PyMuPDFProcessor with image extraction to {self.image_dir}"
|
||||
"Initialized PyMuPDFProcessor with image extraction to %s",
|
||||
self.image_dir,
|
||||
)
|
||||
else:
|
||||
logger.info("Initialized PyMuPDFProcessor without image extraction")
|
||||
@@ -175,9 +176,11 @@ class PyMuPDFProcessor(DocumentProcessor):
|
||||
await progress_callback(100, 100, "Processing complete")
|
||||
|
||||
logger.info(
|
||||
f"Successfully processed PDF {filename or '<bytes>'}: "
|
||||
f"{metadata['page_count']} pages, {len(md_text)} chars, "
|
||||
f"{metadata.get('image_count', 0)} images"
|
||||
"Successfully processed PDF %s: %s pages, %s chars, %s images",
|
||||
filename or "<bytes>",
|
||||
metadata["page_count"],
|
||||
len(md_text),
|
||||
metadata.get("image_count", 0),
|
||||
)
|
||||
|
||||
return ProcessingResult(
|
||||
@@ -250,5 +253,5 @@ class PyMuPDFProcessor(DocumentProcessor):
|
||||
test_doc.close()
|
||||
return True
|
||||
except Exception as e:
|
||||
logger.error(f"PyMuPDF health check failed: {e}")
|
||||
logger.error("PyMuPDF health check failed: %s", e)
|
||||
return False
|
||||
|
||||
@@ -41,7 +41,7 @@ class ProcessorRegistry:
|
||||
name = processor.name
|
||||
|
||||
if name in self._processors:
|
||||
logger.warning(f"Processor '{name}' already registered, replacing")
|
||||
logger.warning("Processor '%s' already registered, replacing", name)
|
||||
|
||||
self._processors[name] = (processor, priority)
|
||||
|
||||
@@ -62,8 +62,10 @@ class ProcessorRegistry:
|
||||
self._priority_order.append(name)
|
||||
|
||||
logger.info(
|
||||
f"Registered processor: {name} "
|
||||
f"(priority={priority}, supports={len(processor.supported_mime_types)} types)"
|
||||
"Registered processor: %s (priority=%s, supports=%s types)",
|
||||
name,
|
||||
priority,
|
||||
len(processor.supported_mime_types),
|
||||
)
|
||||
|
||||
def get_processor(self, name: str) -> Optional[DocumentProcessor]:
|
||||
@@ -93,10 +95,10 @@ class ProcessorRegistry:
|
||||
for name in self._priority_order:
|
||||
processor = self._processors[name][0]
|
||||
if processor.supports(content_type):
|
||||
logger.debug(f"Found processor '{name}' for type '{content_type}'")
|
||||
logger.debug("Found processor '%s' for type '%s'", name, content_type)
|
||||
return processor
|
||||
|
||||
logger.debug(f"No processor found for type '{content_type}'")
|
||||
logger.debug("No processor found for type '%s'", content_type)
|
||||
return None
|
||||
|
||||
def list_processors(self) -> list[str]:
|
||||
@@ -150,7 +152,7 @@ class ProcessorRegistry:
|
||||
f"Registered processors: {', '.join(self.list_processors())}"
|
||||
)
|
||||
|
||||
logger.info(f"Processing with '{processor.name}' processor")
|
||||
logger.info("Processing with '%s' processor", processor.name)
|
||||
|
||||
# Process
|
||||
return await processor.process(
|
||||
|
||||
@@ -71,7 +71,7 @@ class TesseractProcessor(DocumentProcessor):
|
||||
)
|
||||
|
||||
self.default_lang = default_lang
|
||||
logger.info(f"Initialized TesseractProcessor: lang={default_lang}")
|
||||
logger.info("Initialized TesseractProcessor: lang=%s", default_lang)
|
||||
|
||||
@property
|
||||
def name(self) -> str:
|
||||
@@ -137,8 +137,9 @@ class TesseractProcessor(DocumentProcessor):
|
||||
}
|
||||
|
||||
logger.debug(
|
||||
f"Tesseract OCR completed: {len(text)} chars, "
|
||||
f"confidence={avg_confidence:.1f}%"
|
||||
"Tesseract OCR completed: %s chars, confidence=%s%%",
|
||||
len(text),
|
||||
format(avg_confidence, ".1f"),
|
||||
)
|
||||
|
||||
return ProcessingResult(
|
||||
@@ -149,7 +150,7 @@ class TesseractProcessor(DocumentProcessor):
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Tesseract processing failed: {e}")
|
||||
logger.error("Tesseract processing failed: %s", e)
|
||||
raise ProcessorError(f"OCR failed: {str(e)}") from e
|
||||
|
||||
async def health_check(self) -> bool:
|
||||
|
||||
@@ -68,9 +68,11 @@ class UnstructuredProcessor(DocumentProcessor):
|
||||
self.progress_interval = progress_interval
|
||||
|
||||
logger.info(
|
||||
f"Initialized UnstructuredProcessor: {api_url}, "
|
||||
f"strategy={default_strategy}, languages={self.default_languages}, "
|
||||
f"progress_interval={progress_interval}s"
|
||||
"Initialized UnstructuredProcessor: %s, strategy=%s, languages=%s, progress_interval=%ss",
|
||||
api_url,
|
||||
default_strategy,
|
||||
self.default_languages,
|
||||
progress_interval,
|
||||
)
|
||||
|
||||
@property
|
||||
@@ -117,9 +119,9 @@ class UnstructuredProcessor(DocumentProcessor):
|
||||
total=None, # Unknown total duration # type: ignore
|
||||
message=message, # type: ignore
|
||||
)
|
||||
logger.debug(f"Progress update sent: {elapsed}s elapsed")
|
||||
logger.debug("Progress update sent: %ss elapsed", elapsed)
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to send progress update: {e}")
|
||||
logger.warning("Failed to send progress update: %s", e)
|
||||
logger.debug("Progress poller stopped")
|
||||
|
||||
async def _make_api_request(
|
||||
@@ -165,7 +167,9 @@ class UnstructuredProcessor(DocumentProcessor):
|
||||
data["extract_image_block_types"] = ",".join(extract_image_block_types)
|
||||
|
||||
logger.debug(
|
||||
f"Processing with Unstructured API: strategy={strategy}, languages={languages}"
|
||||
"Processing with Unstructured API: strategy=%s, languages=%s",
|
||||
strategy,
|
||||
languages,
|
||||
)
|
||||
|
||||
try:
|
||||
@@ -202,8 +206,9 @@ class UnstructuredProcessor(DocumentProcessor):
|
||||
}
|
||||
|
||||
logger.debug(
|
||||
f"Successfully processed: {len(elements)} elements, "
|
||||
f"{len(parsed_text)} characters"
|
||||
"Successfully processed: %s elements, %s characters",
|
||||
len(elements),
|
||||
len(parsed_text),
|
||||
)
|
||||
|
||||
return ProcessingResult(
|
||||
@@ -214,10 +219,10 @@ class UnstructuredProcessor(DocumentProcessor):
|
||||
)
|
||||
|
||||
except httpx.HTTPError as e:
|
||||
logger.error(f"Unstructured API HTTP error: {e}")
|
||||
logger.error("Unstructured API HTTP error: %s", e)
|
||||
raise ProcessorError(f"HTTP error: {str(e)}") from e
|
||||
except Exception as e:
|
||||
logger.error(f"Unstructured API processing failed: {e}")
|
||||
logger.error("Unstructured API processing failed: %s", e)
|
||||
raise ProcessorError(f"Processing failed: {str(e)}") from e
|
||||
|
||||
async def process(
|
||||
@@ -306,5 +311,5 @@ class UnstructuredProcessor(DocumentProcessor):
|
||||
response = await client.get(f"{self.api_url}/healthcheck")
|
||||
return response.status_code == 200
|
||||
except Exception as e:
|
||||
logger.warning(f"Unstructured health check failed: {e}")
|
||||
logger.warning("Unstructured health check failed: %s", e)
|
||||
return False
|
||||
|
||||
@@ -30,11 +30,11 @@ class BM25SparseEmbeddingProvider:
|
||||
model_name: FastEmbed BM25 model name (default: Qdrant/bm25)
|
||||
"""
|
||||
self.model_name = model_name
|
||||
logger.info(f"Initializing BM25 sparse embedding provider: {model_name}")
|
||||
logger.info("Initializing BM25 sparse embedding provider: %s", model_name)
|
||||
|
||||
# Initialize FastEmbed sparse embedding model
|
||||
self.model = SparseTextEmbedding(model_name=model_name)
|
||||
logger.info(f"BM25 sparse embedding model loaded: {model_name}")
|
||||
logger.info("BM25 sparse embedding model loaded: %s", model_name)
|
||||
|
||||
def encode(self, text: str) -> dict[str, Any]:
|
||||
"""
|
||||
|
||||
@@ -33,7 +33,10 @@ class OllamaEmbeddingProvider(EmbeddingProvider):
|
||||
self.client = httpx.AsyncClient(verify=verify_ssl, timeout=timeout)
|
||||
self._dimension: int | None = None # Will be detected dynamically
|
||||
logger.info(
|
||||
f"Initialized Ollama provider: {base_url} (model={model}, verify_ssl={verify_ssl})"
|
||||
"Initialized Ollama provider: %s (model=%s, verify_ssl=%s)",
|
||||
base_url,
|
||||
model,
|
||||
verify_ssl,
|
||||
)
|
||||
|
||||
self._check_model_is_loaded(autoload=True)
|
||||
@@ -82,11 +85,13 @@ class OllamaEmbeddingProvider(EmbeddingProvider):
|
||||
instead of relying on hardcoded values.
|
||||
"""
|
||||
if self._dimension is None:
|
||||
logger.debug(f"Detecting embedding dimension for model {self.model}...")
|
||||
logger.debug("Detecting embedding dimension for model %s...", self.model)
|
||||
test_embedding = await self.embed("test")
|
||||
self._dimension = len(test_embedding)
|
||||
logger.info(
|
||||
f"Detected embedding dimension: {self._dimension} for model {self.model}"
|
||||
"Detected embedding dimension: %s for model %s",
|
||||
self._dimension,
|
||||
self.model,
|
||||
)
|
||||
|
||||
def get_dimension(self) -> int:
|
||||
|
||||
@@ -52,8 +52,8 @@ def get_alembic_config(database_path: str | Path | None = None) -> Config:
|
||||
url = f"sqlite+aiosqlite:///{db_path}"
|
||||
config.set_main_option("sqlalchemy.url", url)
|
||||
|
||||
logger.debug(f"Alembic script location: {script_location}")
|
||||
logger.debug(f"Database: {db_path}")
|
||||
logger.debug("Alembic script location: %s", script_location)
|
||||
logger.debug("Database: %s", db_path)
|
||||
|
||||
return config
|
||||
|
||||
@@ -69,7 +69,7 @@ def upgrade_database(
|
||||
revision: Target revision (default: "head" for latest)
|
||||
"""
|
||||
config = get_alembic_config(database_path)
|
||||
logger.info(f"Upgrading database to revision: {revision}")
|
||||
logger.info("Upgrading database to revision: %s", revision)
|
||||
command.upgrade(config, revision)
|
||||
logger.info("Database upgrade completed successfully")
|
||||
|
||||
@@ -85,7 +85,7 @@ def downgrade_database(
|
||||
revision: Target revision (default: "-1" for previous version)
|
||||
"""
|
||||
config = get_alembic_config(database_path)
|
||||
logger.warning(f"Downgrading database to revision: {revision}")
|
||||
logger.warning("Downgrading database to revision: %s", revision)
|
||||
command.downgrade(config, revision)
|
||||
logger.info("Database downgrade completed successfully")
|
||||
|
||||
@@ -107,7 +107,7 @@ def get_current_revision(database_path: str | Path | None = None) -> str | None:
|
||||
db_path = Path(database_path).resolve()
|
||||
|
||||
if not db_path.exists():
|
||||
logger.debug(f"Database does not exist: {db_path}")
|
||||
logger.debug("Database does not exist: %s", db_path)
|
||||
return None
|
||||
|
||||
try:
|
||||
@@ -133,7 +133,7 @@ def get_current_revision(database_path: str | Path | None = None) -> str | None:
|
||||
return row[0] if row else None
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to get current revision: {e}")
|
||||
logger.error("Failed to get current revision: %s", e)
|
||||
return None
|
||||
|
||||
|
||||
@@ -152,7 +152,7 @@ def stamp_database(
|
||||
revision: Revision to stamp (default: "head" for latest)
|
||||
"""
|
||||
config = get_alembic_config(database_path)
|
||||
logger.info(f"Stamping database with revision: {revision}")
|
||||
logger.info("Stamping database with revision: %s", revision)
|
||||
command.stamp(config, revision)
|
||||
logger.info("Database stamped successfully")
|
||||
|
||||
@@ -181,7 +181,7 @@ def create_migration(message: str, autogenerate: bool = False) -> None:
|
||||
and migrations must be written manually.
|
||||
"""
|
||||
config = get_alembic_config()
|
||||
logger.info(f"Creating new migration: {message}")
|
||||
logger.info("Creating new migration: %s", message)
|
||||
|
||||
if autogenerate:
|
||||
logger.warning(
|
||||
|
||||
@@ -177,8 +177,10 @@ def setup_logging(
|
||||
configure_component_loggers(log_level)
|
||||
|
||||
root_logger.info(
|
||||
f"Logging configured: format={log_format}, level={log_level}, "
|
||||
f"trace_context={include_trace_context}"
|
||||
"Logging configured: format=%s, level=%s, trace_context=%s",
|
||||
log_format,
|
||||
log_level,
|
||||
include_trace_context,
|
||||
)
|
||||
|
||||
|
||||
|
||||
@@ -231,14 +231,15 @@ def setup_metrics(port: int = 9090) -> None:
|
||||
"""
|
||||
try:
|
||||
start_http_server(port)
|
||||
logger.info(f"Prometheus metrics server started on port {port}")
|
||||
logger.info("Prometheus metrics server started on port %s", port)
|
||||
except OSError as e:
|
||||
if "Address already in use" in str(e):
|
||||
logger.warning(
|
||||
f"Metrics port {port} already in use (metrics server likely already running)"
|
||||
"Metrics port %s already in use (metrics server likely already running)",
|
||||
port,
|
||||
)
|
||||
else:
|
||||
logger.error(f"Failed to start metrics server on port {port}: {e}")
|
||||
logger.error("Failed to start metrics server on port %s: %s", port, e)
|
||||
raise
|
||||
|
||||
|
||||
|
||||
@@ -127,7 +127,9 @@ class ObservabilityMiddleware(BaseHTTPMiddleware):
|
||||
)
|
||||
|
||||
logger.error(
|
||||
f"Request failed: {method} {path}",
|
||||
"Request failed: %s %s",
|
||||
method,
|
||||
path,
|
||||
exc_info=True,
|
||||
extra={
|
||||
"method": method,
|
||||
@@ -212,7 +214,10 @@ class ObservabilityMiddleware(BaseHTTPMiddleware):
|
||||
# Log slow requests (>1 second)
|
||||
if duration > 1.0:
|
||||
logger.warning(
|
||||
f"Slow request: {method} {endpoint} took {duration:.3f}s",
|
||||
"Slow request: %s %s took %ss",
|
||||
method,
|
||||
endpoint,
|
||||
format(duration, ".3f"),
|
||||
extra={
|
||||
"method": method,
|
||||
"endpoint": endpoint,
|
||||
|
||||
@@ -73,11 +73,12 @@ def setup_tracing(
|
||||
span_processor = BatchSpanProcessor(otlp_exporter)
|
||||
provider.add_span_processor(span_processor)
|
||||
logger.info(
|
||||
f"OpenTelemetry tracing enabled with OTLP endpoint: {otlp_endpoint}"
|
||||
"OpenTelemetry tracing enabled with OTLP endpoint: %s", otlp_endpoint
|
||||
)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Failed to initialize OTLP exporter: {e}. Continuing without trace export."
|
||||
"Failed to initialize OTLP exporter: %s. Continuing without trace export.",
|
||||
e,
|
||||
)
|
||||
else:
|
||||
logger.info(
|
||||
@@ -93,7 +94,7 @@ def setup_tracing(
|
||||
# Get and store tracer
|
||||
_tracer = trace.get_tracer(__name__)
|
||||
|
||||
logger.info(f"OpenTelemetry tracing initialized for service: {service_name}")
|
||||
logger.info("OpenTelemetry tracing initialized for service: %s", service_name)
|
||||
return _tracer
|
||||
|
||||
|
||||
|
||||
@@ -30,7 +30,7 @@ class AnthropicProvider(Provider):
|
||||
self.client = AsyncAnthropic(api_key=api_key)
|
||||
self.model = generation_model
|
||||
|
||||
logger.info(f"Initialized Anthropic provider (model={self.model})")
|
||||
logger.info("Initialized Anthropic provider (model=%s)", self.model)
|
||||
|
||||
@property
|
||||
def supports_embeddings(self) -> bool:
|
||||
|
||||
@@ -75,8 +75,10 @@ class BedrockProvider(Provider):
|
||||
self.client = boto3.client("bedrock-runtime", **client_kwargs)
|
||||
|
||||
logger.info(
|
||||
f"Initialized Bedrock provider in region {region_name or 'default'} "
|
||||
f"(embedding_model={embedding_model}, generation_model={generation_model})"
|
||||
"Initialized Bedrock provider in region %s (embedding_model=%s, generation_model=%s)",
|
||||
region_name or "default",
|
||||
embedding_model,
|
||||
generation_model,
|
||||
)
|
||||
|
||||
@property
|
||||
@@ -115,8 +117,8 @@ class BedrockProvider(Provider):
|
||||
# Unknown model - try Titan format as default
|
||||
else:
|
||||
logger.warning(
|
||||
f"Unknown embedding model format for {self.embedding_model}, "
|
||||
"using Titan format as default"
|
||||
"Unknown embedding model format for %s, using Titan format as default",
|
||||
self.embedding_model,
|
||||
)
|
||||
return {"inputText": text}
|
||||
|
||||
@@ -143,8 +145,8 @@ class BedrockProvider(Provider):
|
||||
# Unknown model - try Titan format as default
|
||||
else:
|
||||
logger.warning(
|
||||
f"Unknown embedding response format for {self.embedding_model}, "
|
||||
"trying Titan format"
|
||||
"Unknown embedding response format for %s, trying Titan format",
|
||||
self.embedding_model,
|
||||
)
|
||||
return response.get("embedding", response.get("embeddings", [None])[0])
|
||||
|
||||
@@ -183,7 +185,7 @@ class BedrockProvider(Provider):
|
||||
return embedding
|
||||
|
||||
except (BotoCoreError, ClientError) as e:
|
||||
logger.error(f"Bedrock embedding error: {e}")
|
||||
logger.error("Bedrock embedding error: %s", e)
|
||||
raise
|
||||
|
||||
async def embed_batch(self, texts: list[str]) -> list[list[float]]:
|
||||
@@ -220,13 +222,14 @@ class BedrockProvider(Provider):
|
||||
"""
|
||||
if self._dimension is None and self.supports_embeddings:
|
||||
logger.debug(
|
||||
f"Detecting embedding dimension for model {self.embedding_model}..."
|
||||
"Detecting embedding dimension for model %s...", self.embedding_model
|
||||
)
|
||||
test_embedding = await self.embed("test")
|
||||
self._dimension = len(test_embedding)
|
||||
logger.info(
|
||||
f"Detected embedding dimension: {self._dimension} "
|
||||
f"for model {self.embedding_model}"
|
||||
"Detected embedding dimension: %s for model %s",
|
||||
self._dimension,
|
||||
self.embedding_model,
|
||||
)
|
||||
|
||||
def get_dimension(self) -> int:
|
||||
@@ -300,8 +303,8 @@ class BedrockProvider(Provider):
|
||||
# Unknown model - try Claude format as default
|
||||
else:
|
||||
logger.warning(
|
||||
f"Unknown generation model format for {self.generation_model}, "
|
||||
"using Claude format as default"
|
||||
"Unknown generation model format for %s, using Claude format as default",
|
||||
self.generation_model,
|
||||
)
|
||||
return {
|
||||
"anthropic_version": "bedrock-2023-05-31",
|
||||
@@ -343,8 +346,8 @@ class BedrockProvider(Provider):
|
||||
# Unknown model - try common response fields
|
||||
else:
|
||||
logger.warning(
|
||||
f"Unknown generation response format for {self.generation_model}, "
|
||||
"trying common fields"
|
||||
"Unknown generation response format for %s, trying common fields",
|
||||
self.generation_model,
|
||||
)
|
||||
# Try common response field names
|
||||
for field in ["text", "generation", "outputText", "completion"]:
|
||||
@@ -389,7 +392,7 @@ class BedrockProvider(Provider):
|
||||
return text
|
||||
|
||||
except (BotoCoreError, ClientError) as e:
|
||||
logger.error(f"Bedrock generation error: {e}")
|
||||
logger.error("Bedrock generation error: %s", e)
|
||||
raise
|
||||
|
||||
async def close(self) -> None:
|
||||
|
||||
@@ -46,9 +46,11 @@ class OllamaProvider(Provider):
|
||||
self._dimension: int | None = None # Detected dynamically for embeddings
|
||||
|
||||
logger.info(
|
||||
f"Initialized Ollama provider: {base_url} "
|
||||
f"(embedding_model={embedding_model}, generation_model={generation_model}, "
|
||||
f"verify_ssl={verify_ssl})"
|
||||
"Initialized Ollama provider: %s (embedding_model=%s, generation_model=%s, verify_ssl=%s)",
|
||||
base_url,
|
||||
embedding_model,
|
||||
generation_model,
|
||||
verify_ssl,
|
||||
)
|
||||
|
||||
# Pre-check and auto-load models
|
||||
@@ -140,13 +142,14 @@ class OllamaProvider(Provider):
|
||||
"""
|
||||
if self._dimension is None and self.supports_embeddings:
|
||||
logger.debug(
|
||||
f"Detecting embedding dimension for model {self.embedding_model}..."
|
||||
"Detecting embedding dimension for model %s...", self.embedding_model
|
||||
)
|
||||
test_embedding = await self.embed("test")
|
||||
self._dimension = len(test_embedding)
|
||||
logger.info(
|
||||
f"Detected embedding dimension: {self._dimension} "
|
||||
f"for model {self.embedding_model}"
|
||||
"Detected embedding dimension: %s for model %s",
|
||||
self._dimension,
|
||||
self.embedding_model,
|
||||
)
|
||||
|
||||
def get_dimension(self) -> int:
|
||||
|
||||
@@ -120,11 +120,11 @@ async def get_indexed_doc_types(user_id: str) -> set[str]:
|
||||
if point.payload and point.payload.get("doc_type")
|
||||
}
|
||||
|
||||
logger.debug(f"Found indexed document types for user {user_id}: {doc_types}")
|
||||
logger.debug("Found indexed document types for user %s: %s", user_id, doc_types)
|
||||
return doc_types
|
||||
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to query Qdrant for doc_types: {e}")
|
||||
logger.warning("Failed to query Qdrant for doc_types: %s", e)
|
||||
return set()
|
||||
|
||||
|
||||
|
||||
@@ -100,9 +100,13 @@ class BM25HybridSearchAlgorithm(SearchAlgorithm):
|
||||
score_threshold = kwargs.get("score_threshold", self.score_threshold)
|
||||
|
||||
logger.info(
|
||||
f"BM25 hybrid search: query='{query}', user={user_id}, "
|
||||
f"limit={limit}, score_threshold={score_threshold}, doc_type={doc_type}, "
|
||||
f"fusion={self.fusion_name}"
|
||||
"BM25 hybrid search: query='%s', user=%s, limit=%s, score_threshold=%s, doc_type=%s, fusion=%s",
|
||||
query,
|
||||
user_id,
|
||||
limit,
|
||||
score_threshold,
|
||||
doc_type,
|
||||
self.fusion_name,
|
||||
)
|
||||
|
||||
# Generate dense embedding for semantic search
|
||||
@@ -112,7 +116,7 @@ class BM25HybridSearchAlgorithm(SearchAlgorithm):
|
||||
dense_embedding = await embedding_service.embed(query)
|
||||
# Store for reuse by callers (e.g., viz_routes PCA visualization)
|
||||
self.query_embedding = dense_embedding
|
||||
logger.debug(f"Generated dense embedding (dimension={len(dense_embedding)})")
|
||||
logger.debug("Generated dense embedding (dimension=%s)", len(dense_embedding))
|
||||
|
||||
# Generate sparse embedding for BM25 keyword search
|
||||
with trace_operation("search.get_bm25_service"):
|
||||
@@ -120,8 +124,8 @@ class BM25HybridSearchAlgorithm(SearchAlgorithm):
|
||||
with trace_operation("search.sparse_embedding_bm25"):
|
||||
sparse_embedding = await bm25_service.encode_async(query)
|
||||
logger.debug(
|
||||
f"Generated sparse embedding "
|
||||
f"({len(sparse_embedding['indices'])} non-zero terms)"
|
||||
"Generated sparse embedding (%s non-zero terms)",
|
||||
len(sparse_embedding["indices"]),
|
||||
)
|
||||
|
||||
# Build Qdrant filter
|
||||
@@ -189,15 +193,16 @@ class BM25HybridSearchAlgorithm(SearchAlgorithm):
|
||||
raise
|
||||
|
||||
logger.info(
|
||||
f"Qdrant {self.fusion_name.upper()} fusion returned {len(search_response.points)} results "
|
||||
f"(before deduplication)"
|
||||
"Qdrant %s fusion returned %s results (before deduplication)",
|
||||
self.fusion_name.upper(),
|
||||
len(search_response.points),
|
||||
)
|
||||
|
||||
if search_response.points:
|
||||
# Log top 3 fusion scores to help with threshold tuning
|
||||
top_scores = [p.score for p in search_response.points[:3]]
|
||||
logger.debug(
|
||||
f"Top 3 {self.fusion_name.upper()} fusion scores: {top_scores}"
|
||||
"Top 3 %s fusion scores: %s", self.fusion_name.upper(), top_scores
|
||||
)
|
||||
|
||||
# Deduplicate by (doc_id, doc_type, chunk_start, chunk_end)
|
||||
@@ -233,12 +238,12 @@ class BM25HybridSearchAlgorithm(SearchAlgorithm):
|
||||
if len(results) >= limit:
|
||||
break
|
||||
|
||||
logger.info(f"Returning {len(results)} unverified results after deduplication")
|
||||
logger.info("Returning %s unverified results after deduplication", len(results))
|
||||
if results:
|
||||
result_details = [
|
||||
f"{r.doc_type}_{r.id} (score={r.score:.3f}, title='{r.title}')"
|
||||
for r in results[:5] # Show top 5
|
||||
]
|
||||
logger.debug(f"Top results: {', '.join(result_details)}")
|
||||
logger.debug("Top results: %s", ", ".join(result_details))
|
||||
|
||||
return results
|
||||
|
||||
@@ -67,20 +67,26 @@ async def _get_chunk_from_qdrant(
|
||||
excerpt = point.payload.get("excerpt")
|
||||
if excerpt:
|
||||
logger.debug(
|
||||
f"Retrieved chunk from Qdrant for {doc_type} {doc_id}: "
|
||||
f"{len(excerpt)} chars"
|
||||
"Retrieved chunk from Qdrant for %s %s: %s chars",
|
||||
doc_type,
|
||||
doc_id,
|
||||
len(excerpt),
|
||||
)
|
||||
return str(excerpt)
|
||||
|
||||
logger.debug(
|
||||
f"Chunk not found in Qdrant for {doc_type} {doc_id}, "
|
||||
f"chunk [{chunk_start}:{chunk_end}]. Will fall back to document fetch."
|
||||
"Chunk not found in Qdrant for %s %s, chunk [%s:%s]. Will fall back to document fetch.",
|
||||
doc_type,
|
||||
doc_id,
|
||||
chunk_start,
|
||||
chunk_end,
|
||||
)
|
||||
return None
|
||||
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Error querying Qdrant for chunk: {e}. Falling back to document fetch.",
|
||||
"Error querying Qdrant for chunk: %s. Falling back to document fetch.",
|
||||
e,
|
||||
exc_info=True,
|
||||
)
|
||||
return None
|
||||
@@ -129,8 +135,11 @@ async def _get_chunk_by_index_from_qdrant(
|
||||
excerpt = point.payload.get("excerpt")
|
||||
if excerpt:
|
||||
logger.debug(
|
||||
f"Retrieved adjacent chunk {chunk_index} from Qdrant for "
|
||||
f"{doc_type} {doc_id}: {len(excerpt)} chars"
|
||||
"Retrieved adjacent chunk %s from Qdrant for %s %s: %s chars",
|
||||
chunk_index,
|
||||
doc_type,
|
||||
doc_id,
|
||||
len(excerpt),
|
||||
)
|
||||
return str(excerpt)
|
||||
|
||||
@@ -138,8 +147,11 @@ async def _get_chunk_by_index_from_qdrant(
|
||||
|
||||
except Exception as e:
|
||||
logger.debug(
|
||||
f"Could not retrieve adjacent chunk {chunk_index} for "
|
||||
f"{doc_type} {doc_id}: {e}"
|
||||
"Could not retrieve adjacent chunk %s for %s %s: %s",
|
||||
chunk_index,
|
||||
doc_type,
|
||||
doc_id,
|
||||
e,
|
||||
)
|
||||
return None
|
||||
|
||||
@@ -181,19 +193,21 @@ async def _get_deck_metadata_from_qdrant(
|
||||
stack_id = point.payload.get("stack_id")
|
||||
if board_id is not None and stack_id is not None:
|
||||
logger.debug(
|
||||
f"Retrieved deck metadata for card {card_id}: "
|
||||
f"board_id={board_id}, stack_id={stack_id}"
|
||||
"Retrieved deck metadata for card %s: board_id=%s, stack_id=%s",
|
||||
card_id,
|
||||
board_id,
|
||||
stack_id,
|
||||
)
|
||||
return {"board_id": int(board_id), "stack_id": int(stack_id)}
|
||||
|
||||
logger.debug(
|
||||
f"Could not find deck metadata in Qdrant for card {card_id} "
|
||||
f"(might be legacy data without board_id/stack_id)"
|
||||
"Could not find deck metadata in Qdrant for card %s (might be legacy data without board_id/stack_id)",
|
||||
card_id,
|
||||
)
|
||||
return None
|
||||
|
||||
except Exception as e:
|
||||
logger.debug(f"Error querying Qdrant for deck metadata: {e}")
|
||||
logger.debug("Error querying Qdrant for deck metadata: %s", e)
|
||||
return None
|
||||
|
||||
|
||||
@@ -389,8 +403,9 @@ async def get_chunk_with_context(
|
||||
|
||||
if chunk_text:
|
||||
logger.info(
|
||||
f"Retrieved chunk from Qdrant cache for {doc_type} {doc_id} "
|
||||
f"(avoids document re-fetch/re-parse)"
|
||||
"Retrieved chunk from Qdrant cache for %s %s (avoids document re-fetch/re-parse)",
|
||||
doc_type,
|
||||
doc_id,
|
||||
)
|
||||
|
||||
# Fetch adjacent chunks for context expansion
|
||||
@@ -495,24 +510,30 @@ async def get_chunk_with_context(
|
||||
return None
|
||||
|
||||
logger.info(
|
||||
f"Falling back to document fetch for {doc_type} {doc_id} "
|
||||
f"(Qdrant cache miss, possibly legacy data)"
|
||||
"Falling back to document fetch for %s %s (Qdrant cache miss, possibly legacy data)",
|
||||
doc_type,
|
||||
doc_id,
|
||||
)
|
||||
|
||||
# Fetch full document text (notes, deck cards, news items, etc.)
|
||||
full_text = await _fetch_document_text(nc_client, doc_id, doc_type, user_id)
|
||||
if full_text is None:
|
||||
logger.warning(
|
||||
f"Could not fetch document text for {doc_type} {doc_id}, "
|
||||
"skipping context expansion"
|
||||
"Could not fetch document text for %s %s, skipping context expansion",
|
||||
doc_type,
|
||||
doc_id,
|
||||
)
|
||||
return None
|
||||
|
||||
# Validate offsets
|
||||
if chunk_start < 0 or chunk_end > len(full_text) or chunk_start >= chunk_end:
|
||||
logger.warning(
|
||||
f"Invalid chunk offsets for {doc_type} {doc_id}: "
|
||||
f"start={chunk_start}, end={chunk_end}, doc_len={len(full_text)}"
|
||||
"Invalid chunk offsets for %s %s: start=%s, end=%s, doc_len=%s",
|
||||
doc_type,
|
||||
doc_id,
|
||||
chunk_start,
|
||||
chunk_end,
|
||||
len(full_text),
|
||||
)
|
||||
return None
|
||||
|
||||
@@ -650,13 +671,18 @@ async def _fetch_document_text(
|
||||
board_id=board_id, stack_id=stack_id, card_id=int(doc_id)
|
||||
)
|
||||
logger.debug(
|
||||
f"Retrieved deck card {doc_id} using metadata "
|
||||
f"(board_id={board_id}, stack_id={stack_id})"
|
||||
"Retrieved deck card %s using metadata (board_id=%s, stack_id=%s)",
|
||||
doc_id,
|
||||
board_id,
|
||||
stack_id,
|
||||
)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Failed to fetch card with metadata (board_id={board_id}, "
|
||||
f"stack_id={stack_id}, card_id={doc_id}): {e}, falling back to iteration"
|
||||
"Failed to fetch card with metadata (board_id=%s, stack_id=%s, card_id=%s): %s, falling back to iteration",
|
||||
board_id,
|
||||
stack_id,
|
||||
doc_id,
|
||||
e,
|
||||
)
|
||||
|
||||
# Fallback: Iterate through all boards/stacks (for legacy data or if fast path failed)
|
||||
@@ -671,7 +697,9 @@ async def _fetch_document_text(
|
||||
# Skip deleted boards (soft delete: deletedAt > 0)
|
||||
if board.deletedAt > 0:
|
||||
logger.debug(
|
||||
f"Skipping deleted board {board.id} while searching for card {doc_id}"
|
||||
"Skipping deleted board %s while searching for card %s",
|
||||
board.id,
|
||||
doc_id,
|
||||
)
|
||||
continue
|
||||
|
||||
@@ -686,13 +714,15 @@ async def _fetch_document_text(
|
||||
card = c
|
||||
card_found = True
|
||||
logger.debug(
|
||||
f"Found deck card {doc_id} in board {board.id}, "
|
||||
f"stack {stack.id} (fallback iteration)"
|
||||
"Found deck card %s in board %s, stack %s (fallback iteration)",
|
||||
doc_id,
|
||||
board.id,
|
||||
stack.id,
|
||||
)
|
||||
break
|
||||
|
||||
if not card_found:
|
||||
logger.warning(f"Deck card {doc_id} not found in any board/stack")
|
||||
logger.warning("Deck card %s not found in any board/stack", doc_id)
|
||||
return None
|
||||
|
||||
# Type narrowing: card is set if we reach here
|
||||
@@ -705,10 +735,12 @@ async def _fetch_document_text(
|
||||
content_parts.append(card.description)
|
||||
return "\n\n".join(content_parts)
|
||||
else:
|
||||
logger.warning(f"Unsupported doc_type for context expansion: {doc_type}")
|
||||
logger.warning("Unsupported doc_type for context expansion: %s", doc_type)
|
||||
return None
|
||||
except Exception as e:
|
||||
logger.error(f"Error fetching document {doc_type} {doc_id}: {e}", exc_info=True)
|
||||
logger.error(
|
||||
"Error fetching document %s %s: %s", doc_type, doc_id, e, exc_info=True
|
||||
)
|
||||
return None
|
||||
|
||||
|
||||
|
||||
@@ -118,7 +118,7 @@ class PDFHighlighter:
|
||||
try:
|
||||
shutil.rmtree(temp_dir)
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to clean up temp directory {temp_dir}: {e}")
|
||||
logger.warning("Failed to clean up temp directory %s: %s", temp_dir, e)
|
||||
|
||||
return full_text, page_boundaries
|
||||
|
||||
@@ -202,7 +202,7 @@ class PDFHighlighter:
|
||||
try:
|
||||
page_words = page.get_text("words")
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to extract words from page: {e}")
|
||||
logger.error("Failed to extract words from page: %s", e)
|
||||
return 0
|
||||
|
||||
if not page_words:
|
||||
@@ -225,8 +225,12 @@ class PDFHighlighter:
|
||||
)
|
||||
]
|
||||
logger.debug(
|
||||
f"Filtered to {len(page_words)} words in region "
|
||||
f"({rx0:.0f}, {ry0:.0f}, {rx1:.0f}, {ry1:.0f})"
|
||||
"Filtered to %s words in region (%s, %s, %s, %s)",
|
||||
len(page_words),
|
||||
format(rx0, ".0f"),
|
||||
format(ry0, ".0f"),
|
||||
format(rx1, ".0f"),
|
||||
format(ry1, ".0f"),
|
||||
)
|
||||
|
||||
if not page_words:
|
||||
@@ -286,17 +290,19 @@ class PDFHighlighter:
|
||||
if len(current_matches) >= len(chunk_words) * 0.5:
|
||||
matches = current_matches
|
||||
logger.debug(
|
||||
f"Found match at position {start_pos}: "
|
||||
f"{len(matches)}/{len(chunk_words)} words"
|
||||
"Found match at position %s: %s/%s words",
|
||||
start_pos,
|
||||
len(matches),
|
||||
len(chunk_words),
|
||||
)
|
||||
break # Take FIRST match, not best/longest
|
||||
|
||||
if not matches:
|
||||
logger.debug(f"No word matches found (chunk has {len(chunk_words)} words)")
|
||||
logger.debug("No word matches found (chunk has %s words)", len(chunk_words))
|
||||
return 0
|
||||
|
||||
logger.debug(
|
||||
f"Matched {len(matches)} words out of {len(chunk_words)} chunk words"
|
||||
"Matched %s words out of %s chunk words", len(matches), len(chunk_words)
|
||||
)
|
||||
|
||||
# Build rectangles from matched words
|
||||
@@ -324,8 +330,9 @@ class PDFHighlighter:
|
||||
# A chunk should be mostly contiguous text
|
||||
if large_gaps > len(matches) * 0.3: # More than 30% have gaps
|
||||
logger.debug(
|
||||
f"Rejecting scattered matches: {large_gaps} large gaps "
|
||||
f"out of {len(matches)} matches"
|
||||
"Rejecting scattered matches: %s large gaps out of %s matches",
|
||||
large_gaps,
|
||||
len(matches),
|
||||
)
|
||||
return 0
|
||||
|
||||
@@ -512,12 +519,12 @@ class PDFHighlighter:
|
||||
rects = page.search_for(phrase.strip())
|
||||
if rects:
|
||||
anchor_rect = rects[0] # Use first match
|
||||
logger.debug(f"Found chunk anchor using phrase: '{phrase[:30]}...'")
|
||||
logger.debug("Found chunk anchor using phrase: '%s...'", phrase[:30])
|
||||
break
|
||||
|
||||
if not anchor_rect:
|
||||
page_num = page.number + 1 if page.number is not None else "unknown"
|
||||
logger.warning(f"Could not find chunk text on page {page_num}")
|
||||
logger.warning("Could not find chunk text on page %s", page_num)
|
||||
return 0
|
||||
|
||||
# Calculate chunk height based on character count
|
||||
@@ -558,8 +565,10 @@ class PDFHighlighter:
|
||||
fill_shape.commit()
|
||||
|
||||
logger.debug(
|
||||
f"Added bounding box at y={chunk_rect.y0:.0f}-{chunk_rect.y1:.0f} "
|
||||
f"(estimated {estimated_lines:.1f} lines)"
|
||||
"Added bounding box at y=%s-%s (estimated %s lines)",
|
||||
format(chunk_rect.y0, ".0f"),
|
||||
format(chunk_rect.y1, ".0f"),
|
||||
format(estimated_lines, ".1f"),
|
||||
)
|
||||
|
||||
return 1
|
||||
@@ -626,7 +635,9 @@ class PDFHighlighter:
|
||||
# Log if page differs from stored metadata
|
||||
if stored_page_number and stored_page_number != page_num:
|
||||
logger.info(
|
||||
f"Chunk primarily on page {page_num}, metadata says {stored_page_number}"
|
||||
"Chunk primarily on page %s, metadata says %s",
|
||||
page_num,
|
||||
stored_page_number,
|
||||
)
|
||||
|
||||
# Extract page text
|
||||
@@ -644,8 +655,12 @@ class PDFHighlighter:
|
||||
page_text_length = page_end - page_start
|
||||
|
||||
logger.debug(
|
||||
f"Extracted {len(chunk_text)} chars on page {page_num} "
|
||||
f"(offsets {page_relative_start}-{page_relative_end} of {page_text_length})"
|
||||
"Extracted %s chars on page %s (offsets %s-%s of %s)",
|
||||
len(chunk_text),
|
||||
page_num,
|
||||
page_relative_start,
|
||||
page_relative_end,
|
||||
page_text_length,
|
||||
)
|
||||
|
||||
# Get page and add highlights
|
||||
@@ -672,13 +687,15 @@ class PDFHighlighter:
|
||||
doc.close()
|
||||
|
||||
logger.info(
|
||||
f"Generated {len(png_bytes):,} byte image with {highlight_count} highlights"
|
||||
"Generated %s byte image with %s highlights",
|
||||
format(len(png_bytes), ","),
|
||||
highlight_count,
|
||||
)
|
||||
|
||||
return (png_bytes, page_num, highlight_count)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error highlighting chunk: {e}", exc_info=True)
|
||||
logger.error("Error highlighting chunk: %s", e, exc_info=True)
|
||||
return None
|
||||
|
||||
finally:
|
||||
@@ -688,7 +705,9 @@ class PDFHighlighter:
|
||||
shutil.rmtree(temp_pdf_path.parent)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Failed to delete temp directory {temp_pdf_path.parent}: {e}"
|
||||
"Failed to delete temp directory %s: %s",
|
||||
temp_pdf_path.parent,
|
||||
e,
|
||||
)
|
||||
|
||||
@staticmethod
|
||||
@@ -791,11 +810,11 @@ class PDFHighlighter:
|
||||
)
|
||||
results[chunk_index] = ([normalized], page_num)
|
||||
|
||||
logger.info(f"Computed bboxes for {len(results)}/{len(chunks)} chunks")
|
||||
logger.info("Computed bboxes for %s/%s chunks", len(results), len(chunks))
|
||||
return results
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error computing chunk bboxes: {e}", exc_info=True)
|
||||
logger.error("Error computing chunk bboxes: %s", e, exc_info=True)
|
||||
return results
|
||||
|
||||
finally:
|
||||
@@ -805,7 +824,7 @@ class PDFHighlighter:
|
||||
try:
|
||||
shutil.rmtree(temp_pdf_path.parent)
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to clean up temp dir: {e}")
|
||||
logger.warning("Failed to clean up temp dir: %s", e)
|
||||
|
||||
@staticmethod
|
||||
def highlight_chunks_batch(
|
||||
@@ -853,8 +872,9 @@ class PDFHighlighter:
|
||||
doc = pymupdf.open(temp_pdf_path)
|
||||
|
||||
logger.debug(
|
||||
f"Batch highlighting: {len(chunks)} chunks, "
|
||||
f"{len(page_boundaries)} pages"
|
||||
"Batch highlighting: %s chunks, %s pages",
|
||||
len(chunks),
|
||||
len(page_boundaries),
|
||||
)
|
||||
|
||||
# Group chunks by their target page for efficient rendering
|
||||
@@ -873,7 +893,7 @@ class PDFHighlighter:
|
||||
)
|
||||
|
||||
if not chunk_page_info:
|
||||
logger.warning(f"Chunk {chunk_index}: not found on any page")
|
||||
logger.warning("Chunk %s: not found on any page", chunk_index)
|
||||
continue
|
||||
|
||||
page_num = chunk_page_info["page_num"]
|
||||
@@ -881,8 +901,10 @@ class PDFHighlighter:
|
||||
# Log if page differs from stored metadata
|
||||
if stored_page_num and stored_page_num != page_num:
|
||||
logger.debug(
|
||||
f"Chunk {chunk_index}: found on page {page_num}, "
|
||||
f"metadata says {stored_page_num}"
|
||||
"Chunk %s: found on page %s, metadata says %s",
|
||||
chunk_index,
|
||||
page_num,
|
||||
stored_page_num,
|
||||
)
|
||||
|
||||
# Extract page-relative portion of chunk text
|
||||
@@ -905,7 +927,7 @@ class PDFHighlighter:
|
||||
)
|
||||
|
||||
logger.debug(
|
||||
f"Chunks distributed across {len(chunks_by_page)} unique pages"
|
||||
"Chunks distributed across %s unique pages", len(chunks_by_page)
|
||||
)
|
||||
|
||||
# OPTIMIZATION: Render each page ONCE, then draw highlights using PIL
|
||||
@@ -929,7 +951,9 @@ class PDFHighlighter:
|
||||
page_rect = page.rect
|
||||
|
||||
logger.debug(
|
||||
f"Page {page_num}: rendered once, processing {len(page_chunks)} chunks"
|
||||
"Page %s: rendered once, processing %s chunks",
|
||||
page_num,
|
||||
len(page_chunks),
|
||||
)
|
||||
|
||||
for (
|
||||
@@ -949,7 +973,7 @@ class PDFHighlighter:
|
||||
)
|
||||
|
||||
if bbox is None:
|
||||
logger.warning(f"Chunk {chunk_index}: could not find bbox")
|
||||
logger.warning("Chunk %s: could not find bbox", chunk_index)
|
||||
continue
|
||||
|
||||
# Copy base image for this chunk
|
||||
@@ -985,24 +1009,27 @@ class PDFHighlighter:
|
||||
results[chunk_index] = (png_bytes, page_num, 1)
|
||||
|
||||
logger.debug(
|
||||
f"Chunk {chunk_index}: {len(png_bytes):,} bytes, "
|
||||
f"page {page_num}, bbox {pil_bbox}"
|
||||
"Chunk %s: %s bytes, page %s, bbox %s",
|
||||
chunk_index,
|
||||
format(len(png_bytes), ","),
|
||||
page_num,
|
||||
pil_bbox,
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Chunk {chunk_index}: error - {e}")
|
||||
logger.error("Chunk %s: error - %s", chunk_index, e)
|
||||
continue
|
||||
|
||||
doc.close()
|
||||
|
||||
logger.info(
|
||||
f"Batch highlighted {len(results)}/{len(chunks)} chunks successfully"
|
||||
"Batch highlighted %s/%s chunks successfully", len(results), len(chunks)
|
||||
)
|
||||
|
||||
return results
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Error in batch highlighting: {e}", exc_info=True)
|
||||
logger.error("Error in batch highlighting: %s", e, exc_info=True)
|
||||
return results
|
||||
|
||||
finally:
|
||||
@@ -1011,4 +1038,4 @@ class PDFHighlighter:
|
||||
try:
|
||||
shutil.rmtree(temp_pdf_path.parent)
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to clean up temp dir: {e}")
|
||||
logger.warning("Failed to clean up temp dir: %s", e)
|
||||
|
||||
@@ -77,8 +77,12 @@ class SemanticSearchAlgorithm(SearchAlgorithm):
|
||||
score_threshold = kwargs.get("score_threshold", self.score_threshold)
|
||||
|
||||
logger.info(
|
||||
f"Semantic search: query='{query}', user={user_id}, "
|
||||
f"limit={limit}, score_threshold={score_threshold}, doc_type={doc_type}"
|
||||
"Semantic search: query='%s', user=%s, limit=%s, score_threshold=%s, doc_type=%s",
|
||||
query,
|
||||
user_id,
|
||||
limit,
|
||||
score_threshold,
|
||||
doc_type,
|
||||
)
|
||||
|
||||
# Generate embedding for query
|
||||
@@ -87,7 +91,7 @@ class SemanticSearchAlgorithm(SearchAlgorithm):
|
||||
# Store for reuse by callers (e.g., viz_routes PCA visualization)
|
||||
self.query_embedding = query_embedding
|
||||
logger.debug(
|
||||
f"Generated embedding for query (dimension={len(query_embedding)})"
|
||||
"Generated embedding for query (dimension=%s)", len(query_embedding)
|
||||
)
|
||||
|
||||
# Build Qdrant filter
|
||||
@@ -127,14 +131,14 @@ class SemanticSearchAlgorithm(SearchAlgorithm):
|
||||
raise
|
||||
|
||||
logger.info(
|
||||
f"Qdrant returned {len(search_response.points)} results "
|
||||
f"(before deduplication)"
|
||||
"Qdrant returned %s results (before deduplication)",
|
||||
len(search_response.points),
|
||||
)
|
||||
|
||||
if search_response.points:
|
||||
# Log top 3 scores to help with threshold tuning
|
||||
top_scores = [p.score for p in search_response.points[:3]]
|
||||
logger.debug(f"Top 3 similarity scores: {top_scores}")
|
||||
logger.debug("Top 3 similarity scores: %s", top_scores)
|
||||
|
||||
# Deduplicate by (doc_id, doc_type, chunk_start, chunk_end)
|
||||
# This allows multiple chunks from same doc, but removes duplicate chunks
|
||||
@@ -155,12 +159,12 @@ class SemanticSearchAlgorithm(SearchAlgorithm):
|
||||
if len(results) >= limit:
|
||||
break
|
||||
|
||||
logger.info(f"Returning {len(results)} unverified results after deduplication")
|
||||
logger.info("Returning %s unverified results after deduplication", len(results))
|
||||
if results:
|
||||
result_details = [
|
||||
f"{r.doc_type}_{r.id} (score={r.score:.3f}, title='{r.title}')"
|
||||
for r in results[:5] # Show top 5
|
||||
]
|
||||
logger.debug(f"Top results: {', '.join(result_details)}")
|
||||
logger.debug("Top results: %s", ", ".join(result_details))
|
||||
|
||||
return results
|
||||
|
||||
@@ -116,7 +116,7 @@ def register_auth_tools(mcp: FastMCP) -> None:
|
||||
)
|
||||
init_response = await flow_client.initiate()
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to initiate Login Flow v2: {e}")
|
||||
logger.error("Failed to initiate Login Flow v2: %s", e)
|
||||
return ProvisionAccessResponse(
|
||||
status="error",
|
||||
message=f"Failed to start login flow: {e}",
|
||||
@@ -227,7 +227,7 @@ def register_auth_tools(mcp: FastMCP) -> None:
|
||||
try:
|
||||
session = await storage.get_login_flow_session(user_id)
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to check login flow session for {user_id}: {e}")
|
||||
logger.error("Failed to check login flow session for %s: %s", user_id, e)
|
||||
return ProvisionStatusResponse(
|
||||
status="error",
|
||||
message=f"Failed to check login flow session: {e}",
|
||||
@@ -264,7 +264,7 @@ def register_auth_tools(mcp: FastMCP) -> None:
|
||||
poll_token=session["poll_token"],
|
||||
)
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to poll Login Flow v2: {e}")
|
||||
logger.error("Failed to poll Login Flow v2: %s", e)
|
||||
return ProvisionStatusResponse(
|
||||
status="error",
|
||||
message=f"Failed to check login status: {e}",
|
||||
@@ -434,7 +434,7 @@ def register_auth_tools(mcp: FastMCP) -> None:
|
||||
)
|
||||
init_response = await flow_client.initiate()
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to initiate Login Flow v2 for scope update: {e}")
|
||||
logger.error("Failed to initiate Login Flow v2 for scope update: %s", e)
|
||||
return UpdateScopesResponse(
|
||||
status="error",
|
||||
message=f"Failed to start re-provisioning flow: {e}",
|
||||
|
||||
@@ -215,7 +215,7 @@ def configure_calendar_tools(mcp: FastMCP):
|
||||
try:
|
||||
start_datetime = dt.datetime.fromisoformat(start_date)
|
||||
except ValueError:
|
||||
logger.warning(f"Invalid start_date format: {start_date}")
|
||||
logger.warning("Invalid start_date format: %s", start_date)
|
||||
|
||||
if end_date:
|
||||
try:
|
||||
@@ -228,7 +228,7 @@ def configure_calendar_tools(mcp: FastMCP):
|
||||
try:
|
||||
end_datetime = dt.datetime.fromisoformat(end_date)
|
||||
except ValueError:
|
||||
logger.warning(f"Invalid end_date format: {end_date}")
|
||||
logger.warning("Invalid end_date format: %s", end_date)
|
||||
|
||||
# Build filters dictionary
|
||||
filters = {}
|
||||
@@ -519,7 +519,7 @@ def configure_calendar_tools(mcp: FastMCP):
|
||||
all_events.extend(cal_events)
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Error getting events from calendar {calendar['name']}: {e}"
|
||||
"Error getting events from calendar %s: %s", calendar["name"], e
|
||||
)
|
||||
continue
|
||||
|
||||
@@ -593,7 +593,7 @@ def configure_calendar_tools(mcp: FastMCP):
|
||||
try:
|
||||
start_datetime = dt.datetime.strptime(date_range_start, "%Y-%m-%d")
|
||||
except ValueError:
|
||||
logger.warning(f"Invalid date_range_start format: {date_range_start}")
|
||||
logger.warning("Invalid date_range_start format: %s", date_range_start)
|
||||
|
||||
if date_range_end:
|
||||
try:
|
||||
@@ -601,7 +601,7 @@ def configure_calendar_tools(mcp: FastMCP):
|
||||
hour=23, minute=59, second=59
|
||||
)
|
||||
except ValueError:
|
||||
logger.warning(f"Invalid date_range_end format: {date_range_end}")
|
||||
logger.warning("Invalid date_range_end format: %s", date_range_end)
|
||||
|
||||
# Build constraints
|
||||
constraints = {
|
||||
@@ -686,7 +686,7 @@ def configure_calendar_tools(mcp: FastMCP):
|
||||
try:
|
||||
start_datetime = dt.datetime.strptime(start_date, "%Y-%m-%d")
|
||||
except ValueError:
|
||||
logger.warning(f"Invalid start_date format: {start_date}")
|
||||
logger.warning("Invalid start_date format: %s", start_date)
|
||||
|
||||
if end_date:
|
||||
try:
|
||||
@@ -694,7 +694,7 @@ def configure_calendar_tools(mcp: FastMCP):
|
||||
hour=23, minute=59, second=59
|
||||
)
|
||||
except ValueError:
|
||||
logger.warning(f"Invalid end_date format: {end_date}")
|
||||
logger.warning("Invalid end_date format: %s", end_date)
|
||||
|
||||
# Build filter criteria
|
||||
filter_criteria = {}
|
||||
|
||||
@@ -266,7 +266,7 @@ async def _provision_nextcloud_access(ctx: Context, user_id: str) -> Provisionin
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to initiate provisioning: {e}")
|
||||
logger.error("Failed to initiate provisioning: %s", e)
|
||||
return ProvisioningResult(
|
||||
success=False,
|
||||
message=f"Failed to initiate provisioning: {str(e)}",
|
||||
@@ -337,7 +337,7 @@ async def _revoke_nextcloud_access(ctx: Context, user_id: str) -> RevocationResu
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to revoke access: {e}")
|
||||
logger.error("Failed to revoke access: %s", e)
|
||||
return RevocationResult(
|
||||
success=False,
|
||||
message=f"Failed to revoke access: {str(e)}",
|
||||
@@ -542,7 +542,7 @@ async def _check_logged_in(ctx: Context, user_id: str) -> str:
|
||||
return "Login cancelled by user."
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to check login status: {e}")
|
||||
logger.error("Failed to check login status: %s", e)
|
||||
return f"Error checking login status: {str(e)}"
|
||||
|
||||
|
||||
|
||||
@@ -72,7 +72,7 @@ async def parse_document(
|
||||
|
||||
registry = get_registry()
|
||||
|
||||
logger.debug(f"Parsing document of type '{content_type}'")
|
||||
logger.debug("Parsing document of type '%s'", content_type)
|
||||
|
||||
try:
|
||||
# Process using registry (auto-selects processor based on MIME type)
|
||||
@@ -83,12 +83,14 @@ async def parse_document(
|
||||
progress_callback=progress_callback,
|
||||
)
|
||||
|
||||
logger.info(f"Successfully parsed document with '{result.processor}' processor")
|
||||
logger.info(
|
||||
"Successfully parsed document with '%s' processor", result.processor
|
||||
)
|
||||
|
||||
return result.text, result.metadata
|
||||
|
||||
except ProcessorError as e:
|
||||
logger.error(f"Document processing failed: {e}")
|
||||
logger.error("Document processing failed: %s", e)
|
||||
# Fallback to base64 with error metadata
|
||||
parsed_text = f"Document could not be parsed. Base64 content: {base64.b64encode(content).decode('ascii')[:200]}..."
|
||||
metadata = {
|
||||
|
||||
@@ -91,7 +91,9 @@ class DocumentChunker:
|
||||
]
|
||||
|
||||
logger.debug(
|
||||
f"Chunked document into {len(chunks)} chunks "
|
||||
f"(chunk_size={self.chunk_size}, overlap={self.overlap})"
|
||||
"Chunked document into %s chunks (chunk_size=%s, overlap=%s)",
|
||||
len(chunks),
|
||||
self.chunk_size,
|
||||
self.overlap,
|
||||
)
|
||||
return chunks
|
||||
|
||||
@@ -42,7 +42,7 @@ def html_to_markdown(html_content: str | None) -> str:
|
||||
)
|
||||
return markdown.strip()
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to convert HTML to Markdown: {e}")
|
||||
logger.warning("Failed to convert HTML to Markdown: %s", e)
|
||||
# Fallback: strip all HTML tags as a last resort
|
||||
|
||||
text = re.sub(r"<[^>]+>", " ", html_content)
|
||||
|
||||
@@ -104,7 +104,7 @@ async def get_user_client_basic_auth(
|
||||
f"User must configure background sync in Astrolabe personal settings."
|
||||
)
|
||||
|
||||
logger.info(f"Using app password for background sync: {user_id}")
|
||||
logger.info("Using app password for background sync: %s", user_id)
|
||||
return NextcloudClient(
|
||||
base_url=nextcloud_host,
|
||||
username=user_id,
|
||||
@@ -141,7 +141,7 @@ async def get_user_client_oauth(
|
||||
f"User must complete the OAuth provisioning flow."
|
||||
)
|
||||
|
||||
logger.info(f"Using OAuth refresh token for background sync: {user_id}")
|
||||
logger.info("Using OAuth refresh token for background sync: %s", user_id)
|
||||
return NextcloudClient.from_token(
|
||||
base_url=nextcloud_host,
|
||||
token=token,
|
||||
@@ -208,7 +208,7 @@ async def user_scanner_task(
|
||||
task_status: Status object for signaling task readiness
|
||||
"""
|
||||
mode_label = "BasicAuth" if use_basic_auth else "OAuth"
|
||||
logger.info(f"[{mode_label}] Scanner started for user: {user_id}")
|
||||
logger.info("[%s] Scanner started for user: %s", mode_label, user_id)
|
||||
settings = get_settings()
|
||||
max_consecutive_errors = 5
|
||||
|
||||
@@ -221,12 +221,14 @@ async def user_scanner_task(
|
||||
)
|
||||
try:
|
||||
await nc_client.capabilities() # Lightweight OCS call to validate creds
|
||||
logger.info(f"[{mode_label}] Credentials validated for {user_id}")
|
||||
logger.info("[%s] Credentials validated for %s", mode_label, user_id)
|
||||
except HTTPStatusError as e:
|
||||
if e.response.status_code in (401, 403):
|
||||
logger.warning(
|
||||
f"[{mode_label}] Credential validation failed for {user_id} "
|
||||
f"(HTTP {e.response.status_code}), not starting scan loop"
|
||||
"[%s] Credential validation failed for %s (HTTP %s), not starting scan loop",
|
||||
mode_label,
|
||||
user_id,
|
||||
e.response.status_code,
|
||||
)
|
||||
return
|
||||
raise
|
||||
@@ -234,13 +236,15 @@ async def user_scanner_task(
|
||||
await nc_client.close()
|
||||
except NotProvisionedError:
|
||||
logger.warning(
|
||||
f"[{mode_label}] User {user_id} not provisioned, not starting scan loop"
|
||||
"[%s] User %s not provisioned, not starting scan loop", mode_label, user_id
|
||||
)
|
||||
return
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"[{mode_label}] Pre-validation failed for {user_id}: {e}. "
|
||||
f"Proceeding to scan loop (has its own error handling)."
|
||||
"[%s] Pre-validation failed for %s: %s. Proceeding to scan loop (has its own error handling).",
|
||||
mode_label,
|
||||
user_id,
|
||||
e,
|
||||
)
|
||||
|
||||
consecutive_errors = 0
|
||||
@@ -264,7 +268,9 @@ async def user_scanner_task(
|
||||
|
||||
except NotProvisionedError:
|
||||
logger.warning(
|
||||
f"[{mode_label}] User {user_id} no longer provisioned, stopping scanner"
|
||||
"[%s] User %s no longer provisioned, stopping scanner",
|
||||
mode_label,
|
||||
user_id,
|
||||
)
|
||||
break
|
||||
|
||||
@@ -272,16 +278,19 @@ async def user_scanner_task(
|
||||
status_code = e.response.status_code
|
||||
if status_code in (401, 403):
|
||||
logger.warning(
|
||||
f"[{mode_label}] Scanner auth failed for {user_id} "
|
||||
f"(HTTP {status_code}), stopping scanner. "
|
||||
f"User may need to re-provision credentials."
|
||||
"[%s] Scanner auth failed for %s (HTTP %s), stopping scanner. User may need to re-provision credentials.",
|
||||
mode_label,
|
||||
user_id,
|
||||
status_code,
|
||||
)
|
||||
break
|
||||
elif status_code == 429:
|
||||
retry_after = min(int(e.response.headers.get("Retry-After", "60")), 300)
|
||||
logger.warning(
|
||||
f"[{mode_label}] Scanner rate-limited for {user_id}, "
|
||||
f"backing off {retry_after}s"
|
||||
"[%s] Scanner rate-limited for %s, backing off %ss",
|
||||
mode_label,
|
||||
user_id,
|
||||
retry_after,
|
||||
)
|
||||
try:
|
||||
with anyio.move_on_after(retry_after):
|
||||
@@ -294,16 +303,24 @@ async def user_scanner_task(
|
||||
else:
|
||||
consecutive_errors += 1
|
||||
logger.error(
|
||||
f"[{mode_label}] Scanner HTTP error for {user_id}: {e} "
|
||||
f"({consecutive_errors}/{max_consecutive_errors})",
|
||||
"[%s] Scanner HTTP error for %s: %s (%s/%s)",
|
||||
mode_label,
|
||||
user_id,
|
||||
e,
|
||||
consecutive_errors,
|
||||
max_consecutive_errors,
|
||||
exc_info=True,
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
consecutive_errors += 1
|
||||
logger.error(
|
||||
f"[{mode_label}] Scanner error for {user_id}: {e} "
|
||||
f"({consecutive_errors}/{max_consecutive_errors})",
|
||||
"[%s] Scanner error for %s: %s (%s/%s)",
|
||||
mode_label,
|
||||
user_id,
|
||||
e,
|
||||
consecutive_errors,
|
||||
max_consecutive_errors,
|
||||
exc_info=True,
|
||||
)
|
||||
|
||||
@@ -313,8 +330,10 @@ async def user_scanner_task(
|
||||
|
||||
if consecutive_errors >= max_consecutive_errors:
|
||||
logger.error(
|
||||
f"[{mode_label}] Scanner for {user_id} hit {max_consecutive_errors} "
|
||||
f"consecutive errors, stopping scanner"
|
||||
"[%s] Scanner for %s hit %s consecutive errors, stopping scanner",
|
||||
mode_label,
|
||||
user_id,
|
||||
max_consecutive_errors,
|
||||
)
|
||||
break
|
||||
|
||||
@@ -325,7 +344,7 @@ async def user_scanner_task(
|
||||
except anyio.get_cancelled_exc_class():
|
||||
break
|
||||
|
||||
logger.info(f"[{mode_label}] Scanner stopped for user: {user_id}")
|
||||
logger.info("[%s] Scanner stopped for user: %s", mode_label, user_id)
|
||||
|
||||
|
||||
async def multi_user_processor_task(
|
||||
@@ -352,7 +371,7 @@ async def multi_user_processor_task(
|
||||
task_status: Status object for signaling task readiness
|
||||
"""
|
||||
mode_label = "BasicAuth" if use_basic_auth else "OAuth"
|
||||
logger.info(f"[{mode_label}] Processor {worker_id} started")
|
||||
logger.info("[%s] Processor %s started", mode_label, worker_id)
|
||||
task_status.started()
|
||||
|
||||
while not shutdown_event.is_set():
|
||||
@@ -378,34 +397,47 @@ async def multi_user_processor_task(
|
||||
continue
|
||||
|
||||
except anyio.EndOfStream:
|
||||
logger.info(f"[{mode_label}] Processor {worker_id}: Stream closed, exiting")
|
||||
logger.info(
|
||||
"[%s] Processor %s: Stream closed, exiting", mode_label, worker_id
|
||||
)
|
||||
break
|
||||
|
||||
except NotProvisionedError:
|
||||
if doc_task:
|
||||
logger.warning(
|
||||
f"[{mode_label}] User {doc_task.user_id} not provisioned, "
|
||||
f"skipping {doc_task.doc_type}_{doc_task.doc_id}"
|
||||
"[%s] User %s not provisioned, skipping %s_%s",
|
||||
mode_label,
|
||||
doc_task.user_id,
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
)
|
||||
continue
|
||||
|
||||
except Exception as e:
|
||||
if doc_task:
|
||||
logger.error(
|
||||
f"[{mode_label}] Processor {worker_id} error processing "
|
||||
f"{doc_task.doc_type}_{doc_task.doc_id}: {e}",
|
||||
"[%s] Processor %s error processing %s_%s: %s",
|
||||
mode_label,
|
||||
worker_id,
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
e,
|
||||
exc_info=True,
|
||||
)
|
||||
else:
|
||||
logger.error(
|
||||
f"[{mode_label}] Processor {worker_id} error: {e}", exc_info=True
|
||||
"[%s] Processor %s error: %s",
|
||||
mode_label,
|
||||
worker_id,
|
||||
e,
|
||||
exc_info=True,
|
||||
)
|
||||
|
||||
finally:
|
||||
if nc_client:
|
||||
await nc_client.close()
|
||||
|
||||
logger.info(f"[{mode_label}] Processor {worker_id} stopped")
|
||||
logger.info("[%s] Processor %s stopped", mode_label, worker_id)
|
||||
|
||||
|
||||
# Backward compatibility alias
|
||||
@@ -482,7 +514,7 @@ async def user_manager_task(
|
||||
mode_label = "BasicAuth" if use_basic_auth else "OAuth"
|
||||
|
||||
logger.info(
|
||||
f"[{mode_label}] User manager started (poll interval: {poll_interval}s)"
|
||||
"[%s] User manager started (poll interval: %ss)", mode_label, poll_interval
|
||||
)
|
||||
task_status.started()
|
||||
|
||||
@@ -503,7 +535,9 @@ async def user_manager_task(
|
||||
new_users = provisioned_users - active_users
|
||||
for user_id in new_users:
|
||||
logger.info(
|
||||
f"[{mode_label}] Starting scanner for newly provisioned user: {user_id}"
|
||||
"[%s] Starting scanner for newly provisioned user: %s",
|
||||
mode_label,
|
||||
user_id,
|
||||
)
|
||||
cancel_scope = anyio.CancelScope()
|
||||
user_states[user_id] = UserSyncState(
|
||||
@@ -529,7 +563,7 @@ async def user_manager_task(
|
||||
revoked_users = active_users - provisioned_users
|
||||
for user_id in revoked_users:
|
||||
logger.info(
|
||||
f"[{mode_label}] Stopping scanner for revoked user: {user_id}"
|
||||
"[%s] Stopping scanner for revoked user: %s", mode_label, user_id
|
||||
)
|
||||
state = user_states.get(user_id)
|
||||
if state:
|
||||
@@ -537,12 +571,16 @@ async def user_manager_task(
|
||||
# Note: state will be removed by _run_user_scanner_with_scope on exit
|
||||
|
||||
if new_users:
|
||||
logger.info(f"[{mode_label}] Started {len(new_users)} new scanner(s)")
|
||||
logger.info(
|
||||
"[%s] Started %s new scanner(s)", mode_label, len(new_users)
|
||||
)
|
||||
if revoked_users:
|
||||
logger.info(f"[{mode_label}] Stopped {len(revoked_users)} scanner(s)")
|
||||
logger.info(
|
||||
"[%s] Stopped %s scanner(s)", mode_label, len(revoked_users)
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"[{mode_label}] User manager error: {e}", exc_info=True)
|
||||
logger.error("[%s] User manager error: %s", mode_label, e, exc_info=True)
|
||||
|
||||
# Sleep until next poll
|
||||
try:
|
||||
@@ -553,9 +591,11 @@ async def user_manager_task(
|
||||
|
||||
# Cancel all remaining scanners on shutdown
|
||||
logger.info(
|
||||
f"[{mode_label}] User manager shutting down, cancelling {len(user_states)} scanner(s)"
|
||||
"[%s] User manager shutting down, cancelling %s scanner(s)",
|
||||
mode_label,
|
||||
len(user_states),
|
||||
)
|
||||
for state in list(user_states.values()):
|
||||
state.cancel_scope.cancel()
|
||||
|
||||
logger.info(f"[{mode_label}] User manager stopped")
|
||||
logger.info("[%s] User manager stopped", mode_label)
|
||||
|
||||
@@ -92,9 +92,11 @@ class PCA:
|
||||
self.explained_variance_ratio_ = np.zeros(self.n_components)
|
||||
|
||||
logger.debug(
|
||||
f"PCA fit: {n_samples} samples, {n_features} features → "
|
||||
f"{self.n_components} components, "
|
||||
f"explained variance: {self.explained_variance_ratio_}"
|
||||
"PCA fit: %s samples, %s features → %s components, explained variance: %s",
|
||||
n_samples,
|
||||
n_features,
|
||||
self.n_components,
|
||||
self.explained_variance_ratio_,
|
||||
)
|
||||
|
||||
return self
|
||||
|
||||
@@ -122,13 +122,19 @@ async def write_placeholder_point(
|
||||
)
|
||||
|
||||
logger.debug(
|
||||
f"Wrote placeholder for {doc_type}_{doc_id} (user={user_id}, "
|
||||
f"modified_at={modified_at})"
|
||||
"Wrote placeholder for %s_%s (user=%s, modified_at=%s)",
|
||||
doc_type,
|
||||
doc_id,
|
||||
user_id,
|
||||
modified_at,
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Failed to write placeholder for {doc_type}_{doc_id}: {e}",
|
||||
"Failed to write placeholder for %s_%s: %s",
|
||||
doc_type,
|
||||
doc_id,
|
||||
e,
|
||||
exc_info=True,
|
||||
)
|
||||
raise
|
||||
@@ -180,7 +186,9 @@ async def query_document_metadata(
|
||||
return None
|
||||
|
||||
except Exception as e:
|
||||
logger.warning(f"Error querying document metadata for {doc_type}_{doc_id}: {e}")
|
||||
logger.warning(
|
||||
"Error querying document metadata for %s_%s: %s", doc_type, doc_id, e
|
||||
)
|
||||
return None
|
||||
|
||||
|
||||
@@ -219,11 +227,16 @@ async def delete_placeholder_point(
|
||||
),
|
||||
)
|
||||
|
||||
logger.debug(f"Deleted placeholder for {doc_type}_{doc_id} (user={user_id})")
|
||||
logger.debug(
|
||||
"Deleted placeholder for %s_%s (user=%s)", doc_type, doc_id, user_id
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Failed to delete placeholder for {doc_type}_{doc_id}: {e}",
|
||||
"Failed to delete placeholder for %s_%s: %s",
|
||||
doc_type,
|
||||
doc_id,
|
||||
e,
|
||||
exc_info=True,
|
||||
)
|
||||
raise
|
||||
@@ -271,13 +284,16 @@ async def update_placeholder_status(
|
||||
)
|
||||
|
||||
logger.debug(
|
||||
f"Updated placeholder status for {doc_type}_{doc_id} to '{status}' "
|
||||
f"(user={user_id})"
|
||||
"Updated placeholder status for %s_%s to '%s' (user=%s)",
|
||||
doc_type,
|
||||
doc_id,
|
||||
status,
|
||||
user_id,
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Failed to update placeholder status for {doc_type}_{doc_id}: {e}"
|
||||
"Failed to update placeholder status for %s_%s: %s", doc_type, doc_id, e
|
||||
)
|
||||
# Don't raise - status updates are non-critical
|
||||
|
||||
|
||||
@@ -100,7 +100,7 @@ async def processor_task(
|
||||
user_id: User being processed
|
||||
task_status: Status object for signaling task readiness
|
||||
"""
|
||||
logger.info(f"Processor {worker_id} started")
|
||||
logger.info("Processor %s started", worker_id)
|
||||
|
||||
# Signal that the task has started and is ready
|
||||
task_status.started()
|
||||
@@ -130,18 +130,21 @@ async def processor_task(
|
||||
|
||||
except anyio.EndOfStream:
|
||||
# Scanner finished and closed stream, exit gracefully
|
||||
logger.info(f"Processor {worker_id}: Scanner finished, exiting")
|
||||
logger.info("Processor %s: Scanner finished, exiting", worker_id)
|
||||
break
|
||||
|
||||
except Exception as e:
|
||||
logger.error(
|
||||
f"Processor {worker_id} error processing "
|
||||
f"{doc_task.doc_type}_{doc_task.doc_id}: {e}",
|
||||
"Processor %s error processing %s_%s: %s",
|
||||
worker_id,
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
e,
|
||||
exc_info=True,
|
||||
)
|
||||
# Continue to next document (no task_done() needed with streams)
|
||||
|
||||
logger.info(f"Processor {worker_id} stopped")
|
||||
logger.info("Processor %s stopped", worker_id)
|
||||
|
||||
|
||||
async def process_document(doc_task: DocumentTask, nc_client: NextcloudClient):
|
||||
@@ -157,8 +160,11 @@ async def process_document(doc_task: DocumentTask, nc_client: NextcloudClient):
|
||||
start_time = time.time()
|
||||
|
||||
logger.debug(
|
||||
f"Processing {doc_task.doc_type}_{doc_task.doc_id} "
|
||||
f"for {doc_task.user_id} ({doc_task.operation})"
|
||||
"Processing %s_%s for %s (%s)",
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
doc_task.user_id,
|
||||
doc_task.operation,
|
||||
)
|
||||
|
||||
with trace_operation(
|
||||
@@ -197,7 +203,10 @@ async def process_document(doc_task: DocumentTask, nc_client: NextcloudClient):
|
||||
),
|
||||
)
|
||||
logger.info(
|
||||
f"Deleted {doc_task.doc_type}_{doc_task.doc_id} for {doc_task.user_id}"
|
||||
"Deleted %s_%s for %s",
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
doc_task.user_id,
|
||||
)
|
||||
|
||||
# Record successful deletion metrics
|
||||
@@ -223,15 +232,22 @@ async def process_document(doc_task: DocumentTask, nc_client: NextcloudClient):
|
||||
except (HTTPStatusError, Exception) as e:
|
||||
if attempt < max_retries - 1:
|
||||
logger.warning(
|
||||
f"Retry {attempt + 1}/{max_retries} for "
|
||||
f"{doc_task.doc_type}_{doc_task.doc_id}: {e}"
|
||||
"Retry %s/%s for %s_%s: %s",
|
||||
attempt + 1,
|
||||
max_retries,
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
e,
|
||||
)
|
||||
await anyio.sleep(retry_delay)
|
||||
retry_delay *= 2 # Exponential backoff
|
||||
else:
|
||||
logger.error(
|
||||
f"Failed to index {doc_task.doc_type}_{doc_task.doc_id} "
|
||||
f"after {max_retries} retries: {e}"
|
||||
"Failed to index %s_%s after %s retries: %s",
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
max_retries,
|
||||
e,
|
||||
)
|
||||
# Record failed processing metrics
|
||||
duration = time.time() - start_time
|
||||
@@ -348,7 +364,11 @@ async def _index_document(
|
||||
break
|
||||
except Exception as e:
|
||||
logger.warning(
|
||||
f"Failed to fetch card with metadata (board_id={board_id}, stack_id={stack_id}, card_id={doc_task.doc_id}): {e}, falling back to iteration"
|
||||
"Failed to fetch card with metadata (board_id=%s, stack_id=%s, card_id=%s): %s, falling back to iteration",
|
||||
board_id,
|
||||
stack_id,
|
||||
doc_task.doc_id,
|
||||
e,
|
||||
)
|
||||
|
||||
# Fallback: Iterate through all boards/stacks (for legacy data or if fast path failed)
|
||||
@@ -454,27 +474,32 @@ async def _index_document(
|
||||
if "page_boundaries" in file_metadata:
|
||||
page_boundaries = file_metadata["page_boundaries"]
|
||||
logger.info(
|
||||
f"Page boundaries for {file_path}: "
|
||||
f"{len(page_boundaries)} pages, text length: {len(content)}"
|
||||
"Page boundaries for %s: %s pages, text length: %s",
|
||||
file_path,
|
||||
len(page_boundaries),
|
||||
len(content),
|
||||
)
|
||||
# Log first 3 page boundaries for debugging
|
||||
for boundary in page_boundaries[:3]:
|
||||
logger.debug(
|
||||
f" Page {boundary['page']}: "
|
||||
f"offsets [{boundary['start_offset']}:{boundary['end_offset']}]"
|
||||
" Page %s: offsets [%s:%s]",
|
||||
boundary["page"],
|
||||
boundary["start_offset"],
|
||||
boundary["end_offset"],
|
||||
)
|
||||
# Verify last boundary matches text length
|
||||
if page_boundaries:
|
||||
last_boundary = page_boundaries[-1]
|
||||
if last_boundary["end_offset"] != len(content):
|
||||
logger.warning(
|
||||
f"Text length mismatch: content={len(content)}, "
|
||||
f"last_boundary_end={last_boundary['end_offset']}"
|
||||
"Text length mismatch: content=%s, last_boundary_end=%s",
|
||||
len(content),
|
||||
last_boundary["end_offset"],
|
||||
)
|
||||
else:
|
||||
logger.debug(f"No page_boundaries in metadata for {file_path}")
|
||||
logger.debug("No page_boundaries in metadata for %s", file_path)
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to process file {file_path}: {e}")
|
||||
logger.error("Failed to process file %s: %s", file_path, e)
|
||||
raise
|
||||
|
||||
# Tokenize and chunk (using configured chunk size and overlap)
|
||||
@@ -509,26 +534,32 @@ async def _index_document(
|
||||
# Diagnostic: Verify page number assignment
|
||||
assigned_count = sum(1 for c in chunks if c.page_number is not None)
|
||||
logger.info(
|
||||
f"Assigned page numbers to {assigned_count}/{len(chunks)} chunks "
|
||||
f"for {file_path}"
|
||||
"Assigned page numbers to %s/%s chunks for %s",
|
||||
assigned_count,
|
||||
len(chunks),
|
||||
file_path,
|
||||
)
|
||||
|
||||
# Log first 3 chunks to see their page assignments
|
||||
for i, chunk in enumerate(chunks[:3]):
|
||||
logger.debug(
|
||||
f" Chunk {i}: page={chunk.page_number}, "
|
||||
f"offsets=[{chunk.start_offset}:{chunk.end_offset}]"
|
||||
" Chunk %s: page=%s, offsets=[%s:%s]",
|
||||
i,
|
||||
chunk.page_number,
|
||||
chunk.start_offset,
|
||||
chunk.end_offset,
|
||||
)
|
||||
|
||||
# Warning if NO page numbers were assigned
|
||||
if assigned_count == 0:
|
||||
logger.warning(
|
||||
f"NO page numbers assigned! "
|
||||
f"Text length: {len(content)}, "
|
||||
f"Chunks: {len(chunks)}, "
|
||||
f"Chunk offset range: [{chunks[0].start_offset}:{chunks[-1].end_offset}], "
|
||||
f"Page boundaries: {len(page_boundaries_list)} pages, "
|
||||
f"First boundary: {page_boundaries_list[0] if page_boundaries_list else 'None'}"
|
||||
"NO page numbers assigned! Text length: %s, Chunks: %s, Chunk offset range: [%s:%s], Page boundaries: %s pages, First boundary: %s",
|
||||
len(content),
|
||||
len(chunks),
|
||||
chunks[0].start_offset,
|
||||
chunks[-1].end_offset,
|
||||
len(page_boundaries_list),
|
||||
page_boundaries_list[0] if page_boundaries_list else "None",
|
||||
)
|
||||
|
||||
# Extract chunk texts for embedding
|
||||
@@ -603,7 +634,7 @@ async def _index_document(
|
||||
|
||||
page_boundaries_list = cast(list[dict[str, Any]], page_boundaries)
|
||||
|
||||
logger.info(f"Computing chunk bboxes for {len(chunk_data)} PDF chunks")
|
||||
logger.info("Computing chunk bboxes for %s PDF chunks", len(chunk_data))
|
||||
|
||||
batch_results = await anyio.to_thread.run_sync( # type: ignore[attr-defined]
|
||||
lambda: PDFHighlighter.compute_chunk_bboxes_batch(
|
||||
@@ -617,7 +648,9 @@ async def _index_document(
|
||||
for chunk_index, (bboxes, _) in batch_results.items():
|
||||
chunk_bboxes[chunk_index] = bboxes
|
||||
|
||||
logger.info(f"Computed bboxes for {len(chunk_bboxes)}/{len(chunks)} chunks")
|
||||
logger.info(
|
||||
"Computed bboxes for %s/%s chunks", len(chunk_bboxes), len(chunks)
|
||||
)
|
||||
|
||||
# Run all embedding/highlighting operations in parallel
|
||||
# - Dense embeddings: I/O bound (API call)
|
||||
@@ -753,7 +786,10 @@ async def _index_document(
|
||||
except Exception as e:
|
||||
# Log but don't fail indexing if placeholder deletion fails
|
||||
logger.warning(
|
||||
f"Failed to delete placeholder for {doc_task.doc_type}_{doc_task.doc_id}: {e}"
|
||||
"Failed to delete placeholder for %s_%s: %s",
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
e,
|
||||
)
|
||||
|
||||
# Upsert to Qdrant in batches. Now that we no longer embed PNG payloads,
|
||||
@@ -779,10 +815,15 @@ async def _index_document(
|
||||
)
|
||||
if batch_end < len(points):
|
||||
logger.debug(
|
||||
f"Upserted batch {batch_start // BATCH_SIZE + 1}/{(len(points) + BATCH_SIZE - 1) // BATCH_SIZE}"
|
||||
"Upserted batch %s/%s",
|
||||
batch_start // BATCH_SIZE + 1,
|
||||
(len(points) + BATCH_SIZE - 1) // BATCH_SIZE,
|
||||
)
|
||||
|
||||
logger.info(
|
||||
f"Indexed {doc_task.doc_type}_{doc_task.doc_id} for {doc_task.user_id} "
|
||||
f"({len(chunks)} chunks)"
|
||||
"Indexed %s_%s for %s (%s chunks)",
|
||||
doc_task.doc_type,
|
||||
doc_task.doc_id,
|
||||
doc_task.user_id,
|
||||
len(chunks),
|
||||
)
|
||||
|
||||
@@ -534,7 +534,7 @@ async def get_qdrant_client() -> AsyncQdrantClient:
|
||||
# Detect mode and initialize client accordingly
|
||||
if settings.qdrant_url:
|
||||
# Network mode
|
||||
logger.info(f"Using Qdrant network mode: {settings.qdrant_url}")
|
||||
logger.info("Using Qdrant network mode: %s", settings.qdrant_url)
|
||||
provisional = AsyncQdrantClient(
|
||||
url=settings.qdrant_url,
|
||||
api_key=settings.qdrant_api_key,
|
||||
@@ -548,7 +548,7 @@ async def get_qdrant_client() -> AsyncQdrantClient:
|
||||
else:
|
||||
# Persistent local mode - use path parameter
|
||||
logger.info(
|
||||
f"Using Qdrant persistent mode: {settings.qdrant_location}"
|
||||
"Using Qdrant persistent mode: %s", settings.qdrant_location
|
||||
)
|
||||
provisional = AsyncQdrantClient(path=settings.qdrant_location)
|
||||
else:
|
||||
@@ -580,14 +580,14 @@ async def get_qdrant_client() -> AsyncQdrantClient:
|
||||
# `get_collection()`) is the only existence-probe permitted on a
|
||||
# collection-scoped JWT — it returns 200 with the collection
|
||||
# detail on hit and 404 on miss.
|
||||
logger.debug(f"Fetching collection '{collection_name}' details...")
|
||||
logger.debug("Fetching collection '%s' details...", collection_name)
|
||||
collection_info = None
|
||||
try:
|
||||
collection_info = await provisional.get_collection(collection_name)
|
||||
except UnexpectedResponse as exc:
|
||||
if exc.status_code != 404:
|
||||
raise
|
||||
logger.debug(f"Collection '{collection_name}' not found (404).")
|
||||
logger.debug("Collection '%s' not found (404).", collection_name)
|
||||
except ValueError as exc:
|
||||
# Local/in-memory qdrant_client raises ValueError(f"Collection
|
||||
# {name} not found") instead of UnexpectedResponse — see
|
||||
@@ -602,12 +602,12 @@ async def get_qdrant_client() -> AsyncQdrantClient:
|
||||
# multi-user-basic CI jobs all exercise this path.
|
||||
if "not found" not in str(exc):
|
||||
raise
|
||||
logger.debug(f"Collection '{collection_name}' not found (local mode).")
|
||||
logger.debug("Collection '%s' not found (local mode).", collection_name)
|
||||
|
||||
if collection_info is not None:
|
||||
# Collection exists - validate dimensions
|
||||
logger.debug(
|
||||
f"Collection '{collection_name}' found, validating dimensions..."
|
||||
"Collection '%s' found, validating dimensions...", collection_name
|
||||
)
|
||||
# Handle both named vectors (dict) and legacy single vector
|
||||
vectors = collection_info.config.params.vectors
|
||||
@@ -633,8 +633,10 @@ async def get_qdrant_client() -> AsyncQdrantClient:
|
||||
)
|
||||
|
||||
logger.info(
|
||||
f"Using existing Qdrant collection: {collection_name} "
|
||||
f"(dimension={actual_dimension}, model={settings.get_embedding_model_name()})"
|
||||
"Using existing Qdrant collection: %s (dimension=%s, model=%s)",
|
||||
collection_name,
|
||||
actual_dimension,
|
||||
settings.get_embedding_model_name(),
|
||||
)
|
||||
|
||||
# Existing collections may pre-date the doc_id normalization /
|
||||
@@ -658,8 +660,10 @@ async def get_qdrant_client() -> AsyncQdrantClient:
|
||||
# Collection doesn't exist - create it
|
||||
embedding_model = settings.get_embedding_model_name()
|
||||
logger.info(
|
||||
f"Collection '{collection_name}' not found, creating with "
|
||||
f"dimension={expected_dimension}, model={embedding_model}..."
|
||||
"Collection '%s' not found, creating with dimension=%s, model=%s...",
|
||||
collection_name,
|
||||
expected_dimension,
|
||||
embedding_model,
|
||||
)
|
||||
await provisional.create_collection(
|
||||
collection_name=collection_name,
|
||||
@@ -678,12 +682,10 @@ async def get_qdrant_client() -> AsyncQdrantClient:
|
||||
},
|
||||
)
|
||||
logger.info(
|
||||
f"Created Qdrant collection: {collection_name}\n"
|
||||
f" Dense vector dimension: {expected_dimension}\n"
|
||||
f" Dense embedding model: {embedding_model}\n"
|
||||
f" Sparse vectors: BM25 (for hybrid search)\n"
|
||||
f" Distance: COSINE\n"
|
||||
f"Background sync will index all documents with dense + sparse vectors."
|
||||
"Created Qdrant collection: %s\\n Dense vector dimension: %s\\n Dense embedding model: %s\\n Sparse vectors: BM25 (for hybrid search)\\n Distance: COSINE\\nBackground sync will index all documents with dense + sparse vectors.",
|
||||
collection_name,
|
||||
expected_dimension,
|
||||
embedding_model,
|
||||
)
|
||||
# Freshly created collection has no payload schema yet; pass
|
||||
# {} explicitly to skip the otherwise-redundant
|
||||
|
||||
@@ -155,7 +155,7 @@ async def get_last_indexed_timestamp(user_id: str) -> int | None:
|
||||
)
|
||||
|
||||
num_points = len(points)
|
||||
logger.info(f"Found {num_points} indexed notes in Qdrant for user {user_id}")
|
||||
logger.info("Found %s indexed notes in Qdrant for user %s", num_points, user_id)
|
||||
|
||||
if points:
|
||||
timestamps = [
|
||||
@@ -165,14 +165,16 @@ async def get_last_indexed_timestamp(user_id: str) -> int | None:
|
||||
]
|
||||
max_timestamp = max(timestamps) if timestamps else 0
|
||||
logger.info(
|
||||
f"Max indexed_at: {max_timestamp}, timestamps sample: {timestamps[:3]}"
|
||||
"Max indexed_at: %s, timestamps sample: %s",
|
||||
max_timestamp,
|
||||
timestamps[:3],
|
||||
)
|
||||
return int(max_timestamp) if max_timestamp > 0 else None
|
||||
|
||||
logger.info(f"No indexed notes found for user {user_id}")
|
||||
logger.info("No indexed notes found for user %s", user_id)
|
||||
return None
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to get last indexed timestamp: {e}", exc_info=True)
|
||||
logger.warning("Failed to get last indexed timestamp: %s", e, exc_info=True)
|
||||
return None
|
||||
|
||||
|
||||
@@ -198,7 +200,7 @@ async def scanner_task(
|
||||
user_id: User to scan
|
||||
task_status: Status object for signaling task readiness
|
||||
"""
|
||||
logger.info(f"Scanner task started for user: {user_id}")
|
||||
logger.info("Scanner task started for user: %s", user_id)
|
||||
settings = get_settings()
|
||||
|
||||
# Signal that the task has started and is ready
|
||||
@@ -215,7 +217,7 @@ async def scanner_task(
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"Scanner error: {e}", exc_info=True)
|
||||
logger.error("Scanner error: %s", e, exc_info=True)
|
||||
|
||||
# Sleep until next interval or wake event
|
||||
try:
|
||||
@@ -247,7 +249,10 @@ async def scan_user_documents(
|
||||
|
||||
scan_id = random.randint(1000, 9999)
|
||||
logger.info(
|
||||
f"[SCAN-{scan_id}] Starting scan for user: {user_id}, initial_sync={initial_sync}"
|
||||
"[SCAN-%s] Starting scan for user: %s, initial_sync=%s",
|
||||
scan_id,
|
||||
user_id,
|
||||
initial_sync,
|
||||
)
|
||||
|
||||
with trace_operation(
|
||||
@@ -266,7 +271,9 @@ async def scan_user_documents(
|
||||
)
|
||||
if prune_before:
|
||||
logger.info(
|
||||
f"[SCAN-{scan_id}] Using pruneBefore={prune_before} to optimize data transfer"
|
||||
"[SCAN-%s] Using pruneBefore=%s to optimize data transfer",
|
||||
scan_id,
|
||||
prune_before,
|
||||
)
|
||||
|
||||
# For deletion tracking, get all doc_ids in Qdrant (for incremental sync)
|
||||
@@ -303,7 +310,7 @@ async def scan_user_documents(
|
||||
if point.payload is not None and "doc_id" in point.payload
|
||||
}
|
||||
|
||||
logger.debug(f"Found {len(indexed_doc_ids)} indexed documents in Qdrant")
|
||||
logger.debug("Found %s indexed documents in Qdrant", len(indexed_doc_ids))
|
||||
|
||||
# Stream notes from Nextcloud and process immediately
|
||||
note_count = 0
|
||||
@@ -341,7 +348,8 @@ async def scan_user_documents(
|
||||
doc_key = (user_id, doc_id)
|
||||
if doc_key in _potentially_deleted:
|
||||
logger.debug(
|
||||
f"Document {doc_id} reappeared, removing from deletion grace period"
|
||||
"Document %s reappeared, removing from deletion grace period",
|
||||
doc_id,
|
||||
)
|
||||
del _potentially_deleted[doc_key]
|
||||
|
||||
@@ -368,14 +376,17 @@ async def scan_user_documents(
|
||||
stale_threshold = get_settings().vector_sync_scan_interval * 5
|
||||
if placeholder_age > stale_threshold:
|
||||
logger.debug(
|
||||
f"Found stale placeholder for note {doc_id} "
|
||||
f"(age={placeholder_age:.1f}s), requeuing"
|
||||
"Found stale placeholder for note %s (age=%ss), requeuing",
|
||||
doc_id,
|
||||
format(placeholder_age, ".1f"),
|
||||
)
|
||||
needs_indexing = True
|
||||
else:
|
||||
logger.debug(
|
||||
f"Skipping note {doc_id} with recent placeholder "
|
||||
f"(age={placeholder_age:.1f}s < {stale_threshold:.1f}s)"
|
||||
"Skipping note %s with recent placeholder (age=%ss < %ss)",
|
||||
doc_id,
|
||||
format(placeholder_age, ".1f"),
|
||||
format(stale_threshold, ".1f"),
|
||||
)
|
||||
|
||||
if needs_indexing:
|
||||
@@ -399,11 +410,11 @@ async def scan_user_documents(
|
||||
queued += 1
|
||||
|
||||
# Log and record metrics after streaming
|
||||
logger.info(f"[SCAN-{scan_id}] Found {note_count} notes for {user_id}")
|
||||
logger.info("[SCAN-%s] Found %s notes for %s", scan_id, note_count, user_id)
|
||||
record_vector_sync_scan(note_count)
|
||||
|
||||
if initial_sync:
|
||||
logger.info(f"Sent {queued} documents for initial sync: {user_id}")
|
||||
logger.info("Sent %s documents for initial sync: %s", queued, user_id)
|
||||
return
|
||||
|
||||
# Check for deleted documents (in Qdrant but not in Nextcloud)
|
||||
@@ -426,8 +437,10 @@ async def scan_user_documents(
|
||||
if time_missing >= grace_period:
|
||||
# Grace period elapsed, send for deletion
|
||||
logger.info(
|
||||
f"Document {doc_id} missing for {time_missing:.1f}s "
|
||||
f"(>{grace_period:.1f}s grace period), sending deletion"
|
||||
"Document %s missing for %ss (>%ss grace period), sending deletion",
|
||||
doc_id,
|
||||
format(time_missing, ".1f"),
|
||||
format(grace_period, ".1f"),
|
||||
)
|
||||
await send_stream.send(
|
||||
DocumentTask(
|
||||
@@ -443,13 +456,16 @@ async def scan_user_documents(
|
||||
del _potentially_deleted[doc_key]
|
||||
else:
|
||||
logger.debug(
|
||||
f"Document {doc_id} still missing "
|
||||
f"({time_missing:.1f}s/{grace_period:.1f}s grace period)"
|
||||
"Document %s still missing (%ss/%ss grace period)",
|
||||
doc_id,
|
||||
format(time_missing, ".1f"),
|
||||
format(grace_period, ".1f"),
|
||||
)
|
||||
else:
|
||||
# First time missing, add to grace period tracking
|
||||
logger.debug(
|
||||
f"Document {doc_id} missing for first time, starting grace period"
|
||||
"Document %s missing for first time, starting grace period",
|
||||
doc_id,
|
||||
)
|
||||
_potentially_deleted[doc_key] = current_time
|
||||
|
||||
@@ -476,7 +492,7 @@ async def scan_user_documents(
|
||||
if point.payload is not None and "doc_id" in point.payload
|
||||
}
|
||||
|
||||
logger.debug(f"Found {len(indexed_file_ids)} indexed files in Qdrant")
|
||||
logger.debug("Found %s indexed files in Qdrant", len(indexed_file_ids))
|
||||
|
||||
# Scan for tagged PDF files
|
||||
file_count = 0
|
||||
@@ -568,7 +584,9 @@ async def scan_user_documents(
|
||||
file_key = (user_id, file_id)
|
||||
if file_key in _potentially_deleted:
|
||||
logger.debug(
|
||||
f"File {file_path} (ID: {file_id}) reappeared, removing from deletion grace period"
|
||||
"File %s (ID: %s) reappeared, removing from deletion grace period",
|
||||
file_path,
|
||||
file_id,
|
||||
)
|
||||
del _potentially_deleted[file_key]
|
||||
|
||||
@@ -595,14 +613,19 @@ async def scan_user_documents(
|
||||
stale_threshold = get_settings().vector_sync_scan_interval * 5
|
||||
if placeholder_age > stale_threshold:
|
||||
logger.debug(
|
||||
f"Found stale placeholder for file {file_path} (ID: {file_id}) "
|
||||
f"(age={placeholder_age:.1f}s), requeuing"
|
||||
"Found stale placeholder for file %s (ID: %s) (age=%ss), requeuing",
|
||||
file_path,
|
||||
file_id,
|
||||
format(placeholder_age, ".1f"),
|
||||
)
|
||||
needs_indexing = True
|
||||
else:
|
||||
logger.debug(
|
||||
f"Skipping file {file_path} (ID: {file_id}) with recent placeholder "
|
||||
f"(age={placeholder_age:.1f}s < {stale_threshold:.1f}s)"
|
||||
"Skipping file %s (ID: %s) with recent placeholder (age=%ss < %ss)",
|
||||
file_path,
|
||||
file_id,
|
||||
format(placeholder_age, ".1f"),
|
||||
format(stale_threshold, ".1f"),
|
||||
)
|
||||
|
||||
if needs_indexing:
|
||||
@@ -627,7 +650,7 @@ async def scan_user_documents(
|
||||
file_queued += 1
|
||||
|
||||
logger.info(
|
||||
f"[SCAN-{scan_id}] Found {file_count} tagged PDFs for {user_id}"
|
||||
"[SCAN-%s] Found %s tagged PDFs for %s", scan_id, file_count, user_id
|
||||
)
|
||||
record_vector_sync_scan(file_count)
|
||||
|
||||
@@ -645,8 +668,10 @@ async def scan_user_documents(
|
||||
if time_missing >= grace_period:
|
||||
# Grace period elapsed, send for deletion
|
||||
logger.info(
|
||||
f"File ID {file_id} missing for {time_missing:.1f}s "
|
||||
f"(>{grace_period:.1f}s grace period), sending deletion"
|
||||
"File ID %s missing for %ss (>%ss grace period), sending deletion",
|
||||
file_id,
|
||||
format(time_missing, ".1f"),
|
||||
format(grace_period, ".1f"),
|
||||
)
|
||||
await send_stream.send(
|
||||
DocumentTask(
|
||||
@@ -662,12 +687,13 @@ async def scan_user_documents(
|
||||
else:
|
||||
# First time missing, add to grace period tracking
|
||||
logger.debug(
|
||||
f"File ID {file_id} missing for first time, starting grace period"
|
||||
"File ID %s missing for first time, starting grace period",
|
||||
file_id,
|
||||
)
|
||||
_potentially_deleted[file_key] = current_time
|
||||
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to scan tagged files for {user_id}: {e}")
|
||||
logger.warning("Failed to scan tagged files for %s: %s", user_id, e)
|
||||
|
||||
queued += file_queued
|
||||
|
||||
@@ -683,7 +709,7 @@ async def scan_user_documents(
|
||||
)
|
||||
queued += news_queued
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to scan news items for {user_id}: {e}")
|
||||
logger.warning("Failed to scan news items for %s: %s", user_id, e)
|
||||
|
||||
# Scan Deck cards
|
||||
deck_queued = 0
|
||||
@@ -697,14 +723,19 @@ async def scan_user_documents(
|
||||
)
|
||||
queued += deck_queued
|
||||
except Exception as e:
|
||||
logger.warning(f"Failed to scan deck cards for {user_id}: {e}")
|
||||
logger.warning("Failed to scan deck cards for %s: %s", user_id, e)
|
||||
|
||||
if queued > 0:
|
||||
logger.info(
|
||||
f"Sent {queued} documents ({file_queued} files, {news_queued} news items, {deck_queued} deck cards) for incremental sync: {user_id}"
|
||||
"Sent %s documents (%s files, %s news items, %s deck cards) for incremental sync: %s",
|
||||
queued,
|
||||
file_queued,
|
||||
news_queued,
|
||||
deck_queued,
|
||||
user_id,
|
||||
)
|
||||
else:
|
||||
logger.debug(f"No changes detected for {user_id}")
|
||||
logger.debug("No changes detected for %s", user_id)
|
||||
|
||||
|
||||
async def scan_news_items(
|
||||
@@ -754,7 +785,7 @@ async def scan_news_items(
|
||||
for point in points
|
||||
if point.payload is not None and "doc_id" in point.payload
|
||||
}
|
||||
logger.debug(f"Found {len(indexed_item_ids)} indexed news items in Qdrant")
|
||||
logger.debug("Found %s indexed news items in Qdrant", len(indexed_item_ids))
|
||||
|
||||
# Fetch all items (News app caps at ~200 per feed via auto-purge)
|
||||
all_items = await nc_client.news.get_items(
|
||||
@@ -762,7 +793,7 @@ async def scan_news_items(
|
||||
type_=NewsItemType.ALL,
|
||||
get_read=True,
|
||||
)
|
||||
logger.debug(f"[SCAN-{scan_id}] Found {len(all_items)} news items")
|
||||
logger.debug("[SCAN-%s] Found %s news items", scan_id, len(all_items))
|
||||
|
||||
item_count = len(all_items)
|
||||
nextcloud_item_ids: set[str] = set()
|
||||
@@ -800,7 +831,8 @@ async def scan_news_items(
|
||||
doc_key = (user_id, doc_id)
|
||||
if doc_key in _potentially_deleted:
|
||||
logger.debug(
|
||||
f"News item {doc_id} reappeared, removing from deletion grace period"
|
||||
"News item %s reappeared, removing from deletion grace period",
|
||||
doc_id,
|
||||
)
|
||||
del _potentially_deleted[doc_key]
|
||||
|
||||
@@ -820,8 +852,9 @@ async def scan_news_items(
|
||||
stale_threshold = settings.vector_sync_scan_interval * 5
|
||||
if placeholder_age > stale_threshold:
|
||||
logger.debug(
|
||||
f"Found stale placeholder for news item {doc_id} "
|
||||
f"(age={placeholder_age:.1f}s), requeuing"
|
||||
"Found stale placeholder for news item %s (age=%ss), requeuing",
|
||||
doc_id,
|
||||
format(placeholder_age, ".1f"),
|
||||
)
|
||||
needs_indexing = True
|
||||
|
||||
@@ -844,7 +877,10 @@ async def scan_news_items(
|
||||
queued += 1
|
||||
|
||||
logger.info(
|
||||
f"[SCAN-{scan_id}] Found {item_count} news items (starred+unread) for {user_id}"
|
||||
"[SCAN-%s] Found %s news items (starred+unread) for %s",
|
||||
scan_id,
|
||||
item_count,
|
||||
user_id,
|
||||
)
|
||||
record_vector_sync_scan(item_count)
|
||||
|
||||
@@ -864,8 +900,10 @@ async def scan_news_items(
|
||||
|
||||
if time_missing >= grace_period:
|
||||
logger.info(
|
||||
f"News item {doc_id} missing for {time_missing:.1f}s "
|
||||
f"(>{grace_period:.1f}s grace period), sending deletion"
|
||||
"News item %s missing for %ss (>%ss grace period), sending deletion",
|
||||
doc_id,
|
||||
format(time_missing, ".1f"),
|
||||
format(grace_period, ".1f"),
|
||||
)
|
||||
await send_stream.send(
|
||||
DocumentTask(
|
||||
@@ -880,7 +918,8 @@ async def scan_news_items(
|
||||
del _potentially_deleted[doc_key]
|
||||
else:
|
||||
logger.debug(
|
||||
f"News item {doc_id} missing for first time, starting grace period"
|
||||
"News item %s missing for first time, starting grace period",
|
||||
doc_id,
|
||||
)
|
||||
_potentially_deleted[doc_key] = current_time
|
||||
|
||||
@@ -932,11 +971,11 @@ async def scan_deck_cards(
|
||||
for point in points
|
||||
if point.payload is not None and "doc_id" in point.payload
|
||||
}
|
||||
logger.debug(f"Found {len(indexed_card_ids)} indexed deck cards in Qdrant")
|
||||
logger.debug("Found %s indexed deck cards in Qdrant", len(indexed_card_ids))
|
||||
|
||||
# Fetch all boards
|
||||
boards = await nc_client.deck.get_boards()
|
||||
logger.debug(f"[SCAN-{scan_id}] Found {len(boards)} deck boards")
|
||||
logger.debug("[SCAN-%s] Found %s deck boards", scan_id, len(boards))
|
||||
|
||||
card_count = 0
|
||||
nextcloud_card_ids: set[str] = set()
|
||||
@@ -949,7 +988,7 @@ async def scan_deck_cards(
|
||||
|
||||
# Skip deleted boards (soft delete: deletedAt > 0)
|
||||
if board.deletedAt > 0:
|
||||
logger.debug(f"[SCAN-{scan_id}] Skipping deleted board {board.id}")
|
||||
logger.debug("[SCAN-%s] Skipping deleted board %s", scan_id, board.id)
|
||||
continue
|
||||
|
||||
# Get stacks for this board
|
||||
@@ -998,7 +1037,8 @@ async def scan_deck_cards(
|
||||
doc_key = (user_id, doc_id)
|
||||
if doc_key in _potentially_deleted:
|
||||
logger.debug(
|
||||
f"Deck card {doc_id} reappeared, removing from deletion grace period"
|
||||
"Deck card %s reappeared, removing from deletion grace period",
|
||||
doc_id,
|
||||
)
|
||||
del _potentially_deleted[doc_key]
|
||||
|
||||
@@ -1018,8 +1058,9 @@ async def scan_deck_cards(
|
||||
stale_threshold = settings.vector_sync_scan_interval * 5
|
||||
if placeholder_age > stale_threshold:
|
||||
logger.debug(
|
||||
f"Found stale placeholder for deck card {doc_id} "
|
||||
f"(age={placeholder_age:.1f}s), requeuing"
|
||||
"Found stale placeholder for deck card %s (age=%ss), requeuing",
|
||||
doc_id,
|
||||
format(placeholder_age, ".1f"),
|
||||
)
|
||||
needs_indexing = True
|
||||
|
||||
@@ -1043,7 +1084,10 @@ async def scan_deck_cards(
|
||||
queued += 1
|
||||
|
||||
logger.info(
|
||||
f"[SCAN-{scan_id}] Found {card_count} deck cards (non-archived) for {user_id}"
|
||||
"[SCAN-%s] Found %s deck cards (non-archived) for %s",
|
||||
scan_id,
|
||||
card_count,
|
||||
user_id,
|
||||
)
|
||||
record_vector_sync_scan(card_count)
|
||||
|
||||
@@ -1062,8 +1106,10 @@ async def scan_deck_cards(
|
||||
|
||||
if time_missing >= grace_period:
|
||||
logger.info(
|
||||
f"Deck card {doc_id} missing for {time_missing:.1f}s "
|
||||
f"(>{grace_period:.1f}s grace period), sending deletion"
|
||||
"Deck card %s missing for %ss (>%ss grace period), sending deletion",
|
||||
doc_id,
|
||||
format(time_missing, ".1f"),
|
||||
format(grace_period, ".1f"),
|
||||
)
|
||||
await send_stream.send(
|
||||
DocumentTask(
|
||||
@@ -1078,7 +1124,8 @@ async def scan_deck_cards(
|
||||
del _potentially_deleted[doc_key]
|
||||
else:
|
||||
logger.debug(
|
||||
f"Deck card {doc_id} missing for first time, starting grace period"
|
||||
"Deck card %s missing for first time, starting grace period",
|
||||
doc_id,
|
||||
)
|
||||
_potentially_deleted[doc_key] = current_time
|
||||
|
||||
|
||||
@@ -92,7 +92,7 @@ async def compute_pca_coordinates(
|
||||
if embedding_dim is None:
|
||||
return {"coordinates_3d": [], "query_coords": []}
|
||||
|
||||
logger.info(f"Detected embedding dimension: {embedding_dim}")
|
||||
logger.info("Detected embedding dimension: %s", embedding_dim)
|
||||
|
||||
# Build chunk vectors array in search_results order (1:1 mapping)
|
||||
chunk_vectors = []
|
||||
@@ -103,7 +103,7 @@ async def compute_pca_coordinates(
|
||||
else:
|
||||
# Chunk not found in vectors (shouldn't happen)
|
||||
logger.warning(
|
||||
f"Chunk {chunk_key} not found in fetched vectors, using zero vector"
|
||||
"Chunk %s not found in fetched vectors, using zero vector", chunk_key
|
||||
)
|
||||
chunk_vectors.append(np.zeros(embedding_dim))
|
||||
|
||||
@@ -129,17 +129,19 @@ async def compute_pca_coordinates(
|
||||
if zero_norm_mask.any():
|
||||
zero_indices = np.where(zero_norm_mask)[0]
|
||||
logger.warning(
|
||||
f"Found {zero_norm_mask.sum()} zero-norm vectors at indices "
|
||||
f"{zero_indices.tolist()}. Replacing with small epsilon to avoid "
|
||||
"division by zero."
|
||||
"Found %s zero-norm vectors at indices %s. Replacing with small epsilon to avoid division by zero.",
|
||||
zero_norm_mask.sum(),
|
||||
zero_indices.tolist(),
|
||||
)
|
||||
# Replace zero norms with small epsilon to avoid NaN
|
||||
norms[zero_norm_mask] = 1e-10
|
||||
|
||||
all_vectors_normalized = all_vectors / norms
|
||||
logger.info(
|
||||
f"Normalized vectors: query_norm={norms[-1][0]:.3f}, "
|
||||
f"doc_norm_range=[{norms[:-1].min():.3f}, {norms[:-1].max():.3f}]"
|
||||
"Normalized vectors: query_norm=%s, doc_norm_range=[%s, %s]",
|
||||
format(norms[-1][0], ".3f"),
|
||||
format(norms[:-1].min(), ".3f"),
|
||||
format(norms[:-1].max(), ".3f"),
|
||||
)
|
||||
|
||||
# Apply PCA dimensionality reduction (768-dim → 3D)
|
||||
@@ -161,9 +163,9 @@ async def compute_pca_coordinates(
|
||||
if nan_mask.any():
|
||||
nan_rows = np.where(nan_mask.any(axis=1))[0]
|
||||
logger.error(
|
||||
f"Found NaN values in PCA output at {len(nan_rows)} points: "
|
||||
f"{nan_rows.tolist()[:10]}. Replacing NaN with 0.0 to prevent "
|
||||
"JSON serialization error."
|
||||
"Found NaN values in PCA output at %s points: %s. Replacing NaN with 0.0 to prevent JSON serialization error.",
|
||||
len(nan_rows),
|
||||
nan_rows.tolist()[:10],
|
||||
)
|
||||
# Replace NaN with 0 to allow JSON serialization
|
||||
coords_3d = np.nan_to_num(coords_3d, nan=0.0)
|
||||
@@ -174,9 +176,10 @@ async def compute_pca_coordinates(
|
||||
chunk_coords_3d = coords_3d[:-1] # All but last are chunks
|
||||
|
||||
logger.info(
|
||||
f"PCA explained variance: PC1={pca.explained_variance_ratio_[0]:.3f}, "
|
||||
f"PC2={pca.explained_variance_ratio_[1]:.3f}, "
|
||||
f"PC3={pca.explained_variance_ratio_[2]:.3f}"
|
||||
"PCA explained variance: PC1=%s, PC2=%s, PC3=%s",
|
||||
format(pca.explained_variance_ratio_[0], ".3f"),
|
||||
format(pca.explained_variance_ratio_[1], ".3f"),
|
||||
format(pca.explained_variance_ratio_[2], ".3f"),
|
||||
)
|
||||
|
||||
# Coordinates already match search_results order (1:1 mapping)
|
||||
|
||||
Reference in New Issue
Block a user