Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
101 changes: 93 additions & 8 deletions application/single_app/functions_data_management.py
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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):
Expand Down Expand Up @@ -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):
Expand All @@ -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(
Expand Down
5 changes: 5 additions & 0 deletions application/single_app/route_backend_data_management.py
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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)


Expand Down
104 changes: 104 additions & 0 deletions docs/explanation/fixes/DATA_MANAGEMENT_HISTORY_DIAGNOSTICS_FIX.md
Original file line number Diff line number Diff line change
@@ -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`
15 changes: 15 additions & 0 deletions docs/explanation/release_notes.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
Loading