diff --git a/application/single_app/functions_data_management.py b/application/single_app/functions_data_management.py index 8661905b0..5b6658aef 100644 --- a/application/single_app/functions_data_management.py +++ b/application/single_app/functions_data_management.py @@ -197,6 +197,12 @@ DATA_MANAGEMENT_HISTORY_UNAVAILABLE_MESSAGE = ( "Data Management history could not be loaded. Please try again later or review application logs." ) +DATA_MANAGEMENT_HISTORY_BUSY_MESSAGE = ( + "Data Management history is temporarily busy because Cosmos DB throttled the request. " + "Wait a moment and refresh this page." +) +DATA_MANAGEMENT_HISTORY_QUERY_MAX_ATTEMPTS = 3 +DATA_MANAGEMENT_HISTORY_QUERY_MAX_RETRY_DELAY_SECONDS = 4.0 DATA_MANAGEMENT_DEFAULT_RECOVERY_JOB_LIMIT = 25 DATA_MANAGEMENT_RECOVERY_QUEUE_DELAY_SECONDS = 60 DATA_MANAGEMENT_RECOVERY_RESUBMIT_DELAY_SECONDS = 120 @@ -378,12 +384,19 @@ def __init__( reason="history_provider_unavailable", status_code=503, maintenance_required=False, + provider_status_code=None, + provider_message="", + retryable=False, ): super().__init__(safe_message) self.safe_message = safe_message self.reason = reason self.status_code = status_code self.maintenance_required = bool(maintenance_required) + # Provider detail is for operator logs only and never reaches the browser. + self.provider_status_code = provider_status_code + self.provider_message = provider_message + self.retryable = bool(retryable) class DataManagementMigrationLeaseLostError(RuntimeError): @@ -9075,26 +9088,78 @@ def _get_data_management_provider_status_code(exc): return status_code +def _get_data_management_provider_message(exc): + """Return provider error text for operator logs, never for the browser.""" + return _safe_text(exc)[:1000] + + def _is_data_management_history_index_error(exc): if _get_data_management_provider_status_code(exc) != 400: return False error_text = _safe_text(exc).lower() + if "composite index" in error_text or "compositeindexes" in error_text: + return True + if "order by" not in error_text: + return False return ( - "composite index" in error_text - or "compositeindexes" in error_text - or ("order by" in error_text and "index" in error_text) + "index" in error_text + or "does not have a corresponding" in error_text + or "not served" in error_text ) +def _is_data_management_history_throttle_error(exc): + if _get_data_management_provider_status_code(exc) in {429, 503}: + return True + error_text = _safe_text(exc).lower() + return "request rate is large" in error_text or "too many requests" in error_text + + +def _is_data_management_history_transient_error(exc): + if isinstance(exc, (ServiceRequestError, ServiceResponseError)): + return True + status_code = _get_data_management_provider_status_code(exc) + return status_code in {408, 449} or (status_code is not None and 500 <= status_code <= 599) + + def _raise_data_management_history_unavailable(exc): + provider_status_code = _get_data_management_provider_status_code(exc) + provider_message = _get_data_management_provider_message(exc) if _is_data_management_history_index_error(exc): raise DataManagementHistoryUnavailableError( safe_message=DATA_MANAGEMENT_HISTORY_INDEX_MAINTENANCE_MESSAGE, reason="missing_history_index", status_code=503, maintenance_required=True, + provider_status_code=provider_status_code, + provider_message=provider_message, ) from exc - raise DataManagementHistoryUnavailableError() from exc + if _is_data_management_history_throttle_error(exc): + raise DataManagementHistoryUnavailableError( + safe_message=DATA_MANAGEMENT_HISTORY_BUSY_MESSAGE, + reason="history_provider_throttled", + status_code=503, + provider_status_code=provider_status_code, + provider_message=provider_message, + retryable=True, + ) from exc + raise DataManagementHistoryUnavailableError( + provider_status_code=provider_status_code, + provider_message=provider_message, + retryable=_is_data_management_history_transient_error(exc), + ) from exc + + +def _get_data_management_history_retry_delay(exc, attempt): + retry_after = _get_backup_retry_after_seconds(exc) or 0.0 + backoff = min( + DATA_MANAGEMENT_HISTORY_QUERY_MAX_RETRY_DELAY_SECONDS, + float(2 ** max(0, attempt - 1)) * 0.25, + ) + return min( + DATA_MANAGEMENT_HISTORY_QUERY_MAX_RETRY_DELAY_SECONDS, + max(backoff, retry_after) + random.uniform(0.0, 0.1), + ) def _query_data_management_history_items(query, parameters, max_item_count=None): @@ -9105,10 +9170,30 @@ def _query_data_management_history_items(query, parameters, max_item_count=None) } if max_item_count is not None: query_kwargs["max_item_count"] = max_item_count - try: - return list(cosmos_data_management_jobs_container.query_items(**query_kwargs)) - except (CosmosHttpResponseError, ServiceRequestError, ServiceResponseError) as exc: - _raise_data_management_history_unavailable(exc) + for attempt in range(1, DATA_MANAGEMENT_HISTORY_QUERY_MAX_ATTEMPTS + 1): + try: + return list(cosmos_data_management_jobs_container.query_items(**query_kwargs)) + except (CosmosHttpResponseError, ServiceRequestError, ServiceResponseError) as exc: + is_last_attempt = attempt >= DATA_MANAGEMENT_HISTORY_QUERY_MAX_ATTEMPTS + should_retry = ( + _is_data_management_history_throttle_error(exc) + or _is_data_management_history_transient_error(exc) + ) + if is_last_attempt or not should_retry: + _raise_data_management_history_unavailable(exc) + retry_delay = _get_data_management_history_retry_delay(exc, attempt) + log_event( + "[DATA_MANAGEMENT] Retrying Data Management history query.", + { + "attempt": attempt, + "status_code": _get_data_management_provider_status_code(exc), + "retry_delay_seconds": round(retry_delay, 3), + "error": _get_data_management_provider_message(exc), + }, + level=logging.WARNING, + ) + time.sleep(retry_delay) + def _query_data_management_history_page( diff --git a/application/single_app/route_backend_data_management.py b/application/single_app/route_backend_data_management.py index 5d2b7cc53..bf0750b08 100644 --- a/application/single_app/route_backend_data_management.py +++ b/application/single_app/route_backend_data_management.py @@ -77,7 +77,10 @@ def _data_management_history_unavailable_response(list_kind, exc): "history_list": list_kind, "reason": getattr(exc, "reason", "history_provider_unavailable"), "maintenance_required": bool(getattr(exc, "maintenance_required", False)), + "retryable": bool(getattr(exc, "retryable", False)), "error_type": type(original_error).__name__ if original_error else "", + "status_code": getattr(exc, "provider_status_code", None), + "error": getattr(exc, "provider_message", ""), }, level=logging.WARNING if getattr(exc, "maintenance_required", False) else logging.ERROR, exceptionTraceback=True, @@ -91,6 +94,8 @@ def _data_management_history_unavailable_response(list_kind, exc): "maintenance_required": True, "maintenance_action": "cosmos_indexing_policy_maintenance", }) + if getattr(exc, "retryable", False): + payload["retryable"] = True return jsonify(payload), getattr(exc, "status_code", 503) diff --git a/docs/explanation/fixes/DATA_MANAGEMENT_HISTORY_DIAGNOSTICS_FIX.md b/docs/explanation/fixes/DATA_MANAGEMENT_HISTORY_DIAGNOSTICS_FIX.md new file mode 100644 index 000000000..95797319a --- /dev/null +++ b/docs/explanation/fixes/DATA_MANAGEMENT_HISTORY_DIAGNOSTICS_FIX.md @@ -0,0 +1,104 @@ +# Data Management History Diagnostics Fix + +Fixed in version: **0.250.220** +Tracking issue: [#1275](https://github.com/microsoft/simplechat/issues/1275) + +## Issue Description + +`GET /api/admin/data-management/backups` returned **503** and the Backup Inventory panel showed the generic message *"Data Management history could not be loaded. Please try again later or review application logs."* + +The instruction to review application logs was not actionable: the only log line emitted was + +``` +[DEBUG][ERROR][Log] [DATA_MANAGEMENT] Data Management history could not be loaded. -- + {'history_list': 'backups', 'reason': 'history_provider_unavailable', + 'maintenance_required': False, 'error_type': 'CosmosHttpResponseError'} +``` + +`error_type` is the exception class name only. The provider status code and message were discarded, so the failure could not be classified from telemetry. + +## Root Cause Analysis + +Two separate defects. + +**Provider detail was dropped at the raise site.** `_raise_data_management_history_unavailable` constructed `DataManagementHistoryUnavailableError` without retaining the originating status code or message, and `_data_management_history_unavailable_response` logged only `type(original_error).__name__`. + +**Classification was too narrow.** `_is_data_management_history_index_error` required status `400` *and* the literal substring `"composite index"`. Any other provider failure — including throttling — fell through to the generic branch, producing an identical opaque 503 regardless of cause. + +There was also no retry for throttled reads beyond the Cosmos SDK default, and no way for the UI to distinguish a transient condition from a permanent one. + +### Investigation notes + +Several candidates were eliminated before concluding that the instrumentation itself was the blocking problem: + +| Candidate | Outcome | Evidence | +|---|---|---| +| Missing composite index | Ruled out | Cosmos Maintenance reports Indexing Policy Status **Aligned**, 7 containers checked, **Missing Expected Indexes: 0**. `data_management_jobs` is among the checked containers. | +| Parameterized `TOP` unsupported | Ruled out | `SELECT TOP @parameter` is valid Cosmos NoSQL. | +| Cosmos diagnostic `400` entries | Red herring | `400` with `requestCharge 0` and sub-millisecond duration is the normal cross-partition query-plan negotiation. It appears on every cross-partition query, including `tabular_export_runs` and `settings`, while those code paths log success. | + +The remaining candidates are throttling or another non-`400` `CosmosHttpResponseError`. `data_management_jobs` was observed oscillating 1,000 to 5,000 RU on `container_utilization_above_threshold`, and Admin Settings issues a burst of Cosmos-heavy admin calls on page load. + +## Technical Details + +### Files Modified + +| File | Change | +|---|---| +| `application/single_app/functions_data_management.py` | Retain provider detail, classify throttling, broaden index detection, bounded history query retry | +| `application/single_app/route_backend_data_management.py` | Log provider status and message; expose a `retryable` flag | +| `application/single_app/config.py` | Version bump to `0.250.220` | +| `functional_tests/test_data_management_history_pagination.py` | New regression coverage; replaced a brittle exact deployer-version assertion | + +### Code Changes Summary + +**Provider detail retained.** `DataManagementHistoryUnavailableError` now carries `provider_status_code`, `provider_message`, and `retryable`. The route logs `status_code` and `error` alongside the existing fields. Provider text is confined to operator logs and never enters the browser payload; `safe_message` remains a fixed, non-reflective string. + +**Throttle classification.** `_is_data_management_history_throttle_error` matches status `429`/`503` or the text "request rate is large" / "too many requests", and raises with `DATA_MANAGEMENT_HISTORY_BUSY_MESSAGE` plus `retryable=True`. The route surfaces `retryable: true` so the UI can offer a retry rather than pointing at logs. + +**Broader index detection.** `_is_data_management_history_index_error` still requires status `400`, but now also matches `ORDER BY` combined with "does not have a corresponding" or "not served", so maintenance guidance survives provider wording drift. + +**Bounded retry.** `_query_data_management_history_items` retries up to `DATA_MANAGEMENT_HISTORY_QUERY_MAX_ATTEMPTS` (3) for throttled and transient transport errors, with jittered backoff capped at `DATA_MANAGEMENT_HISTORY_QUERY_MAX_RETRY_DELAY_SECONDS` (4). Non-retryable errors fail on the first attempt as before. Each retry logs the attempt, status code, delay, and provider message. + +## Validation + +```bash +python -m pytest -q functional_tests/test_data_management_history_pagination.py +``` + +`12 passed` + +| Test | Assertion | +|---|---| +| `test_history_index_errors_match_alternate_provider_wording` | Index guidance still triggers when the provider omits the word "composite" | +| `test_history_throttling_is_retried_then_reported_as_busy` | A `429` retries exactly `DATA_MANAGEMENT_HISTORY_QUERY_MAX_ATTEMPTS` times, then reports `history_provider_throttled` with `retryable=True` and no provider text in the safe message | +| `test_history_failures_capture_provider_detail_for_operator_logs` | `provider_status_code` and `provider_message` are populated, absent from `safe_message`, and a non-retryable `403` does not retry | +| `test_history_provider_index_errors_are_actionable` | Existing coverage still passes | + +**Regression probe.** Neutralizing `_is_data_management_history_throttle_error` fails `test_history_throttling_is_retried_then_reported_as_busy`, confirming the test exercises the new classification rather than passing incidentally. + +**Full Data Management suite:** 150 passed, 1 failed. The failure, `test_data_management_backup_durability.py::test_backup_recovery_and_admin_progress_are_bounded_and_sanitized`, is pre-existing on `origin/Development` and unrelated. + +### Drive-by test fix + +`test_deployers_apply_the_data_management_history_index` asserted `deployer_version == "1.0.24"` and began failing when `deployers/version.txt` advanced to `1.0.25`. This is the exact brittle pattern the repository instructions prohibit for version assertions. It now uses `compare_simplechat_versions(deployer_version, "1.0.24") >= 0`, preserving the intent — the deployer must include the history index change — without breaking on future bumps. + +### Before / After + +| Behavior | Before | After | +|---|---|---| +| Log content on failure | Exception class name only | Class name plus provider status code and sanitized message | +| Throttled read | Immediate generic 503, "review application logs" | Retries up to 3 times, then retryable busy guidance | +| Index error wording drift | Generic 503 | Maintenance guidance | +| Browser payload | Generic error string | Same string, plus `retryable` when applicable | +| Provider text exposure | Not exposed | Still not exposed | + +## Follow-up + +The underlying provider failure is still unconfirmed. Once this ships, the next occurrence will record the status code and message directly, which should identify it in a single log line. If it proves to be throttling, the bounded retry added here may resolve it outright; the source blob checkpoint batching in `0.250.218` also reduces sustained write pressure on the same containers. + +## Cross-References + +- Issue: [#1275](https://github.com/microsoft/simplechat/issues/1275) +- Related: `docs/explanation/fixes/DATA_MANAGEMENT_HISTORY_INDEX_500_FIX.md` +- Functional test: `functional_tests/test_data_management_history_pagination.py` diff --git a/docs/explanation/release_notes.md b/docs/explanation/release_notes.md index 71afe9473..6f29b8bf6 100644 --- a/docs/explanation/release_notes.md +++ b/docs/explanation/release_notes.md @@ -6,6 +6,21 @@ For feature-focused and fix-focused drill-downs by version, see [Features by Ver #### Bug Fixes +* **Data Management History Failure Diagnostics** + * Backup Inventory and Job History failures returned a generic 503 telling admins to review application logs, while the logs recorded only the exception class name. The provider status code and message were discarded, making the failure impossible to diagnose. + * Failures now log the Cosmos status code and sanitized provider message. Provider text stays in operator logs and is never returned to the browser. + * (Ref: #1275, `functions_data_management.py`, `route_backend_data_management.py`, Data Management history) + +* **Data Management History Throttle Handling** + * Throttled history reads previously produced the same opaque error as a permanent failure. + * Cosmos throttling is now detected, retried up to three times with jittered backoff, and reported as temporary busy guidance with a retryable flag instead of a generic error. + * (Ref: #1275, `functions_data_management.py`, Cosmos history query retry) + +* **Data Management History Index Guidance** + * Missing-index detection required the exact phrase "composite index", so equivalent provider wording fell through to the generic error. + * Detection now also matches `ORDER BY` failures reported as having no corresponding index, keeping the Cosmos indexing maintenance guidance actionable. + * (Ref: #1275, `functions_data_management.py`, Cosmos indexing maintenance) + * **Source Blob Backup ETag Failure** * Fixed every source blob failing backup with "Source blob changed while it was being backed up", which meant user documents, group documents, public documents, and chat attachments were never actually backed up. * Root cause was comparing an ETag from `list_blobs()` (unquoted XML element) against one from `get_blob_properties()` (RFC-quoted HTTP header); the two never matched, so the post-transfer consistency check always failed after the blob had already been downloaded and uploaded. diff --git a/functional_tests/test_data_management_history_pagination.py b/functional_tests/test_data_management_history_pagination.py index a76709068..e7d8813b2 100644 --- a/functional_tests/test_data_management_history_pagination.py +++ b/functional_tests/test_data_management_history_pagination.py @@ -32,6 +32,9 @@ MODULE_PATH = APP_ROOT / "functions_data_management.py" ROUTE_MODULE_PATH = APP_ROOT / "route_backend_data_management.py" sys.path.insert(0, str(APP_ROOT)) +sys.path.insert(0, str(Path(__file__).resolve().parent)) + +from test_support.versioning import compare_simplechat_versions class FakeHistoryContainer: @@ -523,6 +526,83 @@ def __init__(self, message, status_code=400): assert "ORDER BY c.created_at DESC, c.id DESC" in container.queries[0]["query"] +def test_history_index_errors_match_alternate_provider_wording(monkeypatch): + """Index guidance must survive provider wording that omits the word composite.""" + container = FailingHistoryContainer() + module = load_data_management_module(monkeypatch, container) + + class FakeCosmosHttpResponseError(Exception): + def __init__(self, message, status_code=400): + super().__init__(message) + self.status_code = status_code + + module.CosmosHttpResponseError = FakeCosmosHttpResponseError + container.error = FakeCosmosHttpResponseError( + "The ORDER BY query does not have a corresponding index that it can be served from." + ) + + with pytest.raises(module.DataManagementHistoryUnavailableError) as exc_info: + module.get_data_management_jobs_page(page_size=25) + + assert exc_info.value.reason == "missing_history_index" + assert exc_info.value.maintenance_required is True + + +def test_history_throttling_is_retried_then_reported_as_busy(monkeypatch): + """Throttled history reads retry briefly, then surface retryable busy guidance.""" + container = FailingHistoryContainer() + module = load_data_management_module(monkeypatch, container) + monkeypatch.setattr(module.time, "sleep", lambda _seconds: None) + + class FakeCosmosHttpResponseError(Exception): + def __init__(self, message, status_code=429): + super().__init__(message) + self.status_code = status_code + + module.CosmosHttpResponseError = FakeCosmosHttpResponseError + container.error = FakeCosmosHttpResponseError( + "Request rate is large. More Request Units may be needed.", + ) + + with pytest.raises(module.DataManagementHistoryUnavailableError) as exc_info: + module.get_data_management_jobs_page(page_size=25) + + error = exc_info.value + assert error.reason == "history_provider_throttled" + assert error.retryable is True + assert error.status_code == 503 + assert "busy" in error.safe_message.lower() + assert "Request Units" not in error.safe_message + assert len(container.queries) == module.DATA_MANAGEMENT_HISTORY_QUERY_MAX_ATTEMPTS + + +def test_history_failures_capture_provider_detail_for_operator_logs(monkeypatch): + """Provider status and message must reach logs without reaching the browser.""" + container = FailingHistoryContainer() + module = load_data_management_module(monkeypatch, container) + monkeypatch.setattr(module.time, "sleep", lambda _seconds: None) + + class FakeCosmosHttpResponseError(Exception): + def __init__(self, message, status_code=403): + super().__init__(message) + self.status_code = status_code + + module.CosmosHttpResponseError = FakeCosmosHttpResponseError + container.error = FakeCosmosHttpResponseError( + "Request blocked by network firewall rules.", + ) + + with pytest.raises(module.DataManagementHistoryUnavailableError) as exc_info: + module.get_data_management_jobs_page(page_size=25) + + error = exc_info.value + assert error.provider_status_code == 403 + assert "network firewall" in error.provider_message + assert "network firewall" not in error.safe_message + assert error.retryable is False + assert len(container.queries) == 1, "Non-retryable provider errors must not retry" + + def test_expired_and_final_empty_continuations_fail_or_finish_safely(monkeypatch): """Reject expired state and return a safe empty final page.""" jobs = [ @@ -712,4 +792,6 @@ def test_deployers_apply_the_data_management_history_index(): assert "indexing_policy=DATA_MANAGEMENT_HISTORY_INDEXING_POLICY" in config_source assert '"path": "/created_at", "order": "descending"' in config_source assert '"path": "/id", "order": "descending"' in config_source - assert deployer_version == "1.0.24" + assert compare_simplechat_versions(deployer_version, "1.0.24") >= 0, ( + f"Deployer version must include the history index change, got {deployer_version}" + )