3 posts tagged with "presidio"

+

Part 4 built a callback that masks PII in what the gateway logs without touching what the caller receives. It also noted that the first working version used a blocking HTTP client inside an async def, and that this cost 200-350ms across four sequential requests.

That post ended with an admission: four requests in a row is the wrong test. A blocked event loop barely shows when nothing else is waiting. The damage should appear under concurrency, and we had not measured it.

This is that measurement, and the result is a shape rather than a number. With the blocking client, some batches take many times longer than they should. With the async client, none do. The medians barely differ, which is exactly why this ships unnoticed.

Two things turned up that were not in the plan. The gateway does not merely slow down — it drops requests. And when it does, the masking call is the thing that timed out, while the caller still gets 200 OK. That means the guarantee Part 4 was built on quietly stops holding under load.

What you need​

• The gateway from Part 1, running
• Presidio and the logging callback from Part 4
• A WEC Inference API key — create one in the portal
• httpx in your Python environment

First, find out how many event loops you have​

Everything here depends on one number, and it is not the number the documentation gives.

The LiteLLM proxy CLI has a --num_workers flag. The published reference says its default is "Number of logical CPUs in the system, or 4 if that cannot be determined." On an eight-core box that would mean eight worker processes, eight event loops, and a blocking call stalling one eighth of your traffic.

Ask the host what is actually running — from outside the container, so nothing inside it can misreport:

docker top llm-gateway

UID    PID       PPID      C  STIME  TTY  TIME      CMD
root   2477458   2477435   3  16:43  ?    00:01:19  /app/.venv/bin/python3 /app/.venv/bin/litellm --config /app/config.yaml --port 4000
root   2481091   2477458   0  16:44  ?    00:00:05  /opt/prisma/binaries/node_modules/prisma/query-engine-debian-openssl-3.0.x -p 53053

Figure 1. One python process runs the whole proxy. The second entry is Prisma, the database client, which does not serve requests.

If --num_workers were greater than one you would see several python processes with the first one as their parent. Confirm it in the startup log:

docker logs llm-gateway 2>&1 | grep -E "Started server process|Uvicorn running" | tail -2

INFO:     Started server process [1]
INFO:     Uvicorn running on http://0.0.0.0:4000 (Press CTRL+C to quit)

Figure 2. One server process. This log accumulates across restarts, so tail -2 keeps you looking at the current one.

Now ask the tool what its default is:

docker exec llm-gateway litellm --help | grep -A5 "^  --num_workers"

  --num_workers INTEGER           Number of worker processes for uvicorn /
                                  gunicorn, or Granian worker processes
                                  (--workers). Default is 1 (from
                                  DEFAULT_NUM_WORKERS_LITELLM_PROXY). With
                                  --run_granian, use --granian_threads for
                                  runtime threads per worker.

Figure 3. The tool's own help text: "Default is 1."

That is a help string. Since we are about to contradict the published documentation, take it from the source too — adjust the python version in the path to match your image:

docker exec llm-gateway grep -rn 'DEFAULT_NUM_WORKERS_LITELLM_PROXY' \
  /app/.venv/lib/python3.13/site-packages/litellm/constants.py

15:DEFAULT_NUM_WORKERS_LITELLM_PROXY = int(os.getenv("DEFAULT_NUM_WORKERS_LITELLM_PROXY", 1))

docker exec llm-gateway env | grep -i worker

So: one process, one event loop, shared by every request in flight. That is the condition that turns a blocking call from a tax into an outage.

A load script​

Fire N requests at once, time each, report the wall clock for the batch. The message carries PII so the masking callback has real work to do. A failed request is counted rather than allowed to abandon the run — you will need that.

"""Fire N chat completions at the gateway at once and report how long they take.

The message carries PII so the Presidio masking callback has real work to do.
A failed request is counted and reported, not allowed to abandon the batch.
"""
import asyncio
import os
import statistics
import sys
import time

import httpx

GATEWAY = "http://127.0.0.1:4000/v1/chat/completions"
KEY = os.environ["LITELLM_MASTER_KEY"]
MODEL = "qwen-small"
PROMPT = (
    "Priya Raghunathan called from 415-555-0134 about her invoice. "
    "Reply with exactly: ok"
)


async def one(client, i):
    start = time.perf_counter()
    try:
        r = await client.post(
            GATEWAY,
            headers={"Authorization": f"Bearer {KEY}"},
            json={
                "model": MODEL,
                "messages": [{"role": "user", "content": PROMPT}],
                "max_tokens": 5,
            },
        )
    except Exception as exc:
        return i, None, None, type(exc).__name__
    return i, r.status_code, time.perf_counter() - start, None


async def main():
    n = int(sys.argv[1])
    async with httpx.AsyncClient(timeout=120.0) as client:
        wall = time.perf_counter()
        results = await asyncio.gather(*(one(client, i) for i in range(n)))
        wall = time.perf_counter() - wall

    times = sorted(e for _, _, e, _ in results if e is not None)
    errors = [err for _, _, _, err in results if err]
    print(f"concurrency {n}  ok {len(times)}  failed {len(errors)}")
    if errors:
        print(f"  errors   {', '.join(sorted(set(errors)))}")
    print(f"  wall     {wall:.2f}s")
    if times:
        print(f"  fastest  {times[0]:.2f}s")
        print(f"  median   {statistics.median(times):.2f}s")
        print(f"  slowest  {times[-1]:.2f}s")


asyncio.run(main())

cd ~/llm-gateway && set -a && . ./.env && set +a
~/.venv/bin/python loadtest.py 8

concurrency 8  ok 8  failed 0
  wall     1.93s
  fastest  1.60s
  median   1.91s
  slowest  1.93s

Figure 4. Eight at once, none failed. On its own this number means nothing yet.

You need a control, or your numbers mean nothing​

Here is the trap. The gateway calls a model over the network. That model has its own latency, its own load, and its own bad afternoons. When a batch takes twelve seconds you cannot tell whether your gateway stalled or the upstream was busy — and if you guess, you will publish nonsense.

So measure the upstream directly, with the gateway out of the path. Copy the file and change the three constants at the top:

cd ~/llm-gateway
cp loadtest.py loadtest_direct.py

GATEWAY = "https://inference.wiline.com/v1/chat/completions"
KEY = os.environ["WEC_API_KEY"]
MODEL = "Qwen2.5-3B-Instruct"

~/.venv/bin/python loadtest_direct.py 8

concurrency 8  ok 8  failed 0
  wall     1.15s
  fastest  1.05s
  median   1.10s
  slowest  1.15s

Figure 5. The same eight requests with the gateway removed. This is the baseline every gateway number gets read against.

Now run the two interleaved, not one after the other, so a slow minute upstream cannot land entirely on one version:

#!/bin/bash
# Interleave gateway runs with direct-to-upstream control runs so an upstream
# slowdown cannot be mistaken for a gateway effect.
set -a; . ./.env; set +a
REPS=5

# A restart takes longer than it looks. Firing requests at a port that is not
# answering yet produces instant failures that have nothing to do with the callback.
printf 'waiting for the gateway'
for _ in $(seq 1 60); do
  curl -sf http://127.0.0.1:4000/health/liveliness >/dev/null 2>&1 && break
  printf '.'; sleep 2
done
curl -sf http://127.0.0.1:4000/health/liveliness >/dev/null 2>&1 || { echo " never came up — aborting"; exit 1; }
echo " up"

# Do not trust a label passed on the command line — ask the gateway which callback
# it actually loaded. A mislabelled run is worse than no run.
LABEL=$(docker logs llm-gateway 2>&1 | grep '\[scrubber\]' | tail -1 | sed 's/.*loaded: //')
if [ -z "$LABEL" ]; then echo "cannot determine loaded callback — aborting"; exit 1; fi
echo "callback in use: $LABEL"

summarise() {
  awk '/^concurrency/{failed=$6} /wall/{wall=$2} END{printf "%s", wall; if (failed+0 > 0) printf "(%d failed)", failed}'
}

# The first request after a restart pays for imports and connection pools, which
# has nothing to do with the callback. Warm both paths before recording anything.
~/.venv/bin/python loadtest.py 4 >/dev/null 2>&1
~/.venv/bin/python loadtest_direct.py 4 >/dev/null 2>&1

for n in 8 16; do
  for i in $(seq 1 $REPS); do
    g=$(~/.venv/bin/python loadtest.py $n | summarise)
    d=$(~/.venv/bin/python loadtest_direct.py $n | summarise)
    echo "$LABEL N=$n rep=$i gateway=$g direct=$d"
  done
done

Three details in there are not decoration, and each one cost a wasted run to learn:

It waits for the gateway. A docker compose restart can take longer than ten seconds, and firing at a port that is not listening yet produces instant failures — gateway=0.03s(8 failed) — that look like a catastrophic result and mean nothing.

It refuses to take a label from you. It reads the loaded callback out of the gateway's log. Pass blocking on the command line while the async callback is loaded and you will measure the same code twice, see no difference, and conclude there is nothing here. That happened twice while writing this.

It throws away a warm-up pass. The first batch after a restart pays for imports and connection pools, and comes in three to six times slower than the next one regardless of which callback is loaded.

Make each version announce itself​

You are about to compare two versions of one file, and you need certainty about which is live. LiteLLM's startup log lists success and failure callbacks but not litellm_settings.callbacks, and there is no endpoint that reports them — /get/config/callbacks answers 200 with {"detail":"Not Found"}.

So have each version say its own name at import, where it costs nothing per request:

# last line of scrubber.py
print("[scrubber] loaded: async httpx.AsyncClient", flush=True)

# last line of scrubber_blocking.py
print("[scrubber] loaded: blocking httpx.Client", flush=True)

Mount both files, and switch with one line of config:

    volumes:
      - ./config.yaml:/app/config.yaml:ro
      - ./scrubber.py:/app/scrubber.py:ro
      - ./scrubber_blocking.py:/app/scrubber_blocking.py:ro
      - ./recognizers.json:/app/recognizers.json:ro

litellm_settings:
  callbacks: ["scrubber.instance"]          # or scrubber_blocking.instance

sed -i 's/scrubber.instance/scrubber_blocking.instance/' config.yaml
docker compose restart litellm

The experiment script prints the loaded callback as its first line, so every run carries its own proof of what it measured.

The numbers​

./run_experiment.sh

With the async client:

callback in use: async httpx.AsyncClient
async httpx.AsyncClient N=8 rep=1 gateway=0.98s direct=1.09s
async httpx.AsyncClient N=8 rep=2 gateway=0.86s direct=0.80s
async httpx.AsyncClient N=8 rep=3 gateway=0.92s direct=0.96s
async httpx.AsyncClient N=8 rep=4 gateway=0.78s direct=0.85s
async httpx.AsyncClient N=8 rep=5 gateway=0.90s direct=0.82s
async httpx.AsyncClient N=16 rep=1 gateway=1.61s direct=1.49s
async httpx.AsyncClient N=16 rep=2 gateway=1.65s direct=1.26s
async httpx.AsyncClient N=16 rep=3 gateway=1.28s direct=1.35s
async httpx.AsyncClient N=16 rep=4 gateway=1.33s direct=1.42s
async httpx.AsyncClient N=16 rep=5 gateway=1.77s direct=1.56s

Figure 6. The async client. Every gateway number sits beside its control, at both concurrency levels. Nothing stands out because nothing happened.

Then swap the callback and run the same thing:

waiting for the gateway up
callback in use: blocking httpx.Client
blocking httpx.Client N=8 rep=1 gateway=1.20s direct=0.93s
blocking httpx.Client N=8 rep=2 gateway=0.96s direct=0.83s
blocking httpx.Client N=8 rep=3 gateway=0.92s direct=0.86s
blocking httpx.Client N=8 rep=4 gateway=0.73s direct=0.90s
blocking httpx.Client N=8 rep=5 gateway=1.70s direct=0.90s
blocking httpx.Client N=16 rep=1 gateway=70.18s direct=2.00s
blocking httpx.Client N=16 rep=2 gateway=1.75s direct=1.70s
blocking httpx.Client N=16 rep=3 gateway=2.33s direct=1.78s
blocking httpx.Client N=16 rep=4 gateway=2.88s direct=1.49s
blocking httpx.Client N=16 rep=5 gateway=5.14s direct=1.19s

Figure 7. The blocking client. Same script, same load, one word different in the code. The control column holds at 1.19-2.00s throughout.

Figure 8. Every batch from Figures 6 and 7 on a log axis. The control stays inside a narrow band in all four groups. The async runs stay with it. Two blocking runs leave it.

Read the async rows first. At N=8 the gateway's median is 0.90s and the control's is 0.85s. The callback, Presidio round trips and all, disappears into the model's own latency.

Now the blocking row at N=8. Median 0.96s against a 0.90s control. That is 0.06s. If you measured medians and shipped, you would call it fine — and the worst batch in the same five took 1.70s while its own control took 0.90s.

At N=16 it stops hiding. The median goes to 2.88s against 1.70s, and the tail runs off the chart.

It does not just get slow. It drops requests.​

Before failure counting was added to the load script, a blocking run died outright:

httpx.RemoteProtocolError: Server disconnected without sending a response.

Two of ten batches in that run lost requests that way. Zero async batches ever did. The gateway was not slow for those callers. It hung up on them.

Ask the gateway what it thinks happened:

docker logs llm-gateway 2>&1 | grep -c "httpcore/_sync"
docker logs llm-gateway 2>&1 | grep -A1 "httpx.ReadTimeout" | tail -4

77
INFO:     172.22.0.1:47566 - "POST /v1/chat/completions HTTP/1.1" 200 OK
--
httpx.ReadTimeout: timed out
INFO:     172.22.0.1:52870 - "POST /v1/chat/completions HTTP/1.1" 200 OK

Figure 9. httpcore/_sync appears 77 times. The async client would produce _async. And the timeout sits between two 200 OK lines.

That _sync is the fingerprint. It proves the failing call is the blocking Presidio call and not something else in the stack. The full error names the caller:

LiteLLM:ERROR: logging_worker.py:103 - LoggingWorker error: timed out
  File ".../httpcore/_sync/connection_pool.py", line 236, in handle_request
  httpcore.ReadTimeout: timed out

Now look at what surrounds it. 200 OK. The requests succeeded. The masking is what failed.

That is the part worth stopping on, because Part 4's whole promise was that PII reaches your traces already masked. Under load, with the blocking client, the masking call times out against its own ten-second limit while the caller receives a normal success. Nothing in the response tells you the guarantee lapsed. You would have to be reading the gateway's stderr to know.

What is actually happening​

httpx.Client inside an async def does not yield. When the callback calls Presidio, the thread running the event loop sits in a socket read until Presidio answers, and during that time the loop services nothing — not another request's model call, not a response coming back. It is one loop, as you confirmed at the start.

Each request triggers several of these calls: the messages, the copy in the standard logging object, and the response. So under concurrency the requests do not overlap. They queue, and each one's wait is every earlier one's Presidio time added together. That is why the effect is not a constant tax — it depends on how many requests happen to arrive while the loop is held, which is also why the numbers are spiky rather than uniformly worse.

Past a certain queue depth the waits exceed the scrubber's own timeout=10.0 and the masking gives up, while client connections waiting on a frozen loop get dropped. The median hides all of it because most batches get lucky. The tail is the truth.

Fixing it​

The fix is the one Part 4 landed on, and this is the evidence for it: httpx.AsyncClient with await, which yields the loop while Presidio works.

diff scrubber.py scrubber_blocking.py

26,27c26,27
<     async with httpx.AsyncClient(timeout=10.0) as client:
<         r = await client.post(f"{ANALYZER}/analyze", json={"text": text, "language": "en"})
---
>     with httpx.Client(timeout=10.0) as client:
>         r = client.post(f"{ANALYZER}/analyze", json={"text": text, "language": "en"})

Two words and an await. That is the whole difference between Figure 6 and Figure 7.

More workers is not the fix, and the documentation explains why better than we could. On --timeout_worker_healthcheck, describing --num_workers > 1:

"the supervisor process pings each worker; a worker that does not respond within this window (for example because its event loop is blocked by synchronous work) is killed with SIGKILL and replaced."

At one worker there is no supervisor, so a blocked loop stalls. At several, a blocked worker gets killed and everything in flight on it dies instead of waiting. Neither is a fix for synchronous work on an event loop. Fix the call.

What we did not test​

Five reps per cell is enough to show that a stall exists next to a steady control. It is not enough to characterise the distribution — how often, how bad, or how it scales past N=16. If you run this in production, run it longer and look at percentiles.

We did not test --num_workers > 1, streaming responses, or a slow or remote Presidio rather than a healthy local container.

What the timeout actually costs you​

The obvious worry, when the masking call times out on a request that returned 200 OK, is that the unmasked payload lands in the trace anyway. It does not.

Sustained load — six rounds of twenty-four concurrent requests, each carrying a name and a phone number — produced 77 masking timeouts in the gateway log. Of the 144 requests, 62 traces reached Langfuse and 82 never arrived at all. Every one of the 62 was properly masked. None carried a raw name.

So the failure is not a privacy failure. It is an observability failure, and a quiet one: under sustained load more than half the traffic simply is not recorded, while every caller gets a normal success. If you are reading trace volume as a proxy for traffic, or counting on traces for an audit trail, that gap is the thing to watch — and it is invisible from the response side.

Further reading​

• Part 4 — clean traces, untouched answers — the callback measured here
• Part 3 — mask PII at the gateway — the Presidio setup
• Observe production with Langfuse — where these traces land

++

Part 3 configured Presidio to mask prompts at logging time and deliberately stopped short of proving it. Nothing had been wired to a logging destination yet, so there was no trace to inspect.

This post wires one up, finds <PERSON> where it should be — and then finds the customer's real email address sitting a few lines below it, in the model's reply.

++

Part 2 ended with the gateway deciding which model answers each request — and still forwarding every prompt verbatim, including the ones carrying customer names, emails and phone numbers.

This post puts a PII filter in that path. Not in front of the model, though: in front of the logs. The model reading your prompt is doing its job; the risk is what gets stored. So the raw text goes to the model and a masked copy goes to your logging.

That is what the gateway advertises. Following its documented configuration got me the opposite — a model that answered correctly and a reply that came back as <LOCATION>. This is how to find that and how to fix it.