Add access logging + host TCP sampler to diagnose download failures (#362)

Halide CI intermittently fails to reach pypi.halide-lang.org with uv
"client error (Connect): operation timed out" (3 retries, ~47s). The
appliance had no request-level visibility, so failures couldn't be
localized. This adds two complementary, low-overhead data sources:

- Caddy JSON access log for the pypi site -> dedicated caddy-logs volume,
  rotated, kept off the ACME/TLS log stream. Distinguishes a truncated
  download (status 200, size < content-length) from a request that never
  arrived (absent), and shows whether the server was serving other clients
  during an incident.
- monitor/sample.sh: a network_mode:host sidecar (netmon) that samples host
  TCP stack counters every 15s (accept-queue drops, conntrack, SYN_RECV,
  retransmits, load) to net-samples.tsv. Tells us whether lost SYNs were
  dropped on this host vs upstream of it.
- Caddy global `metrics` on 127.0.0.1:2019 for on-demand in-flight snapshots.

Correlating these against a live failure showed the server serving identical
requests from other runners in the same window while the failing runner's
request never reached Caddy and every host drop counter stayed flat --
i.e. the loss is upstream of the host (network path / OpenStack NAT), not
the server software.

Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

Author: alexreinking

caddy/Caddyfile

@@ -1,4 +1,29 @@
+{
+	# Expose Prometheus metrics on the admin endpoint (localhost:2019/metrics
+	# inside the container) so we can snapshot in-flight requests and accepted
+	# vs. active connections on demand while diagnosing download failures:
+	#   docker compose exec caddy wget -qO- 127.0.0.1:2019/metrics | grep caddy_
+	# (use 127.0.0.1, not localhost: admin binds IPv4 only and wget prefers ::1)
+	metrics
+}
+
 pypi.halide-lang.org {
+	# Access log for every request that reaches Caddy. This is the key signal
+	# for the intermittent wheel-download failures: a truncated download shows
+	# up as status 200 with a `size` smaller than the wheel's content-length,
+	# whereas a client-side connect timeout never appears here at all (which
+	# would point at the network path rather than the server). Written to a
+	# dedicated volume so it is not interleaved with Caddy's TLS/ACME logs and
+	# is not rolled off by Docker's log driver.
+	log {
+		output file /var/log/caddy/access.log {
+			roll_size 100MiB
+			roll_keep 20
+			roll_keep_for 2160h
+		}
+		format json
+	}
+
 	# Serve the (large, static) wheel files directly from disk so that
 	# downloads don't tie up pypiserver's small Waitress thread pool. Only
 	# the generated indexes and uploads (POST) still hit the Python server.

docker-compose.yml

@@ -68,13 +68,33 @@ services:
       - ${HALIDE_BB_PYPI_PACKAGES_DIR:-./data/packages}:/wheels:ro
       - caddy-data:/data
       - caddy-config:/config
+      - caddy-logs:/var/log/caddy
+    logging:
+      driver: local
+    restart: unless-stopped
+
+  # Host-level TCP/network sampler for diagnosing the intermittent
+  # wheel-download connect timeouts. network_mode: host so the /proc/net
+  # counters it reads reflect the host stack that terminates inbound :443,
+  # not this container's own namespace. See monitor/sample.sh.
+  netmon:
+    image: alpine:3.20
+    network_mode: host
+    command: sh /monitor/sample.sh
+    volumes:
+      - ./monitor:/monitor:ro
+      - netmon-logs:/var/log/netmon
+    environment:
+      SAMPLE_INTERVAL: "15"
     logging:
       driver: local
     restart: unless-stopped
 
 volumes:
   caddy-data:
   caddy-config:
+  caddy-logs:
+  netmon-logs:
   db-data:
 
 secrets:

monitor/sample.sh

@@ -0,0 +1,91 @@
+#!/bin/sh
+# Host-level network sampler for diagnosing the intermittent wheel-download
+# connect timeouts (uv reports "client error (Connect): operation timed out").
+#
+# Runs as a docker-compose sidecar with network_mode: host, so the /proc/net
+# counters below reflect the *host* TCP stack -- where inbound :443 SYNs are
+# accepted and NATed to the caddy container -- rather than the sidecar's own
+# namespace. It only reads /proc, so no extra tooling is needed.
+#
+# Emits one TSV row per interval. The failure is a connect timeout, which
+# never reaches Caddy and so leaves no trace in Caddy's access log; these
+# host counters are how we tell *where* the connection is being lost:
+#
+#   * listen_overflows / listen_drops / reqq_full_drop climbing, or syn_recv
+#     spiking, or conntrack near conntrack_max, or load1 high  -> the loss is
+#     on THIS host (accept-queue overflow / table exhaustion / CPU stall), and
+#     we tune the host or Caddy accordingly.
+#   * all of the above flat and low while CI reports failures -> the SYNs are
+#     being dropped UPSTREAM (OpenStack floating-IP NAT / network path) and
+#     never reached us; the fix is an infra/network escalation, not the server.
+#
+# Counters from /proc/net/{snmp,netstat} are cumulative since boot -- diff
+# adjacent rows (by epoch) during analysis to get per-interval rates.
+#
+# Caveat: with Docker's userland-proxy enabled (the default), host:443 has a
+# docker-proxy listener whose accept-queue drops show up here as
+# listen_drops/overflows; with it disabled (pure iptables DNAT) accept-queue
+# pressure instead lands in the caddy container's namespace, so cross-check
+# against Caddy's caddy_http_requests_in_flight metric when interpreting.
+
+set -u
+
+INTERVAL="${SAMPLE_INTERVAL:-15}"
+OUT="${SAMPLE_OUT:-/var/log/netmon/net-samples.tsv}"
+MAX_BYTES="${SAMPLE_MAX_BYTES:-104857600}"  # rotate at 100 MiB, keep one prior
+
+mkdir -p "$(dirname "$OUT")"
+
+# Pull one named field out of /proc/net/snmp or /proc/net/netstat. These files
+# store, per protocol label, a header row of field names followed by a values
+# row; map names->columns from the header, then print the matching value.
+field() {
+  # $1=file  $2=label (e.g. Tcp, TcpExt)  $3=field name
+  awk -v L="$2:" -v F="$3" '
+    $1==L {
+      if (!(L in seen)) { for (i=2;i<=NF;i++) col[$i]=i; seen[L]=1; next }
+      print $(col[F])
+    }' "$1"
+}
+
+if [ ! -f "$OUT" ]; then
+  printf 'epoch\tiso\tload1\tconntrack\tconntrack_max\tcurr_estab\tsyn_recv\tactive_opens\tpassive_opens\tattempt_fails\tretrans_segs\tout_rsts\tlisten_overflows\tlisten_drops\treqq_full_drop\tsyncookies_sent\ttcp_timeouts\tsyn_retrans\n' > "$OUT"
+fi
+
+while :; do
+  epoch=$(date +%s)
+  iso=$(date -u +%Y-%m-%dT%H:%M:%SZ)
+  load1=$(cut -d' ' -f1 /proc/loadavg)
+  ct=$(cat /proc/sys/net/netfilter/nf_conntrack_count 2>/dev/null || echo -1)
+  ctmax=$(cat /proc/sys/net/netfilter/nf_conntrack_max 2>/dev/null || echo -1)
+
+  curr_estab=$(field /proc/net/snmp Tcp CurrEstab)
+  active_opens=$(field /proc/net/snmp Tcp ActiveOpens)
+  passive_opens=$(field /proc/net/snmp Tcp PassiveOpens)
+  attempt_fails=$(field /proc/net/snmp Tcp AttemptFails)
+  retrans_segs=$(field /proc/net/snmp Tcp RetransSegs)
+  out_rsts=$(field /proc/net/snmp Tcp OutRsts)
+
+  listen_overflows=$(field /proc/net/netstat TcpExt ListenOverflows)
+  listen_drops=$(field /proc/net/netstat TcpExt ListenDrops)
+  reqq_full_drop=$(field /proc/net/netstat TcpExt TCPReqQFullDrop)
+  syncookies_sent=$(field /proc/net/netstat TcpExt SyncookiesSent)
+  tcp_timeouts=$(field /proc/net/netstat TcpExt TCPTimeouts)
+  syn_retrans=$(field /proc/net/netstat TcpExt TCPSynRetrans)
+
+  # SYN_RECV (TCP state 0x03) across IPv4+IPv6: half-open / accept-queue depth.
+  syn_recv=$(cat /proc/net/tcp /proc/net/tcp6 2>/dev/null | awk '$4=="03"' | wc -l | tr -d ' ')
+
+  printf '%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\t%s\n' \
+    "$epoch" "$iso" "$load1" "$ct" "$ctmax" "$curr_estab" "$syn_recv" \
+    "$active_opens" "$passive_opens" "$attempt_fails" "$retrans_segs" "$out_rsts" \
+    "$listen_overflows" "$listen_drops" "$reqq_full_drop" "$syncookies_sent" \
+    "$tcp_timeouts" "$syn_retrans" >> "$OUT"
+
+  sz=$(wc -c < "$OUT" 2>/dev/null || echo 0)
+  if [ "$sz" -gt "$MAX_BYTES" ]; then
+    mv "$OUT" "$OUT.1"
+  fi
+
+  sleep "$INTERVAL"
+done