Skip to content

Lab: Intermittent 5xx Under Load

This lab reproduces intermittent request failures caused by sync worker starvation on Azure App Service Linux.

The app intentionally mixes slow and fast endpoints:

  • /slow sleeps 5-15 seconds.
  • /fast returns immediately.

When a burst of concurrent slow requests occupies the limited Gunicorn sync workers, fast requests queue behind them and start timing out.

graph TD
    A[Deploy B1 Linux app with 2 sync workers] --> B[Launch 20 concurrent /slow requests]
    B --> C[Immediately call /fast 10 times]
    C --> D[Observe queued fast requests]
    D --> E[Collect trigger CSV + /diag/stats]
    E --> F[Query AppServiceHTTPLogs for 200 vs 499 pattern]
    F --> G[Confirm worker starvation causal chain]

This guide is designed to diagnose intermittent 5xx-like customer symptoms where the root cause is worker pool saturation and request queueing rather than random platform instability, using a B1 Linux Python 3.11 app with Gunicorn sync, --workers 2, --timeout 30, a trigger of 20 concurrent /slow requests followed by 10 /fast requests, and sanitized artifacts from a real run.

Lab Metadata

Attribute Value
Difficulty Intermediate
Estimated Duration 45-60 minutes
Tier Basic
Failure Mode Intermittent request failures caused by sync-worker starvation and request queueing under mixed slow and fast load
Skills Practiced Load-pattern analysis, worker-model troubleshooting, HTTP log interpretation, queueing correlation

Status code interpretation

The artifact run primarily shows HTTP 499 in App Service HTTP logs for timed-out client-side requests.

In customer incidents this usually appears as intermittent "5xx/unavailable" behavior from the caller perspective, even when backend logs include 499 rather than 500.


1) Background

1.1 Mechanism overview

This failure mode is a queueing problem:

  1. A small sync worker pool accepts work.
  2. Long-running requests occupy workers.
  3. New requests cannot execute until a worker is free.
  4. Waiting clients hit timeout thresholds.
  5. Logs show a mixed pattern of successes and timeouts.

1.2 App and process model in this lab

From baseline/app-config.json:

Setting Value Why it matters
linuxFxVersion PYTHON|3.11 Linux Python runtime
appCommandLine gunicorn --bind 0.0.0.0:8000 --workers 2 --worker-class sync --timeout 30 app:app Hard cap of 2 concurrent request executions
alwaysOn false Startup behavior not primary in this run
numberOfWorkers 1 Single app instance for deterministic load

With sync workers, a worker handles one request at a time. If two workers are blocked on /slow, /fast waits in queue.

1.3 Request starvation diagram

flowchart TD
    A[20 concurrent /slow requests] --> B[Worker 1 busy]
    A --> C[Worker 2 busy]
    D[/fast requests arrive/] --> E[Queue behind /slow]
    E --> F{Client timeout reached?}
    F -->|Yes| G[Client abort / 499 in logs]
    F -->|No| H[Eventually 200]

    style B fill:#ef6c00,color:#fff
    style C fill:#ef6c00,color:#fff
    style G fill:#c62828,color:#fff
    style H fill:#2e7d32,color:#fff

1.4 Endpoint behavior from app code

Endpoint Behavior Typical duration
/slow Random sleep between 5 and 15 seconds seconds to tens of seconds when queued
/fast Immediate JSON response milliseconds when not queued
/diag/stats Process and endpoint counters milliseconds

Because /slow blocks worker threads in sync mode, it is an ideal lab endpoint to reproduce starvation.

1.5 Why this resembles intermittent 5xx incidents

In real systems, users often report:

  • Some requests succeed.
  • Some requests fail with gateway/service-unavailable messages.
  • Failures are clustered during brief load bursts.

That pattern matches this lab's mixed-success output under constrained workers.

1.6 Internal queueing timeline

sequenceDiagram
    participant ClientA as Slow Clients (x20)
    participant ClientB as Fast Clients (x10)
    participant FE as App Service Front End
    participant Gunicorn as Gunicorn sync workers=2
    participant App as Flask app

    ClientA->>FE: Burst /slow
    FE->>Gunicorn: Dispatch first two /slow
    Gunicorn->>App: worker 1 executes /slow
    Gunicorn->>App: worker 2 executes /slow
    ClientB->>FE: /fast requests
    FE->>Gunicorn: Queue /fast (no free worker)
    Note over Gunicorn: queue wait grows
    alt Client timeout reached
        FE-->>ClientB: timeout/aborted (logged as 499)
    else Worker frees up in time
        Gunicorn->>App: execute /fast
        FE-->>ClientB: 200
    end

1.7 Signal map for this failure mode

Signal Expected direction under starvation
/slow request durations high (often near timeout bounds)
/fast request durations bimodal (very fast or near timeout)
/fast timeout count increases during slow burst
HTTP status mix 200 mixed with timeout-like statuses (499 in this run)
Console worker timeout entries possible but not guaranteed in short runs

1.8 Distinguishing from other incident classes

Incident class Primary signal How this lab differs
Dependency outage external dependency errors Here, failure appears even without dependency calls
CPU saturation high CPU, slow compute everywhere Here, queueing from sync workers dominates
Memory pressure reclaim/swap trends Here, fast endpoint fails due queue delay, not low memory
Platform restart platform lifecycle errors Here, platform logs mainly startup informational events

1.9 Practical troubleshooting takeaway

If fast endpoints fail only when slow endpoints are concurrent, investigate worker model first:

  1. Worker class (sync vs async/threaded)
  2. Worker count
  3. Timeout alignment between client and server
  4. Concurrency profile of requests

2) Hypothesis

2.1 Falsifiable hypothesis statement

If we run 20 concurrent /slow requests against a Gunicorn app configured with only 2 sync workers and then send 10 /fast requests, then:

  • a significant share of /fast will time out,
  • /slow will also partially time out,
  • HTTP logs will show mixed 200/499 pattern,

which confirms worker starvation and queueing.

2.2 Causal chain

  1. SLOW_CONCURRENCY=20 saturates the two sync workers.
  2. /fast requests queue behind /slow.
  3. Client-side timeout thresholds are reached (15s for fast, 45s for slow in trigger artifacts).
  4. Timed-out requests surface as status 000 in trigger output and 499 in App Service HTTP logs.
flowchart TD
    A[Limited sync workers=2] --> B[Concurrent /slow saturates workers]
    B --> C[/fast cannot start promptly]
    C --> D[Queue wait increases]
    D --> E[Client timeout threshold exceeded]
    E --> F[499 in HTTP logs and timeout at caller]

2.3 Proof criteria

Proof criterion Threshold Evidence source
Slow endpoint stress is real At least 20 slow attempts with multiple long durations slow-responses-*.csv
Fast endpoint starvation At least 50% fast timeout rate during slow burst fast-responses-*.csv
Mixed status pattern Both success and timeout-like statuses in same run Trigger CSV + KQL HTTP
Queueing signature Fast endpoint durations include near-timeout values Trigger CSV + KQL TimeTaken
No mandatory platform crash Platform logs can remain informational KQL platform export

2.4 Disproof criteria

Any of these weaken/disprove starvation hypothesis:

  • Fast requests remain consistently low-latency under slow concurrency burst.
  • Slow requests do not occupy workers long enough to cause queueing.
  • Timeouts occur without corresponding slow burst.
  • Failures align with platform restarts instead of queueing behavior.

2.5 Variables

Independent variables

Variable Value in this run
Gunicorn worker count 2
Worker class sync
Gunicorn timeout 30 seconds
Slow concurrency burst 20 requests
Fast request volume 10 requests
Client max-time used by trigger 45 seconds (for both endpoints in script)

Dependent variables

Variable Source
Per-request status and latency trigger CSV artifacts
Endpoint status distribution KQL HTTP export
Endpoint TimeTaken KQL HTTP export
Endpoint hit counters /diag/stats artifacts
Runtime/platform error messages KQL console/platform exports

Controlled conditions

Control Value
SKU B1
Region Korea Central
Runtime Python 3.11
App version same Flask code and trigger

2.6 Causal validation matrix

Observation Expected if hypothesis true Actual artifact result
Slow request long tails Yes Yes (~45s timeouts present)
Fast requests time out under slow load Yes Yes (6/10 timeout in fast CSV)
Status mix in logs Yes Yes (200 and 499 both present)
Clear platform crash required No No (platform logs informational)

2.7 Confounders and boundaries

  • Trigger script captures one burst window; repeated runs can vary slightly.
  • App Service HTTP status 499 indicates client abort/timeouts; external monitoring may categorize this as availability impact akin to intermittent 5xx symptoms.
  • Console timeout logs may be absent for short windows even when queueing is evident.

Do not overfit on one status code

For this incident class, causal interpretation should prioritize timing and queueing behavior over a single status code family.


3) Runbook

3.1 Prerequisites

az version
az bicep version
az account show --output table
Command/Flag Purpose
az version Verify Azure CLI is installed and display installed version
az bicep version Confirm Bicep CLI is available for template deployment
az account show Verify the active subscription context before deployment
--output table Display output in human-readable table format

3.2 Set standard variables

export RG="rg-lab-5xx"
export LOCATION="koreacentral"
export BASE_NAME="lab5xx"
export APP_PACKAGE_PATH="/tmp/intermittent-5xx-app.zip"

3.3 Create resource group

az group create --name "$RG" --location "$LOCATION"
Command/Flag Purpose
az group create Create a resource group to contain all lab resources
--name Resource group name
--location Azure region for the resource group

3.4 Deploy Bicep (actual lab template path)

az deployment group create \
  --resource-group "$RG" \
  --template-file "labs/intermittent-5xx/main.bicep" \
  --parameters baseName="$BASE_NAME" location="$LOCATION"
Command/Flag Purpose
az deployment group create Deploy Azure resources from a Bicep template
--resource-group Target resource group for the deployment
--template-file Path to the Bicep template defining lab infrastructure (App Service, Log Analytics)
--parameters Override template parameters for base name and region

Extract deployment outputs:

export APP_NAME=$(az deployment group show \
  --resource-group "$RG" \
  --name "main" \
  --query "properties.outputs.appName.value" \
  --output tsv)

export APP_HOSTNAME=$(az deployment group show \
  --resource-group "$RG" \
  --name "main" \
  --query "properties.outputs.defaultHostName.value" \
  --output tsv)

export APP_URL="https://${APP_HOSTNAME}"
Command Purpose
az deployment group show --resource-group "$RG" --name "main" --query "properties.outputs.appName.value" --output tsv Reads the appName deployment output from the main resource-group deployment.
--resource-group "$RG" --name "main" --query "properties.outputs.appName.value" --output tsv Looks up the deployment in this resource group.
--name "main" --query "properties.outputs.appName.value" --output tsv Targets the deployment record named main.
--query "properties.outputs.appName.value" --output tsv Projects only the appName output's value field.
--output tsv Returns the selected output value as plain text for shell variable assignment.
az deployment group show --resource-group "$RG" --name "main" --query "properties.outputs.defaultHostName.value" --output tsv Reads the defaultHostName deployment output from the main resource-group deployment.
--resource-group "$RG" --name "main" --query "properties.outputs.defaultHostName.value" --output tsv Looks up the deployment in this resource group.
--name "main" --query "properties.outputs.defaultHostName.value" --output tsv Targets the deployment record named main.
--query "properties.outputs.defaultHostName.value" --output tsv Projects only the defaultHostName output's value field.
--output tsv Returns the selected output value as plain text for shell variable assignment.

3.5 Deploy application package

cd "labs/intermittent-5xx/app"
zip --recurse-paths "$APP_PACKAGE_PATH" .

az webapp deploy \
  --resource-group "$RG" \
  --name "$APP_NAME" \
  --src-path "$APP_PACKAGE_PATH" \
  --type zip
Command Purpose
az webapp deploy --resource-group "$RG" --name "$APP_NAME" --src-path "$APP_PACKAGE_PATH" --type zip Deploys the packaged intermittent-5xx sample app to the target web app as a ZIP deployment.
--resource-group "$RG" --name "$APP_NAME" --src-path "$APP_PACKAGE_PATH" --type zip Runs the deployment in this resource group.
--name "$APP_NAME" --src-path "$APP_PACKAGE_PATH" --type zip Targets this web app.
--src-path "$APP_PACKAGE_PATH" --type zip Uses the ZIP package built from the lab app directory as deployment input.
--type zip Tells Azure CLI to perform a ZIP deployment.

Restart app for clean test state:

az webapp restart --resource-group "$RG" --name "$APP_NAME"
Command Purpose
az webapp restart --resource-group "$RG" --name "$APP_NAME" Restarts the web app so the workload begins from a clean post-deploy state.
--resource-group "$RG" --name "$APP_NAME" Restarts the app in this resource group.
--name "$APP_NAME" Targets this web app.

3.6 Baseline health checks

curl --silent "$APP_URL/"
curl --silent "$APP_URL/health"
curl --silent "$APP_URL/fast"
curl --silent "$APP_URL/diag/stats"

Baseline artifact values from this run:

Artifact Key values
baseline/diag-stats.json request_count=3, active_slow_requests=0, endpoint_counters={diag_stats:2, root:1}
baseline/app-config.json gunicorn --workers 2 --worker-class sync --timeout 30

3.7 Trigger starvation workload (actual trigger script)

bash "labs/intermittent-5xx/trigger.sh" "$APP_URL"

Script behavior:

  1. Launches 20 concurrent /slow requests.
  2. Immediately sends 10 /fast requests.
  3. Prints per-request status and elapsed time.

3.8 Capture post-trigger diagnostics

curl --silent "$APP_URL/diag/stats" > /tmp/intermittent-5xx-diag-stats-after.json
curl --silent "$APP_URL/diag/env" > /tmp/intermittent-5xx-diag-env-after.json

The Application Insights overview is the highest-signal Portal view to open right after the trigger script finishes. Failed requests is the primary burst indicator, Server response time separates fast-path latency from slow-endpoint queueing, and Server requests lets you correlate the failure burst with the request-volume burst from /slow. Keep the window at one hour so the starvation pattern isn't smoothed away by older traffic, and click the Failed requests tile to drill into the failure telemetry.

3.9 Query Log Analytics

Resolve workspace identifiers:

export LOG_WORKSPACE_NAME=$(az deployment group show \
  --resource-group "$RG" \
  --name "main" \
  --query "properties.outputs.logAnalyticsWorkspaceName.value" \
  --output tsv)

export LOG_WORKSPACE_ID=$(az monitor log-analytics workspace show \
  --resource-group "$RG" \
  --workspace-name "$LOG_WORKSPACE_NAME" \
  --query "customerId" \
  --output tsv)
Command Purpose
az deployment group show --resource-group "$RG" --name "main" --query "properties.outputs.logAnalyticsWorkspaceName.value" --output tsv Reads the logAnalyticsWorkspaceName deployment output from the main deployment.
--resource-group "$RG" --name "main" --query "properties.outputs.logAnalyticsWorkspaceName.value" --output tsv Looks up the deployment in this resource group.
--name "main" --query "properties.outputs.logAnalyticsWorkspaceName.value" --output tsv Targets the deployment record named main.
--query "properties.outputs.logAnalyticsWorkspaceName.value" --output tsv Projects only the logAnalyticsWorkspaceName output's value field.
--output tsv Returns the workspace name as plain text for shell variable assignment.
az monitor log-analytics workspace show --resource-group "$RG" --workspace-name "$LOG_WORKSPACE_NAME" --query "customerId" --output tsv Retrieves the Log Analytics workspace resource and emits its workspace customer ID.
--resource-group "$RG" --workspace-name "$LOG_WORKSPACE_NAME" --query "customerId" --output tsv Looks up the workspace in this resource group.
--workspace-name "$LOG_WORKSPACE_NAME" --query "customerId" --output tsv Targets this Log Analytics workspace.
--query "customerId" --output tsv Projects only the workspace customerId field.
--output tsv Returns the workspace customer ID as plain text for shell variable assignment.

HTTP detail query

az monitor log-analytics query \
  --workspace "$LOG_WORKSPACE_ID" \
  --analytics-query "AppServiceHTTPLogs | where TimeGenerated > ago(2h) | project TimeGenerated, CsUriStem, ScStatus, TimeTaken, CsHost | order by TimeGenerated desc" \
  --output json
Command/Flag Purpose
az monitor log-analytics query Execute a KQL query against a Log Analytics workspace
--workspace Log Analytics workspace customer ID to query
--analytics-query KQL query projecting per-request HTTP details for timing analysis
--output json Return raw JSON for programmatic analysis

Status by endpoint query

az monitor log-analytics query \
  --workspace "$LOG_WORKSPACE_ID" \
  --analytics-query "AppServiceHTTPLogs | where TimeGenerated > ago(2h) | summarize total=count(), s200=countif(ScStatus==200), s499=countif(ScStatus==499), s5xx=countif(ScStatus>=500) by CsUriStem | order by total desc" \
  --output json
Command/Flag Purpose
az monitor log-analytics query Execute a KQL query against a Log Analytics workspace
--analytics-query KQL query summarizing status code distribution (200/499/5xx) per endpoint
--output json Return raw JSON for programmatic analysis

Endpoint latency profile query

az monitor log-analytics query \
  --workspace "$LOG_WORKSPACE_ID" \
  --analytics-query "AppServiceHTTPLogs | where TimeGenerated > ago(2h) | summarize avgMs=avg(TimeTaken), p95Ms=percentile(TimeTaken,95), maxMs=max(TimeTaken) by CsUriStem | order by p95Ms desc" \
  --output json
Command/Flag Purpose
az monitor log-analytics query Execute a KQL query against a Log Analytics workspace
--analytics-query KQL query computing latency percentiles (avg, p95, max) per endpoint
--output json Return raw JSON for programmatic analysis

Console and platform query

az monitor log-analytics query \
  --workspace "$LOG_WORKSPACE_ID" \
  --analytics-query "AppServiceConsoleLogs | where TimeGenerated > ago(2h) | project TimeGenerated, ResultDescription | order by TimeGenerated desc" \
  --output json

az monitor log-analytics query \
  --workspace "$LOG_WORKSPACE_ID" \
  --analytics-query "AppServicePlatformLogs | where TimeGenerated > ago(2h) | project TimeGenerated, Level, Message | order by TimeGenerated desc" \
  --output json
Command Purpose
az monitor log-analytics query --workspace "$LOG_WORKSPACE_ID" --analytics-query "AppServiceConsoleLogs | where TimeGenerated > ago(2h) | project TimeGenerated, ResultDescription | order by TimeGenerated desc" --output json Queries AppServiceConsoleLogs for recent console output so you can inspect runtime messages and errors during the failure window.
--workspace "$LOG_WORKSPACE_ID" --analytics-query "AppServiceConsoleLogs | where TimeGenerated > ago(2h) | project TimeGenerated, ResultDescription | order by TimeGenerated desc" --output json Runs the KQL query against this Log Analytics workspace.
--analytics-query "AppServiceConsoleLogs | where TimeGenerated > ago(2h) | project TimeGenerated, ResultDescription | order by TimeGenerated desc" --output json Projects recent TimeGenerated and ResultDescription columns from AppServiceConsoleLogs, ordered newest first.
--output json Returns the query result as JSON.
az monitor log-analytics query --workspace "$LOG_WORKSPACE_ID" --analytics-query "AppServicePlatformLogs | where TimeGenerated > ago(2h) | project TimeGenerated, Level, Message | order by TimeGenerated desc" --output json Queries AppServicePlatformLogs for recent platform lifecycle messages during the failure window.
--workspace "$LOG_WORKSPACE_ID" --analytics-query "AppServicePlatformLogs | where TimeGenerated > ago(2h) | project TimeGenerated, Level, Message | order by TimeGenerated desc" --output json Runs the KQL query against this Log Analytics workspace.
--analytics-query "AppServicePlatformLogs | where TimeGenerated > ago(2h) | project TimeGenerated, Level, Message | order by TimeGenerated desc" --output json Projects recent TimeGenerated, Level, and Message columns from AppServicePlatformLogs, ordered newest first.
--output json Returns the query result as JSON.
Command/Flag Purpose
az monitor log-analytics query Execute a KQL query against a Log Analytics workspace
--workspace Log Analytics workspace customer ID to query
--analytics-query (first) KQL query filtering AppServiceConsoleLogs for runtime output and errors
--analytics-query (second) KQL query filtering AppServicePlatformLogs for lifecycle events
--output json Return raw JSON for programmatic analysis

3.10 KQL snippets for portal troubleshooting

Keep the blade-level Time range wide enough to cover the intermittent failure window, since this lab's 5xx pattern usually spans hours rather than minutes, and leave Show: 1000 results so summarized status distributions aren't truncated. Save a snippet to the Queries hub once it proves useful so the next on-call engineer can re-run the same triage in one click.

AppServiceHTTPLogs
| where TimeGenerated > ago(2h)
| summarize total=count(), s200=countif(ScStatus==200), s499=countif(ScStatus==499), s5xx=countif(ScStatus>=500) by CsUriStem
| order by total desc
AppServiceHTTPLogs
| where TimeGenerated > ago(2h)
| summarize avgMs=avg(TimeTaken), p95Ms=percentile(TimeTaken, 95), maxMs=max(TimeTaken) by CsUriStem, ScStatus
| order by p95Ms desc
AppServiceHTTPLogs
| where TimeGenerated > ago(2h)
| where CsUriStem in ("/slow", "/fast")
| project TimeGenerated, CsUriStem, ScStatus, TimeTaken
| order by TimeGenerated asc
AppServicePlatformLogs
| where TimeGenerated > ago(2h)
| project TimeGenerated, Level, Message
| order by TimeGenerated desc

3.11 Verification checklist

  • [ ] Trigger executed with 20 /slow and 10 /fast.
  • [ ] Slow and fast CSV artifacts captured.
  • [ ] /fast timeout ratio increased during /slow burst.
  • [ ] KQL HTTP logs show mixed status pattern.
  • [ ] /diag/stats shows endpoint counters after run.
  • [ ] Console/platform exports checked.

3.12 Common pitfalls

Pitfall Symptom Fix
Wrong Bicep path Deployment error Use labs/intermittent-5xx/main.bicep
Trigger against wrong app URL No expected pattern Re-resolve APP_URL from deployment outputs
Missing diagnostics linkage Empty KQL tables Verify diagnostic setting on web app
Running trigger repeatedly without waiting Mixed windows hard to interpret Label each run and time-bound KQL queries

3.13 Decision tree for incident triage

flowchart TD
    A[Observe intermittent failures] --> B{Are slow endpoints active concurrently?}
    B -->|No| C[Investigate dependency or platform issues]
    B -->|Yes| D{Fast endpoints degrade simultaneously?}
    D -->|No| E[Investigate endpoint-specific logic]
    D -->|Yes| F[Check worker count and worker class]
    F --> G[Validate queueing pattern in TimeTaken and status mix]
    G --> H[Apply concurrency/worker tuning]

4) Experiment Log

4.1 Artifact inventory used

All values below come from:

labs/intermittent-5xx/artifacts-sanitized/

Category Files used
Baseline baseline/diag-stats.json, baseline/app-config.json
Trigger response files trigger/slow-responses-20260404T053453Z.csv, trigger/fast-responses-20260404T053453Z.csv
Post-trigger state trigger/diag-stats-after-20260404T053453Z.json
KQL exports trigger/kql-http-20260404T060610Z.json, trigger/kql-console-20260404T060610Z.json, trigger/kql-platform-20260404T060610Z.json

4.2 Baseline state

From baseline/diag-stats.json:

Metric Value
request_count 3
active_slow_requests 0
endpoint_counters.diag_stats 2
endpoint_counters.root 1
pid 1897

From baseline/app-config.json:

Config key Value
appCommandLine gunicorn --bind 0.0.0.0:8000 --workers 2 --worker-class sync --timeout 30 app:app
linuxFxVersion PYTHON|3.11
resourceGroup rg-lab-5xx

4.3 Trigger CSV evidence: slow endpoint

From slow-responses-20260404T053453Z.csv (20 requests):

Metric Value
Total requests 20
200 responses 9
000 timeout responses 11
Success ratio 45%
Timeout ratio 55%
Average elapsed (s) 35.924
p95 elapsed (s) 45.001
Max elapsed (s) 45.001

Representative rows:

Endpoint Index Status Elapsed (s)
slow 1 200 36.720223
slow 10 200 12.683494
slow 11 000 44.999914
slow 16 000 45.001025
slow 20 000 45.000372

4.4 Trigger CSV evidence: fast endpoint

From fast-responses-20260404T053453Z.csv (10 requests):

Metric Value
Total requests 10
200 responses 4
000 timeout responses 6
Success ratio 40%
Timeout ratio 60%
Average elapsed (s) 9.404
p95 elapsed (s) 15.001
Max elapsed (s) 15.001

Per-request rows (exact):

Endpoint Index Status Elapsed (s)
fast 1 200 0.646940
fast 2 000 15.000374
fast 3 000 15.000239
fast 4 000 15.001060
fast 5 000 15.000587
fast 6 000 15.000307
fast 7 000 15.000966
fast 8 200 2.012888
fast 9 200 0.719541
fast 10 200 0.656119

4.5 Post-trigger app state

From diag-stats-after-20260404T053453Z.json:

Metric Value
request_count 17
active_slow_requests 0
endpoint_counters.slow 10
endpoint_counters.fast 1
endpoint_counters.diag_stats 3
endpoint_counters.health 1
endpoint_counters.diag_env 1
endpoint_counters.root 1

Interpretation:

  • Endpoint counters reflect requests that reached the app handler.
  • Trigger CSV includes client-observed timeouts before some requests completed server-side.

4.6 KQL HTTP aggregate summary

From kql-http-20260404T060610Z.json:

Aggregate metric Value
Total rows 60
200 rows 29
499 rows 31

Status by endpoint:

Endpoint 200 499 Total
/slow 16 24 40
/fast 5 7 12
/diag/stats 4 0 4
/health 2 0 2
/diag/env 1 0 1
/ 1 0 1

4.6.1 Log Analytics KQL query for status distribution by endpoint (portal verification)

To cross-verify the aggregate 200 / 499 status mix summarized in §4.6 (60 rows from kql-http-20260404T060610Z.json, split 29 200 / 31 499, with /slow accounting for 40 rows and /fast for 12) is a real property of the raw AppServiceHTTPLogs rows and not a JSON-parse artifact of the sanitized export, the Log Analytics workspace Logs blade was opened against the same workspace from a fresh live reproduction and a per-endpoint status distribution query was executed interactively against the current live data:

Azure portal Log Analytics workspace Logs blade for workspace law-lab5xx-o4evin7tt76tc with breadcrumb "Home > law-lab5xx-o4evin7tt76tc". Blade heading reads "law-lab5xx-o4evin7tt76tc | Logs" and the sub-heading reads "Log Analytics workspace". The left navigation shows Logs highlighted, with sibling entries Overview, Activity log, Access control (IAM), Tags, Diagnose and solve problems, Resource visualizer, Settings, Classic, Monitoring, Automation, and Help. The query editor tab reads "New Query 1*" and the KQL editor shows a four-line query: line 1 `AppServiceHTTPLogs`, line 2 `| where TimeGenerated > ago(1h)`, line 3 `| summarize total=count(), s200=countif(ScStatus==200), s499=countif(ScStatus==499) by CsUriStem`, line 4 `| order by total desc`. The query bar has a green Run button, Time range set to "Set in query", Show set to "1000 results", and the mode dropdown is on "KQL mode". The Results tab is active (sibling tab: Chart). The grid has four columns "CsUriStem", "total", "s200", "s499" with 5 rows: `/slow` 20 7 13, `/fast` 3 2 1, `/diag/stats` 2 1 1, `/` 1 1 0, `/health` 1 1 0. Bottom left shows query duration "0s 515ms" and "Display time (UTC+00:00)". Bottom right shows "Query details" and pagination "1 - 5 of 5".

Purpose: Provide an independent Portal-side execution of a per-endpoint status distribution query so a reviewer can confirm that the mixed 200 / 499 signature in §4.6 (roughly 60% 499 on /slow, 58% 499 on /fast) is a real property of the raw AppServiceHTTPLogs rows the Log Analytics service holds — and can also see that the failure mode reproduces with the same shape (majority 499 on /slow, minority 499 bleeding into /fast, zero 5xx anywhere) when the trigger is re-run against a freshly deployed lab instance.

Look for:

  • Blade heading reads "law-lab5xx-o4evin7tt76tc | Logs" and the sub-heading reads "Log Analytics workspace" — this confirms the query ran against the same workspace attached to this lab's Web App via diagnostic settings, matching the workspace referenced by the sanitized JSON exports in §4.1.
  • The KQL editor shows exactly the query AppServiceHTTPLogs | where TimeGenerated > ago(1h) | summarize total=count(), s200=countif(ScStatus==200), s499=countif(ScStatus==499) by CsUriStem | order by total desc — countif(ScStatus==200) and countif(ScStatus==499) are conditional counts that partition each row group by status code without requiring separate pivot queries. Rows with any other status (e.g., 500, 502, 503) would not be counted in either the s200 or s499 columns and would show as total > s200 + s499.
  • The Results grid shows exactly 5 rows (pagination "1 - 5 of 5") and every row satisfies total == s200 + s499 — no third status class exists in this window. This falsifies the hypothesis "the app is returning genuine 5xx errors": every failure recorded is a 499 (client aborted before the server sent a response), not a 500 / 502 / 503 (server-side error).
  • The /slow row shows total 20, s200 7, s499 13 — 65% of /slow requests were aborted by the client at the 45-second curl --max-time boundary because the Gunicorn sync worker was still executing the artificial 5-15 s time.sleep() inside the handler when the client gave up.
  • The /fast row shows total 3, s200 2, s499 1 — a supposedly sub-100 ms endpoint recorded a 499 in the same window. This is the "starvation bleed" signature: /fast inherited the client-timeout fate because both sync workers were occupied serving /slow when the /fast request arrived, so it sat in the socket backlog until the client aborted.
  • The /diag/stats row shows total 2, s200 1, s499 1 — a low-volume secondary starvation-bleed signal from the diagnostic endpoint itself getting queued behind occupied workers, confirming that even in-app diagnostic endpoints suffer when the sync worker pool is saturated.
  • The / and /health rows each show total 1, s200 1, s499 0 — probe cadence during the trigger window; these endpoints exist for verification (see §5) and should not be interpreted as failure-mode signals.
  • Query duration in bottom left reads a small millisecond value (here 0s 515ms) — confirming the workspace is not throttled and the query hit indexed data, so the returned row count and status distribution are authoritative and not a partial-scan timeout.

Expected result: The 5 rows returned by the Portal show /slow, /fast, and /diag/stats with a mix of 200 and 499 statuses (with /slow and /fast as the dominant starvation signal and /diag/stats as low-volume bleed from the in-app diagnostic endpoint) and / and /health returning only 200, matching §4's overall verdict that the failure mode is worker starvation causing client aborts, not server errors: the app is healthy at the HTTP layer but sync workers cannot service concurrent long-running requests fast enough, so clients time out and record 499. If instead the Portal query returned rows with ScStatus 500, 502, or 503 in a non-zero third-column count (added as an additional countif(ScStatus>=500 and ScStatus<600) in a variant of this query), the verdict would need to be re-graded to "confirmed with outage" because the failure mode would have progressed from client-side timeouts to server-side worker recycles or platform-level errors.

Next step: If a future reproduction shows the /slow s499 count at or near 0 (i.e., almost all /slow requests succeeded within the 45-second client timeout), the trigger is not actually saturating the workers — inspect labs/intermittent-5xx/trigger.sh for a concurrency regression (the default is 20 concurrent /slow requests against 2 sync workers, producing 10 requests-worth of demand per worker). Conversely, if /fast shows s499 == total (every /fast request aborted), the sleep distribution in labs/intermittent-5xx/app/app.py may have been widened beyond the intended 5-15 s range, holding workers so long that even burst-mode /fast requests cannot be serviced within their timeout.

4.7 KQL latency profile by endpoint

From KQL HTTP export (TimeTaken in milliseconds):

Endpoint Count Avg ms p95 ms Max ms
/slow 40 36,440.3 44,894 44,921
/fast 12 11,046.8 14,484 44,865
/diag/stats 4 11.5 6 33
/health 2 19.0 3 35

Key signature:

  • /fast shows both very low and very high durations in the same run, which is expected when queueing behind occupied sync workers.

4.7.1 Log Analytics KQL query for latency percentiles by endpoint (portal verification)

To cross-verify the per-endpoint latency profile summarized in §4.7 (/slow avg 36,440 ms / p95 44,894 ms / max 44,921 ms across 40 rows; /fast avg 11,047 ms / p95 14,484 ms / max 44,865 ms across 12 rows) is a faithful reduction of the raw TimeTaken column and not a JSON-parse rounding artifact, the same Log Analytics workspace Logs blade was reopened and a per-endpoint per-status percentile query was executed interactively against the current live data. Splitting by CsUriStem, ScStatus in one query is important because the aggregate row-level table in §4.7 combines both status classes and hides the client-timeout signature inside the /slow average:

Azure portal Log Analytics workspace Logs blade for workspace law-lab5xx-o4evin7tt76tc with breadcrumb "Home > law-lab5xx-o4evin7tt76tc". Blade heading reads "law-lab5xx-o4evin7tt76tc | Logs" and the sub-heading reads "Log Analytics workspace". The left navigation shows Logs highlighted, with sibling entries Overview, Activity log, Access control (IAM), Tags, Diagnose and solve problems, Resource visualizer, Settings, Classic, Monitoring, Automation, and Help. The query editor tab reads "New Query 1*" and the KQL editor shows a five-line query: line 1 `AppServiceHTTPLogs`, line 2 `| where TimeGenerated > ago(1h)`, line 3 `| where CsUriStem in ("/slow", "/fast")`, line 4 `| summarize avgMs=avg(TimeTaken), p95Ms=percentile(TimeTaken, 95), maxMs=max(TimeTaken) by CsUriStem, ScStatus`, line 5 `| order by p95Ms desc`. The query bar has a green Run button, Time range set to "Set in query", Show set to "1000 results", and the mode dropdown is on "KQL mode". The Results tab is active (sibling tab: Chart). The grid has five columns "CsUriStem", "ScStatus", "avgMs", "p95Ms", "maxMs" with 4 rows sorted by p95Ms desc: `/slow` 499 44652.38461538462 44693 44693, `/fast` 499 44548 44548 44548, `/slow` 200 20850.14285714286 33975 33975, `/fast` 200 4997.5 9992 9992. Bottom left shows query duration "1s 37ms" and "Display time (UTC+00:00)". Bottom right shows "Query details" and pagination "1 - 4 of 4".

Purpose: Provide an independent Portal-side execution of a per-endpoint per-status percentile query so a reviewer can confirm three claims from §4.7: (1) /slow requests that ended in a 499 cluster tightly at the 45-second client timeout because that is when the client gave up, (2) /slow requests that returned 200 fall into the 5-15 s app-simulated sleep range plus queueing delay, and (3) /fast requests that returned 200 are inflated well above the sub-100 ms baseline because they share the same sync worker pool as /slow.

Look for:

  • The /slow 499 row shows avgMs ≈ 44652, p95Ms 44693, maxMs 44693 — all three statistics cluster within ~41 ms of each other and sit ~307-348 ms below the 45-second curl --max-time 45 client timeout, confirming that the 499 is the client giving up shortly before the configured deadline (the ~350 ms gap absorbs TCP FIN round-trip and the client's event-loop scheduling latency) and not a variable-latency degradation. If avgMs were, say, 30,000 ms with maxMs at 90,000 ms instead, that would suggest an intermediate load balancer timeout at a different value.
  • The /fast 499 row shows avgMs 44548 — this is the single /fast request that was aborted, and its latency being nearly identical to the /slow 499 cluster proves the /fast request was queued behind a /slow request and inherited the same 45-second client deadline, not that /fast itself takes 45 seconds inside the handler.
  • The /slow 200 row shows avgMs ≈ 20850, p95Ms 33975, maxMs 33975 — successful /slow requests average ~20.9 s (roughly a ~15 s queue wait plus the app's 5-15 s intended sleep), and the slowest that still returned 200 (33,975 ms) sat in the queue for ~20 seconds before its sync worker was free to run the sleep and return. The Portal aggregate view does not expose the minimum, so any statement about the fastest /slow 200 in this window requires querying raw rows directly — the "Representative rows" table in §4.8 shows only a single /slow 200 sample (37,019 ms) drawn from a different sanitized reproduction and is not sufficient to establish an observed minimum for the fresh window shown here.
  • The /fast 200 row shows avgMs 4997.5, p95Ms 9992, maxMs 9992 — a supposedly sub-100 ms endpoint took on average 5 seconds and up to 10 seconds at p95 to return successfully. This is a 50× to 100× latency inflation and is the single strongest piece of evidence that /fast shares the same worker pool as /slow (there is no --worker-class=gthread or async worker in the Gunicorn config; both endpoints compete for the same 2 sync worker slots).
  • Rows are sorted by p95Ms desc — the top two rows are both 499 (44,693 ms and 44,548 ms), then the next two are 200 (33,975 ms and 9,992 ms). The fact that no 200 row exceeds any 499 row's p95Ms confirms the client-timeout boundary (~45 s) is strictly above the app-side latency ceiling, so no successful request "runs longer than the timeout allows" and every request over the deadline is aborted client-side.
  • Query duration in bottom left reads 1s 37ms — slightly longer than the §4.6.1 status-distribution query (0s 515ms) because percentile() is more expensive than countif(), but still well under the 30-second workspace query timeout, so the returned percentile values are authoritative and not a partial-scan estimate.

Expected result: The two 499 rows cluster at the ~45 s client-timeout boundary, the /slow 200 row falls in the 5-15 s app sleep range plus queueing, and the /fast 200 row shows 50-100× latency inflation over its sub-100 ms baseline — collectively confirming that the failure signature is client-side timeouts driven by sync-worker saturation, not by app-side crashes or platform-side outages. If instead the Portal query returned a /fast 200 row with p95Ms under 100 ms, the trigger did not actually saturate the workers (perhaps because the workers were recycled between the trigger and the query, or the trigger arrived before the worker pool was fully warmed) — in that case this cross-verification is invalid and the trigger must be re-run before drawing conclusions from the raw KQL export in §4.8.

Next step: If a future reproduction shows maxMs on the /slow 499 row substantially higher than the curl --max-time boundary (for example 60+ seconds instead of ~45 seconds), the client-side timeout was likely raised or removed — re-check labs/intermittent-5xx/trigger.sh for a --max-time regression. If instead maxMs on the /slow 200 row approaches the 45-second curl --max-time boundary itself (for example 40+ seconds when the current baseline is ~34 seconds), the sleep distribution in labs/intermittent-5xx/app/app.py was likely widened beyond the intended 5-15 s range, making the sync-worker saturation more aggressive than this lab's hypothesis models and shifting the failure mode toward "confirmed with outage" rather than "supported (starvation causes client aborts)".

4.8 Raw KQL sample rows (sanitized)

Representative rows from kql-http-20260404T060610Z.json:

TimeGenerated CsUriStem ScStatus TimeTaken
2026-04-04T05:36:26.941612Z /fast 200 1
2026-04-04T05:36:23.677624Z /fast 499 14411
2026-04-04T05:35:37.981987Z /slow 499 44430
2026-04-04T05:35:30.516813Z /slow 200 37019
2026-04-04T05:35:23.646864Z /fast 499 14393

4.9 Console and platform exports

Console log export

From kql-console-20260404T060610Z.json:

  • rows: []

No console entries were captured in this window.

Platform log export

From kql-platform-20260404T060610Z.json:

  • Lifecycle informational events (site start, warmup probe success, container running).
  • No explicit failure/restart entry in sampled period.

Sample rows:

TimeGenerated Level Message
2026-04-04T05:05:05.5422387Z Informational Site started.
2026-04-04T05:05:05.0599636Z Informational Site startup probe succeeded after 8.0666499 seconds.
2026-04-04T05:04:56.9229799Z Informational Container is running.

4.10 Hypothesis verdict

Result: Supported

Why supported:

  1. Under a 20-request slow burst, slow endpoint timeout ratio reached 55%.
  2. Fast endpoint timeout ratio reached 60% despite fast handler logic.
  3. KQL HTTP logs show mixed 200/499 pattern with high durations for /fast and /slow.
  4. Pattern is strongly consistent with sync worker starvation and queueing.

Not required for support in this run:

  • Console timeout text was absent.
  • Platform restart event was absent.

These are optional corroborators, not mandatory if timing/status pattern already proves queueing.

4.11 Recommendations

  1. Increase Gunicorn worker capacity or move to async/threaded worker model for mixed latency workloads.
  2. Isolate slow operations from front-door request path (queue, background job, or dedicated endpoint plan).
  3. Align client timeout and server timeout intentionally (avoid accidental mismatch where client cancels first).
  4. Monitor endpoint-specific latency and status distribution, not only aggregate app success rate.
  5. Use synthetic mixed-load probes (/slow + /fast) in pre-production to detect starvation early.

4.12 Suggested follow-up experiments

Experiment Change Expected outcome
Worker count increase --workers 2 → --workers 4 Reduced queue timeout rate
Worker class change sync → gthread or async worker Better tolerance to mixed slow/fast traffic
Slow concurrency reduction 20 → 8 Lower timeout ratios
Timeout tuning Increase client timeout, evaluate tail Fewer client-abort events but longer waits

Expected Evidence

This section defines what you SHOULD observe at each phase of the lab. Use it to validate your investigation is on track.

Before Trigger (Baseline)

Evidence Source Expected State What to Capture
AppServiceHTTPLogs All 200s with low latency Baseline query snapshot for /fast, /slow, /diag/stats
AppServiceConsoleLogs Normal Gunicorn startup with sync workers Boot line showing 3 sync workers and timeout settings
AppServicePlatformLogs Normal startup sequence only "Site started" and no restart loop
/diag/stats Balanced counters, no queue stress Baseline endpoint counters and process info

During Incident

Evidence Source Expected State Key Indicator
AppServiceHTTPLogs (/slow) Predominant 499 near timeout edge TimeTaken ~4877-4918 ms on timed-out slow requests
Trigger CSV + HTTP logs Mixed success and timeout pattern Concurrent burst yields 200+499 in same window
Worker model evidence Sync workers blocked by long CPU-bound work /fast waits behind occupied workers
Client-side observations Caller sees intermittent unavailability 499 indicates client disconnect before completion

After Recovery

Evidence Source Expected State Key Indicator
AppServiceHTTPLogs 200 responses return to normal after burst ends Fast-path latency normalizes when slow load stops
/diag/stats Queue-pressure behavior subsides Request handling resumes without timeout-like clustering
Platform/Console logs No mandatory platform crash required Recovery can occur without restart
Incident interpretation 499 treated as timeout symptom, not server 5xx Confirms worker exhaustion pattern rather than random platform failure

Evidence Timeline

graph TD
    A[Baseline Capture] --> B[Trigger Fault]
    B --> C[During: Collect Evidence]
    C --> D[After: Compare to Baseline]
    D --> E[Verdict: Confirmed/Falsified]

Evidence Chain: Why This Proves the Hypothesis

Falsification Logic

If you observe /slow requests clustering near timeout with 499, plus concurrent degradation of /fast while sync workers are occupied, the hypothesis is CONFIRMED because queueing and worker starvation explain the intermittent failures.

If you do NOT observe timeout clustering during slow-request bursts, the hypothesis is FALSIFIED — consider dependency failures, platform restarts, or non-worker bottlenecks.


Clean Up

az group delete --name "$RG" --yes --no-wait
Command/Flag Purpose
az group delete Delete the resource group and all contained resources
--name Resource group to delete
--yes Skip confirmation prompt
--no-wait Return immediately without waiting for deletion to complete


See Also


Sources