diff --git a/README.md b/README.md index 265d543..0ec61d3 100644 --- a/README.md +++ b/README.md @@ -268,10 +268,10 @@ The functions include a built-in encryption mechanism for sensitive information: - Falls back to an estimate (about 4 characters per token) while no `tiktoken` encoding is loaded, for example on offline installations without a `tiktoken` cache, so the chat still goes through. The encoding is downloaded in the background; requests do not wait for it (the very first one at most 5 seconds). Estimated counts are marked: `tokensEstimated` in the Log Analytics record and the log line, `~` in the status message. - Also works for API requests. Since Open WebUI 0.10, the filter's outlet step runs for them too. There is no chat window to show a status message, but the metrics are still logged and sent to Log Analytics. - On Open WebUI 0.11, response time and request tokens stay correct when Open WebUI adds RAG context or a code interpreter prompt to the user message after the filter's inlet step. -- Optionally sends logs to an [Azure Log Analytics Workspace](https://learn.microsoft.com/en-us/azure/azure-monitor/logs/log-analytics-workspace-overview) (`SEND_TO_LOG_ANALYTICS=true`). The record is sent in the background with a 10 second timeout, so responses do not wait for Log Analytics. +- Optionally sends a record per response to an [Azure Log Analytics Workspace](https://learn.microsoft.com/en-us/azure/azure-monitor/logs/log-analytics-workspace-overview) (`SEND_TO_LOG_ANALYTICS=true`) in the background (10 second timeout), so responses do not wait for Log Analytics: through the **Logs Ingestion API** (data collection rule; Microsoft Entra ID with a client secret, a managed identity on App Service / Functions / Container Apps / VMs, or AKS workload identity), or through the deprecated HTTP Data Collector API as a fallback. `LOG_ANALYTICS_INGESTION_API` selects `auto` (default), `logs_ingestion`, `data_collector` or `both`. > [!WARNING] -> The filter uses the Azure Monitor HTTP Data Collector API. Microsoft ended support for it on September 14, 2026; ingestion still works, but not for workspaces behind Azure Monitor Private Link (AMPLS). The [Logs ingestion API](https://learn.microsoft.com/en-us/azure/azure-monitor/logs/custom-logs-migrate) that replaces it is not supported yet. See [How to set up Azure Log Analytics](./docs/setup-azure-log-analytics.md). +> Microsoft ended support for the HTTP Data Collector API on September 14, 2026; ingestion still works (TLS 1.2+), but not with Azure Monitor Private Link (AMPLS). Since 2.7.0 the filter supports the [Logs Ingestion API](https://learn.microsoft.com/en-us/azure/azure-monitor/logs/logs-ingestion-api-overview) that replaces it, and logs a one-time warning while it still uses the Data Collector API. See [How to set up Azure Log Analytics](./docs/setup-azure-log-analytics.md), including how to migrate the existing `OpenWebuiMetrics_CL` table and keep its column names. 🔗 [Time Token Tracker in Open WebUI](https://openwebui.com/f/owndev/time_token_tracker) @@ -323,7 +323,7 @@ tests/e2e/run.sh --image v0.11.3-slim gemini # one suite on another Open WebUI tests/e2e/check_owui_api.sh latest # static check of the Open WebUI APIs the functions use ``` -The five suites (gemini, azure, n8n, infomaniak, filters) run about 300 checks in 7-10 minutes. Results are reported as `PASS`, `FAIL` or `KNOWN` (a failure that matches a registered known bug, shown with its issue and the branch with the pending fix). See the [testing guide](./docs/testing.md) for options, debugging and how to add scenarios. +The five suites (gemini, azure, n8n, infomaniak, filters) run about 500 checks in 15-20 minutes. Results are reported as `PASS`, `FAIL` or `KNOWN` (a failure that matches a registered known bug, shown with its issue and the branch with the pending fix). See the [testing guide](./docs/testing.md) for options, debugging and how to add scenarios. ## 💪 Contributing diff --git a/docs/setup-azure-log-analytics.md b/docs/setup-azure-log-analytics.md index 834eccd..3347f1f 100644 --- a/docs/setup-azure-log-analytics.md +++ b/docs/setup-azure-log-analytics.md @@ -1,32 +1,366 @@ # Setup Azure Log Analytics Workspace > [!WARNING] -> The Time Token Tracker sends its records through the Azure Monitor [HTTP Data Collector API](https://learn.microsoft.com/en-us/previous-versions/azure/azure-monitor/logs/data-collector-api) (`https://.ods.opinsights.azure.com/api/logs`, signed with the workspace shared key). Microsoft has deprecated this API. Support ended on **September 14, 2026**, but ingestion still works for clients that use TLS 1.2 or later. The API does not work with workspaces behind an Azure Monitor Private Link Scope (AMPLS). Microsoft recommends the [Logs ingestion API](https://learn.microsoft.com/en-us/azure/azure-monitor/logs/custom-logs-migrate) instead, which the filter does not support yet. +> The Time Token Tracker can send its records through two Azure Monitor APIs: +> +> - the **[Logs Ingestion API](https://learn.microsoft.com/en-us/azure/azure-monitor/logs/logs-ingestion-api-overview)** (recommended, since filter version 2.7.0): a data collection rule (DCR) and a Microsoft Entra ID identity; +> - the **[HTTP Data Collector API](https://learn.microsoft.com/en-us/previous-versions/azure/azure-monitor/logs/data-collector-api)** (`https://.ods.opinsights.azure.com/api/logs`, signed with the workspace shared key). Microsoft has deprecated it: support ended on **September 14, 2026**, but ingestion still works for clients that use TLS 1.2 or later. It does not work with workspaces behind an Azure Monitor Private Link Scope (AMPLS). As of October 9, 2026, Microsoft has not published a date after which ingestion stops. +> +> While the filter still uses the HTTP Data Collector API, it logs a one-time warning. See [Migrate from the HTTP Data Collector API to the Logs Ingestion API](https://learn.microsoft.com/en-us/azure/azure-monitor/logs/custom-logs-migrate) for Microsoft's guide. ## Installation - [Create Workspace](https://learn.microsoft.com/en-us/azure/azure-monitor/logs/quick-create-workspace) -## Get Shared Key +## Choose the API -To send data from Time Token Tracker to Azure Log Analytics, a shared key is required. This can be found under `Settings` > `Agents` > `Primary key`. +`SEND_TO_LOG_ANALYTICS` is the master switch for both APIs. `LOG_ANALYTICS_INGESTION_API` selects which one the filter uses: - +| `LOG_ANALYTICS_INGESTION_API` | Logs Ingestion API | HTTP Data Collector API | +| --- | --- | --- | +| `auto` (default; also any unknown value, with a warning) | when its settings are complete | when the Logs Ingestion settings are not complete (exactly as in 2.6.2). If some Logs Ingestion valves are set but not all, a one-time warning lists the missing ones | +| `logs_ingestion` | when its settings are complete; otherwise nothing is sent and a one-time warning lists the missing valves | never | +| `data_collector` | never | always (the existing shared key setup) | +| `both` | when its settings are complete | when the workspace ID and shared key are set | + +- `auto` switches to the Logs Ingestion API as soon as its valves are complete. Keep `data_collector` while you prepare the new setup, and switch when everything is in place. +- `both` writes every record through both APIs. Use it only with a **separate** table ([Option B](#option-b-new-table-side-by-side)). With a migrated table ([Option A](#option-a-migrate-the-table-in-place)) every record would be stored twice. +- The choice depends on the configuration only. A failed send is logged and never switches the API. +- While no API can send (for example `logs_ingestion` with incomplete settings, or `auto` / `both` when neither API is complete), every response also logs the warning `Failed to send data to Log Analytics (chat=..., message=...)`. The one-time warning logged before it names the missing valves. + +## Logs Ingestion API + +The filter requests a Microsoft Entra ID token itself (no extra Python packages), caches it per identity, refreshes it before it expires and sends each record to `{endpoint}/dataCollectionRules/{immutable ID}/streams/{stream}?api-version=2023-01-01`. Any 2xx answer counts as success (the API answers `204`). + +### Permissions for the setup + +- **Monitoring Contributor** to create the data collection rule (and a data collection endpoint, if you need one). +- **Log Analytics Contributor** (`Microsoft.OperationalInsights/workspaces/tables/migrate/action`) to migrate the table (Option A) or to create a table (Option B). +- `Microsoft.Authorization/roleAssignments/write` on the DCR for the [role assignment](#role-assignment), for example **Owner**, **User Access Administrator** or **Role Based Access Control Administrator**. Without it, someone who has it must do the role assignment for you. + +### Collect the values first + +You need these values in the templates and valves below: + +- Subscription ID, resource group and workspace name. +- The workspace's **resource ID** and **region**: + + ```bash + az monitor log-analytics workspace show --resource-group --workspace-name \ + --query "{id: id, location: location}" + ``` + + In the portal: workspace > **Overview** > **JSON View**. +- For a client secret: the app registration's **Directory (tenant) ID** and **Application (client) ID** (**Microsoft Entra ID** > **App registrations** > your app > **Overview**). See [Identity](#identity). +- Azure US Government or Azure operated by 21Vianet: run `az cloud set --name AzureUSGovernment` (or `AzureChinaCloud`) before `az login`, and see [Sovereign clouds](#sovereign-clouds). + +### Look at the existing table + +Run this query in the workspace (**Logs**): + +```kusto +OpenWebuiMetrics_CL | getschema +``` + +The HTTP Data Collector API names each column after the first value it saw, with a type suffix: `_g` for strings that look like a GUID, `_d` for every JSON number, `_b` for booleans, `_s` for other strings and `_t` for date-times. A later value that does not fit gets another column. For a table filled by the filter you can expect `chatId_g`, `messageId_g`, `model_s`, `userId_g` and/or `userId_s` (`unknown` for requests without a user), `responseTime_d`, `requestTokens_d`, `responseTokens_d`, `tokensPerSecond_d`, `avgRequestTokens_d`, `avgResponseTokens_d`, `tokensEstimated_b` (since 2.6.2) and maybe `timestamp_t` or `chatId_s`. Your table decides; check it with `getschema` before you write the DCR. + +Then choose one of the two options: + +- **Option A: migrate the table in place.** The table keeps its name and column names, so existing queries, dashboards and the Power BI report keep working. Irreversible. +- **Option B: new table side by side.** A new table with clean column names; the old data stays in `OpenWebuiMetrics_CL`. Queries and dashboards need changes. + +### Option A: migrate the table in place + +1. Update the filter to 2.7.0 and set `LOG_ANALYTICS_INGESTION_API=data_collector` explicitly, so that entering the new valves later does not switch yet. Make sure at least one record from version 2.6.2 or newer has arrived, so that `tokensEstimated_b` exists. +2. Migrate the table. This is **irreversible**: + + ```bash + az monitor log-analytics workspace table migrate --resource-group \ + --workspace-name --table-name OpenWebuiMetrics_CL + ``` + + The HTTP Data Collector API keeps writing into the existing columns after the migration. +3. Run `getschema` again ([Look at the existing table](#look-at-the-existing-table)), adapt [template A1](#template-a1-dcr-for-the-migrated-table) to it and create the DCR. Read back its `id`, `immutableId` and logs ingestion endpoint. +4. Assign the role on the DCR ([Role assignment](#role-assignment)). +5. Wait: a new role assignment can take up to 30 minutes, and new data can take up to 15 minutes to show up. +6. Set the Logs Ingestion valves: the identity, `LOG_ANALYTICS_DCR_ENDPOINT` and `LOG_ANALYTICS_DCR_IMMUTABLE_ID`. With template A1, `LOG_ANALYTICS_DCR_STREAM_NAME` can stay empty. +7. Switch `LOG_ANALYTICS_INGESTION_API` to `logs_ingestion` (or `auto`). +8. **Verify.** Send one chat message. The Open WebUI log shows `Log Analytics data sent via the Logs Ingestion API`. After up to 15 minutes, this query shows new rows (rows from the HTTP Data Collector API have `SourceSystem == "RestAPI"`): + + ```kusto + OpenWebuiMetrics_CL + | where TimeGenerated > ago(30m) + | summarize count() by SourceSystem + ``` + + A `204` only means "accepted". If no rows appear, check the DCR metrics **Logs Transformation Errors per Min** and **Logs Rows Dropped per Min** and, after enabling the DCR's error logs, the `DCRLogErrors` table. Usually the `transformKql` does not match the table's columns. +9. **Rollback:** switch back to `data_collector`. This works as long as nobody changed the table schema after the migration. Records that failed while the Logs Ingestion API was active are not resent. + +> [!WARNING] +> While the HTTP Data Collector API still writes to the migrated table, do not add columns or edit the schema: that stops legacy ingestion for the whole table. A column that does not exist at migration time cannot be added safely until the Data Collector writes have stopped. + +#### Template A1: DCR for the migrated table + +Save this as `dcr-openwebui.json`, fill in the region and the workspace resource ID, and adapt `transformKql` to your `getschema` output (see the notes below): + +```json +{ + "location": "", + "kind": "Direct", + "properties": { + "streamDeclarations": { + "Custom-OpenWebuiMetrics_CL": { + "columns": [ + { "name": "timestamp", "type": "datetime" }, + { "name": "chatId", "type": "string" }, + { "name": "messageId", "type": "string" }, + { "name": "model", "type": "string" }, + { "name": "userId", "type": "string" }, + { "name": "responseTime", "type": "real" }, + { "name": "requestTokens", "type": "long" }, + { "name": "responseTokens", "type": "long" }, + { "name": "tokensPerSecond", "type": "real" }, + { "name": "tokensEstimated", "type": "boolean" }, + { "name": "avgRequestTokens", "type": "real" }, + { "name": "avgResponseTokens", "type": "real" } + ] + } + }, + "destinations": { + "logAnalytics": [ + { + "workspaceResourceId": "/subscriptions//resourceGroups//providers/Microsoft.OperationalInsights/workspaces/", + "name": "workspace" + } + ] + }, + "dataFlows": [ + { + "streams": ["Custom-OpenWebuiMetrics_CL"], + "destinations": ["workspace"], + "transformKql": "source | project TimeGenerated = todatetime(timestamp), chatId_g = tostring(chatId), messageId_g = tostring(messageId), model_s = tostring(model), userId_g = tostring(userId), responseTime_d = toreal(responseTime), requestTokens_d = toreal(requestTokens), responseTokens_d = toreal(responseTokens), tokensPerSecond_d = toreal(tokensPerSecond), tokensEstimated_b = tobool(tokensEstimated), avgRequestTokens_d = toreal(avgRequestTokens), avgResponseTokens_d = toreal(avgResponseTokens)", + "outputStream": "Custom-OpenWebuiMetrics_CL" + } + ] + } +} +``` + +Create the DCR with `az rest` (a relative `/subscriptions/...` URL, so `az` uses the Resource Manager endpoint of the current cloud): + +```bash +az rest --method put \ + --url "/subscriptions//resourceGroups//providers/Microsoft.Insights/dataCollectionRules/?api-version=2023-03-11" \ + --body @dcr-openwebui.json +``` + +In PowerShell, quote the body argument (`--body '@dcr-openwebui.json'`; a bare `@` is the splatting operator), or use `Invoke-AzRestMethod -Path "?api-version=2023-03-11" -Method PUT -Payload (Get-Content dcr-openwebui.json -Raw)`. `az monitor data-collection rule create --rule-file` is not used here, because it is not verified that it keeps `"kind": "Direct"`. + +Read the values back: + +```bash +az rest --method get \ + --url "/subscriptions//resourceGroups//providers/Microsoft.Insights/dataCollectionRules/?api-version=2023-03-11" \ + --query "{id: id, immutableId: properties.immutableId, endpoint: properties.endpoints.logsIngestion}" +``` + +- `id` is the scope of the [role assignment](#role-assignment). +- `immutableId` (`dcr-` followed by 32 hex characters) goes into `LOG_ANALYTICS_DCR_IMMUTABLE_ID`. +- `endpoint` goes into `LOG_ANALYTICS_DCR_ENDPOINT`. + +Notes on the template: + +- **Stream.** The stream name must start with `Custom-` and is local to the DCR. `Custom-OpenWebuiMetrics_CL` is the filter's default stream name (`Custom-_CL`), so `LOG_ANALYTICS_DCR_STREAM_NAME` can stay empty. `outputStream` `Custom-` selects the table. +- **GUIDs.** `chatId`, `messageId` and `userId` are declared as `string`, because stream declarations have no `guid` type. Log Analytics stores GUIDs as strings, so `tostring()` into a `_g` column is the intended mapping. +- **Adapt to `getschema`.** Transformations support only some functions, among them `toguid`, `iif`, `isnull`, `isnotnull`, `tostring`, `toreal`, `tobool` and `todatetime` (`coalesce` is **not** supported): + - A table with `userId_s` instead of `userId_g`: use `userId_s = tostring(userId)`. + - A table with both: `userId_g = iif(isnotnull(toguid(userId)), tostring(userId), ""), userId_s = iif(isnull(toguid(userId)), tostring(userId), "")`. The same applies to `chatId_s`. + - A table with `timestamp_t`: add `timestamp_t = todatetime(timestamp)`. + - An output column that does not exist in the table is accepted but not stored. +- **Private link.** For a data collection endpoint (DCE) instead: remove `"kind": "Direct"`, add `"dataCollectionEndpointId": ""` under `properties`, and use the DCE's logs ingestion URL as `LOG_ANALYTICS_DCR_ENDPOINT` (see [DCE and private link](#dce-and-private-link)). + +### Option B: new table side by side -## Configure the Time Token Tracker +1. Update the filter to 2.7.0 and set `LOG_ANALYTICS_INGESTION_API=data_collector` while you prepare. +2. Create the table `OpenWebuiMetricsV2_CL` **first** (the DCR's `outputStream` refers to it). Save this as `table.json`: + + ```json + { + "properties": { + "schema": { + "name": "OpenWebuiMetricsV2_CL", + "columns": [ + { "name": "TimeGenerated", "type": "datetime" }, + { "name": "chatId", "type": "string" }, + { "name": "messageId", "type": "string" }, + { "name": "model", "type": "string" }, + { "name": "userId", "type": "string" }, + { "name": "responseTime", "type": "real" }, + { "name": "requestTokens", "type": "long" }, + { "name": "responseTokens", "type": "long" }, + { "name": "tokensPerSecond", "type": "real" }, + { "name": "tokensEstimated", "type": "boolean" }, + { "name": "avgRequestTokens", "type": "real" }, + { "name": "avgResponseTokens", "type": "real" } + ] + } + } + } + ``` + + ```bash + az rest --method put \ + --url "/subscriptions//resourceGroups//providers/Microsoft.OperationalInsights/workspaces//tables/OpenWebuiMetricsV2_CL?api-version=2022-10-01" \ + --body @table.json + ``` + +3. Create the DCR from [template A1](#template-a1-dcr-for-the-migrated-table) with two changes (the stream name stays `Custom-OpenWebuiMetrics_CL`, so `LOG_ANALYTICS_DCR_STREAM_NAME` can stay empty): + - `"outputStream": "Custom-OpenWebuiMetricsV2_CL"` + - `"transformKql": "source | project TimeGenerated = todatetime(timestamp), chatId, messageId, model, userId, responseTime, requestTokens, responseTokens, tokensPerSecond, tokensEstimated, avgRequestTokens, avgResponseTokens"` +4. Assign the role ([Role assignment](#role-assignment)) and set the Logs Ingestion valves. +5. Set `LOG_ANALYTICS_INGESTION_API=both` during the transition. The HTTP Data Collector API keeps writing to the old table, the Logs Ingestion API to the new one. +6. Verify as in Option A step 8, with `OpenWebuiMetricsV2_CL`. +7. Switch to `auto` (or `logs_ingestion`) once your queries and dashboards use the new table. + +**Portal alternative (no CLI).** Workspace > **Tables** > **Create** > **New custom log (DCR based)**. The wizard needs a data collection endpoint (create it first, in the workspace's region) and a sample JSON file: one record with the fields listed under [Record fields](#record-fields-and-sending). In the transformation editor use `source | extend TimeGenerated = todatetime(timestamp)`. The wizard's stream is `Custom-
`, for example `Custom-OpenWebuiMetricsV2_CL`, so set `LOG_ANALYTICS_DCR_STREAM_NAME` to it and use the DCE's logs ingestion URL as `LOG_ANALYTICS_DCR_ENDPOINT`. The immutable ID is in the DCR's **Overview** > **JSON View**. Option A has no portal path: a DCR for an existing table must be created manually. + +**Query across both tables:** + +```kusto +union + (OpenWebuiMetrics_CL + | project TimeGenerated, + chatId = tostring(column_ifexists("chatId_g", "")), model = model_s, + userId = tostring(column_ifexists("userId_g", "")), + responseTime = responseTime_d, requestTokens = tolong(requestTokens_d), + responseTokens = tolong(responseTokens_d), tokensPerSecond = tokensPerSecond_d), + (OpenWebuiMetricsV2_CL + | project TimeGenerated, chatId, model, userId, responseTime, requestTokens, + responseTokens, tokensPerSecond) +``` + +In `both` mode every record is in both tables; pick a cut-over time in dashboards. + +### Identity + +**App registration with a client secret** (`LOG_ANALYTICS_AUTH_MODE=client_secret`, the default): + +1. **Microsoft Entra ID** > **App registrations** > **New registration** (no redirect URI). +2. Note the **Application (client) ID** (`LOG_ANALYTICS_CLIENT_ID`) and the **Directory (tenant) ID** (`LOG_ANALYTICS_TENANT_ID`). +3. **Certificates & secrets** > **New client secret**. Copy the secret's **Value** (not the Secret ID) right away; it cannot be shown again. This goes into `LOG_ANALYTICS_CLIENT_SECRET`, which is stored encrypted when `WEBUI_SECRET_KEY` is set. +4. Note the expiry date. An expired secret logs `AADSTS7000222`. + +**Managed identity** (`LOG_ANALYTICS_AUTH_MODE=managed_identity`). The filter detects the platform from its environment at every token request: + +- **App Service, Functions, Container Apps:** enable a system-assigned or user-assigned identity. For a user-assigned identity, set `LOG_ANALYTICS_CLIENT_ID` to its client ID; leave it empty for the system-assigned one. +- **Virtual machines and scale sets:** the same; the filter calls the instance metadata service (IMDS) directly, never through a proxy. +- **AKS workload identity:** enable workload identity and the OIDC issuer on the cluster (preconfigured on AKS Automatic), label the pod `azure.workload.identity/use: "true"`, annotate its service account with `azure.workload.identity/client-id`, and add a federated credential to the identity with the cluster's OIDC issuer URL, the subject `system:serviceaccount::` and the audience `api://AzureADTokenExchange`. Tenant and client ID come from `AZURE_TENANT_ID` / `AZURE_CLIENT_ID` (set by the webhook) unless the valves are set. In Azure US Government and 21Vianet also set `LOG_ANALYTICS_AUTHORITY_HOST`: the webhook's `AZURE_AUTHORITY_HOST` is ignored. +- **Not supported:** Service Fabric, Azure Arc, Cloud Shell / Azure Machine Learning, AKS identity bindings and certificate credentials. They log an error; use a client secret there. + +### Role assignment + +Assign **Monitoring Metrics Publisher** on the DCR to the identity: + +- Portal: DCR > **Access control (IAM)** > **Add role assignment** > **Monitoring Metrics Publisher** > **User, group, or service principal** (the app registration) or **Managed identity**. +- CLI: + + ```bash + az role assignment create --assignee \ + --role "Monitoring Metrics Publisher" --scope + ``` + + The DCR resource ID is the `id` you read back after creating the DCR. For a managed identity use its principal (object) ID, shown on the resource's **Identity** page. + +A new role assignment can take up to 30 minutes; until then the API answers `403`. + +### Valves + +Set the valves of the Time Token Tracker filter (**Admin Panel → Functions → Time Token Tracker → Valves**). Every valve can also get a default from an environment variable of the same name in the Open WebUI container; values saved in the valves take precedence. + +| Valve / environment variable | Default | Description | +| --- | --- | --- | +| `SEND_TO_LOG_ANALYTICS` | off | `true` turns on sending (`1`, `yes` and `on` also work). Any other value, including `false`, turns it off. The master switch for both APIs. | +| `LOG_ANALYTICS_INGESTION_API` | `auto` | `auto`, `logs_ingestion`, `data_collector` or `both` (see [Choose the API](#choose-the-api)). | +| `LOG_ANALYTICS_DCR_ENDPOINT` | – | The DCR's logs ingestion endpoint (`https://--.logs.z1.ingest.monitor.azure.com`) or a DCE's logs ingestion URL. Must use `https://` (added when the scheme is missing). | +| `LOG_ANALYTICS_DCR_IMMUTABLE_ID` | – | The DCR's `immutableId` (`dcr-...`), not its name or resource ID. | +| `LOG_ANALYTICS_DCR_STREAM_NAME` | `Custom-_CL` | The stream in the DCR. Empty uses the default, e.g. `Custom-OpenWebuiMetrics_CL`. | +| `LOG_ANALYTICS_AUTH_MODE` | `client_secret` | `client_secret` or `managed_identity` (also AKS workload identity). | +| `LOG_ANALYTICS_TENANT_ID` | – | Directory (tenant) ID, a GUID or domain. Workload identity falls back to `AZURE_TENANT_ID`. | +| `LOG_ANALYTICS_CLIENT_ID` | – | Application (client) ID of the app registration; with `managed_identity` the client ID of a user-assigned identity (empty: system-assigned). Workload identity falls back to `AZURE_CLIENT_ID`. | +| `LOG_ANALYTICS_CLIENT_SECRET` | – | The client secret's value (not its ID). Stored encrypted when `WEBUI_SECRET_KEY` is set. | +| `LOG_ANALYTICS_AUTHORITY_HOST` | `https://login.microsoftonline.com` | Microsoft Entra ID authority, see [Sovereign clouds](#sovereign-clouds). Must use `https://`. | +| `LOG_ANALYTICS_INGESTION_SCOPE` | `https://monitor.azure.com/.default` | Token scope, see [Sovereign clouds](#sovereign-clouds). | +| `LOG_ANALYTICS_WORKSPACE_ID` | – | HTTP Data Collector API only: the workspace ID. | +| `LOG_ANALYTICS_SHARED_KEY` | – | HTTP Data Collector API only: the workspace's primary key. Stored encrypted when `WEBUI_SECRET_KEY` is set. | +| `LOG_ANALYTICS_LOG_TYPE` | `OpenWebuiMetrics` | The custom log name of the HTTP Data Collector API (`_CL`) and the base of the default stream name. | + +> [!NOTE] +> Since 2.7.0 `LOG_ANALYTICS_LOG_TYPE` can also be set by an environment variable; version 2.6.2 ignored it. An installation that set this variable anyway and never saved the valve now sends to `_CL` instead of `OpenWebuiMetrics_CL`. An empty variable (for example `LOG_ANALYTICS_LOG_TYPE=${LOG_ANALYTICS_LOG_TYPE}` in a compose file while the host variable is not set) counts as unset. + +The Logs Ingestion settings count as complete when the endpoint, the immutable ID and a stream name are set, `LOG_ANALYTICS_AUTH_MODE` is valid, the endpoint and authority use `https://` and, for `client_secret`, the tenant ID, client ID and client secret are set. + +### DCE and private link + +A DCR created with `"kind": "Direct"` has its own logs ingestion endpoint (`properties.endpoints.logsIngestion`). You need a data collection endpoint (DCE) only for private link (AMPLS) or for a DCR without that endpoint (older DCRs, the portal wizard). Endpoints cannot be added to an existing DCR. + +### Sovereign clouds + +| Cloud | `LOG_ANALYTICS_AUTHORITY_HOST` | `LOG_ANALYTICS_INGESTION_SCOPE` | +| --- | --- | --- | +| Azure public | `https://login.microsoftonline.com` | `https://monitor.azure.com/.default` | +| Azure US Government | `https://login.microsoftonline.us` | `https://monitor.azure.us/.default` | +| Microsoft Azure operated by 21Vianet | `https://login.partner.microsoftonline.cn` | `https://monitor.azure.cn/.default` | + +The double-slash form `https://monitor.azure.com//.default` from Microsoft's REST tutorial works as well. + +### Troubleshooting + +Each failed record logs one line in the Open WebUI log. Records are not retried. + +| Log line contains | Cause | Fix | +| --- | --- | --- | +| `Exception when sending to Logs Ingestion API: ClientConnectorError` or `TimeoutError` | The endpoint cannot be reached, or does not answer within 10 s: wrong `LOG_ANALYTICS_DCR_ENDPOINT`, DNS, a firewall or proxy, or a workspace behind private link (AMPLS) that needs a DCE. | Check the endpoint and the network path from the Open WebUI container; see [DCE and private link](#dce-and-private-link). | +| `Error sending to Logs Ingestion API: 400` | The record does not match the DCR's stream declaration. | Compare the `streamDeclarations` with the [record fields](#record-fields-and-sending). | +| `Error sending to Logs Ingestion API: 401` | The token was rejected. | `LOG_ANALYTICS_INGESTION_SCOPE` must match the cloud of the endpoint. A second 401 in a row pauses token requests for 30 s. | +| `Error sending to Logs Ingestion API: 403` | The identity has no Monitoring Metrics Publisher role on the DCR, or the assignment is younger than 30 minutes. | Assign the role on the DCR ([Role assignment](#role-assignment)) and wait. | +| `Error sending to Logs Ingestion API: 404` | Wrong endpoint, immutable ID or stream name. | Compare with the values read back from the DCR. | +| `Error sending to Logs Ingestion API: 413` | The record exceeds 1 MB per call. | – | +| `Error sending to Logs Ingestion API: 429` | Throttled (per DCR: 12,000 requests or 2 GB per minute); the line shows `Retry-After`. | The record is dropped. | +| `Could not get a Microsoft Entra ID token ... AADSTS7000215` | Invalid client secret. | Use the secret's value, not its ID. | +| `... AADSTS7000222` | The client secret has expired. | Create a new secret. | +| `... AADSTS700016` | Application not found in the tenant. | Check `LOG_ANALYTICS_CLIENT_ID`, `LOG_ANALYTICS_TENANT_ID` and `LOG_ANALYTICS_AUTHORITY_HOST`. | +| `... AADSTS90002` | Tenant not found. | Check `LOG_ANALYTICS_TENANT_ID` and the cloud's authority. | +| `... AADSTS70011` or `AADSTS500011` | Invalid scope. | `LOG_ANALYTICS_INGESTION_SCOPE` must match the cloud. | +| `... AADSTS700212` | Workload identity: the federated token has the wrong audience. | The federated credential needs the audience `api://AzureADTokenExchange`. | +| `... no managed identity endpoint reachable` | `managed_identity` outside Azure, or no identity assigned. | Assign an identity, or use a client secret. | +| `... (managed identity (App Service)): 400 - check LOG_ANALYTICS_CLIENT_ID` | App Service, Functions or Container Apps: `LOG_ANALYTICS_CLIENT_ID` is not the client ID of a user-assigned identity assigned to the app, or it is empty while the app has no system-assigned identity. The line ends with the token service's message (for example `Unable to load the proper Managed Identity.`) and `correlationId`. | Correct the client ID, or assign the identity to the app (or enable its system-assigned identity). | +| `... workload identity needs a tenant and client ID` | AKS: `AZURE_FEDERATED_TOKEN_FILE` is set, but `AZURE_TENANT_ID` / `AZURE_CLIENT_ID` are not and the valves are empty. The webhook takes the client ID from the service account annotation. | Annotate the service account with `azure.workload.identity/client-id`, check that the pod is labelled `azure.workload.identity/use: "true"` and has the variables (restart it after a change), or set `LOG_ANALYTICS_TENANT_ID` / `LOG_ANALYTICS_CLIENT_ID`. | +| `... AZURE_FEDERATED_TOKEN_FILE could not be read` or `is empty` | AKS: the projected service account token is missing or not readable at that path. | Check the pod label, the service account and the volume the webhook mounts. | +| `... is not supported` | Managed identity on Service Fabric, Azure Arc, Cloud Shell / Azure ML, or AKS identity bindings. | Use a client secret. | +| `could not be decrypted` | The stored client secret was encrypted with another `WEBUI_SECRET_KEY`. | Enter the client secret again. | +| `keeping the cached token for Ns` | A token refresh failed; the still-valid token is used until shortly before it expires. | Fix the cause shown in the line. | +| `Log Analytics record dropped: no usable token` | A token request failed (or tokens keep being rejected) less than 30 s ago. | See the token error logged before it; the next attempt follows automatically after 30 s. | +| `not fully configured (missing: ...)` | Logs Ingestion valves are missing or invalid (`must use https`, `unknown value`). | Set the listed valves. Logged once per process. | +| `Failed to send data to Log Analytics (chat=..., message=...)` | A warning per record: no API can send (see the one-time `not fully configured` warning before it), or the HTTP Data Collector API send failed (see the line before it). | Set the missing valves, or fix the cause shown before it. | +| `does not look like an immutable ID` | `LOG_ANALYTICS_DCR_IMMUTABLE_ID` is not `dcr-` followed by 32 hex characters (it is still used). | Copy `immutableId` from the DCR's JSON view, not the DCR name or resource ID. | +| `HTTP Data Collector API, which Microsoft deprecated` | The filter still sends through the deprecated API. | Set up the Logs Ingestion API. Logged once per process. | +| `Log Analytics data sent via the Logs Ingestion API`, but no rows | The API accepted the record (204), the DCR dropped it. | See Option A step 8: DCR metrics and `DCRLogErrors`; usually `transformKql` does not match the table. | + +## HTTP Data Collector API (deprecated) + +### Get Shared Key + +To send data through the HTTP Data Collector API, a shared key is required. This can be found under `Settings` > `Agents` > `Primary key`. + + -Set the valves of the Time Token Tracker filter (**Admin Panel → Functions → Time Token Tracker → Valves**). You can also set defaults with environment variables of the Open WebUI container. Values saved in the valves take precedence over these. +Set `SEND_TO_LOG_ANALYTICS`, `LOG_ANALYTICS_WORKSPACE_ID`, `LOG_ANALYTICS_SHARED_KEY` and optionally `LOG_ANALYTICS_LOG_TYPE` (see [Valves](#valves)). With only these valves set, the filter sends exactly the same request as in version 2.6.2 and logs a one-time deprecation warning. Log Analytics adds a type suffix to the names of custom fields, for example `requestTokens_d` and `tokensEstimated_b`. -| Valve / environment variable | Description | -| --- | --- | -| `SEND_TO_LOG_ANALYTICS` | `true` turns on sending (`1`, `yes` and `on` also work). Any other value, including `false`, turns it off. Default: off. | -| `LOG_ANALYTICS_WORKSPACE_ID` | The Workspace ID. | -| `LOG_ANALYTICS_SHARED_KEY` | The primary key from above. When saved as a valve, it is stored encrypted if `WEBUI_SECRET_KEY` is set. | -| `LOG_ANALYTICS_LOG_TYPE` | Valve only. The name of the custom log. Default: `OpenWebuiMetrics`. | +## Record fields and sending -When sending is on, each response creates one record with `timestamp` (UTC, ISO 8601 with `Z`), `chatId`, `messageId`, `model`, `userId`, `responseTime`, `requestTokens`, `responseTokens`, `tokensPerSecond` and `tokensEstimated`. With `CALCULATE_ALL_MESSAGES` and `SHOW_AVERAGE_TOKENS` on (the default), it also has `avgRequestTokens` and `avgResponseTokens`. Log Analytics adds a type suffix to the names of custom fields, for example `requestTokens_d` and `tokensEstimated_b`. +When sending is on, each response creates one record with `timestamp` (UTC, ISO 8601 with `Z`), `chatId`, `messageId`, `model`, `userId`, `responseTime`, `requestTokens`, `responseTokens`, `tokensPerSecond` and `tokensEstimated`. With `CALCULATE_ALL_MESSAGES` and `SHOW_AVERAGE_TOKENS` on (the default), it also has `avgRequestTokens` and `avgResponseTokens`. Both APIs get the same record. -The filter sends the record in the background, so the response does not wait for Log Analytics. A send that takes longer than 10 seconds, or more than 5 seconds to connect, is aborted. Failed sends are logged as errors in the Open WebUI log and are not retried. +The filter sends the record in the background, so the response does not wait for Log Analytics. A send that takes longer than 10 seconds, or more than 5 seconds to connect, is aborted; for the Logs Ingestion API the token request has its own 10 second limit. Failed sends are logged in the Open WebUI log and are not retried. > [!NOTE] > Since Open WebUI 0.10, outlet filters also run for requests sent directly to the API (`/api/chat/completions` without a chat). Since version 2.6.2 the filter records these requests as well. They do not belong to a chat, so their `chatId` is a generated UUID. @@ -39,8 +373,8 @@ How the values are measured: ## Show Logs -To view these logs, go to `Logs` > `Custom Logs`. All logs will be listed there. -> It may take a few minutes for the first logs to become visible. +To view these logs, go to `Logs` > `Custom Logs`, or run a query such as `OpenWebuiMetrics_CL | take 10` (or `OpenWebuiMetricsV2_CL` for Option B). +> It may take a few minutes for the first logs to become visible, and 10 to 15 minutes after a schema change. diff --git a/docs/testing.md b/docs/testing.md index 8c59124..5cb5ea9 100644 --- a/docs/testing.md +++ b/docs/testing.md @@ -76,6 +76,8 @@ group adds about 5.5 minutes (query-generation timeouts, the query-generation pa and the 45 s retrieval limit are waited for; with the Azure pipeline 2.8.x of `main`, as in the meta-test, its requests fail at once): with the Azure pipeline 3.0.0 a full run took 790 s (gemini 130 s, azure 420 s, n8n 72 s, infomaniak 36 s, filters 103 s). +The filters `ingest` group (Logs Ingestion API) adds about 2.5 minutes: 1000 s +(gemini 150 s, azure 424 s, n8n 71 s, infomaniak 36 s, filters 259 s). Network downloads on first use come on top (`pip install google-genai` when the Gemini function is created, the tiktoken encodings the `filters` suite caches before its first scenario). How many checks each suite has @@ -149,19 +151,35 @@ events), a **background title task** and that the server log has no unexpected | `azure` | `pipelines/azure/azure_ai_foundry.py` | `mock_azure.py` (requires `api-version`; answers prompts with a `` block like a plain model, without `context`; query generation, embeddings, tool calls, a ~300 KB and a > 4 MiB stream event, `content: null`), `mock_search.py` (Azure AI Search and an App Service managed identity token endpoint, see below) | `valves` (from 3.0.0 also the `AZURE_AI_SEARCH_*` valves, their defaults, enums and the password input of the key, and no `AZURE_AI_SEARCH_MODE`), `models` (`AZURE_AI_MODEL` lists separated by `;`, `,` or spaces with exact names, `AZURE_AI_PIPELINE_PREFIX`, model from an `*.openai.azure.com` URL, predefined and fallback models), `api` (api-key and Bearer header, path and api-version, allow-listed body: extra client keys dropped, tools forwarded, `stream_options` only for streams; JSON 400 (exactly Azure's message, nothing appended) and text/plain 500 errors), `dotted` (`gpt-4.1`, `Phi-3.5-mini-instruct` reach upstream intact, model in header or body), `browser` (full status sequence, error status with exactly Azure's message), `tasks` (title task, also with Azure AI Search valves, #123), `rag` (the pipe's own Azure AI Search retrieval, 3.0.0, #187; `suites/_azure_rag.py`: API and browser path, stream and non-stream, Foundry `/models` endpoint; search request body per `query_type`, query text rules, embeddings for `deployment_name` (v1 route, gateway prefix, Bearer) and `endpoint` (api-version, own key or access token, chat key only on the same scheme, host and port), integrated vectorizer; `fields_mapping` with `select`, separator and fallback, list-valued titles; `filter`, `top_n_documents` (2 x candidates), `strictness` (per query), the api-version valve, the document budget (auto, also with a large `top_n_documents`, valve, unlimited, dropping a document); prompt placement, one block and one system message, `in_scope` and the tool-results clause, `role_information`, sanitizing (also nested tags, titles and file names), list and image-only content, Open WebUI's tool-images message, an attached file (`` and RAG template around the prompt); citations, `context` event and `message.context`, scores per score type and with `AZURE_AI_INCLUDE_SEARCH_SCORES` off; `[docX]` → links, also split across stream deltas (API and browser, also without a finish chunk; in API streams all text before `[DONE]` and nothing after it), already linked or with parentheses in the URL (stream and non-stream), with a dotted deployment name; links in the history sent back as `[docX]` (also links saved before 2.8.0 with `)` in the URL; a hostile history line in linear time); only referenced sources saved and the show-all valve (also for an answer that cites only a document the search did not return, `[doc9]`, or one next to `[doc1]`); a context event over 128 KiB, an upstream event of ~300 KB (read and passed on) and one over 4 MiB (an error, API and browser); `content: null`; tool rounds (one search, reused only by a tool round of the same message with unchanged valves, no duplicate sources also when the tool round references a document, a non-stream tool call), tools and `stream_options` forwarded, tasks without retrieval and without `data_sources` (also for a saved chat without a websocket session); query generation (follow-ups, `always` / `off`, transcript with Open WebUI's conversation summary, max queries, `` with draft queries, fallback also for JSON nested too deep, partial and all-failed results, merge order by reciprocal rank fusion and reranker score, model in the body, the pause after 3 timeouts in a row: per model, reset by a success, still on after 16 s); auth: key, key valve, access token, system- and user-assigned managed identity (`mi_res_id`), token errors; fail-closed errors with a terminal status (HTTP 500/403/402/404/400/302/429/503, connection, retries, the 45 s retrieval limit, an answer larger than 16 MB, configuration errors, client `data_sources` (API stream and non-stream and the browser path as from an inlet filter: the error naming the removal of On Your Data in 3.0.0, the pipe's ERROR line and the terminal error status, nothing forwarded; an empty list is ignored), `context_length_exceeded` (exactly Azure's message and the budget hint)); Stop during a search and during query generation; `AZURE_AI_SEARCH_MODE=on_your_data` stored by a 2.9.0 pre-release or set in the environment is ignored; `log.debug`: the staged file run in the driver process with every logger at DEBUG logs no key or token, see below; `notice.none`: no On Your Data retirement notice of 2.8.1 in the server log), `logs` (no API key, no search key or token, no citation text, no generated queries, document titles or URLs in the server log at INFO and above) | | `n8n` | `pipelines/n8n/n8n.py` | `mock_n8n.py` | `api` (request payload contract, bearer / Cloudflare headers, usage, `intermediateSteps` tool display with verbosity and truncation, `` blocks, history / `INPUT_FIELD` / `RESPONSE_FIELD` valves, plain text, NDJSON, SSE streams in separate and coalesced writes with plain lines and `event:` / `id:` / `retry:` fields, OpenAI-style chunks, UTF-8 characters split across writes, braces inside strings, a large object trickling in as small writes (server CPU), webhook error), `browser` (saved answer, usage and final status for JSON, NDJSON, UTF-8, an n8n error chunk, a broken stream and a webhook error; chat context sent to the workflow for chat turns vs. background tasks; Stop during a stream and a non-stream request), `tasks` (title task without and with a chat id) | | `infomaniak` | `pipelines/infomaniak/infomaniak.py` | `mock_infomaniak.py` | `models` (llm models only, `NAME_PREFIX`), `api` (product id and bearer key, allow-listed body, SSE stream normal, coalesced into one write and split mid-JSON; OpenAI-style and Infomaniak `error.description` errors with one log line each), `browser` (saved answer, usage and status events for those streams plus no final newline, CRLF, a broken stream and an upstream error; Stop during the stream and while waiting for the response headers), `tasks` | -| `filters` | `filters/*.py` + probe pipe | `mock_la.py` (Azure Log Analytics Data Collector API; the suite starts it, see below) | `model` / `global` (filters attached per model via `meta.filterIds` and as global filters: `features.web_search` → `__metadata__.features.google_search_tool`, `vertex_ai_search` + `VERTEX_AI_RAG_STORE`, API request without `features`, `time_token_tracker` outlet on the API path with exact token counts, its status in the browser path, background task without `__event_emitter__`), `spec` (`SEND_TO_LOG_ANALYTICS` env parsing, encrypted shared key, valve names), `la` (Log Analytics records: signature, headers, payload and exact counts on the API and browser path, special tokens, multi-turn averages, sending switched off, HTTP errors, a slow and a hanging endpoint do not delay the answer, estimate marker), `valves` (compact status), `correlation` (inlet/outlet correlation when Open WebUI rewrites the last user message, concurrent identical requests), `encoding` (model-specific encoding, `gpt-4o` → `o200k_base`), `offline` (the tiktoken download hangs: estimates, one load at a time, retry, server not blocked), `multimodel` (multi-model chat and the features dict the models share), `search` (`google_search_tool` with features `{}`, `null` or without web_search, other feature keys kept, no per-user permission check), `vertex` (per-request data store, store only with the feature, `features: null`) | +| `filters` | `filters/*.py` + probe pipe | `mock_la.py` (Azure Log Analytics: HTTP Data Collector API, Logs Ingestion API, Microsoft Entra ID token endpoint, managed identity endpoints; the suite starts it, see below) | `model` / `global` (filters attached per model via `meta.filterIds` and as global filters: `features.web_search` → `__metadata__.features.google_search_tool`, `vertex_ai_search` + `VERTEX_AI_RAG_STORE`, API request without `features`, `time_token_tracker` outlet on the API path with exact token counts, its status in the browser path, background task without `__event_emitter__`), `spec` (`SEND_TO_LOG_ANALYTICS` env parsing, encrypted shared key and client secret, Logs Ingestion valve defaults, valve names), `la` (Log Analytics records through the HTTP Data Collector API: signature, headers, payload and exact counts on the API and browser path, special tokens, multi-turn averages, sending switched off, HTTP errors, a slow and a hanging endpoint do not delay the answer, estimate marker), `ingest` (Logs Ingestion API, #188: request shape and 204, token cache (scope and tenant in its key) / concurrency / refresh, refresh failure with a still-valid token (also inside the back-off), the 30 s token back-off (still on after 20 s) and its end, token and HTTP errors with one log line each including a second revocation, a late 401 for a replaced token and a persistent 401, a secret echoed across the cut points of an error text, undecryptable secret, https-only endpoint and authority and other invalid settings, slow / hanging / unreachable endpoints, mode selection and fallback, `both` (also with one side incomplete), deprecation warning, sovereign cloud valves, App Service (also its `{statusCode, message, correlationId}` error) / IMDS (without proxy) / workload identity, no secret or token in the log, DEBUG lines included), `valves` (compact status), `correlation` (inlet/outlet correlation when Open WebUI rewrites the last user message, concurrent identical requests), `encoding` (model-specific encoding, `gpt-4o` → `o200k_base`), `offline` (the tiktoken download hangs: estimates, one load at a time, retry, server not blocked), `multimodel` (multi-model chat and the features dict the models share), `search` (`google_search_tool` with features `{}`, `null` or without web_search, other feature keys kept, no per-user permission check), `vertex` (per-request data store, store only with the feature, `features: null`) | The **probe pipe** (`tests/e2e/probe/probe_pipe.py`) answers with a JSON report of what Open WebUI handed it (body keys, model and messages, `__metadata__` features / params / model id, `__task__`, whether an `__event_emitter__` exists), so filter → pipe coupling is tested without a provider. `PROBE_SLEEP=` in the last user message delays its answer (overlapping requests), `PROBE_SLEEP[]=` only that model's answer -(multi-model chats). +(multi-model chats). `PROBE_ENV=` sets (or, for `null`, removes) the environment +variables of a JSON object in that file in the server process, for an allow-list of +managed identity, workload identity and proxy variables only; the `ingest` group uses +it to switch between App Service, IMDS and workload identity without a restart and +puts the container's own `IDENTITY_ENDPOINT` / `IDENTITY_HEADER` (set by `run.sh` for +the azure suite) back at its end. The values go through the file, never through the +chat text. `PROBE_LOG=` writes +everything the `time_token_tracker` logger logs, DEBUG included, to that file +(`PROBE_LOG=off` stops it): the server log runs at INFO, so the `filters` suite captures +the tracker's DEBUG output while its Log Analytics groups run (`tracker_debug.log` in +the output directory) and checks it for plaintext secrets (`log.no-secrets-debug`). The `filters` suite sets up the Log Analytics mock itself: it maps the workspace host -`.ods.opinsights.azure.com` to 127.0.0.1 in the container's `/etc/hosts`, installs -a throw-away test CA into the container's trust store and starts `mocks/mock_la.py` -(HTTPS on 127.0.0.1:443, control routes on :9105). It also creates the user +`.ods.opinsights.azure.com`, the login hosts `login.microsoftonline.com` / +`login.microsoftonline.us` and two DCR ingestion hosts to 127.0.0.1 and an +unreachable DCR host to 127.0.0.9 in the container's `/etc/hosts` (the login and DCR +lines are removed again at the end), installs a throw-away test CA into the container's +trust store (kept across `--reuse` runs, valid 30 days; the server certificate lists +every mapped host and is reissued when a name is missing) and starts +`mocks/mock_la.py` (HTTPS on 127.0.0.1:443, control routes on :9105, managed identity +endpoints on 127.0.0.1:9107 and 127.0.0.2:9107). The `ingest` group takes about two +and a half minutes, mostly timeout, token-expiry and token back-off waits. It also creates the user `filters-user@example.com`; the `gemini` suite creates `e2e-gemini-user@example.com`. The `offline` group needs a fresh container (tiktoken keeps loaded encodings per process), so do not rerun it with `--reuse`. @@ -190,8 +208,9 @@ values among them), so a DEBUG server log cannot show what the pipe logs. Instea query generation, errors, client `data_sources` with a key, also streamed); no log record may contain a key or token. -Checks per suite on Open WebUI v0.11.4-slim in strict known mode (observed 2026-10-10 on -branch `feature/azure-search-pipeline-mode` with the Azure pipeline 3.0.0): +Checks per suite on Open WebUI v0.11.4-slim in strict known mode (observed 2026-10-10, +`main` 4b80e24 (Azure pipeline 3.0.0) plus the Logs Ingestion API of #188: 2 new +`spec` checks, the `ingest` group with 41 and `log.no-secrets-debug`): | Suite | Checks | PASS / KNOWN | | --- | ---: | ---: | @@ -199,10 +218,10 @@ branch `feature/azure-search-pipeline-mode` with the Azure pipeline 3.0.0): | `azure` | 198 | 198 / 0 | | `n8n` | 51 | 51 / 0 | | `infomaniak` | 32 | 31 / 1 | -| `filters` | 57 | 57 / 0 | -| **all** | **419** | **418 / 1** | +| `filters` | 101 | 101 / 0 | +| **all** | **463** | **462 / 1** | -There is no FAIL and no obsolete marker; `v0.11.3-slim` gives the same azure counts. +No FAIL and no obsolete marker; `v0.11.3-slim` gives the same azure and filters counts. `harness/known_*.py` registers one known bug, `infomaniak-name-prefix` (`NAME_PREFIX` is read only once, no fix yet, `fixed_in=""`): the one KNOWN. The markers of the 62 bugs fixed by #182-#185 were dropped after the merge; their checks stay and must pass. @@ -290,6 +309,7 @@ The output directory contains: | `summary.md` | Markdown summary (used as GitHub Actions job summary), with notes on partial results and cut-short mock answers | | `server.log` | output of the Open WebUI server (`/tmp/e2e/server.log` in the container, the same text as `docker logs`) | | `mocks.txt` | output of the mock servers | +| `mock_la.txt`, `tracker_debug.log` | `filters` suite only: output of the Log Analytics mock, and what `time_token_tracker` logged (DEBUG included) while the Log Analytics groups ran | | `functions/` | the exact function files that were tested (converted to LF line endings), plus `SOURCES.txt` (where they came from) | `results.json` and `summary.md` are also written when the run is cut short (Ctrl-C, @@ -390,7 +410,7 @@ suites/ one module per suite: GROUPS + async def run(t: Suite); _*. helper modules (e.g. _azure_rag.py, the azure rag group), not suites mocks/ aiohttp provider mocks + serve_all.py (127.0.0.1:9101-9104 and :9106 in the container); mock_la.py (Log Analytics) is started by the filters - suite (:443, :9105) + suite (:443, :9105, :9107) probe/probe_pipe.py test-only pipe reporting what Open WebUI passes to a pipe ``` diff --git a/filters/time_token_tracker.py b/filters/time_token_tracker.py index 8e042fe..dced3e0 100644 --- a/filters/time_token_tracker.py +++ b/filters/time_token_tracker.py @@ -4,18 +4,19 @@ author_url: https://github.com/owndev/ project_url: https://github.com/owndev/Open-WebUI-Functions funding_url: https://github.com/sponsors/owndev -version: 2.6.2 +version: 2.7.0 required_open_webui_version: 0.8.0 license: Apache License 2.0 -description: A filter for tracking the response time and token usage of a request with Azure Log Analytics integration. +description: A filter for tracking the response time and token usage of a request with Azure Log Analytics integration (Logs Ingestion API or the deprecated HTTP Data Collector API). features: - Tracks the response time of a request. - Tracks Token Usage. - Calculates the average tokens per message. - Calculates the tokens per second. - - Sends metrics to Azure Log Analytics in the background (10 s timeout), so responses do not wait for it. + - Sends metrics to Azure Log Analytics in the background (10 s timeout), so responses do not wait for it: through the Azure Monitor Logs Ingestion API (data collection rule, Microsoft Entra ID token from a client secret, a managed identity on App Service / Functions / Container Apps / VMs, or AKS workload identity; tokens are cached and refreshed before they expire), or through the deprecated HTTP Data Collector API (shared key) as a fallback. LOG_ANALYTICS_INGESTION_API selects auto, logs_ingestion, data_collector or both. - Falls back to a len(text) // 4 token estimate while no tiktoken encoding is loaded (e.g. offline), without holding up requests. Estimates are marked (tokensEstimated in the record and the log line, "~" in the status). changelog: + - 2.7.0 - Azure Monitor Logs Ingestion API (#188). New valves LOG_ANALYTICS_INGESTION_API, LOG_ANALYTICS_DCR_ENDPOINT, LOG_ANALYTICS_DCR_IMMUTABLE_ID, LOG_ANALYTICS_DCR_STREAM_NAME, LOG_ANALYTICS_AUTH_MODE, LOG_ANALYTICS_TENANT_ID, LOG_ANALYTICS_CLIENT_ID, LOG_ANALYTICS_CLIENT_SECRET, LOG_ANALYTICS_AUTHORITY_HOST and LOG_ANALYTICS_INGESTION_SCOPE, all with environment variable defaults; LOG_ANALYTICS_LOG_TYPE can now also be set by environment variable (an installation that set that variable before, when it was ignored, and never saved the valve now sends to that log type; an empty variable counts as unset). With the default "auto", records go to the Logs Ingestion API as soon as its settings are complete, otherwise through the HTTP Data Collector API exactly as in 2.6.2, which now logs a one-time deprecation warning. Tokens (client secret, managed identity, AKS workload identity) are requested without extra packages, cached per identity and refreshed before they expire; concurrent records share one token request, and a failed refresh keeps using the still-valid token. After a failed token request, or when fresh tokens keep being rejected (401), new token requests pause for 30 s. Endpoint and authority must use https. Any 2xx counts as success (the API answers 204). 400, 401, 403, 404, 413 and 429 are logged once each with a hint (scope, role assignment, DCR ID, stream name, 1 MB limit, Retry-After); records are not retried. "both" writes each record to both APIs for a side-by-side migration. - 2.6.2 - Open WebUI >= 0.10 compatibility. outlet() no longer raises a TypeError when Open WebUI runs outlet filters without an event emitter (API requests), so the Log Analytics send and later outlet filters are no longer skipped; the Log Analytics send no longer depends on the status event, a missing chat id falls back to a generated one, and messageId is the message id Open WebUI passes to the outlet (generated if absent). Open WebUI awaits outlet() before it returns an API response, so the Log Analytics send now runs in a background task with its own timeout (10 s, 5 s to connect) instead of AIOHTTP_CLIENT_TIMEOUT (no timeout by default); a slow or unreachable Log Analytics endpoint no longer delays or stalls responses. The record timestamp is UTC with a "Z" suffix, and the new boolean record field tokensEstimated tells estimated token counts from exact ones. SEND_TO_LOG_ANALYTICS="false" (or any value other than 1/true/yes/on) now disables the send instead of enabling it. A tiktoken encoding that cannot be loaded (offline, no cache) or a text it cannot encode no longer aborts the chat; token counts fall back to an estimate. The encoding is loaded in a worker thread, one load per encoding at a time; requests that arrive while it loads estimate instead of waiting, only the request that starts the first load waits (at most 5 s), and a failed load is retried in the background at most every 5 minutes. inlet() and outlet() are correlated through the request's __metadata__ (shared by both on Open WebUI 0.11), so the metrics stay correct when Open WebUI changes the last user message after the inlet (RAG context, legacy code interpreter prompt); the message fingerprint remains the fallback. - 2.6.1 - Replaced global variables with per-request fingerprinted storage to mitigate concurrency issues. Uses a hash of user ID, model, and the last user message to correlate inlet/outlet calls. Adds TTL-based cleanup for stale entries. Note: Open WebUI does not expose a guaranteed per-request ID in both inlet and outlet, so edge-case collisions remain theoretically possible when identical messages are sent simultaneously by anonymous users. """ @@ -28,10 +29,13 @@ import base64 import hashlib import datetime +import math import os +import re import logging import aiohttp from typing import Optional, Any +from urllib.parse import quote, quote_plus from open_webui.env import SRC_LOG_LEVELS from cryptography.fernet import Fernet, InvalidToken import tiktoken @@ -80,6 +84,168 @@ # default, which means no timeout at all. _LOG_ANALYTICS_TIMEOUT = aiohttp.ClientTimeout(total=10, sock_connect=5) +# Azure Monitor Logs Ingestion API (data collection rules, Microsoft Entra ID). +# A token is requested once per identity (cache key), not once per record: +# concurrent records wait on one lock per key and share the result. A token is +# refreshed _TOKEN_REFRESH_MARGIN seconds before it expires (at the latest at +# half its lifetime). When a refresh fails, the still-valid cached token keeps +# being used until _TOKEN_EXPIRY_SKEW seconds (at most a quarter of its +# lifetime) before it expires, so a short Entra ID or proxy outage loses no +# records. A failed token request, or a second 401 in a row, blocks new token +# requests for that key for _TOKEN_RETRY_INTERVAL seconds; records without a +# usable token are dropped meanwhile instead of sending one token request each. +# These dicts hold only access tokens, timestamps and keys: never the client +# secret, the IDENTITY_HEADER or the federated assertion, nor a hash of them. +_LOGS_INGESTION_API_VERSION = "2023-01-01" +_DEFAULT_AUTHORITY_HOST = "https://login.microsoftonline.com" +_DEFAULT_INGESTION_SCOPE = "https://monitor.azure.com/.default" +_IMDS_AUTHORITY = "http://169.254.169.254" +_TOKEN_REFRESH_MARGIN = 300 +_TOKEN_EXPIRY_SKEW = 60 +_TOKEN_RETRY_INTERVAL = 30 +# key -> (token, refresh_at, usable_until), time.monotonic() based +_ingestion_tokens: dict[tuple, tuple[str, float, float]] = {} +_ingestion_token_locks: dict[tuple, asyncio.Lock] = {} +_ingestion_token_failures: dict[tuple, float] = {} # key -> monotonic failure time +_ingestion_token_rejected: set[tuple] = set() # last token got a 401, no 2xx since +# One-time warnings (deprecation, incomplete settings): once per process. +_log_analytics_warnings: set[str] = set() + +_INGESTION_API_MODES = ("auto", "logs_ingestion", "data_collector", "both") +_AUTH_MODES = ("client_secret", "managed_identity") +_DCR_IMMUTABLE_ID = re.compile(r"dcr-[0-9a-fA-F]{32}") +_JWT_BEARER = "urn:ietf:params:oauth:client-assertion-type:jwt-bearer" +_DATA_COLLECTOR_DEPRECATION = ( + "Log Analytics: sending through the HTTP Data Collector API, which Microsoft " + "deprecated (support ended on 2026-09-14). Set up the Logs Ingestion API " + "(LOG_ANALYTICS_DCR_ENDPOINT, LOG_ANALYTICS_DCR_IMMUTABLE_ID and a Microsoft " + "Entra ID identity), see docs/setup-azure-log-analytics.md. This warning is " + "logged once." +) +# Token sources (managed identity is detected from the environment). +_TOKEN_SOURCE_LABELS = { + "client_secret": "client secret", + "app_service": "managed identity (App Service)", + "imds": "managed identity (IMDS)", + "workload_identity": "workload identity", + "service_fabric": "managed identity (Service Fabric)", + "azure_arc": "managed identity (Azure Arc)", + "cloud_shell": "managed identity (Cloud Shell / Azure ML)", + "identity_binding": "workload identity (AKS identity binding)", +} +_UNSUPPORTED_TOKEN_SOURCES = { + "service_fabric": "managed identity on Service Fabric", + "azure_arc": "managed identity on Azure Arc", + "cloud_shell": "managed identity on Cloud Shell / Azure ML", + "identity_binding": "AKS identity bindings (AZURE_KUBERNETES_TOKEN_PROXY)", +} +# Hints for Microsoft Entra ID error codes (error_codes[0], never the text). +_AADSTS_HINTS = { + 7000215: "invalid client secret: use the secret's value, not its ID " + "(LOG_ANALYTICS_CLIENT_SECRET).", + 7000222: "the client secret has expired: create a new one.", + 700016: "application not found in the tenant: check LOG_ANALYTICS_CLIENT_ID, " + "LOG_ANALYTICS_TENANT_ID and LOG_ANALYTICS_AUTHORITY_HOST.", + 90002: "tenant not found: check LOG_ANALYTICS_TENANT_ID and " + "LOG_ANALYTICS_AUTHORITY_HOST (cloud).", + 70011: "check LOG_ANALYTICS_INGESTION_SCOPE (it must match the cloud).", + 500011: "check LOG_ANALYTICS_INGESTION_SCOPE (it must match the cloud).", + 700212: "the federated token has the wrong audience (direct federation needs " + "api://AzureADTokenExchange).", +} +# The App Service / Container Apps token service answers 400 ("Unable to load +# the proper Managed Identity.") for an unknown user-assigned client ID, or for +# the system-assigned identity when only user-assigned ones are assigned. +_APP_SERVICE_400_HINT = ( + "check LOG_ANALYTICS_CLIENT_ID: the client ID of a user-assigned identity of " + "this app, or empty for its enabled system-assigned identity." +) +_IMDS_UNREACHABLE = ( + "no managed identity endpoint reachable (not running on Azure, or no identity " + "assigned)" +) +# Off Azure, 169.254.169.254 usually hangs until sock_connect instead of refusing. +_CONNECT_ERRORS = ( + aiohttp.ClientConnectorError, + getattr(aiohttp, "ConnectionTimeoutError", aiohttp.ServerTimeoutError), +) + + +class _TokenError(Exception): + """A token request failed; the message is safe to log (no secret, no token).""" + + +def _read_text(path: str) -> str: + with open(path, encoding="utf-8") as fh: + return fh.read() + + +def _normalize_url(value: str) -> str: + """Strip, drop trailing slashes and add https:// when there is no scheme.""" + value = value.strip().rstrip("/") + if value and "://" not in value: + value = "https://" + value + return value + + +def _first_line(text: Any) -> str: + lines = str(text or "").strip().splitlines() + return lines[0].strip() if lines else "" + + +def _redact(text: str, secrets) -> str: + """Replace every non-empty secret (also URL-encoded) with ***.""" + forms = set() + for secret in secrets: + if secret: + forms.update( + {secret, quote(secret), quote(secret, safe=""), quote_plus(secret)} + ) + for form in sorted(forms, key=len, reverse=True): + text = text.replace(form, "***") + return text + + +def _token_source(cfg: dict) -> tuple[str, str, str]: + """(source, effective tenant, effective client id) for this request. + + Managed identity is detected from the environment in the order + azure-identity uses, on every call (the platform may change it). + """ + if cfg["auth_mode"] == "client_secret": + return "client_secret", cfg["tenant"], cfg["client_id"] + env = os.environ + if env.get("IDENTITY_ENDPOINT"): + if env.get("IDENTITY_HEADER"): + if env.get("IDENTITY_SERVER_THUMBPRINT"): + return "service_fabric", "", cfg["client_id"] + return "app_service", "", cfg["client_id"] + if env.get("IMDS_ENDPOINT"): + return "azure_arc", "", cfg["client_id"] + elif env.get("MSI_ENDPOINT"): + return "cloud_shell", "", cfg["client_id"] + elif env.get("AZURE_FEDERATED_TOKEN_FILE"): + tenant = cfg["tenant"] or env.get("AZURE_TENANT_ID", "").strip() + client_id = cfg["client_id"] or env.get("AZURE_CLIENT_ID", "").strip() + if env.get("AZURE_KUBERNETES_TOKEN_PROXY"): + return "identity_binding", tenant, client_id + return "workload_identity", tenant, client_id + return "imds", "", cfg["client_id"] + + +def _token_lifetime(payload: dict) -> float: + """Seconds until the token expires (expires_in, else expires_on).""" + try: + if payload.get("expires_in") is not None: + lifetime = float(payload["expires_in"]) + else: + lifetime = float(payload.get("expires_on")) - time.time() + except (TypeError, ValueError): + lifetime = math.nan + if not (math.isfinite(lifetime) and lifetime >= 1): + raise _TokenError("token response without a usable expiry") + return lifetime + def _build_request_key(body: dict, user: Optional[dict] = None) -> str: """ @@ -268,7 +434,71 @@ class Valves(BaseModel): json_schema_extra={"input": {"type": "password"}}, ) LOG_ANALYTICS_LOG_TYPE: str = Field( - default="OpenWebuiMetrics", description="Log Analytics log type name." + # An empty variable (compose: LOG_ANALYTICS_LOG_TYPE=${UNSET}) counts + # as unset: 2.6.2 ignored the variable, and an empty log type breaks + # both APIs. + default=os.getenv("LOG_ANALYTICS_LOG_TYPE", "").strip() + or "OpenWebuiMetrics", + description="Log Analytics log type name (HTTP Data Collector API); " + "also the base of the default stream name Custom-_CL.", + ) + LOG_ANALYTICS_INGESTION_API: str = Field( + default=os.getenv("LOG_ANALYTICS_INGESTION_API", "auto"), + description="auto (Logs Ingestion API once its settings are complete, " + "otherwise the deprecated HTTP Data Collector API), logs_ingestion, " + "data_collector or both (side-by-side migration).", + ) + LOG_ANALYTICS_DCR_ENDPOINT: str = Field( + default=os.getenv("LOG_ANALYTICS_DCR_ENDPOINT", ""), + description="Logs ingestion endpoint of the data collection rule " + "(https://--.logs.z1.ingest.monitor.azure.com) or " + "a data collection endpoint (required for private link).", + ) + LOG_ANALYTICS_DCR_IMMUTABLE_ID: str = Field( + default=os.getenv("LOG_ANALYTICS_DCR_IMMUTABLE_ID", ""), + description="Immutable ID of the data collection rule (dcr-...).", + ) + LOG_ANALYTICS_DCR_STREAM_NAME: str = Field( + default=os.getenv("LOG_ANALYTICS_DCR_STREAM_NAME", ""), + description="Stream name in the data collection rule. Empty: " + "Custom-_CL (e.g. Custom-OpenWebuiMetrics_CL).", + ) + LOG_ANALYTICS_AUTH_MODE: str = Field( + default=os.getenv("LOG_ANALYTICS_AUTH_MODE", "client_secret"), + description="client_secret (app registration) or managed_identity " + "(App Service, Functions, Container Apps, VMs, AKS workload identity).", + ) + LOG_ANALYTICS_TENANT_ID: str = Field( + default=os.getenv("LOG_ANALYTICS_TENANT_ID", ""), + description="Microsoft Entra ID tenant (GUID or domain). Workload " + "identity falls back to AZURE_TENANT_ID.", + ) + LOG_ANALYTICS_CLIENT_ID: str = Field( + default=os.getenv("LOG_ANALYTICS_CLIENT_ID", ""), + description="Application (client) ID of the app registration; with " + "managed_identity the client ID of a user-assigned identity (empty: " + "system-assigned). Workload identity falls back to AZURE_CLIENT_ID.", + ) + LOG_ANALYTICS_CLIENT_SECRET: EncryptedStr = Field( + default=os.getenv("LOG_ANALYTICS_CLIENT_SECRET", ""), + description="Client secret value (not the secret ID) of the app " + "registration.", + json_schema_extra={"input": {"type": "password"}}, + ) + LOG_ANALYTICS_AUTHORITY_HOST: str = Field( + default=os.getenv( + "LOG_ANALYTICS_AUTHORITY_HOST", "https://login.microsoftonline.com" + ), + description="Microsoft Entra ID authority: " + "https://login.microsoftonline.us (US Government), " + "https://login.partner.microsoftonline.cn (21Vianet).", + ) + LOG_ANALYTICS_INGESTION_SCOPE: str = Field( + default=os.getenv( + "LOG_ANALYTICS_INGESTION_SCOPE", "https://monitor.azure.com/.default" + ), + description="Token scope: https://monitor.azure.us/.default (US " + "Government), https://monitor.azure.cn/.default (21Vianet).", ) def __init__(self): @@ -303,9 +533,184 @@ def _build_signature(self, date, content_length, method, content_type, resource) ) return authorization + def _warn_once(self, text: str, key: Optional[str] = None) -> None: + """Log a WARNING once per process (per ``key``, default the text).""" + key = key or text + if key not in _log_analytics_warnings: + _log_analytics_warnings.add(key) + self.log.warning(text) + + def _ingestion_api_mode(self) -> str: + """LOG_ANALYTICS_INGESTION_API normalized; unknown values mean auto.""" + raw = str(self.valves.LOG_ANALYTICS_INGESTION_API or "").strip() + mode = raw.lower().replace("-", "_") or "auto" + if mode not in _INGESTION_API_MODES: + self._warn_once( + f"Log Analytics: unknown LOG_ANALYTICS_INGESTION_API value " + f"{raw[:32]!r} (use auto, logs_ingestion, data_collector or both); " + f"using auto" + ) + mode = "auto" + return mode + + def _logs_ingestion_config(self) -> tuple[dict, list]: + """ + Snapshot of the Logs Ingestion settings of this request, normalized, + and the names of the missing (or invalid) valves. + + The background task must not read self.valves (Open WebUI swaps them + per request). client_secret stays the stored, still encrypted value; + it is decrypted only for the token request. Without WEBUI_SECRET_KEY, + or for an environment default, it is plaintext: never log cfg as a + whole, only its non-secret fields. + """ + v = self.valves + + def text(value) -> str: + return str(value or "").strip() + + log_type = text(v.LOG_ANALYTICS_LOG_TYPE) + auth_raw = text(v.LOG_ANALYTICS_AUTH_MODE) + cfg = { + "endpoint": _normalize_url(text(v.LOG_ANALYTICS_DCR_ENDPOINT)), + "dcr_id": text(v.LOG_ANALYTICS_DCR_IMMUTABLE_ID), + "stream": text(v.LOG_ANALYTICS_DCR_STREAM_NAME) + or (f"Custom-{log_type}_CL" if log_type else ""), + "auth_mode": auth_raw.lower().replace("-", "_") or "client_secret", + "authority": _normalize_url(text(v.LOG_ANALYTICS_AUTHORITY_HOST)) + or _DEFAULT_AUTHORITY_HOST, + "tenant": text(v.LOG_ANALYTICS_TENANT_ID), + "client_id": text(v.LOG_ANALYTICS_CLIENT_ID), + "client_secret": text(v.LOG_ANALYTICS_CLIENT_SECRET), + "scope": text(v.LOG_ANALYTICS_INGESTION_SCOPE) or _DEFAULT_INGESTION_SCOPE, + } + missing = [] + if not cfg["endpoint"]: + missing.append("LOG_ANALYTICS_DCR_ENDPOINT") + elif not cfg["endpoint"].lower().startswith("https://"): + missing.append("LOG_ANALYTICS_DCR_ENDPOINT (must use https)") + if not cfg["dcr_id"]: + missing.append("LOG_ANALYTICS_DCR_IMMUTABLE_ID") + if not cfg["stream"]: + missing.append("LOG_ANALYTICS_DCR_STREAM_NAME") + if cfg["auth_mode"] not in _AUTH_MODES: + missing.append(f"LOG_ANALYTICS_AUTH_MODE (unknown value {auth_raw[:32]!r})") + if not cfg["authority"].lower().startswith("https://"): + missing.append("LOG_ANALYTICS_AUTHORITY_HOST (must use https)") + if cfg["auth_mode"] == "client_secret": + for name, field in ( + ("LOG_ANALYTICS_TENANT_ID", "tenant"), + ("LOG_ANALYTICS_CLIENT_ID", "client_id"), + ("LOG_ANALYTICS_CLIENT_SECRET", "client_secret"), + ): + if not cfg[field]: + missing.append(name) + return cfg, missing + + def _logs_ingestion_partial(self) -> bool: + """True when any valve that only the Logs Ingestion API uses is set.""" + v = self.valves + names = ( + "LOG_ANALYTICS_DCR_ENDPOINT", + "LOG_ANALYTICS_DCR_IMMUTABLE_ID", + "LOG_ANALYTICS_DCR_STREAM_NAME", + "LOG_ANALYTICS_TENANT_ID", + "LOG_ANALYTICS_CLIENT_ID", + "LOG_ANALYTICS_CLIENT_SECRET", + ) + auth = str(v.LOG_ANALYTICS_AUTH_MODE or "").strip().lower().replace("-", "_") + if auth not in ("", "client_secret"): + return True + return any(str(getattr(v, name) or "").strip() for name in names) + def _send_to_log_analytics(self, data, chat_id: str, message_id: str) -> bool: """ - Sign the request now and send it to Azure Log Analytics in a + Send the record through the API(s) LOG_ANALYTICS_INGESTION_API selects, + each in a background task. Returns True if at least one send started. + + The settings are read here, before outlet() returns, so the background + tasks get the valve values of this request. + """ + if not self.valves.SEND_TO_LOG_ANALYTICS: + self.log.debug("Log Analytics send skipped: not configured") + return False + + mode = self._ingestion_api_mode() + dc_missing = [ + name + for name in ("LOG_ANALYTICS_WORKSPACE_ID", "LOG_ANALYTICS_SHARED_KEY") + if not getattr(self.valves, name) + ] + li_cfg, li_missing, li_partial = None, [], False + if mode != "data_collector": + try: + li_cfg, li_missing = self._logs_ingestion_config() + li_partial = self._logs_ingestion_partial() + except Exception as e: + if mode != "auto": + raise + # A bug in the new code must not stop a 2.6.2 configuration. + self._warn_once( + f"Log Analytics: could not evaluate the Logs Ingestion API " + f"settings ({type(e).__name__}); using the HTTP Data Collector API" + ) + li_cfg, li_missing, li_partial = None, ["(error)"], False + li_ready = li_cfg is not None and not li_missing + dc_ready = not dc_missing + + send_li = send_dc = False + if mode == "data_collector": + send_dc = True + elif mode == "logs_ingestion": + send_li = li_ready + if not li_ready: + self._warn_once( + f"Log Analytics: LOG_ANALYTICS_INGESTION_API=logs_ingestion, but " + f"the Logs Ingestion API is not fully configured (missing: " + f"{', '.join(li_missing)}); records are not sent" + ) + elif mode == "both": + send_li, send_dc = li_ready, dc_ready + if not li_ready and not dc_ready: + self._warn_once( + f"Log Analytics: LOG_ANALYTICS_INGESTION_API=both, but neither API " + f"is fully configured (missing: " + f"{', '.join(li_missing + dc_missing)}); records are not sent" + ) + elif not li_ready or not dc_ready: + api = ( + "Logs Ingestion API" if not li_ready else "HTTP Data Collector API" + ) + self._warn_once( + f"Log Analytics: LOG_ANALYTICS_INGESTION_API=both, but the {api} " + f"is not fully configured (missing: " + f"{', '.join(li_missing or dc_missing)}); sending only through " + f"the other one" + ) + else: # auto + send_li = li_ready + send_dc = not li_ready + if not li_ready and li_partial: + fallback = ( + "using the HTTP Data Collector API" + if dc_ready + else "records are not sent" + ) + self._warn_once( + f"Log Analytics: the Logs Ingestion API is not fully configured " + f"(missing: {', '.join(li_missing)}); {fallback}" + ) + + sent = False + if send_li: + sent = self._send_to_logs_ingestion(li_cfg, data, chat_id, message_id) + if send_dc: + sent = self._send_to_data_collector(data, chat_id, message_id) or sent + return sent + + def _send_to_data_collector(self, data, chat_id: str, message_id: str) -> bool: + """ + Sign the request now and send it to the HTTP Data Collector API in a background task. Returns False when sending is not configured. The request is built here, before outlet() returns, so the background @@ -347,6 +752,7 @@ def _send_to_log_analytics(self, data, chat_id: str, message_id: str) -> bool: "time-generated-field": "timestamp", } + self._warn_once(_DATA_COLLECTOR_DEPRECATION) task = asyncio.create_task( self._post_to_log_analytics(uri, headers, data, chat_id, message_id) ) @@ -400,6 +806,399 @@ async def _post_to_log_analytics( ) return False + def _send_to_logs_ingestion( + self, cfg: dict, data, chat_id: str, message_id: str + ) -> bool: + """Send a record to the Logs Ingestion API in a background task.""" + if not _DCR_IMMUTABLE_ID.fullmatch(cfg["dcr_id"]): + # The value is not logged; once per distinct value. + self._warn_once( + "Log Analytics: LOG_ANALYTICS_DCR_IMMUTABLE_ID does not look like an " + "immutable ID (dcr- followed by 32 hex characters); copy immutableId " + "from the DCR's JSON view, not the DCR name or resource ID", + key=f"dcr-immutable-id:{cfg['dcr_id']}", + ) + self.log.debug( + f"Sending to the Logs Ingestion API (endpoint={cfg['endpoint']}, " + f"dcr={cfg['dcr_id']}, stream={cfg['stream']}, auth={cfg['auth_mode']})" + ) + task = asyncio.create_task( + self._post_to_logs_ingestion(cfg, data, chat_id, message_id) + ) + _log_analytics_sends.add(task) + task.add_done_callback(_log_analytics_sends.discard) + return True + + @staticmethod + def _ingestion_hint(status: int, cfg: dict, retry_after: Optional[str]) -> str: + """Actionable hint for an HTTP error of the Logs Ingestion API.""" + if status == 400: + return ( + "the record does not match the stream declaration of the DCR " + "(columns and types)." + ) + if status == 401: + return ( + "the token was rejected; check that LOG_ANALYTICS_INGESTION_SCOPE " + "matches the cloud of LOG_ANALYTICS_DCR_ENDPOINT." + ) + if status == 403: + return ( + "the identity needs the Monitoring Metrics Publisher role on the " + "data collection rule; a new role assignment can take up to 30 " + "minutes to take effect." + ) + if status == 404: + return ( + f"check LOG_ANALYTICS_DCR_ENDPOINT, LOG_ANALYTICS_DCR_IMMUTABLE_ID " + f"({cfg['dcr_id']}) and LOG_ANALYTICS_DCR_STREAM_NAME ({cfg['stream']})." + ) + if status == 413: + return "the record exceeds the limit of 1 MB per call." + if status == 429: + # Retry-After is seconds or an HTTP date: shown as it came. + value = " ".join(str(retry_after or "").split())[:64] or "not given" + return ( + f"throttled (per DCR: 12,000 requests or 2 GB per minute); " + f"Retry-After: {value}. The record is dropped, not retried." + ) + return "" + + async def _post_to_logs_ingestion( + self, cfg: dict, data, chat_id: str, message_id: str + ) -> bool: + """ + POST a record to the Logs Ingestion API (runs as a background task). + Reads only cfg, never self.valves. Logs one line per failed record. + """ + got = await self._get_ingestion_token(cfg, chat_id, message_id) + if got is None: + return False # already logged + token, key = got + uri = ( + f"{cfg['endpoint']}/dataCollectionRules/{quote(cfg['dcr_id'], safe='')}" + f"/streams/{quote(cfg['stream'], safe='')}" + f"?api-version={_LOGS_INGESTION_API_VERSION}" + ) + request_id = str(uuid.uuid4()) + headers = { + "Authorization": f"Bearer {token}", + "Content-Type": "application/json", + "x-ms-client-request-id": request_id, + } + session = None + response = None + try: + session = aiohttp.ClientSession( + trust_env=True, timeout=_LOG_ANALYTICS_TIMEOUT + ) + response = await session.request( + method="POST", url=uri, json=data, headers=headers + ) + status = response.status + if 200 <= status < 300: + _ingestion_token_rejected.discard(key) + self.log.info( + f"Log Analytics data sent via the Logs Ingestion API " + f"(chat={chat_id}, message={message_id})" + ) + return True + body = await response.text() + code = response.headers.get("x-ms-error-code", "") + detail = "" + try: + payload = json.loads(body) + except ValueError: + payload = None + error = payload.get("error") if isinstance(payload, dict) else None + if isinstance(error, dict): + code = code or str(error.get("code") or "") + detail = str(error.get("message") or "") + detail = " ".join(_redact(detail or body, [token]).split())[:300] + code = " ".join(_redact(code, [token]).split())[:100] + hint = self._ingestion_hint( + status, cfg, response.headers.get("Retry-After") + ) + if status == 401: + self._ingestion_token_unauthorized(key, token) + head = f"{status} {code}" if code else str(status) + self.log.error( + f"Error sending to Logs Ingestion API: {head}: " + f"{hint + ' ' if hint else ''}Response: {detail} " + f"(request={request_id}, chat={chat_id}, message={message_id})" + ) + except Exception as e: + # str() of a timeout is empty: name the exception type. + reason = _redact(f"{type(e).__name__}: {e}", [token]) + self.log.error( + f"Exception when sending to Logs Ingestion API: {reason} " + f"(chat={chat_id}, message={message_id})" + ) + finally: + await cleanup_response(response, session) + return False + + @staticmethod + def _ingestion_token_unauthorized(key: tuple, token: str) -> None: + """ + A 401 from the ingestion endpoint: drop the cached token (only once + for concurrent 401s of the same token). A token fetched right after a + 401 that is rejected too starts the token back-off, so a persistent + 401 (wrong scope or cloud) cannot cause one token request per record. + """ + cached = _ingestion_tokens.get(key) + if not cached or cached[0] != token: + return + _ingestion_tokens.pop(key, None) + if key in _ingestion_token_rejected: + _ingestion_token_failures[key] = time.monotonic() + else: + _ingestion_token_rejected.add(key) + + async def _get_ingestion_token( + self, cfg: dict, chat_id: str, message_id: str + ) -> Optional[tuple[str, tuple]]: + """ + (token, cache key) for the identity in cfg, or None (logged once). + One token request per key at a time; see the module comment. + """ + source, tenant, client_id = _token_source(cfg) + key = ( + cfg["auth_mode"], + source, + cfg["authority"], + tenant, + client_id, + cfg["scope"], + ) + label = _TOKEN_SOURCE_LABELS.get(source, source) + cached = _ingestion_tokens.get(key) + if cached and time.monotonic() < cached[1]: + return cached[0], key + lock = _ingestion_token_locks.setdefault(key, asyncio.Lock()) + async with lock: + now = time.monotonic() + cached = _ingestion_tokens.get(key) # filled while we waited + if cached and now < cached[1]: + return cached[0], key + usable = cached[0] if cached and now < cached[2] else None + failed_at = _ingestion_token_failures.get(key) + if failed_at is not None and now - failed_at < _TOKEN_RETRY_INTERVAL: + if usable: + return usable, key + self.log.warning( + f"Log Analytics record dropped: no usable token for the Logs " + f"Ingestion API ({label}); the last token request failed or its " + f"token was rejected {now - failed_at:.0f}s ago, next token " + f"request in {_TOKEN_RETRY_INTERVAL - (now - failed_at):.0f}s " + f"(chat={chat_id}, message={message_id})" + ) + return None + try: + token, lifetime = await self._request_token( + cfg, source, tenant, client_id + ) + except Exception as e: # always a _TokenError, unless there is a bug + _ingestion_token_failures[key] = time.monotonic() + safe = str(e) if isinstance(e, _TokenError) else type(e).__name__ + keep = ( + f", keeping the cached token for " + f"{cached[2] - time.monotonic():.0f}s" + if usable + else "" + ) + self.log.error( + f"Could not get a Microsoft Entra ID token for the Logs Ingestion " + f"API ({label}){keep}: {safe} (chat={chat_id}, message={message_id})" + ) + return (usable, key) if usable else None + _ingestion_token_failures.pop(key, None) + now = time.monotonic() + _ingestion_tokens[key] = ( + token, + now + max(lifetime - _TOKEN_REFRESH_MARGIN, lifetime / 2), + now + lifetime - min(_TOKEN_EXPIRY_SKEW, lifetime / 4), + ) + return token, key + + @staticmethod + def _token_error_text( + source: str, status: int, payload: Any, body: str, secrets: list + ) -> str: + """ + Loggable text of a failed token response. Every field is redacted + before it is truncated: a secret cut by the truncation would no longer + match and a fragment of it would be logged. + """ + + def field(value: Any, limit: int) -> str: + return " ".join(_redact(str(value or ""), secrets).split())[:limit] + + if not isinstance(payload, dict): + return f"{status} response: {_redact(_first_line(body), secrets)[:200]}" + description = _redact(_first_line(payload.get("error_description")), secrets) + if source not in ("client_secret", "workload_identity"): + # IMDS answers {error, error_description}; App Service, Functions + # and Container Apps answer {statusCode, message, correlationId}. + error = field(payload.get("error"), 100) + if not description: + description = _redact(_first_line(payload.get("message")), secrets) + description = description[:200] or "no error description" + if source == "app_service" and status == 400: + description = f"{_APP_SERVICE_400_HINT} Detail: {description}" + text = f"{status} {error} - " if error else f"{status} - " + text += description + correlation_id = field(payload.get("correlationId"), 64) + if correlation_id: + text += f" (correlationId={correlation_id})" + return text + error = field(payload.get("error"), 100) or "error" + description = description[:200] + codes = payload.get("error_codes") + try: + code = int(codes[0]) if isinstance(codes, list) and codes else None + except (TypeError, ValueError): + code = None + head = f"{status} {error}" + (f" AADSTS{code}" if code is not None else "") + hint = _AADSTS_HINTS.get(code) if code is not None else None + text = f"{head}: " + (f"{hint} " if hint else "") + f"Detail: {description}" + ids = [ + f"{name}={field(payload[name], 64)}" + for name in ("trace_id", "correlation_id") + if payload.get(name) + ] + if ids: + text += f" ({', '.join(ids)})" + return text + + async def _request_token( + self, cfg: dict, source: str, tenant: str, client_id: str + ) -> tuple[str, float]: + """ + Request an access token: (token, lifetime in seconds). + + Reads only cfg and the environment, never self.valves. Every failure + leaves as a _TokenError with a redacted text: only this method knows + the plaintext client secret, IDENTITY_HEADER and federated assertion, + which are read here, used once and never stored or logged. + """ + secrets: list = [] + session = None + response = None + try: + if source in _UNSUPPORTED_TOKEN_SOURCES: + raise _TokenError( + f"{_UNSUPPORTED_TOKEN_SOURCES[source]} is not supported; use " + f"LOG_ANALYTICS_AUTH_MODE=client_secret" + ) + scope = cfg["scope"] + resource = ( + scope[: -len("/.default")] if scope.endswith("/.default") else scope + ) + if source in ("client_secret", "workload_identity"): + form = { + "grant_type": "client_credentials", + "client_id": client_id, + "scope": scope, + } + if source == "client_secret": + stored = cfg["client_secret"] + secret = EncryptedStr.decrypt(stored) + if stored.startswith("encrypted:") and ( + EncryptedStr._get_encryption_key() is None + or secret.startswith("encrypted:") + ): + raise _TokenError( + "LOG_ANALYTICS_CLIENT_SECRET could not be decrypted (was " + "WEBUI_SECRET_KEY changed or removed?); enter the client " + "secret again" + ) + secrets.append(secret) + form["client_secret"] = secret + else: + if not tenant or not client_id: + raise _TokenError( + "workload identity needs a tenant and client ID " + "(LOG_ANALYTICS_TENANT_ID / AZURE_TENANT_ID, " + "LOG_ANALYTICS_CLIENT_ID / AZURE_CLIENT_ID)" + ) + token_file = os.environ.get("AZURE_FEDERATED_TOKEN_FILE", "") + try: + assertion = ( + await asyncio.to_thread(_read_text, token_file) + ).strip() + except OSError as e: # the text names the path, not the content + raise _TokenError( + f"AZURE_FEDERATED_TOKEN_FILE could not be read " + f"({type(e).__name__}: {e})" + ) from None + except Exception as e: + raise _TokenError( + f"AZURE_FEDERATED_TOKEN_FILE could not be read " + f"({type(e).__name__})" + ) from None + if not assertion: + raise _TokenError("AZURE_FEDERATED_TOKEN_FILE is empty") + secrets.append(assertion) + form["client_assertion_type"] = _JWT_BEARER + form["client_assertion"] = assertion + url = f"{cfg['authority']}/{quote(tenant, safe='')}/oauth2/v2.0/token" + session = aiohttp.ClientSession( + trust_env=True, timeout=_LOG_ANALYTICS_TIMEOUT + ) + # data=dict: form-encoded (application/x-www-form-urlencoded) + response = await session.post(url, data=form) + else: + params = {"resource": resource} + if client_id: + params["client_id"] = client_id + if source == "app_service": + # Rotated by the platform: read it now, never cache it. + identity_header = os.environ.get("IDENTITY_HEADER", "") + secrets.append(identity_header) + url = os.environ.get("IDENTITY_ENDPOINT", "") + params["api-version"] = "2019-08-01" + headers = {"X-IDENTITY-HEADER": identity_header} + else: # imds + host = os.environ.get("AZURE_POD_IDENTITY_AUTHORITY_HOST") or "" + host = host.strip().rstrip("/") or _IMDS_AUTHORITY + url = f"{host}/metadata/identity/oauth2/token" + params["api-version"] = "2018-02-01" + headers = {"Metadata": "true"} + # Local endpoints: never through a proxy. + session = aiohttp.ClientSession( + trust_env=False, timeout=_LOG_ANALYTICS_TIMEOUT + ) + response = await session.get(url, params=params, headers=headers) + status = response.status + body = await response.text() + try: + payload = json.loads(body) + except ValueError: + payload = None + if not 200 <= status < 300: + text = self._token_error_text(source, status, payload, body, secrets) + raise _TokenError(_redact(text, secrets)) + if not isinstance(payload, dict): + raise _TokenError(f"{status} response is not JSON") + token = payload.get("access_token") + if not ( + isinstance(token, str) + and token + and all(33 <= ord(c) <= 126 for c in token) + ): + raise _TokenError(f"{status} response without a usable access_token") + return token, _token_lifetime(payload) + except _TokenError: + raise + except Exception as e: + text = f"{type(e).__name__}: {e}" + if source == "imds" and isinstance(e, _CONNECT_ERRORS): + text = f"{_IMDS_UNREACHABLE}: {text}" + raise _TokenError(_redact(text, secrets)[:500]) from None + finally: + await cleanup_response(response, session) + def _get_message_content(self, message): """Extract content from a message, handling different formats.""" content = message.get("content", "") diff --git a/tests/e2e/harness/config.py b/tests/e2e/harness/config.py index 1b3a222..b1616fd 100644 --- a/tests/e2e/harness/config.py +++ b/tests/e2e/harness/config.py @@ -18,7 +18,7 @@ "azure": 9102, "n8n": 9103, "infomaniak": 9104, - "search": 9106, # Azure AI Search; 9105 is the Log Analytics mock control port + "search": 9106, # Azure AI Search; 9105/9107: Log Analytics mock (filters) } # Layout inside the container (run.sh copies tests/e2e/ to E2E_ROOT). diff --git a/tests/e2e/mocks/mock_la.py b/tests/e2e/mocks/mock_la.py index 923063b..3119dc9 100644 --- a/tests/e2e/mocks/mock_la.py +++ b/tests/e2e/mocks/mock_la.py @@ -1,47 +1,115 @@ """ -Azure Monitor HTTP Data Collector API mock (Log Analytics) for the filters suite. +Azure Log Analytics mock for the filters suite: the HTTP Data Collector API, the +Logs Ingestion API (data collection rules), the Microsoft Entra ID token +endpoint and the managed identity endpoints. ``filters/time_token_tracker.py`` posts to -``https://.ods.opinsights.azure.com/api/logs?api-version=2016-04-01``. -The filters suite (tests/e2e/suites/filters.py) maps that host to 127.0.0.1 in -/etc/hosts, installs a throw-away test CA into the container's system store and -starts this mock; it is not part of serve_all.py because it needs the -certificate and port 443. - -- HTTPS on 127.0.0.1:443: ``POST /api/logs``, validated like Azure: SharedKey - signature over "POST\\n\\napplication/json\\nx-ms-date:\\n/api/logs" - (403 InvalidAuthorization), Content-Type exactly application/json (400 - UnsupportedContentType), Log-Type letters/digits/_ up to 100 characters (400 - InvalidLogType), api-version=2016-04-01 (400 InvalidApiVersion / - MissingApiVersion). Every POST is recorded before it is answered. +``https://.ods.opinsights.azure.com/api/logs?api-version=2016-04-01`` +(Data Collector) or to +``https:///dataCollectionRules//streams/?api-version=2023-01-01`` +(Logs Ingestion) with a token from ``https://login.microsoftonline.`` or a +managed identity endpoint. The filters suite (tests/e2e/suites/filters.py) maps +those hosts to 127.0.0.1 in /etc/hosts, installs a throw-away test CA into the +container's system store and starts this mock; it is not part of serve_all.py +because it needs the certificate and port 443. + +- HTTPS on 127.0.0.1:443 (one certificate for every mapped host): + - ``POST /api/logs`` (record kind ``dc``), validated like Azure: SharedKey + signature over "POST\\n\\napplication/json\\nx-ms-date:\\n/api/logs" + (403 InvalidAuthorization), Content-Type exactly application/json (400 + UnsupportedContentType), Log-Type letters/digits/_ up to 100 characters (400 + InvalidLogType), api-version=2016-04-01 (400 InvalidApiVersion / + MissingApiVersion). + - ``POST //oauth2/v2.0/token`` (kind ``token``): form-encoded client + credentials with a client secret or a federated assertion (the current + content of the configured token file); Entra-shaped errors (``error``, + ``error_description``, ``error_codes``, ``trace_id``, ...). Issues + ``e2e-tok-`` tokens. The secret and the assertion are never recorded. + - ``POST /dataCollectionRules//streams/`` (kind ``ingest``): + api-version=2023-01-01, a known, unrevoked, unexpired Bearer token of the + host's cloud (401), Content-Type application/json, configured DCR / stream + (404), JSON array of objects (400), at most 1 MiB (413); 204 on success. +- Managed identity on http://127.0.0.1:9107 and http://127.0.0.2:9107 (kind + ``msi``): ``GET /msi/token`` (App Service, ``X-IDENTITY-HEADER``; a + ``client_id`` starting with ``e2e-unknown`` gets App Service's 400 + ``{statusCode, message, correlationId}``) and + ``GET /metadata/identity/oauth2/token`` (IMDS, ``Metadata: true``). - Tarpit on 127.0.0.3:443: accepts TLS connections, waits 8 s and closes them (a hanging download for tiktoken's encoding host, offline group). -- Control on http://127.0.0.1:9105: ``GET /__requests`` (recorded POSTs), - ``POST /__reset`` (records, mode), ``POST /__mode`` ``{"status": 500, - "delay": 6}`` (answer status / seconds before answering), ``GET /__tarpit`` +- Control on http://127.0.0.1:9105: ``GET /__requests[?kind=dc|token|ingest|msi|all]`` + (recorded requests, default ``dc``), ``POST /__reset`` (records, modes), + ``POST /__mode`` ``{"target": "dc"|"token"|"ingest"|"msi", "status": 500, + "delay": 6, "expires_in", "retry_after", "error_code", "echo_secret", + "echo_at_cut"}`` (each + call replaces the whole mode of its target; target defaults to dc), + ``POST /__config`` ``{tenant, client_secret, dcr_id, stream, + identity_header, token_file}``, ``GET /__tokens`` (issued access tokens), + ``POST /__revoke`` (invalidate every issued token), ``GET /__tarpit`` (connection times seen by the tarpit). +Every request is recorded before it is answered; stdout gets one line per +request without tokens, secrets, identity headers or assertions. + usage: python3 mock_la.py """ import asyncio import base64 +import datetime import hashlib import hmac import json import re +import secrets import ssl import sys import time +import uuid +from urllib.parse import parse_qs, quote_plus from aiohttp import web CONTROL_PORT = 9105 +MSI_PORT = 9107 # 9106 is mocks/mock_search.py (serve_all.py) +MSI_HOSTS = ("127.0.0.1", "127.0.0.2") TARPIT_HOST = "127.0.0.3" TARPIT_SECONDS = 8 API_VERSION = "2016-04-01" +INGEST_API_VERSION = "2023-01-01" +MAX_BODY = 1024 * 1024 +JWT_BEARER = "urn:ietf:params:oauth:client-assertion-type:jwt-bearer" +MSI_RESOURCES = ("https://monitor.azure.com", "https://monitor.azure.com/") +TARGETS = ("dc", "token", "ingest", "msi") +LOGIN_CLOUDS = {"login.microsoftonline.com": "com", "login.microsoftonline.us": "us"} + + +def default_mode() -> dict: + return { + "status": 200, + "delay": 0.0, + "expires_in": 3599, + "retry_after": None, + "error_code": None, + "echo_secret": False, + "echo_at_cut": False, + } -STATE = {"records": [], "status": 200, "delay": 0.0, "tarpit": []} + +STATE = { + "records": [], + "modes": {target: default_mode() for target in TARGETS}, + "tarpit": [], + "config": { + "tenant": "", + "client_secret": "", + "dcr_id": "", + "stream": "", + "identity_header": "", + "token_file": "", + }, + # access token -> {"index", "expires" (monotonic), "cloud", "revoked"} + "tokens": {}, +} def expected_auth(workspace: str, key: str, raw: bytes, date: str) -> str: @@ -51,6 +119,72 @@ def expected_auth(workspace: str, key: str, raw: bytes, date: str) -> str: return f"SharedKey {workspace}:{base64.b64encode(digest.digest()).decode()}" +def mode(target: str) -> dict: + return STATE["modes"][target] + + +def issue_token(cloud: str) -> tuple: + """New access token of ``cloud`` with the target mode's lifetime.""" + token = f"e2e-tok-{secrets.token_hex(16)}" + index = len(STATE["tokens"]) + STATE["tokens"][token] = { + "index": index, + "expires": time.monotonic(), # set by the caller + "cloud": cloud, + "revoked": False, + } + return token, index + + +def bare_host(request: web.Request) -> str: + return (request.host or "").split(":")[0].lower() + + +def entra_error( + host: str, + status: int, + error: str, + code: int, + text: str, + echo: str = "", + at_cut: bool = False, +) -> web.Response: + """An error response shaped like Microsoft Entra ID's token endpoint. + + ``echo``: the secret / assertion is echoed in the first line of + error_description (plain and form-encoded). With ``at_cut`` it straddles + the filter's cut points instead: ``error`` (100 characters), the first + line of ``error_description`` (200), ``trace_id`` and ``correlation_id`` + (64 each), each with the first 10 characters of the secret (plain or + form-encoded) before the cut. A filter that truncates before it redacts + logs those characters. + """ + first = f"AADSTS{code}: {text} e2e mock" + trace_id, correlation_id = str(uuid.uuid4()), str(uuid.uuid4()) + if echo and at_cut: + head = f"AADSTS{code}: " + error = "e" * 90 + echo + first = head + "p" * (190 - len(head)) + quote_plus(echo) + trace_id = "t" * 54 + echo + correlation_id = "c" * 54 + quote_plus(echo) + elif echo: + first = f"AADSTS{code}: echo {echo} {quote_plus(echo)} e2e mock" + stamp = datetime.datetime.now(datetime.timezone.utc).strftime("%Y-%m-%d %H:%M:%SZ") + body = { + "error": error, + "error_description": ( + f"{first}\r\nTrace ID: {trace_id}\r\nCorrelation ID: {correlation_id}" + f"\r\nTimestamp: {stamp}" + ), + "error_codes": [code], + "timestamp": stamp, + "trace_id": trace_id, + "correlation_id": correlation_id, + "error_uri": f"https://{host}/error?code={code}", + } + return web.json_response(body, status=status) + + def make_api(workspace: str, key: str) -> web.Application: async def logs(request: web.Request) -> web.Response: raw = await request.read() @@ -65,6 +199,7 @@ async def logs(request: web.Request) -> web.Response: log_type = request.headers.get("Log-Type", "") STATE["records"].append( { + "kind": "dc", "method": request.method, "host": request.host, "path": request.path, @@ -79,8 +214,9 @@ async def logs(request: web.Request) -> web.Response: print( f"LA POST {request.path} auth_ok={auth_ok} body={raw[:300]!r}", flush=True ) - if STATE["delay"]: - await asyncio.sleep(STATE["delay"]) + dc = mode("dc") + if dc["delay"]: + await asyncio.sleep(dc["delay"]) error = None api_version = request.query.get("api-version") if api_version is None: @@ -97,31 +233,403 @@ async def logs(request: web.Request) -> web.Response: error = (403, "InvalidAuthorization") elif body is None: error = (400, "InvalidDataFormat") - elif STATE["status"] != 200: - error = (STATE["status"], "E2EForced") + elif dc["status"] != 200: + error = (dc["status"], "E2EForced") if error: return web.json_response( {"Error": error[1], "Message": "e2e mock"}, status=error[0] ) return web.Response(status=200) - app = web.Application() + async def token(request: web.Request) -> web.Response: + """Microsoft Entra ID client credentials (secret or federated assertion).""" + raw = await request.read() + host = bare_host(request) + content_type = request.headers.get("Content-Type", "") + form = {} + if content_type.split(";")[0].strip() == "application/x-www-form-urlencoded": + form = { + k: v[0] + for k, v in parse_qs( + raw.decode("utf-8", "replace"), keep_blank_values=True + ).items() + } + cfg = STATE["config"] + secret = form.get("client_secret") + assertion = form.get("client_assertion") + file_content = "" + if cfg["token_file"]: + try: + with open(cfg["token_file"], encoding="utf-8") as fh: + file_content = fh.read().strip() + except OSError: + file_content = "" + rec = { + "kind": "token", + "method": request.method, + "host": host, + "path": request.path, + "tenant": request.match_info["tenant"], + "content_type": content_type, + "form": { + k: ("" if k in ("client_secret", "client_assertion") else v) + for k, v in form.items() + }, + "grant_type": form.get("grant_type"), + "client_id": form.get("client_id"), + "scope": form.get("scope"), + "auth": "secret" + if secret is not None + else ("assertion" if assertion is not None else None), + "secret_ok": secret is not None + and bool(cfg["client_secret"]) + and secret == cfg["client_secret"], + "assertion_ok": assertion is not None + and form.get("client_assertion_type") == JWT_BEARER + and bool(file_content) + and assertion == file_content, + "token_index": None, + "status": None, + "received": time.time(), + } + STATE["records"].append(rec) + m = mode("token") + if m["delay"]: + await asyncio.sleep(m["delay"]) + echo = (secret or assertion or "") if m["echo_secret"] else "" + cloud = LOGIN_CLOUDS.get(host, "") + scopes = ( + f"https://monitor.azure.{cloud}/.default", + f"https://monitor.azure.{cloud}//.default", + ) + + def error(status: int, name: str, code: int, text: str) -> web.Response: + return entra_error(host, status, name, code, text, echo, m["echo_at_cut"]) + + if rec["content_type"].split(";")[0].strip() != ( + "application/x-www-form-urlencoded" + ): + resp = error(400, "invalid_request", 900144, "no form") + elif form.get("grant_type") != "client_credentials": + resp = error(400, "unsupported_grant_type", 70003, "grant type") + elif rec["tenant"] != cfg["tenant"]: + resp = error(400, "invalid_request", 90002, "Tenant not found.") + elif not cloud or form.get("scope") not in scopes: + resp = error(400, "invalid_scope", 70011, "The provided scope is invalid.") + elif str(form.get("client_id") or "").startswith("e2e-unknown"): + resp = error( + 400, + "unauthorized_client", + 700016, + "Application not found in the directory.", + ) + elif rec["auth"] == "secret" and not rec["secret_ok"]: + resp = error( + 401, "invalid_client", 7000215, "Invalid client secret provided." + ) + elif rec["auth"] == "assertion" and not rec["assertion_ok"]: + resp = error( + 401, + "invalid_client", + 700212, + "No matching federated identity record found.", + ) + elif rec["auth"] is None: + resp = error(401, "invalid_client", 7000216, "Client credential missing.") + elif m["status"] != 200: + resp = error( + m["status"], + "temporarily_unavailable" if m["status"] >= 500 else "invalid_request", + int(m["error_code"] or 90000), + "Forced by the e2e mock.", + ) + else: + access, index = issue_token(cloud) + lifetime = int(m["expires_in"]) + STATE["tokens"][access]["expires"] = time.monotonic() + lifetime + rec["token_index"] = index + resp = web.json_response( + { + "token_type": "Bearer", + "expires_in": lifetime, + "ext_expires_in": lifetime, + "access_token": access, + } + ) + rec["status"] = resp.status + print( + f"LA TOKEN {host} tenant={rec['tenant']} client_id={rec['client_id']} " + f"auth={rec['auth']} -> {resp.status} " + f"token#{rec['token_index']}", + flush=True, + ) + return resp + + async def ingest(request: web.Request) -> web.Response: + """Logs Ingestion API: POST a JSON array to a DCR stream.""" + raw = await request.read() + try: + body = json.loads(raw) + except ValueError: + body = None + host = bare_host(request) + auth = request.headers.get("Authorization", "") + bearer = auth[len("Bearer ") :] if auth.startswith("Bearer ") else "" + known = STATE["tokens"].get(bearer) + headers = dict(request.headers) + for name in list(headers): + if name.lower() == "authorization": + headers[name] = ( + f"Bearer " + if known + else ("Bearer " if bearer else "") + ) + expired = bool(known) and time.monotonic() >= known["expires"] + rec = { + "kind": "ingest", + "method": request.method, + "host": host, + "path": request.path, + "query": dict(request.query), + "headers": headers, + "raw_len": len(raw), + "body": body, + "token_ok": bool(known) and not known["revoked"], + "token_index": known["index"] if known else None, + "token_expired": expired, + "status": None, + "received": time.time(), + } + STATE["records"].append(rec) + m = mode("ingest") + if m["delay"]: + await asyncio.sleep(m["delay"]) + cfg = STATE["config"] + cloud = "us" if host.endswith(".azure.us") else "com" + extra = {} + if request.query.get("api-version") != INGEST_API_VERSION: + error = (400, "InvalidApiVersion") + elif not known or known["revoked"]: + error = (401, "InvalidToken") + elif expired: + error = (401, "TokenExpired") + elif known["cloud"] != cloud: + error = (401, "InvalidAudience") + elif request.headers.get("Content-Type") != "application/json": + error = (400, "UnsupportedContentType") + elif request.match_info["dcr"] != cfg["dcr_id"]: + error = (404, "DcrNotFound") + elif request.match_info["stream"] != cfg["stream"]: + error = (404, "StreamNotFound") + elif not ( + isinstance(body, list) and all(isinstance(item, dict) for item in body) + ): + error = (400, "InvalidJson") + elif len(raw) > MAX_BODY: + error = (413, "ContentLengthLimitExceeded") + elif m["status"] != 200: + error = (m["status"], m["error_code"] or "E2EForced") + if m["retry_after"] is not None: + extra["Retry-After"] = str(m["retry_after"]) + else: + error = None + if error: + resp = web.json_response( + {"error": {"code": error[1], "message": "e2e mock"}}, + status=error[0], + headers={"x-ms-error-code": error[1], **extra}, + ) + else: + resp = web.Response(status=204) + rec["status"] = resp.status + print( + f"LA INGEST {host}{request.path} token#{rec['token_index']} " + f"token_ok={rec['token_ok']} expired={expired} -> {resp.status} " + f"body={raw[:200]!r}", + flush=True, + ) + return resp + + app = web.Application(client_max_size=4 * MAX_BODY) app.router.add_post("/api/logs", logs) + app.router.add_post("/{tenant}/oauth2/v2.0/token", token) + app.router.add_post("/dataCollectionRules/{dcr}/streams/{stream}", ingest) + return app + + +def make_msi() -> web.Application: + """Managed identity endpoints (App Service and IMDS), plain HTTP.""" + + async def handle(request: web.Request, flavour: str) -> web.Response: + sockname = ( + request.transport.get_extra_info("sockname") if request.transport else None + ) + query = dict(request.query) + cfg = STATE["config"] + if flavour == "app_service": + header_ok = ( + bool(cfg["identity_header"]) + and request.headers.get("X-IDENTITY-HEADER") == cfg["identity_header"] + ) + version = "2019-08-01" + elif flavour == "imds": + header_ok = request.headers.get("Metadata") == "true" + version = "2018-02-01" + else: + header_ok, version = False, "" + rec = { + "kind": "msi", + "flavour": flavour, + "method": request.method, + "local_ip": sockname[0] if sockname else None, + "path": request.path, + "query": query, + "client_id": query.get("client_id"), + "header_ok": header_ok, + "token_index": None, + "status": None, + "received": time.time(), + } + STATE["records"].append(rec) + m = mode("msi") + if m["delay"]: + await asyncio.sleep(m["delay"]) + if flavour == "unknown": + resp = web.json_response({"error": "not_found"}, status=404) + elif ( + flavour == "app_service" + and header_ok + and str(query.get("client_id") or "").startswith("e2e-unknown") + ): + # What App Service / Container Apps answer for a client ID that is + # not assigned to the app (microsoft/azure-container-apps#442). + rec["correlation_id"] = str(uuid.uuid4()) + resp = web.json_response( + { + "statusCode": 400, + "message": "Unable to load the proper Managed Identity.", + "correlationId": rec["correlation_id"], + }, + status=400, + ) + elif not header_ok: + if flavour == "imds": + resp = web.json_response( + { + "error": "invalid_request", + "error_description": "Required metadata header not specified", + }, + status=400, + ) + else: + resp = web.json_response({"error": "invalid_request"}, status=401) + elif query.get("api-version") != version: + resp = web.json_response( + {"error": "invalid_request", "error_description": "api-version"}, + status=400, + ) + elif query.get("resource") not in MSI_RESOURCES: + resp = web.json_response( + {"error": "invalid_resource", "error_description": "resource"}, + status=400, + ) + elif m["status"] != 200: + resp = web.json_response( + {"error": "e2e_forced", "error_description": "Forced by the e2e mock."}, + status=m["status"], + ) + else: + access, index = issue_token("com") + lifetime = int(m["expires_in"]) + STATE["tokens"][access]["expires"] = time.monotonic() + lifetime + rec["token_index"] = index + expires_on = str(int(time.time()) + lifetime) + if flavour == "app_service": + payload = { + "access_token": access, + "expires_on": expires_on, + "resource": query.get("resource"), + "token_type": "Bearer", + "client_id": query.get("client_id") or "e2e-system-assigned", + } + else: + payload = { + "access_token": access, + "refresh_token": "", + "expires_in": str(lifetime), + "expires_on": expires_on, + "not_before": str(int(time.time())), + "resource": query.get("resource"), + "token_type": "Bearer", + } + resp = web.json_response(payload) + rec["status"] = resp.status + print( + f"LA MSI {flavour} {rec['local_ip']} {request.path} " + f"client_id={rec['client_id']} header_ok={header_ok} -> {resp.status} " + f"token#{rec['token_index']}", + flush=True, + ) + return resp + + async def app_service(request: web.Request) -> web.Response: + return await handle(request, "app_service") + + async def imds(request: web.Request) -> web.Response: + return await handle(request, "imds") + + async def unknown(request: web.Request) -> web.Response: + return await handle(request, "unknown") + + app = web.Application() + app.router.add_get("/msi/token", app_service) + app.router.add_get("/metadata/identity/oauth2/token", imds) + app.router.add_route("*", "/{tail:.*}", unknown) return app def make_control() -> web.Application: - async def requests(_: web.Request) -> web.Response: - return web.json_response(STATE["records"]) + async def requests(request: web.Request) -> web.Response: + kind = request.query.get("kind", "dc") + records = STATE["records"] + if kind != "all": + records = [r for r in records if r.get("kind") == kind] + return web.json_response(records) async def reset(_: web.Request) -> web.Response: - STATE.update(records=[], status=200, delay=0.0) + STATE["records"] = [] + STATE["modes"] = {target: default_mode() for target in TARGETS} + return web.json_response({"ok": True}) + + async def set_mode(request: web.Request) -> web.Response: + data = await request.json() + target = data.get("target", "dc") + if target not in TARGETS: + return web.json_response({"error": f"unknown target {target}"}, status=400) + new = default_mode() + new["status"] = int(data.get("status", 200)) + new["delay"] = float(data.get("delay", 0)) + new["expires_in"] = int(data.get("expires_in", 3599)) + new["retry_after"] = data.get("retry_after") + new["error_code"] = data.get("error_code") + new["echo_secret"] = bool(data.get("echo_secret", False)) + new["echo_at_cut"] = bool(data.get("echo_at_cut", False)) + STATE["modes"][target] = new return web.json_response({"ok": True}) - async def mode(request: web.Request) -> web.Response: + async def config(request: web.Request) -> web.Response: data = await request.json() - STATE["status"] = int(data.get("status", 200)) - STATE["delay"] = float(data.get("delay", 0)) + for name in STATE["config"]: + if name in data: + STATE["config"][name] = str(data[name] or "") + return web.json_response({"ok": True}) + + async def tokens(_: web.Request) -> web.Response: + return web.json_response(sorted(STATE["tokens"])) + + async def revoke(_: web.Request) -> web.Response: + for info in STATE["tokens"].values(): + info["revoked"] = True return web.json_response({"ok": True}) async def tarpit_log(_: web.Request) -> web.Response: @@ -130,7 +638,10 @@ async def tarpit_log(_: web.Request) -> web.Response: app = web.Application() app.router.add_get("/__requests", requests) app.router.add_post("/__reset", reset) - app.router.add_post("/__mode", mode) + app.router.add_post("/__mode", set_mode) + app.router.add_post("/__config", config) + app.router.add_get("/__tokens", tokens) + app.router.add_post("/__revoke", revoke) app.router.add_get("/__tarpit", tarpit_log) return app @@ -145,14 +656,17 @@ async def tarpit(_reader, writer) -> None: async def main(workspace: str, key: str, certfile: str, keyfile: str) -> None: tls = ssl.create_default_context(ssl.Purpose.CLIENT_AUTH) tls.load_cert_chain(certfile, keyfile) - sites = ( - (make_api(workspace, key), "127.0.0.1", 443, tls), - (make_control(), "127.0.0.1", CONTROL_PORT, None), - ) - for app, host, port, context in sites: + msi = make_msi() + sites = [ + (make_api(workspace, key), ("127.0.0.1",), 443, tls), + (make_control(), ("127.0.0.1",), CONTROL_PORT, None), + (msi, MSI_HOSTS, MSI_PORT, None), + ] + for app, hosts, port, context in sites: runner = web.AppRunner(app, access_log=None) await runner.setup() - await web.TCPSite(runner, host, port, ssl_context=context).start() + for host in hosts: + await web.TCPSite(runner, host, port, ssl_context=context).start() await asyncio.start_server(tarpit, TARPIT_HOST, 443) print("mock LA ready", flush=True) await asyncio.Event().wait() diff --git a/tests/e2e/mocks/serve_all.py b/tests/e2e/mocks/serve_all.py index 7716bd2..ec58211 100644 --- a/tests/e2e/mocks/serve_all.py +++ b/tests/e2e/mocks/serve_all.py @@ -7,7 +7,8 @@ infomaniak 127.0.0.1:9104 mock_infomaniak.py search 127.0.0.1:9106 mock_search.py (Azure AI Search + managed identity tokens) -(9105 is the control port of mock_la.py, which the filters suite starts.) +(9105 and 9107 are the control and managed identity ports of mock_la.py, which +the filters suite starts.) usage: python serve_all.py # serve until stopped diff --git a/tests/e2e/probe/probe_pipe.py b/tests/e2e/probe/probe_pipe.py index 558a340..404e47f 100644 --- a/tests/e2e/probe/probe_pipe.py +++ b/tests/e2e/probe/probe_pipe.py @@ -1,19 +1,108 @@ """ title: E2E Metadata Probe author: owndev -version: 0.2.0 +version: 0.4.0 license: Apache License 2.0 -description: Test-only pipe for tests/e2e. Answers with a JSON report of what Open WebUI hands a pipe (body keys, model and messages, __metadata__ features/params/model_id, __task__, whether an __event_emitter__ exists), so filter -> pipe coupling and background-task behaviour can be asserted without a provider. "PROBE_SLEEP=" in the last user message delays the answer (at most 10 s), so concurrent requests overlap; "PROBE_SLEEP[]=" delays only the answer of that model (multi-model chats). +description: Test-only pipe for tests/e2e. Answers with a JSON report of what Open WebUI hands a pipe (body keys, model and messages, __metadata__ features/params/model_id, __task__, whether an __event_emitter__ exists), so filter -> pipe coupling and background-task behaviour can be asserted without a provider. "PROBE_SLEEP=" in the last user message delays the answer (at most 10 s), so concurrent requests overlap; "PROBE_SLEEP[]=" delays only the answer of that model (multi-model chats). "PROBE_ENV=" sets (or, for null, removes) the environment variables listed in a JSON object in that file in the server process, for an allow-list of managed identity, workload identity and proxy variables only (the report lists env_applied / env_rejected); the values go through the file, never through the chat text. "PROBE_LOG=" writes everything the time_token_tracker logger logs, DEBUG included, to that file (the server log runs at INFO); "PROBE_LOG=off" stops it (the report has log_capture). """ import asyncio import json +import logging +import os import re from typing import Any, Optional PREFIX = "PROBE:" SLEEP = re.compile(r"PROBE_SLEEP(?:\[([^\]]+)\])?=(\d+(?:\.\d+)?)") MAX_SLEEP = 10.0 +ENV = re.compile(r"PROBE_ENV=(/\S+)") +LOG = re.compile(r"PROBE_LOG=(/\S+|off)") +# Loggers whose DEBUG output PROBE_LOG may capture (never the server's own). +LOG_ALLOWED = ("time_token_tracker",) +# Environment variables the filters suite may change in the server process +# (managed identity / workload identity detection, proxy). run.sh sets only +# IDENTITY_ENDPOINT / IDENTITY_HEADER at docker run (the azure suite's managed +# identity mock); the filters suite puts the container's values back at the end. +ENV_ALLOWED = ( + "IDENTITY_ENDPOINT", + "IDENTITY_HEADER", + "IDENTITY_SERVER_THUMBPRINT", + "IMDS_ENDPOINT", + "MSI_ENDPOINT", + "MSI_SECRET", + "AZURE_POD_IDENTITY_AUTHORITY_HOST", + "AZURE_FEDERATED_TOKEN_FILE", + "AZURE_KUBERNETES_TOKEN_PROXY", + "AZURE_CLIENT_ID", + "AZURE_TENANT_ID", + "AZURE_AUTHORITY_HOST", + "HTTP_PROXY", + "http_proxy", + "NO_PROXY", + "no_proxy", +) + + +def _read_json(path: str) -> Any: + with open(path, encoding="utf-8") as fh: + return json.load(fh) + + +async def _apply_env(path: str) -> dict: + """Set / pop the allow-listed variables of the JSON object in ``path``.""" + applied, rejected, error = [], [], None + try: + values = await asyncio.to_thread(_read_json, path) + if not isinstance(values, dict): + raise ValueError("not a JSON object") + for name, value in values.items(): + if name not in ENV_ALLOWED: + rejected.append(name) + elif value is None: + os.environ.pop(name, None) + applied.append(name) + else: + os.environ[name] = str(value) + applied.append(name) + except (OSError, ValueError) as exc: + error = type(exc).__name__ + return { + "env_applied": sorted(applied), + "env_rejected": sorted(rejected), + "env_error": error, + } + + +def _capture_log(target: str) -> dict: + """Attach a DEBUG FileHandler to the allow-listed loggers (replacing an + earlier one), or remove it again for ``off``. The logger level is raised + to DEBUG while the capture runs and restored afterwards; the records still + propagate to the server log, whose handler keeps its own (INFO) level. + A filter module that is loaded again resets its logger level in + __init__, so start the capture after the module is loaded.""" + try: + for name in LOG_ALLOWED: + logger = logging.getLogger(name) + for handler in list(logger.handlers): + if getattr(handler, "_probe_capture", False): + logger.removeHandler(handler) + handler.close() + logger.setLevel(handler._probe_level) + if target == "off": + continue + handler = logging.FileHandler(target, mode="w", encoding="utf-8") + handler.setLevel(logging.DEBUG) + handler.setFormatter( + logging.Formatter("%(asctime)s %(levelname)s %(name)s %(message)s") + ) + handler._probe_capture = True + handler._probe_level = logger.level + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + return {"log_capture": target} + except (OSError, ValueError) as exc: + return {"log_capture": None, "log_error": type(exc).__name__} def _text(content: Any) -> str: @@ -64,13 +153,20 @@ async def pipe( "has_user": bool(__user__), "stream": body.get("stream"), } + users = [m for m in messages if m.get("role") == "user"] + last = _text(users[-1].get("content")) if users else "" + env = ENV.search(last) if not __task__ else None + if env: + report.update(await _apply_env(env.group(1))) + log = LOG.search(last) if not __task__ else None + if log: + report.update(_capture_log(log.group(1))) text = PREFIX + json.dumps(report, sort_keys=True, default=str) if __task__: # Background tasks parse JSON out of the answer: keep it valid. return json.dumps({"title": "Probe Title", "tags": [], "probe": text}) - users = [m for m in messages if m.get("role") == "user"] model_id = metadata.get("model_id") or body.get("model") - for match in SLEEP.finditer(_text(users[-1].get("content")) if users else ""): + for match in SLEEP.finditer(last): if match.group(1) in (None, model_id): await asyncio.sleep(min(float(match.group(2)), MAX_SLEEP)) break diff --git a/tests/e2e/suites/filters.py b/tests/e2e/suites/filters.py index 0226184..f4c78b6 100644 --- a/tests/e2e/suites/filters.py +++ b/tests/e2e/suites/filters.py @@ -2,10 +2,12 @@ Filters suite: filters/{google_search_tool,vertex_ai_search_tool,time_token_tracker}.py in front of the probe pipe (tests/e2e/probe/probe_pipe.py), which reports what reached the pipe (messages, __metadata__ features/params, ...), so filter -> pipe -coupling is checked without a provider. The tracker's Azure Log Analytics send -goes to mocks/mock_la.py: this suite maps .ods.opinsights.azure.com to -127.0.0.1 in /etc/hosts, installs a throw-away test CA into the container's -system store and starts the mock (HTTPS on 127.0.0.1:443, control on :9105). +coupling is checked without a provider. The tracker's Azure Log Analytics sends +go to mocks/mock_la.py: this suite maps .ods.opinsights.azure.com +(HTTP Data Collector API), the Microsoft Entra ID login hosts and the DCR +ingestion hosts (Logs Ingestion API) to 127.0.0.1 in /etc/hosts, installs a +throw-away test CA into the container's system store and starts the mock (HTTPS +on 127.0.0.1:443, control on :9105, managed identity endpoints on :9107). Token counts are compared with tiktoken in the driver (same encodings, cached in TIKTOKEN_CACHE_DIR before the server needs them). @@ -21,6 +23,22 @@ counts on the API and browser path, special tokens, multi-turn averages, the "exactly two messages" rule, send switched off, HTTP errors, slow / hanging endpoint, estimate marker + ingest Logs Ingestion API: request shape and 204, token cache (scope and + tenant in its key) / concurrency / refresh, refresh failure with a + still-valid token (also inside the back-off), the 30 s token + back-off (still on after 20 s) and its end, token and HTTP errors + with one log line each (a secret echoed at the cut points of the + error text, a second revocation, a late 401 for a replaced + token), undecryptable secret, https-only (endpoint and authority) + and invalid settings, slow / unreachable endpoints, mode selection + and fallback, both APIs (also with one side incomplete), + deprecation warning, sovereign cloud, App Service (also its error + shape) / IMDS / workload identity (environment set through the + probe pipe's PROBE_ENV hook) + +While the Log Analytics groups run, the probe pipe's PROBE_LOG hook writes +everything the tracker logs, DEBUG included, to /e2e/out/tracker_debug.log; +log.no-secrets-debug scans it (the server log runs at INFO). valves compact status (CALCULATE_ALL_MESSAGES / SHOW_* off) correlation inlet/outlet correlation when Open WebUI rewrites the last user message after the inlet, concurrent identical requests @@ -48,18 +66,20 @@ import uuid from email.utils import parsedate_to_datetime from typing import Optional -from urllib.parse import quote +from urllib.parse import quote, quote_plus import httpx from harness import Suite, short from harness.config import VERTEX_RAG_STORE +from harness.logs import ServerLog GROUPS = ( "model", "global", "spec", "la", + "ingest", "valves", "correlation", "encoding", @@ -69,7 +89,15 @@ "vertex", ) # Groups that need the Log Analytics mock (and a warm tracker). -LA_GROUPS = ("la", "valves", "correlation", "encoding", "offline", "multimodel") +LA_GROUPS = ( + "la", + "ingest", + "valves", + "correlation", + "encoding", + "offline", + "multimodel", +) TRACKER_GROUPS = ("model", "global", *LA_GROUPS) PROBE_FID = "e2e_probe" @@ -89,6 +117,7 @@ VERTEX_MODEL = "e2e-probe-vertex" # vertex_ai_search_tool only MULTI_SEARCH_MODEL = "e2e-probe-multi-search" # google_search_tool + tracker MULTI_PLAIN_MODEL = "e2e-probe-multi-plain" # tracker only +ENV_MODEL = "e2e-probe-env" # no filters: carries PROBE_ENV (ingest group) WORKSPACE_MODELS = ( GPT4O_MODEL, DAVINCI_MODEL, @@ -96,6 +125,7 @@ VERTEX_MODEL, MULTI_SEARCH_MODEL, MULTI_PLAIN_MODEL, + ENV_MODEL, ) # time_token_tracker valves (public API: may grow, never shrink) @@ -110,6 +140,16 @@ "LOG_ANALYTICS_WORKSPACE_ID", "LOG_ANALYTICS_SHARED_KEY", "LOG_ANALYTICS_LOG_TYPE", + "LOG_ANALYTICS_INGESTION_API", + "LOG_ANALYTICS_DCR_ENDPOINT", + "LOG_ANALYTICS_DCR_IMMUTABLE_ID", + "LOG_ANALYTICS_DCR_STREAM_NAME", + "LOG_ANALYTICS_AUTH_MODE", + "LOG_ANALYTICS_TENANT_ID", + "LOG_ANALYTICS_CLIENT_ID", + "LOG_ANALYTICS_CLIENT_SECRET", + "LOG_ANALYTICS_AUTHORITY_HOST", + "LOG_ANALYTICS_INGESTION_SCOPE", ) # Log Analytics mock (mocks/mock_la.py) @@ -120,18 +160,42 @@ LA_CTL = "http://127.0.0.1:9105" LA_DIR = "/tmp/e2e-la" LA_OUT = "/e2e/out/mock_la.txt" +# la-setup : the CA is kept across --reuse runs (OpenSSL +# caches CA certificates by subject hash in the long-running server process, so +# a new CA with the same subject could fail verification); the server +# certificate is reissued when it lacks a name or expires within an hour. LA_SETUP = r""" set -e mkdir -p "$1" && cd "$1" -if [ ! -f srv.crt ]; then - openssl req -x509 -newkey rsa:2048 -nodes -keyout ca.key -out ca.crt -days 2 \ +IFS=, read -ra sans <<< "$2" +if [ ! -f ca.crt ] || [ ! -f ca.key ] \ + || ! openssl x509 -in ca.crt -noout -checkend 3600 >/dev/null 2>&1; then + openssl req -x509 -newkey rsa:2048 -nodes -keyout ca.key -out ca.crt -days 30 \ -subj "/CN=E2E Log Analytics CA" 2>/dev/null - openssl req -newkey rsa:2048 -nodes -keyout srv.key -out srv.csr -subj "/CN=$2" \ - 2>/dev/null - printf "subjectAltName=DNS:%s\n" "$2" > ext.cnf + rm -f srv.crt +fi +issue=0 +if [ ! -f srv.crt ] \ + || ! openssl x509 -in srv.crt -noout -checkend 3600 >/dev/null 2>&1; then + issue=1 +else + text=$(openssl x509 -in srv.crt -noout -text) + for san in "${sans[@]}"; do + case "$text" in *"DNS:$san"*) ;; *) issue=1 ;; esac + done +fi +if [ "$issue" = 1 ]; then + ext="DNS:${sans[0]}" + for san in "${sans[@]:1}"; do ext="$ext,DNS:$san"; done + openssl req -newkey rsa:2048 -nodes -keyout srv.key -out srv.csr \ + -subj "/CN=${sans[0]}" 2>/dev/null + printf "subjectAltName=%s\n" "$ext" > ext.cnf openssl x509 -req -in srv.csr -CA ca.crt -CAkey ca.key -CAcreateserial \ - -out srv.crt -days 2 -extfile ext.cnf 2>/dev/null - cp ca.crt /usr/local/share/ca-certificates/e2e-la-ca.crt + -out srv.crt -days 30 -extfile ext.cnf 2>/dev/null +fi +installed=/usr/local/share/ca-certificates/e2e-la-ca.crt +if ! cmp -s ca.crt "$installed"; then + cp ca.crt "$installed" update-ca-certificates >/dev/null 2>&1 fi """ @@ -152,6 +216,64 @@ SLOW_SECONDS = 6 HANG_SECONDS = 20 # longer than the tracker's own 10 s timeout +# Logs Ingestion API (mocks/mock_la.py, ingest group) +TENANT = "11111111-2222-3333-4444-555555555555" +CLIENT_SECRET = "e2e~Secret+/=&value.42" # needs URL encoding; >= 6 chars +DCR_ID = "dcr-0123456789abcdef0123456789abcdef" +DCR_HOST = "e2e-dcr-ab12-westeurope.logs.z1.ingest.monitor.azure.com" +GOV_DCR_HOST = "e2e-dce-cd34.usgovvirginia-1.ingest.monitor.azure.us" +REFUSED_HOST = "e2e-dcr-down-westeurope.logs.z1.ingest.monitor.azure.com" +LOGIN_HOSTS = ("login.microsoftonline.com", "login.microsoftonline.us") +STREAM = f"Custom-{LOG_TYPE}_CL" # default stream name derived from LOG_TYPE +DEFAULT_SCOPE = "https://monitor.azure.com/.default" +TOKEN_PATH = f"/{TENANT}/oauth2/v2.0/token" +MI_PORT = 9107 # MSI_PORT of mocks/mock_la.py +MI_URL = f"http://127.0.0.1:{MI_PORT}" +MI_IMDS_URL = f"http://127.0.0.2:{MI_PORT}" # not covered by NO_PROXY (mi.imds) +PROBE_ENV_FILE = f"{LA_DIR}/probe-env.json" +WI_TOKEN_FILE = f"{LA_DIR}/wi-token" +DEPRECATION = "HTTP Data Collector API, which Microsoft deprecated" +INGEST_HOSTS_LINES = [ + f"127.0.0.1 {host}" for host in (*LOGIN_HOSTS, DCR_HOST, GOV_DCR_HOST) +] + [f"127.0.0.9 {REFUSED_HOST}"] +LA_SANS = (LA_HOST, *LOGIN_HOSTS, DCR_HOST, GOV_DCR_HOST) +# Environment variables the probe pipe may set (tests/e2e/probe/probe_pipe.py). +PROBE_ENV_NAMES = ( + "IDENTITY_ENDPOINT", + "IDENTITY_HEADER", + "IDENTITY_SERVER_THUMBPRINT", + "IMDS_ENDPOINT", + "MSI_ENDPOINT", + "MSI_SECRET", + "AZURE_POD_IDENTITY_AUTHORITY_HOST", + "AZURE_FEDERATED_TOKEN_FILE", + "AZURE_KUBERNETES_TOKEN_PROXY", + "AZURE_CLIENT_ID", + "AZURE_TENANT_ID", + "AZURE_AUTHORITY_HOST", + "HTTP_PROXY", + "http_proxy", + "NO_PROXY", + "no_proxy", +) +# The container's own values of those variables: run.sh sets IDENTITY_ENDPOINT +# and IDENTITY_HEADER at docker run (App Service managed identity for the azure +# suite, mocks/mock_search.py). The driver runs in the same container and sees +# them too; the ingest group removes them while it runs and puts them back at +# the end, for the suites after it and for --reuse runs. +CONTAINER_ENV = { + name: os.environ[name] for name in PROBE_ENV_NAMES if name in os.environ +} +# Issued tokens, identity headers, assertions etc. of the ingest group for the +# final log.no-secrets check (collected in the group's finally). +INGEST_SECRETS: list = [] +# The server log runs at INFO: while the Log Analytics groups run, the probe +# pipe (PROBE_LOG) also writes everything the tracker's logger logs, DEBUG +# included, to this file; log.no-secrets-debug scans it. +DEBUG_LOG = "/e2e/out/tracker_debug.log" +DEBUG_CAPTURE: dict = {"started": False, "problems": []} +TRACKER_LOADED = "Loaded module: function_time_token_tracker" + # tiktoken's encoding host; the offline group points it at the mock's tarpit TIKTOKEN_HOST = "openaipublic.blob.core.windows.net" TARPIT_LINE = f"127.0.0.3 {TIKTOKEN_HOST}" @@ -281,12 +403,16 @@ def close(a, b, rel: float = 1e-6) -> bool: def record_problems(entry: dict, exp: dict, model: str, user_id: str) -> list: - """Differences between one recorded Log Analytics POST and ``exp``. + """Differences between one recorded HTTP Data Collector POST and ``exp``: + the signed 2.6.2 request (``dc_transport_problems``) and the record + (``record_body_problems``).""" + return dc_transport_problems(entry) + record_body_problems( + entry, exp, model, user_id + ) - ``exp``: req, resp, last, req_count, resp_count; optional ``tps`` (default - last / responseTime), ``avg`` (False: no average fields), ``chat_id`` (None: - any UUID), ``message_id`` (compared when given). - """ + +def dc_transport_problems(entry: dict) -> list: + """Host, path, SharedKey signature and headers of a Data Collector POST.""" problems = [] headers = {k.lower(): v for k, v in (entry.get("headers") or {}).items()} if entry.get("host") != LA_HOST: @@ -312,6 +438,57 @@ def record_problems(entry: dict, exp: dict, model: str, user_id: str) -> list: problems.append(f"x-ms-date={headers.get('x-ms-date')}") except (TypeError, ValueError): problems.append(f"x-ms-date={headers.get('x-ms-date')}") + return problems + + +def li_transport_problems( + entry: dict, + host: str = DCR_HOST, + dcr: str = DCR_ID, + stream: str = STREAM, + status: Optional[int] = 204, +) -> list: + """URI, Bearer token and headers of a Logs Ingestion API POST.""" + problems = [] + headers = {k.lower(): v for k, v in (entry.get("headers") or {}).items()} + if entry.get("host") != host: + problems.append(f"host={entry.get('host')}") + if entry.get("path") != f"/dataCollectionRules/{dcr}/streams/{stream}": + problems.append(f"path={entry.get('path')}") + if entry.get("query") != {"api-version": "2023-01-01"}: + problems.append(f"query={entry.get('query')}") + if not entry.get("token_ok") or entry.get("token_expired"): + problems.append( + f"token_ok={entry.get('token_ok')} expired={entry.get('token_expired')}" + ) + if not str(headers.get("authorization", "")).startswith("Bearer list: + """Differences between the record of one recorded POST and ``exp``. + + ``exp``: req, resp, last, req_count, resp_count; optional ``tps`` (default + last / responseTime), ``avg`` (False: no average fields), ``chat_id`` (None: + any UUID), ``message_id`` (compared when given). + """ + problems = [] body = entry.get("body") if not isinstance(body, list) or len(body) != 1 or not isinstance(body[0], dict): return problems + [f"body={short(body, 200)}"] @@ -420,12 +597,15 @@ def send_timeout(t: Suite, mark: int, timeout: float = 8.0) -> float: return 0.5 if outlet_errors(t, mark) else timeout -async def wait_log(t: Suite, mark: int, needle: str, timeout: float) -> list: - """Lines containing ``needle`` logged since ``mark`` (polls up to ``timeout``).""" +async def wait_log( + t: Suite, mark: int, needle: str, timeout: float, n: int = 1 +) -> list: + """Lines containing ``needle`` logged since ``mark``, once there are ``n`` + (polls up to ``timeout``).""" deadline = time.time() + timeout while True: lines = t.log.lines(mark, needle) - if lines or time.time() >= deadline: + if len(lines) >= n or time.time() >= deadline: return lines await asyncio.sleep(0.5) @@ -470,26 +650,48 @@ def __init__(self): self.http = httpx.AsyncClient(base_url=LA_CTL, timeout=30) async def reset(self) -> None: + """Clear the records and reset every mode (config and tokens stay).""" await self.http.post("/__reset") - async def mode(self, status: int = 200, delay: float = 0.0) -> None: - await self.http.post("/__mode", json={"status": status, "delay": delay}) + async def mode( + self, status: int = 200, delay: float = 0.0, target: str = "dc", **extra + ) -> None: + """Replace the whole mode of ``target`` (dc, token, ingest or msi); + ``extra``: expires_in, retry_after, error_code, echo_secret.""" + await self.http.post( + "/__mode", + json={"target": target, "status": status, "delay": delay, **extra}, + ) + + async def records(self, kind: str = "dc") -> list: + """Recorded requests of ``kind`` (dc, token, ingest, msi or all).""" + return (await self.http.get("/__requests", params={"kind": kind})).json() + + async def config(self, **values) -> None: + """tenant, client_secret, dcr_id, stream, identity_header, token_file.""" + await self.http.post("/__config", json=values) + + async def tokens(self) -> list: + """Every access token the mock issued.""" + return (await self.http.get("/__tokens")).json() - async def records(self) -> list: - return (await self.http.get("/__requests")).json() + async def revoke(self) -> None: + """Invalidate every issued token (the next ingestion POST gets 401).""" + await self.http.post("/__revoke") async def tarpit(self) -> list: return (await self.http.get("/__tarpit")).json() - async def wait(self, n: int = 1, timeout: float = 8.0) -> list: - """Recorded POSTs once there are ``n`` (or after ``timeout`` seconds).""" + async def wait(self, n: int = 1, timeout: float = 8.0, kind: str = "dc") -> list: + """Recorded requests of ``kind`` once there are ``n`` (or after + ``timeout`` seconds).""" deadline = time.time() + timeout while time.time() < deadline: - if len(await self.records()) >= n: + if len(await self.records(kind)) >= n: await asyncio.sleep(0.3) # one more would be a duplicate break await asyncio.sleep(0.25) - return await self.records() + return await self.records(kind) async def close(self) -> None: await self.http.aclose() @@ -509,9 +711,12 @@ def kill_stale_mock() -> None: async def start_la_mock() -> tuple: - """Test CA + /etc/hosts entry + mock_la.py; returns (process, client).""" - subprocess.run(["bash", "-c", LA_SETUP, "la-setup", LA_DIR, LA_HOST], check=True) - edit_hosts(LA_HOSTS_LINE, add=True) + """Test CA + /etc/hosts entries + mock_la.py; returns (process, client).""" + subprocess.run( + ["bash", "-c", LA_SETUP, "la-setup", LA_DIR, ",".join(LA_SANS)], check=True + ) + for line in (LA_HOSTS_LINE, *INGEST_HOSTS_LINES): + edit_hosts(line, add=True) kill_stale_mock() await asyncio.sleep(0.5) out = open(LA_OUT, "a", encoding="utf-8") @@ -534,6 +739,14 @@ async def start_la_mock() -> tuple: await asyncio.sleep(0.5) try: await la.reset() + # Over loopback to the mock: the secret never reaches the server log. + await la.config( + tenant=TENANT, + client_secret=CLIENT_SECRET, + dcr_id=DCR_ID, + stream=STREAM, + token_file=WI_TOKEN_FILE, + ) return proc, la except httpx.HTTPError: if proc.poll() is not None: @@ -576,6 +789,8 @@ async def run(t: Suite) -> None: await vertex(t) finally: edit_hosts(TARPIT_LINE, add=False) + for line in INGEST_HOSTS_LINES: # unlike LA_HOSTS_LINE, never left mapped + edit_hosts(line, add=False) for fid in FILTERS: await t.owui.set_global(fid, False) for model_id in WORKSPACE_MODELS: @@ -591,10 +806,49 @@ async def run(t: Suite) -> None: not warnings, f"{len(warnings)} warnings: " + " || ".join(warnings[:3]), ) - t.assert_no_secrets(LA_KEY) + t.assert_no_secrets(LA_KEY, *INGEST_SECRETS) + if DEBUG_CAPTURE["started"]: + debug_no_secrets(t) t.scan_log() +async def tracker_debug_capture(t: Suite, target: str) -> list: + """Start (``target`` an absolute path) or stop (``"off"``) the probe + pipe's PROBE_LOG capture of the tracker's logger at DEBUG. Returns + problems.""" + await upsert_derived_model(t, ENV_MODEL, "E2E Probe Env", []) + r = await t.owui.chat(ENV_MODEL, f"PROBE_LOG={target}") + rep = probe_report(r.content) + if r.status == 200 and rep.get("log_capture") == target: + return [] + return [ + f"PROBE_LOG={target}: HTTP {r.status} capture={rep.get('log_capture')} " + f"error={rep.get('log_error')}" + ] + + +def debug_no_secrets(t: Suite) -> None: + """log.no-secrets for the tracker's DEBUG output (DEBUG_LOG): the same + secrets as the server log check.""" + secrets = dict(t.owui.secrets) + for value in (LA_KEY, *INGEST_SECRETS): + if value: + secrets.setdefault(value, "secret") + capture = ServerLog(DEBUG_LOG) + debug = sum( + " DEBUG time_token_tracker " in line for line in capture.since(0).splitlines() + ) + problems = DEBUG_CAPTURE["problems"] + capture.secrets(0, secrets) + t.check( + "log.no-secrets-debug", + "no plaintext secrets in what time_token_tracker logs, DEBUG included " + "(captured through the probe pipe's PROBE_LOG; the server log runs at INFO)", + debug > 0 and not problems, + f"{debug} DEBUG lines captured; " + + (" || ".join(problems[:5]) if problems else "no secret logged"), + ) + + async def warm_up(t: Suite) -> None: """Load cl100k_base in the driver (fills TIKTOKEN_CACHE_DIR) and repeat a request until the tracker counts it exactly: the server's first load may @@ -826,6 +1080,41 @@ async def spec(t: Suite) -> None: and LA_KEY not in stored, f"stored={short(stored, 40)}", ) + await t.owui.update_valves(TRACKER, LOG_ANALYTICS_CLIENT_SECRET=CLIENT_SECRET) + stored = (await t.owui.get_valves(TRACKER)).get("LOG_ANALYTICS_CLIENT_SECRET") + secret_spec = props.get("LOG_ANALYTICS_CLIENT_SECRET") or {} + input_type = (secret_spec.get("input") or {}).get("type") + t.check( + "spec.client-secret-encrypted", + "LOG_ANALYTICS_CLIENT_SECRET is a password valve and stored encrypted", + isinstance(stored, str) + and stored.startswith("encrypted:") + and CLIENT_SECRET not in stored + and input_type == "password", + f"stored={short(stored, 40)} input.type={input_type!r}", + ) + want = { + "LOG_ANALYTICS_INGESTION_API": "auto", + "LOG_ANALYTICS_AUTH_MODE": "client_secret", + "LOG_ANALYTICS_AUTHORITY_HOST": "https://login.microsoftonline.com", + "LOG_ANALYTICS_INGESTION_SCOPE": DEFAULT_SCOPE, + "LOG_ANALYTICS_LOG_TYPE": "OpenWebuiMetrics", + "LOG_ANALYTICS_DCR_ENDPOINT": "", + "LOG_ANALYTICS_DCR_IMMUTABLE_ID": "", + "LOG_ANALYTICS_DCR_STREAM_NAME": "", + "LOG_ANALYTICS_TENANT_ID": "", + "LOG_ANALYTICS_CLIENT_ID": "", + "LOG_ANALYTICS_CLIENT_SECRET": "", + } + got = {name: (props.get(name) or {}).get("default", MISSING) for name in want} + diff = {name: got[name] for name in want if got[name] != want[name]} + t.check( + "spec.ingest-defaults", + "Logs Ingestion valve defaults (auto, client_secret, public cloud " + "authority and scope, OpenWebuiMetrics, the others empty)", + not diff, + f"differs: {diff}" if diff else f"defaults={got}", + ) await t.owui.replace_valves(TRACKER, {}) names = await t.valve_names(TRACKER) t.check( @@ -840,6 +1129,9 @@ async def spec(t: Suite) -> None: async def la_groups(t: Suite) -> None: proc, la = await start_la_mock() try: + # After the install: a module load resets the tracker's logger level. + DEBUG_CAPTURE["problems"] = await tracker_debug_capture(t, DEBUG_LOG) + DEBUG_CAPTURE["started"] = True await t.owui.update_valves( TRACKER, SEND_TO_LOG_ANALYTICS=True, @@ -859,7 +1151,11 @@ async def la_groups(t: Suite) -> None: await offline(t, la) if t.selected("multimodel"): await multimodel(t, la) + if t.selected("ingest"): + await ingest_group(t, la) finally: + if DEBUG_CAPTURE["started"]: + DEBUG_CAPTURE["problems"] += await tracker_debug_capture(t, "off") await la.close() proc.terminate() try: @@ -1190,6 +1486,1548 @@ async def la_slow(t: Suite, la: LogAnalytics) -> None: ) +# ---------------------------------------------------------- Logs Ingestion API +TOKEN_ERROR = "Could not get a Microsoft Entra ID token" +INGEST_ERROR = "Error sending to Logs Ingestion API" +INGEST_EXCEPTION = "Exception when sending to Logs Ingestion API" +INGEST_SENT = "sent via the Logs Ingestion API" +DROPPED = "Log Analytics record dropped" +# premise of ingest.mi.imds: a trust_env=True request through the same proxy +# environment does not reach the IMDS mock +PROXY_PREMISE = """ +import asyncio, sys, aiohttp +async def main(): + try: + timeout = aiohttp.ClientTimeout(total=5) + async with aiohttp.ClientSession(trust_env=True, timeout=timeout) as s: + async with s.get(sys.argv[1], headers={"Metadata": "true"}) as r: + print("STATUS", r.status) + except Exception as e: + print("ERROR", type(e).__name__) +asyncio.run(main()) +""" +PROXY_ENV = { + "HTTP_PROXY": "http://127.0.0.1:9", # nothing listens + "http_proxy": "http://127.0.0.1:9", + "NO_PROXY": "localhost,127.0.0.1", # the server's other local traffic + "no_proxy": "localhost,127.0.0.1", +} + + +def fresh_client_id(prefix: str = "e2e-app") -> str: + """A client id no earlier request used, i.e. a cold token cache (the cache + lives in the server process and survives --reuse).""" + return f"{prefix}-{uuid.uuid4().hex[:8]}" + + +def li_valves(**over) -> dict: + """Every Logs Ingestion valve with an explicit value and a fresh client id, + then ``over``: update_valves merges into the stored valves, so a valve one + scenario overrides must not leak into the next one.""" + return { + "SEND_TO_LOG_ANALYTICS": True, + "LOG_ANALYTICS_INGESTION_API": "auto", + "LOG_ANALYTICS_DCR_ENDPOINT": f"https://{DCR_HOST}", + "LOG_ANALYTICS_DCR_IMMUTABLE_ID": DCR_ID, + "LOG_ANALYTICS_DCR_STREAM_NAME": "", + "LOG_ANALYTICS_AUTH_MODE": "client_secret", + "LOG_ANALYTICS_TENANT_ID": TENANT, + "LOG_ANALYTICS_CLIENT_ID": fresh_client_id(), + "LOG_ANALYTICS_CLIENT_SECRET": CLIENT_SECRET, + "LOG_ANALYTICS_AUTHORITY_HOST": "https://login.microsoftonline.com", + "LOG_ANALYTICS_INGESTION_SCOPE": DEFAULT_SCOPE, + **over, + } + + +async def set_li_valves(t: Suite, **over) -> dict: + valves = li_valves(**over) + await t.owui.update_valves(TRACKER, **valves) + return valves + + +async def set_env(t: Suite, mapping: Optional[dict] = None) -> list: + """Set the managed identity / proxy environment of the server process + through the probe pipe (PROBE_ENV): every allow-listed name not in + ``mapping`` is removed, so a scenario never inherits one. The values go + through a file, never through the chat text. Returns problems.""" + mapping = mapping or {} + unknown = sorted(set(mapping) - set(PROBE_ENV_NAMES)) + with open(PROBE_ENV_FILE, "w", encoding="utf-8") as fh: + json.dump({name: mapping.get(name) for name in PROBE_ENV_NAMES}, fh) + r = await t.owui.chat(ENV_MODEL, f"PROBE_ENV={PROBE_ENV_FILE}") + rep = probe_report(r.content) + if ( + r.status == 200 + and rep.get("env_applied") == sorted(PROBE_ENV_NAMES) + and not rep.get("env_rejected") + and not rep.get("env_error") + and not unknown + ): + return [] + return [ + f"set_env: HTTP {r.status} applied={rep.get('env_applied')} " + f"rejected={rep.get('env_rejected')} error={rep.get('env_error')} " + f"unknown={unknown}" + ] + + +async def li_chat(t: Suite, text: str, stream: bool = False) -> tuple: + """API request through the tracker: (result, seconds until the answer).""" + t0 = time.time() + r = await t.owui.chat( + PROBE_MODEL, text, stream=stream, features={"web_search": False} + ) + return r, round(time.time() - t0, 2) + + +def token_problems( + toks: list, + client_ids: list, + host: str = LOGIN_HOSTS[0], + scope: str = DEFAULT_SCOPE, + auth: str = "secret", +) -> list: + """Recorded token requests vs. one expected client id per request.""" + if len(toks) != len(client_ids): + return [f"token requests={len(toks)} want {len(client_ids)}"] + problems = [] + for tok, client_id in zip(toks, client_ids): + content_type = str(tok.get("content_type") or "").split(";")[0].strip() + want = { + "host": host, + "path": TOKEN_PATH, + "grant_type": "client_credentials", + "client_id": client_id, + "scope": scope, + "auth": auth, + "status": 200, + } + problems += [ + f"{name}={tok.get(name)!r}" + for name, value in want.items() + if tok.get(name) != value + ] + if content_type != "application/x-www-form-urlencoded": + problems.append(f"content_type={tok.get('content_type')!r}") + if not tok.get(f"{auth}_ok"): + problems.append(f"{auth}_ok=False") + return problems + + +def unclean(t: Suite, mark: int) -> list: + """Tracebacks and unclosed aiohttp sessions logged since ``mark``.""" + tracebacks = [b for b in t.log.error_blocks(mark) if "Traceback" in b] + unclosed = t.log.lines(mark, "Unclosed client session", "Unclosed connector") + return ([f"{len(tracebacks)} tracebacks"] if tracebacks else []) + unclosed[:1] + + +def header(entry: dict, name: str) -> Optional[str]: + for key, value in (entry.get("headers") or {}).items(): + if key.lower() == name.lower(): + return value + return None + + +def once_per_process(t: Suite, needle: str) -> tuple: + """(ok, detail) for a warning the tracker logs once per process, i.e. per + module load: exactly once in this run when the module was loaded during + it (the install loads it, also with --reuse), otherwise at most once in + this run and at least once since the server started.""" + run_lines = t.log.lines(t.log_start, needle) + if t.log.lines(t.log_start, TRACKER_LOADED): + return len(run_lines) == 1, f"{len(run_lines)} in this run (module loaded)" + all_lines = t.log.lines(0, needle) + return ( + len(run_lines) <= 1 and len(all_lines) >= 1, + f"{len(run_lines)} in this run, {len(all_lines)} since the server started", + ) + + +async def ingest_group(t: Suite, la: LogAnalytics) -> None: + state: dict = {"secrets": []} + try: + await upsert_derived_model(t, ENV_MODEL, "E2E Probe Env", []) + # A crashed --reuse run may have left a proxy or identity endpoint set. + state["env_problems"] = await set_env(t) + await ingest_api(t, la) + await ingest_token_cache(t, la) + retry = await ingest_token_errors(t, la, state) + await ingest_http_401(t, la) + await ingest_token_backoff(t, la, retry) # 20 s after token-error + await ingest_http_errors(t, la) + await ingest_refresh(t, la) + await ingest_slow(t, la) + await ingest_modes(t, la) + await ingest_clouds(t, la) + await ingest_managed_identity(t, la, state) + await ingest_retry_after_window(t, la, retry) + finally: + try: + INGEST_SECRETS.extend(await la.tokens()) + await la.reset() + await la.config(stream=STREAM, identity_header="") + except httpx.HTTPError: + pass + INGEST_SECRETS.extend(state["secrets"]) + await set_env(t, CONTAINER_ENV) + await t.owui.replace_valves( + TRACKER, + { + "SEND_TO_LOG_ANALYTICS": True, + "LOG_ANALYTICS_WORKSPACE_ID": WORKSPACE, + "LOG_ANALYTICS_SHARED_KEY": LA_KEY, + "LOG_ANALYTICS_LOG_TYPE": LOG_TYPE, + }, + ) + + +async def ingest_api(t: Suite, la: LogAnalytics) -> None: + """API and browser path: one exact record per response, 204, one token.""" + valves = await set_li_valves(t) + user_id = t.owui.user.get("id") + for stream in (False, True): + await la.reset() + mark = t.mark() + r, _ = await li_chat( + t, f"Logs Ingestion API token count, stream={stream}.", stream + ) + rep = probe_report(r.content) + posts = await la.wait(1, timeout=send_timeout(t, mark, 10), kind="ingest") + sent = await wait_log(t, mark, INGEST_SENT, 5) + await t.log.settle(0.3) + dc = await la.records() + toks = await la.records("token") + exp = expected(rep, r.content) + problems = ( + li_transport_problems(posts[0]) + + record_body_problems(posts[0], exp, PROBE_MODEL, user_id) + if len(posts) == 1 + else [f"ingest posts={len(posts)}"] + ) + rec = record_of(posts[0]) if posts else {} + ids = f"(chat={rec.get('chatId')}, message={rec.get('messageId')})" + if len(sent) != 1 or ids not in sent[0]: + problems.append(f"success lines={sent[:2]}") + if dc: + problems.append(f"dc posts={len(dc)}") + if stream: + if toks: + problems.append(f"token requests={len(toks)} (cached token expected)") + else: + problems += token_problems(toks, [valves["LOG_ANALYTICS_CLIENT_ID"]]) + tag = "stream" if stream else "nonstream" + t.check( + f"ingest.api.{tag}", + f"API {tag}: one exact record to " + "{endpoint}/dataCollectionRules/{dcr}/streams/Custom-_CL with " + "a Bearer token, 204 logged as success; " + + ( + "the cached token is reused" + if stream + else "one form-encoded client credentials token request" + ), + r.status == 200 and bool(rep) and not problems, + f"HTTP {r.status} problems={problems} exp={exp} " + f"outlet_errors={outlet_errors(t, mark)[:1]} rec={short(rec, 250)}", + ) + + await la.reset() + async with t.browser() as b: + c = await b.chat(PROBE_MODEL, "Browser via the Logs Ingestion API", stream=True) + posts = await la.wait(1, timeout=10, kind="ingest") + rep = probe_report(c.content) + exp = {**expected(rep, c.content), "chat_id": c.chat_id, "message_id": c.message_id} + problems = ( + li_transport_problems(posts[0]) + + record_body_problems(posts[0], exp, PROBE_MODEL, user_id) + if len(posts) == 1 + else [f"ingest posts={len(posts)}"] + ) + rec = record_of(posts[0]) if posts else {} + try: + want = status_text(rec) + except (KeyError, TypeError, ValueError): + want = None + tracker = [s for s in c.status_history if "Req:" in (s.get("description") or "")] + t.check( + "ingest.browser", + "browser: the Logs Ingestion record has the chat id and the assistant " + "message id, the status text shows the record's values, done", + c.done + and not problems + and len(tracker) == 1 + and tracker[0].get("description") == want + and tracker[0].get("done") is True, + f"problems={problems} status={tracker} want={want!r}", + ) + + +async def ingest_token_cache(t: Suite, la: LogAnalytics) -> None: + """One token for many records: sequential and concurrent.""" + await la.reset() + await set_li_valves(t) + statuses = [] + for i in range(3): + r, _ = await li_chat(t, f"cached token request {i}") + statuses.append(r.status) + await la.wait(i + 1, timeout=10, kind="ingest") + posts = await la.records("ingest") + toks = await la.records("token") + indexes = [p.get("token_index") for p in posts] + t.check( + "ingest.token-cached", + "3 sequential records: 3 posts with 204, 1 token request, the same token", + statuses == [200] * 3 + and len(posts) == 3 + and all(p.get("status") == 204 for p in posts) + and len(toks) == 1 + and indexes == [toks[0].get("token_index")] * 3, + f"HTTP {statuses} posts={[p.get('status') for p in posts]} " + f"token_indexes={indexes} token_requests={len(toks)}", + ) + + await la.reset() + await set_li_valves(t) + await la.mode(target="token", delay=4) + mark = t.mark() + t0 = time.time() + results = await asyncio.gather( + *(li_chat(t, f"concurrent token request {i}") for i in range(5)) + ) + posts = await la.wait(5, timeout=15, kind="ingest") + sent = await wait_log(t, mark, INGEST_SENT, max(0.5, t0 + 15 - time.time()), n=5) + toks = await la.records("token") + elapsed = sorted(e for _, e in results) + arrived = sorted(round(p["received"] - t0, 2) for p in posts) + t.check( + "ingest.token-concurrent", + "5 concurrent records while the token request takes 4 s: every API answer " + "< 3 s (outlet does not wait), exactly 1 token request, 5 posts with 204 " + "and 5 success lines within 15 s", + all(r.status == 200 for r, _ in results) + and elapsed[-1] < 3 + and len(toks) == 1 + and len(posts) == 5 + and all(p.get("status") == 204 for p in posts) + and bool(arrived) + and arrived[-1] <= 15 + and len(sent) == 5, + f"HTTP {[r.status for r, _ in results]} answers={elapsed}s " + f"token_requests={len(toks)} posts={[p.get('status') for p in posts]} " + f"arrived={arrived} success_lines={len(sent)}", + ) + + # Scope and tenant are part of the cache key: the other scenarios change + # the client id as well, this one keeps it. + await la.reset() + client_id = (await set_li_valves(t))["LOG_ANALYTICS_CLIENT_ID"] + await li_chat(t, "cache key: default scope") + await la.wait(1, timeout=10, kind="ingest") + alt_scope = "https://monitor.azure.com//.default" + await set_li_valves( + t, LOG_ANALYTICS_CLIENT_ID=client_id, LOG_ANALYTICS_INGESTION_SCOPE=alt_scope + ) + await li_chat(t, "cache key: other scope") + await la.wait(2, timeout=10, kind="ingest") + other_tenant = "22222222-3333-4444-5555-666666666666" # unknown to the mock + await set_li_valves( + t, LOG_ANALYTICS_CLIENT_ID=client_id, LOG_ANALYTICS_TENANT_ID=other_tenant + ) + mark = t.mark() + await li_chat(t, "cache key: other tenant") + await wait_log(t, mark, TOKEN_ERROR, 10) + await t.log.settle(1) + errors = t.log.lines(mark, TOKEN_ERROR) + posts = await la.records("ingest") + toks = await la.records("token") + t.expect_errors(mark, ("time_token_tracker", TOKEN_ERROR)) + got = [(tok.get("tenant"), tok.get("scope"), tok.get("client_id")) for tok in toks] + want = [ + (TENANT, DEFAULT_SCOPE, client_id), + (TENANT, alt_scope, client_id), + (other_tenant, DEFAULT_SCOPE, client_id), + ] + statuses = [(p.get("status"), p.get("token_index")) for p in posts] + t.check( + "ingest.token-cache-key", + "the same client id with another scope, then with another tenant: one " + "new token request each (scope and tenant are part of the cache key); " + "the unknown tenant logs one ERROR with the AADSTS90002 hint, nothing " + "is sent with the old tenant's token", + got == want + and statuses + == [(204, toks[0].get("token_index")), (204, toks[1].get("token_index"))] + and len(errors) == 1 + and "AADSTS90002" in errors[0] + and "LOG_ANALYTICS_TENANT_ID" in errors[0], + f"token_requests={got} posts={statuses} errors={errors[:2]}", + ) + + +async def ingest_token_errors(t: Suite, la: LogAnalytics, state: dict) -> dict: + """Wrong secret (one ERROR with the AADSTS hint, then the 30 s back-off), + redaction of an echoed secret, an undecryptable stored secret.""" + await la.reset() + client_id = fresh_client_id() + await set_li_valves( + t, + LOG_ANALYTICS_CLIENT_ID=client_id, + LOG_ANALYTICS_CLIENT_SECRET="e2e-wrong-secret-1", + ) + mark = t.mark() + r1, _ = await li_chat(t, "token error request 1") + errors = await wait_log(t, mark, TOKEN_ERROR, 12) + toks = await la.records("token") + failed_at = toks[0]["received"] if toks else time.time() + mark2 = t.mark() + r2, _ = await li_chat(t, "token error request 2") + dropped = await wait_log(t, mark2, DROPPED, 8) + await t.log.settle(1) + toks = await la.records("token") + posts = await la.records("ingest") + errors = t.log.lines(mark, TOKEN_ERROR) + dirty = unclean(t, mark) + t.expect_errors(mark, ("time_token_tracker", TOKEN_ERROR)) + needles = ("AADSTS7000215", "invalid_client", "not its ID") + t.check( + "ingest.token-error", + "wrong client secret: one ERROR with AADSTS7000215, invalid_client and the " + "'value, not its ID' hint, nothing posted; the next record within 30 s " + "sends no token request and logs one 'record dropped' WARNING", + r1.status == 200 + and r2.status == 200 + and len(errors) == 1 + and all(n in errors[0] for n in needles) + and not posts + and len(toks) == 1 + and len(dropped) == 1 + and not dirty, + f"errors={errors[:2]} token_requests={len(toks)} posts={len(posts)} " + f"dropped={dropped[:1]} unclean={dirty}", + ) + retry = {"client_id": client_id, "failed_at": failed_at} + + wrong = "e2e-wrong+secret/2=" # changes when URL-encoded + state["secrets"].append(quote_plus(wrong)) + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_CLIENT_SECRET=wrong) + await la.mode(target="token", echo_secret=True) + mark = t.mark() + await li_chat(t, "token error echo") + await wait_log(t, mark, TOKEN_ERROR, 12) + await t.log.settle(0.5) + blocks = [b for b in t.log.error_blocks(mark) if TOKEN_ERROR in b] + forms = (wrong, quote_plus(wrong), quote(wrong, safe="")) + leaked = [i for i, form in enumerate(forms) if any(form in b for b in blocks)] + t.expect_errors(mark, ("time_token_tracker", TOKEN_ERROR)) + t.check( + "ingest.token-error-echo", + "an error text that echoes the client secret (plain and form-encoded) is " + "logged redacted (***)", + len(blocks) == 1 and "echo ***" in blocks[0] and not leaked, + f"blocks={len(blocks)} leaked_forms={leaked} " + f"redacted={'***' in (blocks[0] if blocks else '')}", + ) + + cut = "e2e-cut+secret/3=x" + state["secrets"].append(quote_plus(cut)) + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_CLIENT_SECRET=cut) + await la.mode(target="token", echo_secret=True, echo_at_cut=True) + mark = t.mark() + await li_chat(t, "token error echo at the cut points") + await wait_log(t, mark, TOKEN_ERROR, 12) + await t.log.settle(0.5) + blocks = [b for b in t.log.error_blocks(mark) if TOKEN_ERROR in b] + # The first 8 characters of the plain and the form-encoded secret: the + # mock puts 10 of them before each cut point. + leaked = [ + i + for i, prefix in enumerate((cut[:8], quote_plus(cut)[:8])) + if any(prefix in b for b in blocks) + ] + redacted = blocks[0].count("***") if blocks else 0 + t.expect_errors(mark, ("time_token_tracker", TOKEN_ERROR)) + t.check( + "ingest.token-error-echo-cut", + "the client secret echoed across the cut points of the error text " + "(error, first line of error_description, trace_id, correlation_id) is " + "redacted before the text is cut: not even a prefix of it is logged", + len(blocks) == 1 and redacted == 4 and not leaked, + f"blocks={len(blocks)} leaked_prefixes={leaked} redacted={redacted}", + ) + + value = "encrypted:e2e-not-a-fernet-token" + state["secrets"].append(value) + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_CLIENT_SECRET=value) + stored = (await t.owui.get_valves(TRACKER)).get("LOG_ANALYTICS_CLIENT_SECRET") + mark = t.mark() + r, _ = await li_chat(t, "undecryptable secret") + lines = await wait_log(t, mark, "could not be decrypted", 10) + await t.log.settle(1) + lines = t.log.lines(mark, "could not be decrypted") + toks = await la.records("token") + posts = await la.records("ingest") + t.expect_errors(mark, ("time_token_tracker", TOKEN_ERROR)) + t.check( + "ingest.secret-undecryptable", + "a stored client secret that cannot be decrypted (WEBUI_SECRET_KEY " + "changed): one ERROR 'could not be decrypted', nothing sent to Entra ID", + r.status == 200 + and stored == value + and len(lines) == 1 + and not toks + and not posts, + f"HTTP {r.status} stored_unchanged={stored == value} lines={lines[:1]} " + f"token_requests={len(toks)} posts={len(posts)}", + ) + return retry + + +async def ingest_http_401(t: Suite, la: LogAnalytics) -> None: + """A revoked token (twice, with a 204 in between), every token rejected.""" + await la.reset() + await set_li_valves(t) + results = [(await li_chat(t, "401 warm-up (caches token A)"))[0]] + await la.wait(1, timeout=10, kind="ingest") + await la.revoke() + mark = t.mark() + results.append((await li_chat(t, "401 with the revoked token A"))[0]) + await wait_log(t, mark, f"{INGEST_ERROR}: 401", 10) + results.append((await li_chat(t, "401 then a new token B"))[0]) + await la.wait(3, timeout=10, kind="ingest") + # A later, single revocation: the 204 in between ended the "last token got + # a 401" state, so this is no second 401 in a row (no token back-off). + await la.revoke() + results.append((await li_chat(t, "401 with the revoked token B"))[0]) + await wait_log(t, mark, f"{INGEST_ERROR}: 401", 10, n=2) + results.append((await li_chat(t, "401 then a new token C"))[0]) + posts = await la.wait(5, timeout=10, kind="ingest") + await t.log.settle(1) + lines = t.log.lines(mark, INGEST_ERROR) + dropped = t.log.lines(mark, DROPPED) + toks = await la.records("token") + t.expect_errors(mark, ("time_token_tracker", f"{INGEST_ERROR}: 401")) + statuses = [p.get("status") for p in posts] + indexes = [p.get("token_index") for p in posts] + tok = [x.get("token_index") for x in toks] + t.check( + "ingest.http-401", + "a revoked token (401): one line with the scope hint, the next record " + "requests exactly one new token and gets 204; a second revocation after " + "that 204 is handled the same way (no token back-off, nothing dropped)", + [r.status for r in results] == [200] * 5 + and len(lines) == 2 + and all("LOG_ANALYTICS_INGESTION_SCOPE" in line for line in lines) + and statuses == [204, 401, 204, 401, 204] + and len(tok) == 3 + and indexes == [tok[0], tok[0], tok[1], tok[1], tok[2]] + and not dropped, + f"lines={lines[:2]} statuses={statuses} token_indexes={indexes} " + f"token_requests={len(toks)} dropped={dropped[:1]}", + ) + + await la.reset() + await set_li_valves(t) + await la.mode(target="ingest", status=401) + mark = t.mark() + for i in (1, 2): + await li_chat(t, f"persistent 401 request {i}") + await wait_log(t, mark, f"{INGEST_ERROR}: 401", 10, n=i) + mark3 = t.mark() + await li_chat(t, "persistent 401 request 3") + dropped = await wait_log(t, mark3, DROPPED, 8) + await t.log.settle(1) + lines = t.log.lines(mark, f"{INGEST_ERROR}: 401") + toks = await la.records("token") + posts = await la.records("ingest") + t.expect_errors(mark, ("time_token_tracker", f"{INGEST_ERROR}: 401")) + t.check( + "ingest.http-401-persistent", + "every token gets 401: two records with a new token each (one 401 line " + "each), then the token back-off: the third record sends nothing and logs " + "'record dropped'", + len(lines) == 2 + and len(toks) == 2 + and len(posts) == 2 + and [p.get("token_index") for p in posts] + == [tok.get("token_index") for tok in toks] + and len(dropped) == 1, + f"lines={len(lines)} token_requests={len(toks)} posts={len(posts)} " + f"dropped={dropped[:1]}", + ) + + +async def ingest_token_backoff(t: Suite, la: LogAnalytics, retry: dict) -> None: + """The token back-off lasts 30 s, not just a few: 20 s after the failed + token request of ingest.token-error, a record of that identity is still + dropped although the secret is fixed. ingest.token-retry-after-window + checks the end of the same back-off.""" + client_id, failed_at, note = retry["client_id"], retry["failed_at"], "" + if time.time() > failed_at + 24: + # A slow run: too late for that back-off, start another one. + await la.reset() + client_id = fresh_client_id() + await set_li_valves( + t, + LOG_ANALYTICS_CLIENT_ID=client_id, + LOG_ANALYTICS_CLIENT_SECRET="e2e-wrong-secret-3", + ) + mark = t.mark() + await li_chat(t, "token back-off: failed token request") + await wait_log(t, mark, TOKEN_ERROR, 12) + toks = await la.records("token") + failed_at = toks[0]["received"] if toks else time.time() + t.expect_errors(mark, ("time_token_tracker", TOKEN_ERROR)) + note = " (own failed token request, the run was slow)" + await asyncio.sleep(max(0.0, failed_at + 20 - time.time())) + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_CLIENT_ID=client_id) + mark = t.mark() + sent_at = round(time.time() - failed_at, 1) + await li_chat(t, "token back-off: 20 s later, secret fixed") + dropped = await wait_log(t, mark, DROPPED, 8) + await t.log.settle(1) + toks = await la.records("token") + posts = await la.records("ingest") + t.check( + "ingest.token-backoff-duration", + "20 s after a failed token request the identity is still in its 30 s " + "back-off: the record is dropped (one 'record dropped' WARNING), no token " + "request although the secret is fixed now", + 20 <= sent_at < 28 and not toks and not posts and len(dropped) == 1, + f"sent {sent_at}s after the failure{note} token_requests={len(toks)} " + f"posts={len(posts)} dropped={dropped[:1]}", + ) + + +async def ingest_http_errors(t: Suite, la: LogAnalytics) -> None: + """A 401 that arrives after the token was replaced; one actionable log + line per failed record, no retry.""" + await la.reset() + await set_li_valves(t) + await li_chat(t, "late 401 warm-up (caches token A)") + await la.wait(1, timeout=10, kind="ingest") + await la.revoke() + await la.mode(target="ingest", delay=4) + mark = t.mark() + await li_chat(t, "late 401: slow post with token A") # its 401 comes 4 s later + await la.wait(2, timeout=5, kind="ingest") + await la.mode(target="ingest") + await li_chat(t, "late 401: fast post with token A") # 401 at once + await wait_log(t, mark, f"{INGEST_ERROR}: 401", 4) + await li_chat(t, "late 401: new token B") + sent = await wait_log(t, mark, INGEST_SENT, 4) + late = await wait_log(t, mark, f"{INGEST_ERROR}: 401", 8, n=2) + await li_chat(t, "late 401: after the late 401") # still token B + posts = await la.wait(5, timeout=10, kind="ingest") + await t.log.settle(1) + toks = await la.records("token") + dropped = t.log.lines(mark, DROPPED) + t.expect_errors(mark, ("time_token_tracker", f"{INGEST_ERROR}: 401")) + shape = [(p.get("status"), p.get("token_index")) for p in posts] + tok = [x.get("token_index") for x in toks] + # Token B must have been cached before the slow post's 401 came back. + ordered = len(toks) >= 2 and len(posts) >= 2 + ordered = ordered and toks[1]["received"] < posts[1]["received"] + 3.5 + t.check( + "ingest.http-401-late", + "two records in flight with a revoked token: the 401 of the slow one " + "arrives after the new token was cached and does not drop it (the next " + "record reuses it: 2 token requests in all)", + len(tok) == 2 + and shape + == [(204, tok[0]), (401, tok[0]), (401, tok[0]), (204, tok[1]), (204, tok[1])] + and len(sent) == 1 + and len(late) == 2 + and ordered + and not dropped, + f"posts={shape} token_requests={len(toks)} success_lines={len(sent)} " + f"401_lines={len(late)} ordered={ordered} dropped={dropped[:1]}", + ) + + cases = ( + ( + "ingest.http-403", + "403: one ERROR line with the Monitoring Metrics Publisher role and the " + "30 minute propagation hint, no retry", + {"status": 403}, + {}, + (": 403", "Monitoring Metrics Publisher", "30 minutes"), + ), + ( + "ingest.http-404", + "404 (unknown DCR immutable ID): one line naming the DCR ID and stream " + "name valves", + None, + {"LOG_ANALYTICS_DCR_IMMUTABLE_ID": "dcr-" + "f" * 32}, + ( + ": 404", + "LOG_ANALYTICS_DCR_IMMUTABLE_ID", + "LOG_ANALYTICS_DCR_STREAM_NAME", + ), + ), + ( + "ingest.http-413", + "413: one line with the 1 MB limit, no retry", + {"status": 413}, + {}, + (": 413", "1 MB"), + ), + ( + "ingest.http-429", + "429: one line with Retry-After as sent, no retry (one post 3 s later)", + {"status": 429, "retry_after": 17}, + {}, + (": 429", "Retry-After: 17"), + ), + ( + "ingest.http-500", + "500: one line with the response body and the x-ms-client-request-id " + "of the request, no traceback, session closed", + {"status": 500}, + {}, + (f"{INGEST_ERROR}: 500", "e2e mock"), + ), + ) + for sid, title, ingest_mode, over, needles in cases: + await la.reset() + await set_li_valves(t, **over) + if ingest_mode: + await la.mode(target="ingest", **ingest_mode) + mark = t.mark() + r, _ = await li_chat(t, f"{sid} please") + await wait_log(t, mark, INGEST_ERROR, 10) + await asyncio.sleep(3 if sid.endswith("429") else 1.5) # a retry would show + await t.log.settle(0.5) + lines = t.log.lines(mark, INGEST_ERROR) + posts = await la.records("ingest") + dirty = unclean(t, mark) + t.expect_errors(mark, ("time_token_tracker", INGEST_ERROR)) + problems = [] + if len(lines) != 1 or not all(n in lines[0] for n in needles): + problems.append(f"lines={lines[:2]}") + if len(posts) != 1: + problems.append(f"posts={len(posts)}") + if sid.endswith("500"): + logged = re.search(r"request=([0-9a-f-]{36})", lines[0] if lines else "") + sent_id = header(posts[0], "x-ms-client-request-id") if posts else None + if not logged or logged.group(1) != sent_id: + problems.append( + f"request id logged={logged.group(1) if logged else None} " + f"sent={sent_id}" + ) + problems += dirty + t.check(sid, title, r.status == 200 and not problems, f"problems={problems}") + + +async def ingest_refresh(t: Suite, la: LogAnalytics) -> None: + """Token refresh before expiry, and a failed refresh with a valid token.""" + await la.reset() + await set_li_valves(t) + await la.mode(target="token", expires_in=8) # refresh after 4 s + await li_chat(t, "refresh request 1") + posts = await la.wait(1, timeout=10, kind="ingest") + # The filter posts right after it received the token: its refresh time is + # at most 4 s after this post (the mock's token receipt is earlier). + anchor = posts[0]["received"] if posts else time.time() + await li_chat(t, "refresh request 1b, well before half the lifetime") + posts = await la.wait(2, timeout=10, kind="ingest") + toks = await la.records("token") + early = ( + round(posts[1]["received"] - toks[0]["received"], 2) + if len(posts) > 1 and toks + else None + ) + await asyncio.sleep(max(0.0, anchor + 5 - time.time())) + await li_chat(t, "refresh request 2") + posts = await la.wait(3, timeout=10, kind="ingest") + toks = await la.records("token") + gap = round(toks[1]["received"] - toks[0]["received"], 2) if len(toks) > 1 else None + t.check( + "ingest.token-refresh", + "a token with 8 s lifetime is reused for a record in the first half of " + "its lifetime and refreshed after half of it: 2 token requests, the " + "second before the first token expired, the last post uses the new " + "token, no expired token is sent", + len(toks) == 2 + and gap is not None + and gap < 8 + and early is not None + and early < 3.5 + and len(posts) == 3 + and posts[1].get("token_index") == toks[0].get("token_index") + and posts[2].get("token_index") == toks[1].get("token_index") + and all(p.get("status") == 204 and not p.get("token_expired") for p in posts), + f"token_requests={len(toks)} early={early}s gap={gap}s posts=" + f"{[(p.get('status'), p.get('token_index')) for p in posts]}", + ) + + await la.reset() + await set_li_valves(t) + await la.mode(target="token", expires_in=12) # refresh 6 s, usable until 9 s + await li_chat(t, "refresh fallback request 1") + posts = await la.wait(1, timeout=10, kind="ingest") + toks = await la.records("token") + t0 = toks[0]["received"] if toks else time.time() + # refresh due <= anchor + 6, usable until >= t0 + 9 and <= anchor + 9 + anchor = posts[0]["received"] if posts else time.time() + await la.mode(target="token", status=500) + await asyncio.sleep(max(0.0, anchor + 6.3 - time.time())) + mark2 = t.mark() + sent2 = round(time.time() - t0, 2) + await li_chat(t, "refresh fallback request 2") + await la.wait(2, timeout=10, kind="ingest") + # Inside the 30 s token back-off that failure started, the token is still + # usable (until >= t0 + 9): sent with it, no token request. + sent2b = round(time.time() - anchor, 2) + await li_chat(t, "refresh fallback request 2b, in the back-off") + await la.wait(3, timeout=5, kind="ingest") + keep = await wait_log(t, mark2, "keeping the cached token", 5) + await asyncio.sleep(max(0.0, anchor + 9.8 - time.time())) + mark3 = t.mark() + sent3 = round(time.time() - t0, 2) + await li_chat(t, "refresh fallback request 3") + await wait_log(t, mark3, DROPPED, 6) + await t.log.settle(1) + toks = await la.records("token") + posts = await la.records("ingest") + keep = t.log.lines(mark2, "keeping the cached token") + dropped = t.log.lines(mark2, DROPPED) + t.expect_errors(mark2, ("time_token_tracker", "keeping the cached token")) + t.check( + "ingest.token-refresh-fallback", + "the refresh fails while the token is still valid: one ERROR 'keeping the " + "cached token', the record is sent with the old token (204), and so is " + "the next one inside the 30 s back-off; after the token's usable time " + "the next record is dropped without a token request", + len(keep) == 1 + and len(toks) == 2 + and toks[1].get("status") == 500 + and len(posts) == 3 + and all(p.get("token_index") == toks[0].get("token_index") for p in posts) + and all(p.get("status") == 204 for p in posts) + and sent2b < 8.5 + and len(dropped) == 1 + and dropped[0] in t.log.lines(mark3, DROPPED), + f"request2_at={sent2}s request2b_at=post1+{sent2b}s request3_at={sent3}s " + f"keep={keep[:1]} posts=" + f"{[(p.get('status'), p.get('token_index')) for p in posts]} token_requests=" + f"{[(x.get('status'), x.get('token_index')) for x in toks]} dropped={dropped[:2]}", + ) + + +async def ingest_slow(t: Suite, la: LogAnalytics) -> None: + """Hanging token endpoint, slow and hanging ingestion, refused connection: + the API answer never waits.""" + mark0 = t.mark() + results = {} + await la.reset() + await set_li_valves(t) + await la.mode(target="token", delay=HANG_SECONDS) + mark = t.mark() + r, elapsed = await li_chat(t, "token endpoint hangs") + lines = await wait_log(t, mark, TOKEN_ERROR, 15) + posts = await la.records("ingest") + results["token-hang"] = (r.status, elapsed, lines[:1], len(posts)) + ok_a = ( + r.status == 200 + and elapsed < 2 + and len(lines) == 1 + and "TimeoutError" in lines[0] + and not posts + ) + + await la.reset() + await set_li_valves(t) # another client id: (a)'s key is in its back-off + await la.mode(target="ingest", delay=SLOW_SECONDS) + mark = t.mark() + t0 = time.time() + r, elapsed = await li_chat(t, "slow ingestion") + posts = await la.wait(1, timeout=15, kind="ingest") + sent = await wait_log(t, mark, INGEST_SENT, max(0.5, t0 + 15 - time.time())) + sent_at = round(time.time() - t0, 2) + results["slow"] = (r.status, elapsed, len(posts), sent_at, bool(sent)) + ok_b = r.status == 200 and elapsed < 2 and len(posts) == 1 and bool(sent) + ok_b = ok_b and sent_at <= 15 + + await la.reset() + await la.mode(target="ingest", delay=HANG_SECONDS) + mark = t.mark() + r, elapsed = await li_chat(t, "hanging ingestion") + lines = await wait_log(t, mark, INGEST_EXCEPTION, 16) + results["hang"] = (r.status, elapsed, lines[:1]) + ok_c = ( + r.status == 200 and elapsed < 2 and bool(lines) and "TimeoutError" in lines[0] + ) + await la.mode(target="ingest") + t.expect_errors( + mark0, + ("time_token_tracker", TOKEN_ERROR), + ("time_token_tracker", INGEST_EXCEPTION), + ) + print(f" ingest.slow: {results}", flush=True) + t.check( + "ingest.slow-not-blocking", + f"hanging token endpoint, slow ({SLOW_SECONDS} s) and hanging " + f"({HANG_SECONDS} s) ingestion: API answer < 2 s each; the token request " + "times out (ERROR, nothing posted), the slow record arrives <= 15 s, the " + "hanging send times out", + ok_a and ok_b and ok_c, + f"{results}", + ) + + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_DCR_ENDPOINT=f"https://{REFUSED_HOST}") + mark = t.mark() + r, elapsed = await li_chat(t, "unreachable ingestion endpoint") + lines = await wait_log(t, mark, INGEST_EXCEPTION, 5) + await t.log.settle(0.5) + lines = t.log.lines(mark, INGEST_EXCEPTION) + t.expect_errors(mark, ("time_token_tracker", INGEST_EXCEPTION)) + t.check( + "ingest.unreachable", + "ingestion endpoint refuses the connection: API answer < 2 s, one line " + "'Exception when sending to Logs Ingestion API: ClientConnectorError'", + r.status == 200 + and elapsed < 2 + and len(lines) == 1 + and "ClientConnectorError" in lines[0], + f"HTTP {r.status} elapsed={elapsed}s lines={lines[:2]}", + ) + + +async def ingest_modes(t: Suite, la: LogAnalytics) -> None: + """LOG_ANALYTICS_INGESTION_API: auto, data_collector, logs_ingestion, both, + unknown values, invalid settings, deprecation warning.""" + user_id = t.owui.user.get("id") + await la.reset() + await set_li_valves(t) + r, _ = await li_chat(t, "auto with both APIs configured") + posts = await la.wait(1, timeout=10, kind="ingest") + await asyncio.sleep(1) + dc = await la.records() + t.check( + "ingest.mode.auto-li", + "auto with both APIs configured: Logs Ingestion API only", + r.status == 200 + and len(posts) == 1 + and posts[0].get("status") == 204 + and not dc, + f"HTTP {r.status} ingest={[p.get('status') for p in posts]} dc={len(dc)}", + ) + + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_CLIENT_SECRET="") + problems = [] + for i in range(2): + r, _ = await li_chat(t, f"auto with incomplete Logs Ingestion settings {i}") + dc = await la.wait(i + 1, timeout=10) + rep = probe_report(r.content) + if len(dc) != i + 1: + problems.append(f"request {i}: dc posts={len(dc)}") + else: + problems += record_problems( + dc[i], expected(rep, r.content), PROBE_MODEL, user_id + ) + await asyncio.sleep(1) + posts = await la.records("ingest") + once, warnings = once_per_process( + t, + "not fully configured (missing: LOG_ANALYTICS_CLIENT_SECRET); using the " + "HTTP Data Collector API", + ) + t.check( + "ingest.mode.auto-incomplete", + "auto with incomplete Logs Ingestion settings: the 2.6.2 Data Collector " + "request (signature, headers, record), one WARNING naming the missing " + "valve (once per process)", + not problems and not posts and once, + f"problems={problems} ingest={len(posts)} warnings: {warnings}", + ) + + await la.reset() + await set_li_valves( + t, + LOG_ANALYTICS_AUTH_MODE="managed_identity", + LOG_ANALYTICS_DCR_ENDPOINT="", + LOG_ANALYTICS_DCR_IMMUTABLE_ID="", + LOG_ANALYTICS_TENANT_ID="", + LOG_ANALYTICS_CLIENT_ID="", + LOG_ANALYTICS_CLIENT_SECRET="", + ) + r, _ = await li_chat(t, "auto, only LOG_ANALYTICS_AUTH_MODE is set") + dc = await la.wait(1, timeout=10) + await asyncio.sleep(1) + other = [e.get("kind") for e in await la.records("all") if e.get("kind") != "dc"] + problems = ( + record_problems( + dc[0], expected(probe_report(r.content), r.content), PROBE_MODEL, user_id + ) + if len(dc) == 1 + else [f"dc posts={len(dc)}"] + ) + once, warnings = once_per_process( + t, + "not fully configured (missing: LOG_ANALYTICS_DCR_ENDPOINT, " + "LOG_ANALYTICS_DCR_IMMUTABLE_ID); using the HTTP Data Collector API", + ) + t.check( + "ingest.mode.auto-partial-auth", + "auto with LOG_ANALYTICS_AUTH_MODE=managed_identity as the only Logs " + "Ingestion setting: the 2.6.2 Data Collector request, one WARNING naming " + "the missing endpoint and DCR ID (once per process)", + r.status == 200 and not problems and not other and once, + f"HTTP {r.status} problems={problems} other_requests={other} " + f"warnings: {warnings}", + ) + + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_INGESTION_API="data_collector") + r, _ = await li_chat(t, "data_collector forced") + dc = await la.wait(1, timeout=10) + await asyncio.sleep(1) + posts = await la.records("ingest") + toks = await la.records("token") + problems = ( + record_problems( + dc[0], expected(probe_report(r.content), r.content), PROBE_MODEL, user_id + ) + if len(dc) == 1 + else [f"dc posts={len(dc)}"] + ) + t.check( + "ingest.mode.data-collector", + "data_collector with complete Logs Ingestion settings: only the 2.6.2 " + "Data Collector request, no token request", + r.status == 200 and not problems and not posts and not toks, + f"HTTP {r.status} problems={problems} ingest={len(posts)} " + f"token_requests={len(toks)}", + ) + + await la.reset() + await set_li_valves( + t, LOG_ANALYTICS_INGESTION_API="logs_ingestion", LOG_ANALYTICS_DCR_ENDPOINT="" + ) + statuses = [] + for i in range(2): + r, _ = await li_chat(t, f"logs_ingestion incomplete {i}") + statuses.append(r.status) + await asyncio.sleep(2) + everything = await la.records("all") + once, warnings = once_per_process( + t, + "LOG_ANALYTICS_INGESTION_API=logs_ingestion, but the Logs Ingestion API is " + "not fully configured (missing: LOG_ANALYTICS_DCR_ENDPOINT)", + ) + t.check( + "ingest.mode.logs-ingestion-incomplete", + "logs_ingestion without LOG_ANALYTICS_DCR_ENDPOINT: nothing sent, one " + "WARNING naming the valve (once per process)", + statuses == [200, 200] and not everything and once, + f"HTTP {statuses} requests={[e.get('kind') for e in everything]} " + f"warnings: {warnings}", + ) + + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_INGESTION_API="both") + mark = t.mark() + r, _ = await li_chat(t, "both APIs please") + rep = probe_report(r.content) + dc = await la.wait(1, timeout=10) + posts = await la.wait(1, timeout=10, kind="ingest") + sent_dc = await wait_log(t, mark, "Log Analytics data sent successfully", 5) + sent_li = await wait_log(t, mark, INGEST_SENT, 5) + problems = [] + if len(dc) != 1: + problems.append(f"dc posts={len(dc)}") + else: + problems += record_problems( + dc[0], expected(rep, r.content), PROBE_MODEL, user_id + ) + if len(posts) != 1: + problems.append(f"ingest posts={len(posts)}") + else: + problems += li_transport_problems(posts[0]) + if dc and posts and dc[0].get("body") != posts[0].get("body"): + problems.append("dc body != ingest body") + if len(sent_dc) != 1 or len(sent_li) != 1: + problems.append(f"success lines dc={len(sent_dc)} li={len(sent_li)}") + t.check( + "ingest.mode.both", + "both: the same record to the Data Collector API (2.6.2 request) and the " + "Logs Ingestion API, one success line each", + r.status == 200 and not problems, + f"HTTP {r.status} problems={problems}", + ) + + # both, one side incomplete: the record still goes through the other one. + await la.reset() + await set_li_valves( + t, LOG_ANALYTICS_INGESTION_API="both", LOG_ANALYTICS_CLIENT_SECRET="" + ) + r, _ = await li_chat(t, "both, Logs Ingestion settings incomplete") + dc = await la.wait(1, timeout=10) + await asyncio.sleep(1) + other = [e.get("kind") for e in await la.records("all") if e.get("kind") != "dc"] + problems = ( + record_problems( + dc[0], expected(probe_report(r.content), r.content), PROBE_MODEL, user_id + ) + if len(dc) == 1 + else [f"dc posts={len(dc)}"] + ) + problems += [f"Logs Ingestion requests={other}"] if other else [] + once_li, warnings_li = once_per_process( + t, + "LOG_ANALYTICS_INGESTION_API=both, but the Logs Ingestion API is not fully " + "configured (missing: LOG_ANALYTICS_CLIENT_SECRET); sending only through " + "the other one", + ) + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_INGESTION_API="both") + try: + await t.owui.update_valves(TRACKER, LOG_ANALYTICS_WORKSPACE_ID="") + r2, _ = await li_chat(t, "both, Data Collector settings incomplete") + posts = await la.wait(1, timeout=10, kind="ingest") + await asyncio.sleep(1) + dc = await la.records() + finally: + await t.owui.update_valves(TRACKER, LOG_ANALYTICS_WORKSPACE_ID=WORKSPACE) + problems += ( + li_transport_problems(posts[0]) + + record_body_problems( + posts[0], + expected(probe_report(r2.content), r2.content), + PROBE_MODEL, + user_id, + ) + if len(posts) == 1 + else [f"ingest posts={len(posts)}"] + ) + problems += [f"dc posts={len(dc)}"] if dc else [] + once_dc, warnings_dc = once_per_process( + t, + "LOG_ANALYTICS_INGESTION_API=both, but the HTTP Data Collector API is not " + "fully configured (missing: LOG_ANALYTICS_WORKSPACE_ID); sending only " + "through the other one", + ) + t.check( + "ingest.mode.both-one-side", + "both with one API incomplete: the record goes through the other one " + "(Logs Ingestion incomplete: the 2.6.2 Data Collector request; Data " + "Collector incomplete: Logs Ingestion 204), one WARNING each (once per " + "process)", + r.status == 200 and r2.status == 200 and not problems and once_li and once_dc, + f"HTTP {r.status}/{r2.status} problems={problems} warnings: " + f"Logs Ingestion side {warnings_li}; Data Collector side {warnings_dc}", + ) + + hexa = uuid.uuid4().hex[:4] + endpoint_a = f"http://{DCR_HOST}" + dcr_c = f"my-dcr-{hexa}" + mark_a = t.mark() + seen = {} + for name, over in ( + ("a", {"LOG_ANALYTICS_DCR_ENDPOINT": endpoint_a}), + ("b", {"LOG_ANALYTICS_AUTH_MODE": f"bogus-{hexa}"}), + ("c", {"LOG_ANALYTICS_DCR_IMMUTABLE_ID": dcr_c}), + # The client secret must never go out over plain HTTP. + ("d", {"LOG_ANALYTICS_AUTHORITY_HOST": "http://login.microsoftonline.com"}), + ): + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_INGESTION_API="logs_ingestion", **over) + mark = t.mark() + # c: two records with the same value, the hint is logged once + for i in range(2 if name == "c" else 1): + r, _ = await li_chat(t, f"invalid Logs Ingestion setting {name} {i}") + if name == "c": + await wait_log(t, mark, f"{INGEST_ERROR}: 404", 10, n=i + 1) + await asyncio.sleep(1.5) + seen[name] = (r.status, [e.get("kind") for e in await la.records("all")]) + t.expect_errors(mark_a, ("time_token_tracker", f"{INGEST_ERROR}: 404")) + once_https, https = once_per_process( + t, "LOG_ANALYTICS_DCR_ENDPOINT (must use https)" + ) + once_authority, authority = once_per_process( + t, "LOG_ANALYTICS_AUTHORITY_HOST (must use https)" + ) + auth = t.log.lines(mark_a, "LOG_ANALYTICS_AUTH_MODE (unknown value") + dcr_hint = t.log.lines(mark_a, "does not look like an immutable ID") + token_errors = t.log.lines(mark_a, TOKEN_ERROR) + # The DCR ID is no secret: the 404 hint names it on purpose. + shown = [ + line + for line in t.log.lines(mark_a, endpoint_a, dcr_c) + if f"{INGEST_ERROR}: 404" not in line + ] + t.check( + "ingest.config-invalid", + "invalid settings: an http:// endpoint, an http:// authority and an " + "unknown auth mode count as missing (WARNING, nothing sent, no token " + "request); a DCR ID that is not dcr-<32 hex> logs a hint once per value " + "and is still used; the warnings do not show the values", + seen.get("a") == (200, []) + and seen.get("b") == (200, []) + and seen.get("c") == (200, ["token", "ingest", "ingest"]) + and seen.get("d") == (200, []) + and once_https + and once_authority + and len(auth) == 1 + and len(dcr_hint) == 1 + and not token_errors + and not shown, + f"requests={seen} https warnings: endpoint {https}, authority {authority}; " + f"auth={auth[:1]} dcr_hint={len(dcr_hint)} token_errors={token_errors[:1]} " + f"values_shown={shown[:1]}", + ) + + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_INGESTION_API=f" BoGuS-{hexa} ") + mark = t.mark() + for i in range(2): + await li_chat(t, f"unknown mode {i}") + posts = await la.wait(2, timeout=10, kind="ingest") + await asyncio.sleep(1) + dc = await la.records() + lines = t.log.lines(mark, "unknown LOG_ANALYTICS_INGESTION_API value") + t.check( + "ingest.mode.unknown", + "an unknown LOG_ANALYTICS_INGESTION_API value: one WARNING, behaves as auto", + len(lines) == 1 + and len(posts) == 2 + and all(p.get("status") == 204 for p in posts) + and not dc, + f"warnings={lines[:2]} ingest={[p.get('status') for p in posts]} dc={len(dc)}", + ) + + once, warnings = once_per_process(t, DEPRECATION) + t.check( + "ingest.deprecation-warning", + "sending through the HTTP Data Collector API logs one deprecation WARNING " + "per process", + once, + f"{warnings}: {t.log.lines(0, DEPRECATION)[-1:]}", + ) + + +async def ingest_clouds(t: Suite, la: LogAnalytics) -> None: + """Sovereign cloud valves and endpoint normalization.""" + await la.reset() + scope = "https://monitor.azure.us/.default" + valves = await set_li_valves( + t, + LOG_ANALYTICS_AUTHORITY_HOST="login.microsoftonline.us/", + LOG_ANALYTICS_INGESTION_SCOPE=scope, + LOG_ANALYTICS_DCR_ENDPOINT=f"https://{GOV_DCR_HOST}", + ) + r, _ = await li_chat(t, "US Government cloud") + posts = await la.wait(1, timeout=10, kind="ingest") + toks = await la.records("token") + problems = token_problems( + toks, [valves["LOG_ANALYTICS_CLIENT_ID"]], host=LOGIN_HOSTS[1], scope=scope + ) + ( + li_transport_problems(posts[0], host=GOV_DCR_HOST) + if len(posts) == 1 + else [f"ingest posts={len(posts)}"] + ) + t.check( + "ingest.sovereign", + "US Government valves (authority without scheme and with a trailing " + "slash): token from login.microsoftonline.us with the .us scope, record " + "to the .azure.us endpoint, 204", + r.status == 200 and not problems, + f"HTTP {r.status} problems={problems}", + ) + + stream = "Custom-E2E_Explicit" + await la.reset() + await la.config(stream=stream) + try: + await set_li_valves( + t, + LOG_ANALYTICS_DCR_ENDPOINT=f"{DCR_HOST}/", + LOG_ANALYTICS_DCR_STREAM_NAME=stream, + ) + r, _ = await li_chat(t, "endpoint without scheme, explicit stream") + posts = await la.wait(1, timeout=10, kind="ingest") + finally: + await la.config(stream=STREAM) + problems = ( + li_transport_problems(posts[0], stream=stream) + if len(posts) == 1 + else [f"ingest posts={len(posts)}"] + ) + t.check( + "ingest.endpoint-normalized", + "endpoint without https:// and with a trailing slash, explicit " + "LOG_ANALYTICS_DCR_STREAM_NAME: exact URI, 204", + r.status == 200 and not problems, + f"HTTP {r.status} problems={problems}", + ) + + +async def ingest_managed_identity(t: Suite, la: LogAnalytics, state: dict) -> None: + """App Service, IMDS (without proxy), AKS workload identity, unsupported.""" + env_problems = list(state.get("env_problems") or []) + mi_valves = { + "LOG_ANALYTICS_AUTH_MODE": "managed_identity", + "LOG_ANALYTICS_CLIENT_SECRET": "", + } + + header_a = f"e2e-idh-{uuid.uuid4().hex}" + header_b = f"e2e-idh-{uuid.uuid4().hex}" + state["secrets"] += [header_a, header_b] + client_id = fresh_client_id("e2e-uami") + env = {"IDENTITY_ENDPOINT": f"{MI_URL}/msi/token", "IDENTITY_HEADER": header_a} + await la.reset() + await la.config(identity_header=header_a) + await set_li_valves(t, LOG_ANALYTICS_CLIENT_ID=client_id, **mi_valves) + await la.mode(target="msi", expires_in=8) + problems = env_problems + await set_env(t, env) + try: + await li_chat(t, "App Service managed identity 1") + posts = await la.wait(1, timeout=10, kind="ingest") + anchor = posts[0]["received"] if posts else time.time() + problems += await set_env(t, {**env, "IDENTITY_HEADER": header_b}) + await la.config(identity_header=header_b) + await asyncio.sleep(max(0.0, anchor + 5 - time.time())) + await li_chat(t, "App Service managed identity 2") + posts = await la.wait(2, timeout=10, kind="ingest") + finally: + problems += await set_env(t) + await la.config(identity_header="") + msi = await la.records("msi") + toks = await la.records("token") + for rec in msi: + query = rec.get("query") or {} + want = { + "api-version": "2019-08-01", + "resource": "https://monitor.azure.com", + "client_id": client_id, + } + problems += [ + f"{k}={query.get(k)!r}" for k, v in want.items() if query.get(k) != v + ] + if rec.get("flavour") != "app_service" or not rec.get("header_ok"): + problems.append( + f"flavour={rec.get('flavour')} header_ok={rec.get('header_ok')}" + ) + if len(msi) != 2: + problems.append(f"msi requests={len(msi)}") + problems += [p for e in posts for p in li_transport_problems(e)] + t.check( + "ingest.mi.app-service", + "managed identity on App Service: IDENTITY_ENDPOINT with X-IDENTITY-HEADER " + "(read per request: the rotated header is used), api-version 2019-08-01, " + "resource without /.default, user-assigned client_id; 2 records with 204", + len(posts) == 2 and not toks and not problems, + f"problems={problems} posts={len(posts)} token_route={len(toks)}", + ) + + # App Service / Container Apps answer errors as {statusCode, message, + # correlationId}, not {error, error_description}. + header_c = f"e2e-idh-{uuid.uuid4().hex}" + state["secrets"].append(header_c) + env = {"IDENTITY_ENDPOINT": f"{MI_URL}/msi/token", "IDENTITY_HEADER": header_c} + await la.reset() + await la.config(identity_header=header_c) + await set_li_valves( + t, LOG_ANALYTICS_CLIENT_ID=fresh_client_id("e2e-unknown-uami"), **mi_valves + ) + problems = env_problems + await set_env(t, env) + mark = t.mark() + try: + await li_chat(t, "App Service managed identity, client ID not assigned") + await wait_log(t, mark, TOKEN_ERROR, 10) + await t.log.settle(1) + finally: + problems += await set_env(t) + await la.config(identity_header="") + blocks = [b for b in t.log.error_blocks(mark) if TOKEN_ERROR in b] + msi = await la.records("msi") + posts = await la.records("ingest") + t.expect_errors(mark, ("time_token_tracker", TOKEN_ERROR)) + correlation_id = msi[0].get("correlation_id") if len(msi) == 1 else None + needles = ( + "(managed identity (App Service)): 400 - check LOG_ANALYTICS_CLIENT_ID", + "Detail: Unable to load the proper Managed Identity.", + f"(correlationId={correlation_id})", + ) + t.check( + "ingest.mi.app-service-error", + "the App Service / Container Apps token service answers 400 {statusCode, " + "message, correlationId} (client ID not assigned to the app): one ERROR " + "with the LOG_ANALYTICS_CLIENT_ID hint, the service's message and its " + "correlationId; nothing sent", + bool(correlation_id) + and len(blocks) == 1 + and all(n in blocks[0] for n in needles) + and not posts + and not problems, + f"errors={[b[:400] for b in blocks[:2]]} msi={len(msi)} posts={len(posts)} " + f"problems={problems}", + ) + + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_CLIENT_ID="", **mi_valves) + await la.mode(target="msi", expires_in=8) # no stale cache in a --reuse rerun + problems = list(env_problems) + problems += await set_env( + t, {"AZURE_POD_IDENTITY_AUTHORITY_HOST": MI_IMDS_URL, **PROXY_ENV} + ) + try: + r, _ = await li_chat(t, "IMDS managed identity") + posts = await la.wait(1, timeout=10, kind="ingest") + finally: + problems += await set_env(t) + premise = await asyncio.to_thread( + subprocess.run, + [ + "python3", + "-c", + PROXY_PREMISE, + f"{MI_IMDS_URL}/metadata/identity/oauth2/token?api-version=2018-02-01" + "&resource=https://monitor.azure.com", + ], + env={**os.environ, **PROXY_ENV}, + capture_output=True, + text=True, + timeout=30, + ) + premise_out = (premise.stdout or premise.stderr).strip() + msi = await la.records("msi") + for rec in msi: + query = rec.get("query") or {} + if ( + rec.get("flavour") != "imds" + or rec.get("local_ip") != "127.0.0.2" + or not rec.get("header_ok") + or query.get("api-version") != "2018-02-01" + or query.get("resource") != "https://monitor.azure.com" + or "client_id" in query + ): + problems.append(f"msi={short(rec, 200)}") + if len(msi) != 1: + problems.append(f"msi requests={len(msi)}") + problems += ( + li_transport_problems(posts[0]) if len(posts) == 1 else [f"posts={len(posts)}"] + ) + t.check( + "ingest.mi.imds", + "managed identity on a VM (IMDS): Metadata: true, api-version 2018-02-01, " + "system-assigned (no client_id), reached directly although HTTP_PROXY is " + "set (a trust_env request through the same environment fails at the " + "proxy); record with 204", + r.status == 200 and not problems and premise_out.startswith("ERROR Client"), + f"problems={problems} premise={premise_out[:120]!r}", + ) + + hex_a, hex_b = uuid.uuid4().hex, uuid.uuid4().hex + assertion_a, assertion_b = f"e2e-fed-{hex_a}", f"e2e-fed-{hex_b}" + state["secrets"] += [assertion_a, assertion_b] + client_1, client_2 = fresh_client_id("e2e-wi"), fresh_client_id("e2e-wi") + env = { + "AZURE_FEDERATED_TOKEN_FILE": WI_TOKEN_FILE, + "AZURE_TENANT_ID": TENANT, + "AZURE_CLIENT_ID": client_1, + } + with open(WI_TOKEN_FILE, "w", encoding="utf-8") as fh: + fh.write(assertion_a + "\n") + await la.reset() + await set_li_valves( + t, LOG_ANALYTICS_TENANT_ID="", LOG_ANALYTICS_CLIENT_ID="", **mi_valves + ) + await la.mode(target="token", expires_in=8) + problems = env_problems + await set_env(t, env) + try: + await li_chat(t, "workload identity 1") + posts = await la.wait(1, timeout=10, kind="ingest") + anchor = posts[0]["received"] if posts else time.time() + with open(WI_TOKEN_FILE, "w", encoding="utf-8") as fh: + fh.write(assertion_b + "\n") + await asyncio.sleep(max(0.0, anchor + 5 - time.time())) + await li_chat(t, "workload identity 2") + await la.wait(2, timeout=10, kind="ingest") + problems += await set_env(t, {**env, "AZURE_CLIENT_ID": client_2}) + await li_chat(t, "workload identity 3") + posts = await la.wait(3, timeout=10, kind="ingest") + finally: + problems += await set_env(t) + toks = await la.records("token") + problems += token_problems(toks, [client_1, client_1, client_2], auth="assertion") + problems += [ + f"form={tok.get('form')}" + for tok in toks + if "client_secret" in (tok.get("form") or {}) + or (tok.get("form") or {}).get("client_assertion_type") + != "urn:ietf:params:oauth:client-assertion-type:jwt-bearer" + ] + problems += ( + [p for e in posts for p in li_transport_problems(e)] + if len(posts) == 3 + else [f"posts={len(posts)}"] + ) + t.check( + "ingest.mi.workload-identity", + "AKS workload identity: client assertion from AZURE_FEDERATED_TOKEN_FILE " + "(read per token request: the rotated file is used), tenant and client id " + "from AZURE_TENANT_ID / AZURE_CLIENT_ID (a changed AZURE_CLIENT_ID gets its " + "own token), no client secret; 3 records with 204", + not problems, + f"problems={problems}", + ) + + await la.reset() + await set_li_valves(t, **mi_valves) + problems = env_problems + await set_env( + t, {"IDENTITY_ENDPOINT": f"{MI_URL}/arc", "IMDS_ENDPOINT": MI_URL} + ) + mark = t.mark() + try: + await li_chat(t, "Azure Arc managed identity") + lines = await wait_log(t, mark, "Azure Arc is not supported", 8) + await t.log.settle(1) + finally: + problems += await set_env(t) + lines = t.log.lines(mark, "Azure Arc is not supported") + msi = await la.records("msi") + posts = await la.records("ingest") + t.expect_errors(mark, ("time_token_tracker", TOKEN_ERROR)) + t.check( + "ingest.mi.unsupported", + "managed identity on Azure Arc: one ERROR 'not supported', no request", + len(lines) == 1 and not msi and not posts and not problems, + f"lines={lines[:1]} msi={len(msi)} posts={len(posts)} problems={problems}", + ) + + +async def ingest_retry_after_window(t: Suite, la: LogAnalytics, retry: dict) -> None: + """The 30 s token back-off of ingest.token-error ends; the fixed secret + works without a restart (the secret is not part of the cache key).""" + await la.reset() + await set_li_valves(t, LOG_ANALYTICS_CLIENT_ID=retry["client_id"]) + waited = max(0.0, retry["failed_at"] + 31 - time.time()) + await asyncio.sleep(waited) + r, _ = await li_chat(t, "after the token back-off") + posts = await la.wait(1, timeout=10, kind="ingest") + toks = await la.records("token") + problems = token_problems(toks, [retry["client_id"]]) + ( + [p.get("status") for p in posts if p.get("status") != 204] + if len(posts) == 1 + else [f"posts={len(posts)}"] + ) + t.check( + "ingest.token-retry-after-window", + "31 s after the failed token request, the same identity with the fixed " + "secret gets exactly one new token and its record is sent (204)", + r.status == 200 and not problems, + f"waited={waited:.1f}s problems={problems}", + ) + + # ---------------------------------------------------------------------- valves async def valves_group(t: Suite, la: LogAnalytics) -> None: await t.owui.update_valves(