#!/bin/bash
#
# Samples PHP-FPM pool counters and worker memory into daily JSONL files.
# One line per pool per tick. Run by fpm-pool-metrics.service.
#
# Why this exists: pm.status_path only exposes high-water marks ("max active
# processes", "max children reached", "max listen queue") which never decrease
# and RESET ON EVERY RELOAD. After a reload there is no way to answer "was the
# pool saturated an hour ago". This turns those counters into a time series.
#
# Deliberately shell + /proc only: no agent, no daemon, no network. The box has
# 2 vCPU and already runs Apache plus three pools serving three applications.
#
# Output: /var/log/php8.3-fpm/metrics/pool-YYYY-MM-DD.jsonl
#
set -u

INTERVAL="${INTERVAL:-15}"          # seconds between ticks
PSS_EVERY="${PSS_EVERY:-20}"        # do the expensive PSS walk every Nth tick (~5 min at 15s)
OUTDIR="${OUTDIR:-/var/log/php8.3-fpm/metrics}"

# pool_name:socket_path -- keep long first so its line lands first in each tick.
# [reporting] appeared in pool.d on 2026-08-14 but nothing was routed to it until
# 2026-08-17, when reportingProxy moved there; it now carries the busiest route on the
# host, so a sampler that misses it misses most of what matters. This line was the only
# thing needed to cover it -- the ceilings below are read per pool name out of
# POOLCONF_DIR, so reporting.conf's limits ride along automatically. Add a line here
# whenever a pool is added to pool.d -- a pool missing from this list is not sampled at
# all, not even as an "up":false row, so it leaves no trace of its own absence. That is
# why the archive holds no [reporting] rows before 2026-08-17T10, the hour this line was
# added: read that gap as missing coverage, never as an idle pool.
POOLS="long:/run/php/php8.3-fpm-long.sock reporting:/run/php/php8.3-fpm-reporting.sock www:/run/php/php8.3-fpm.sock codeRunner:/run/php/php8.3-fpm-codeRunner.sock"

# Where to read each pool's configured ceilings. Every sample carries the limits it
# was measured against, so a consumer never has to hardcode pm.max_children -- and a
# mid-file config change shows up in the data instead of silently invalidating it.
# This is not hypothetical: [long] went 40 -> 80 on 2026-08-14 (and 80 -> 20 on
# 2026-08-17) while the dashboard kept drawing its capacity rule at 40, which made a
# saturated pool look like a quiet one.
POOLCONF_DIR="${POOLCONF_DIR:-/etc/php/8.3/fpm/pool.d}"

# When a pool is this fraction of max_children busy, dump its per-worker table.
# Only meaningful for [www]: SetHandler passes the real URI through, whereas the
# long pool's ProxyPassMatch rewrites it to /index.php before FPM ever sees it,
# so ?full reports "/index.php" for every long-pool worker.
SATURATION_PCT="${SATURATION_PCT:-50}"

# Minimum gap between ?full dumps. A ?full table is ~500 bytes per worker, so at
# 40 workers each dump is ~21 KB -- writing one every tick through a sustained
# saturation would be ~124 MB/day. A dump a minute is ample for attribution,
# which is all this file is for.
SATURATION_COOLDOWN="${SATURATION_COOLDOWN:-60}"

# FPM's master log. Counted here because the pool status page cannot see any of
# it, yet it holds the evidence for three settings the status counters say nothing
# about: memory_limit (OOM fatals), max_execution_time (timeout fatals), and the
# dynamic PM spare-server values (FPM's own "seems busy" advisory). The 105 OOM
# fatals that were the root cause of the 2026-08-13 incident would be invisible
# to this sampler otherwise.
FPMLOG="${FPMLOG:-/var/log/php8.3-fpm.log}"

mkdir -p "$OUTDIR" || exit 1

# The portal admin UI reads these files directly as www-data, so today's file has
# to be group-readable the moment it is created -- the daily prune job fixes
# permissions too late to help the file currently being written. umask 027 keeps
# them off world: the traffic snapshots alongside them carry client IP addresses.
umask 027
chgrp www-data "$OUTDIR" 2>/dev/null || true
chmod 2750 "$OUTDIR" 2>/dev/null || true

# $1 = socket, $2 = query string: "" for the summary block, "full" for the per-worker table.
#
# QUERY_STRING, not REQUEST_URI. FPM's status page reads its query off QUERY_STRING and
# ignores REQUEST_URI entirely, so the old call -- fpm_status "$sock" '/fpm-status?full'
# -- asked for the per-worker table and silently got the summary block instead. No error,
# no empty output, just the wrong half of the page. That made www-saturation-*.log useless
# for the single question it exists to answer ("which of the three applications is filling
# the pool"), because it never contained a request URI at all.
#
# Verified on the box 2026-08-25: REQUEST_URI='/fpm-status?full' yields no `state:` or
# `request duration:` lines; QUERY_STRING=full yields one set per worker. REQUEST_URI is
# still set for the access log's benefit, but it is decorative here.
fpm_status() {
	SCRIPT_NAME=/fpm-status \
	SCRIPT_FILENAME=/fpm-status \
	REQUEST_METHOD=GET \
	REQUEST_URI="/fpm-status${2:+?$2}" \
	QUERY_STRING="${2:-}" \
	cgi-fcgi -bind -connect "$1" 2>/dev/null
}

# Real accept-queue depth for a pool's UNIX socket: "<pending> <backlog>".
#
# This exists because FPM's own listen_q / max_listen_q are USELESS on this host. FPM can
# only read a socket's accept-queue depth for TCP listeners, so on a UNIX socket both
# fields report 0 no matter how deep the backlog gets. That is not a small gap: on
# 2026-08-14 Apache had 140 requests in flight against 80 busy workers, and FPM reported
# max_listen_q = 0 for the entire day, so the ~60 requests waiting were invisible and the
# pool looked unsaturated while it was queueing hard.
#
# For a LISTEN socket, ss reports Recv-Q as the number of connections the kernel has
# queued that no worker has accepted, and Send-Q as the configured backlog -- so this also
# confirms whether listen.backlog actually took effect.
#
# Sampled once per tick like everything else, so a spike shorter than INTERVAL can still
# be missed; unlike FPM's counters there is no high-water mark to fall back on. If a burst
# is in progress and you want finer resolution, watch it directly:
#   while :; do date -u +%H:%M:%S; ss -lx | grep php8.3-fpm; sleep 1; done
sock_queue() {
	# found is set before exit so the END guard cannot double-print, and a missing socket
	# still yields two numbers rather than an empty string that would break the JSON.
	ss -lx 2>/dev/null | awk -v s="$1" '
		{ for (i = 1; i <= NF; i++) if ($i == s) { print $3 + 0, $4 + 0; found = 1; exit } }
		END { if (!found) print 0, 0 }'
}

# Yields "<pool> <max_children> <pm> <memory_limit_mb> <terminate_s>".
# Keyed on the [section] header rather than the filename, since a file may hold more
# than one pool and the two need not match.
#
# Re-read whenever a pool file changes on disk, NOT once at startup. Read-once was a
# real bug, and a silent one: the [reporting] max_children raise from 32 to 40 and the
# [long] memory_limit raise to 512M both landed on 2026-08-18, and every tick that day
# still reported the values this function had read on 08-17. The fields exist precisely
# so a reader knows what a measurement was taken against, so a stale snapshot does not
# merely lose information -- it attaches the wrong ceiling to every number, which is the
# same class of error as the 08-14 dashboard drawing its capacity rule at a stale 40.
#
# CAVEAT that no amount of re-reading fixes: this is the config ON DISK, which is intent,
# not the ceiling the running master is actually enforcing. An edit without a reload
# shows the new number here while FPM still runs the old one -- exactly what 08-17 looked
# like, the file reading 48 while per-hour peak active pinned at 32. Two cross-checks
# catch the divergence, but only one of them works on a static pool: peak active above
# cfg max_children means the file is behind the master, on any pool. The other check --
# max_children_reached climbing while peak active sits below cfg max_children, meaning
# the master's cap is lower than the file -- holds for DYNAMIC pools only, because FPM
# increments that counter for dynamic and ondemand pm and never for static. [reporting]
# is static and read max_children_reached = 0 through six hours of sitting exactly on its
# ceiling on 2026-08-18, so on a static pool read saturation as peak active == cap and
# ignore the counter entirely. Treat a divergence as "needs a reload", not a measurement.
read_poolconf() {
	awk '
		/^[[:space:]]*\[/ {
			pool = $0
			gsub(/^[[:space:]]*\[|\][[:space:]]*$/, "", pool)
			next
		}
		pool == "" { next }
		/^[[:space:]]*pm[[:space:]]*=/                        { split($0, a, "="); gsub(/[[:space:]]/, "", a[2]);  mode[pool] = a[2] }
		/^[[:space:]]*pm\.max_children[[:space:]]*=/          { split($0, a, "="); gsub(/[[:space:]]/, "", a[2]);  maxc[pool] = a[2] }
		/^[[:space:]]*php_admin_value\[memory_limit\]/        { split($0, a, "="); gsub(/[[:space:]M]/, "", a[2]); mem[pool]  = a[2] }
		/^[[:space:]]*request_terminate_timeout[[:space:]]*=/ { split($0, a, "="); gsub(/[[:space:]s]/, "", a[2]); term[pool] = a[2] }
		END {
			for (p in maxc) printf "%s %s %s %s %s\n", p, maxc[p], (mode[p] ? mode[p] : "unknown"),
				(mem[p] + 0), (term[p] + 0)
		}
	' "$POOLCONF_DIR"/*.conf 2>/dev/null
}

poolconf=$(read_poolconf)

tick=0
last_dump=0

while :; do
	tick=$(( tick + 1 ))
	ts=$(date -u +%Y-%m-%dT%H:%M:%SZ)

	# Unconditionally, every tick. A change-detection gate was tried and dropped: an
	# mtime+size stamp misses an edit made in the same second that keeps the file the
	# same length -- "40" to "48" and "256M" to "512M" are both same-length, and both
	# are edits actually made to these files -- while a content hash costs more
	# processes than the awk it was meant to avoid. One awk over three small files is
	# noise beside the ss, status and /proc work already in a tick.
	poolconf=$(read_poolconf)
	day=${ts%%T*}
	out="$OUTDIR/pool-$day.jsonl"

	# --- host-wide, sampled once per tick -----------------------------------
	read -r load1 _ < /proc/loadavg
	# MemAvailable is the number to trust. Summed worker RSS double-counts the
	# pages forked children share copy-on-write and overstates usage badly.
	read -r memavail swapused < <(awk '
		/^MemAvailable:/ {a=$2}
		/^SwapTotal:/    {t=$2}
		/^SwapFree:/     {f=$2}
		END { printf "%d %d", int(a/1024), int((t-f)/1024) }' /proc/meminfo)
	# Cumulative since boot; the analyser diffs consecutive ticks. Non-zero
	# pswpout deltas mean the box is actively swapping, unlike a stale SwapUsed.
	read -r pswpin pswpout < <(awk '
		/^pswpin/  {i=$2}
		/^pswpout/ {o=$2}
		END { printf "%d %d", i, o }' /proc/vmstat)

	# Cumulative per-pool error counts, re-read on the PSS cadence rather than
	# every tick -- they are monotonic, so holding the previous value between
	# reads is correct, and grepping a multi-MB log every 15s is not worth it.
	# NOTE: these reset when the FPM log rotates. The analyser treats a decrease
	# as a reset instead of a negative delta.
	if [ $(( tick % PSS_EVERY )) -eq 1 ] && [ -r "$FPMLOG" ]; then
		errstats=$(awk '
			match($0, /\[pool [a-zA-Z0-9_-]+\]/) {
				p = substr($0, RSTART + 6, RLENGTH - 7)
				seen[p] = 1

				# One OOM produces TWO log lines from the same child in the same
				# second: the request fatal, then a second fatal as PHP fails to
				# allocate the ~32KB needed to load CustomExceptionHandler. Counting
				# lines would report double -- the sort of silent 2x that has already
				# caused two wrong readings on this box. Key on timestamp + child pid.
				pid = ""
				if (match($0, /child [0-9]+/)) pid = substr($0, RSTART + 6, RLENGTH - 6)
				k = $1 " " $2 "|" pid

				if      ($0 ~ /Allowed memory size/)                { if (!((k "o") in s)) { s[k "o"]; oom[p]++ } }
				else if ($0 ~ /Maximum execution time/)             { if (!((k "t") in s)) { s[k "t"]; tmo[p]++ } }
				else if ($0 ~ /seems busy|reached pm\.max_children/) busy[p]++
				else if ($0 ~ /exited on signal/)                    sig[p]++
			}
			END { for (p in seen) printf "%s %d %d %d %d\n", p, oom[p], tmo[p], busy[p], sig[p] }
		' "$FPMLOG" 2>/dev/null)
	fi

	for entry in $POOLS; do
		pool=${entry%%:*}
		sock=${entry#*:}

		# ONE status call per pool per tick, asking for ?full, because the full page
		# carries the summary block AND the per-worker table. The count matters: the
		# sampler's own polls land inside FPM's `accepted`, and the rollup corrects for
		# that with real_reqs = reqs - samples, which is only true while this loop makes
		# exactly one request per tick. Fetching the summary and the worker table
		# separately doubled it and silently inflated real_reqs by ~240/pool/hour at
		# INTERVAL=15 -- enough to break the §5 canary and to stop the "RECEIVING
		# NOTHING" verdict ever firing. If you ever add another call here, fix
		# pool-metrics-summary.pl's subtrahend in the same commit.
		st=$(fpm_status "$sock" full)
		if [ -z "$st" ]; then
			printf '{"ts":"%s","pool":"%s","up":false}\n' "$ts" "$pool" >> "$out"
			continue
		fi

		# Anchored patterns matter: "^listen queue:" must not catch
		# "listen queue len:", and "^active processes" must not catch
		# "max active processes".
		#
		# `exit` at the first per-worker record is what makes reading the ?full page
		# safe here: every worker block repeats `start since:` and `requests:`, which
		# these patterns would match too, so without the guard the last worker's values
		# would overwrite the pool's start_since. The summary block always precedes the
		# first `pid:` line, so stopping there yields exactly the summary page.
		set -- $(printf '%s\n' "$st" | awk -F': *' '
			/^pid:/                 {exit}
			/^accepted conn/        {a=$2}
			/^listen queue:/        {lq=$2}
			/^max listen queue/     {mlq=$2}
			/^idle processes/       {ip=$2}
			/^active processes/     {ap=$2}
			/^total processes/      {tp=$2}
			/^max active processes/ {map=$2}
			/^max children reached/ {mcr=$2}
			/^slow requests/        {sr=$2}
			/^start since/          {ss=$2}
			END { print a+0, lq+0, mlq+0, ip+0, ap+0, tp+0, map+0, mcr+0, sr+0, ss+0 }')
		accepted=$1; listenq=$2; maxlistenq=$3; idle=$4; active=$5
		total=$6;    maxactive=$7; maxkids=$8;    slow=$9;  since=${10}

		# Per-worker RSS. Peak and mean are reported separately and NOT summed,
		# for the copy-on-write reason above.
		#
		# Matched on exact argv fields, not with index(): awk's own command line
		# contains "php-fpm: pool <name>" via -v, so a substring match counts the
		# awk process itself. That inflated "workers" by one against "total" and
		# pulled rss_avg_mb down by awk's ~3MB. FPM worker titles are exactly
		# "php-fpm: pool <name>", so the field test is both precise and cheaper.
		set -- $(ps -eo rss=,etimes=,args= | awk -v pool="$pool" '
			$3 == "php-fpm:" && $4 == "pool" && $5 == pool {
				n++; s += $1; if ($1 > mx) mx = $1; if ($2 > old) old = $2
			}
			END { printf "%d %.1f %.1f %d", n+0, mx/1024, (n ? s/n/1024 : 0), old+0 }')
		workers=$1; rss_peak=$2; rss_avg=$3; oldest=$4

		# PSS divides each shared page by the number of processes mapping it, so
		# summing it across workers IS a valid total, unlike RSS. Costs a page
		# table walk per worker, hence the reduced cadence.
		pss_total=null
		if [ $(( tick % PSS_EVERY )) -eq 1 ]; then
			# Same exact-field match as above rather than pgrep -f, for the same
			# self-match reason and so both figures always cover the same processes.
			pss_total=$(
				for p in $(ps -eo pid=,args= | awk -v pool="$pool" \
					'$2 == "php-fpm:" && $3 == "pool" && $4 == pool { print $1 }'); do
					awk '/^Pss:/ {print $2}' "/proc/$p/smaps_rollup" 2>/dev/null
				done | awk '{s+=$1} END {printf "%d", int(s/1024)}'
			)
			[ -z "$pss_total" ] && pss_total=null
		fi

		set -- $(printf '%s\n' "${errstats:-}" | awk -v p="$pool" '
			$1 == p { print $2, $3, $4, $5; found = 1 }
			END { if (!found) print 0, 0, 0, 0 }')
		err_oom=$1; err_timeout=$2; warn_busy=$3; child_signal=$4

		# The only true view of queueing on this host -- see sock_queue().
		set -- $(sock_queue "$sock")
		sock_recvq=$1; sock_backlog=$2

		# Age of the oldest request actually IN FLIGHT, in seconds.
		#
		# This is the field that answers "is the pool stalled or merely busy", and it is
		# NOT `oldest_s` above. `oldest_s` comes from ps etimes -- the age of the oldest
		# worker *process* -- and because these workers are never recycled it degenerates
		# into a duplicate of `start_since`: on 2026-08-25 all three pools reported
		# oldest_s == start_since == 14896 down to the second, i.e. "FPM was reloaded 4.1
		# hours ago", three times over. A dashboard tile fed from it reads hours on a
		# completely idle box.
		#
		# FPM's own per-worker table has the real number. Measured at the same moment as
		# the readings above, www had a request 238.09 s into its life -- 79% of the way
		# to its 300 s request_terminate_timeout -- while `oldest_s` said 4.1 h.
		#
		# Two things this must get right:
		#  - Only `state: Running` counts. An Idle worker's `request duration` is the
		#    duration of the request it LAST finished, so including idle workers mixes
		#    live latency with completed history (the same box showed idle workers at
		#    278,960 and 132,271 us from long-finished requests).
		#  - `request duration` is microseconds.
		#
		# Reuses the page already fetched above -- see the one-call note there.
		#
		# The worker serving this very request shows up as Running with a sub-millisecond
		# duration, so this never reads a clean 0 on a genuinely idle pool; it reads 0.0
		# after rounding. Harmless, and it cannot mask a real stall because we take the
		# max.
		oldest_req=$(printf '%s\n' "$st" | awk -F': *' '
			/^state:/            { st = $2 }
			/^request duration:/ { if (st == "Running" && $2+0 > mx) mx = $2+0 }
			END { printf "%.1f", mx/1000000 }')
		[ -z "$oldest_req" ] && oldest_req=0

		# Configured ceilings for THIS pool. max_children is the capacity a consumer
		# should draw against: for a static pool "total" happens to equal it, but for
		# a dynamic pool (www) "total" is only the workers currently alive -- 8 of a
		# possible 40 -- so treating total as capacity understates it fivefold.
		set -- $(printf '%s\n' "${poolconf:-}" | awk -v p="$pool" '
			$1 == p { print $2, $3, $4, $5; found = 1 }
			END { if (!found) print 0, "unknown", 0, 0 }')
		cfg_maxchildren=$1; cfg_pm=$2; cfg_memlimit=$3; cfg_terminate=$4

		printf '{"ts":"%s","pool":"%s","up":true,"accepted":%s,"listen_q":%s,"max_listen_q":%s,"sock_recvq":%s,"sock_backlog":%s,"active":%s,"idle":%s,"total":%s,"max_active":%s,"max_children_reached":%s,"slow_requests":%s,"start_since":%s,"workers":%s,"rss_peak_mb":%s,"rss_avg_mb":%s,"pss_total_mb":%s,"oldest_s":%s,"oldest_req_s":%s,"err_oom":%s,"err_timeout":%s,"warn_busy":%s,"child_signal":%s,"max_children":%s,"pm":"%s","memory_limit_mb":%s,"terminate_timeout_s":%s,"load1":%s,"mem_avail_mb":%s,"swap_used_mb":%s,"pswpin":%s,"pswpout":%s}\n' \
			"$ts" "$pool" "$accepted" "$listenq" "$maxlistenq" \
			"$sock_recvq" "$sock_backlog" "$active" "$idle" \
			"$total" "$maxactive" "$maxkids" "$slow" "$since" "$workers" \
			"$rss_peak" "$rss_avg" "$pss_total" "$oldest" "$oldest_req" \
			"$err_oom" "$err_timeout" "$warn_busy" "$child_signal" \
			"$cfg_maxchildren" "$cfg_pm" "$cfg_memlimit" "$cfg_terminate" \
			"$load1" "$memavail" "$swapused" "$pswpin" "$pswpout" >> "$out"

		# Capture what is actually running when the shared fast pool gets busy.
		# This is the only way to tell which of the three applications caused it.
		# Measured against max_children, NOT total. www is pm=dynamic, so total is only
		# the workers currently alive -- often 8 of a possible 40. Comparing against it
		# fired at "50% busy" on active=4/8, which is 10% of the real ceiling, and filled
		# www-saturation-*.log with dumps of an idle pool.
		if [ "$pool" = "www" ] && [ "${cfg_maxchildren:-0}" -gt 0 ] \
			&& [ $(( active * 100 / cfg_maxchildren )) -ge "$SATURATION_PCT" ] \
			&& [ $(( $(date -u +%s) - last_dump )) -ge "$SATURATION_COOLDOWN" ]; then
			last_dump=$(date -u +%s)
			{
				printf '=== %s active=%s/%s ===\n' "$ts" "$active" "$total"
				# The page already in hand, not a fresh fetch: re-polling here would
				# add a request only on saturated ticks, skewing `accepted` exactly
				# when the numbers matter most (see the one-call note above), and it
				# would describe a moment slightly later than the row just written.
				printf '%s\n' "$st"
			} >> "$OUTDIR/www-saturation-$day.log"
		fi
	done

	sleep "$INTERVAL"
done