fix: count every PHP-FPM stage, stop panicking on a bad URI, report scrape failures

AGENTS.md

@@ -126,3 +126,17 @@ and cannot resolve a tag built from an `ARG`, so an indirected pin is one it wil
   built image with a `--filter=reference=` on the *ghcr.io* name; that filter
   matches the repository name exactly, so it silently finds nothing if the image templates are renamed.
 - The repo has no `.crap-gated` marker, so the touchstone per-function gate does not apply here.
+- `CountProcessState` mirrors PHP-FPM: a child is idle only while accepting, every other stage is active, and
+  an unrecognised stage counts as active so it cannot vanish from the total. The stage list comes from
+  `sapi/fpm/fpm/fpm_request.c` in php-src; `Creating` was missing for years and produced the log spam in
+  hipages/php-fpm_exporter#419, while dropping Finishing/Ending/Info from the total is
+  hipages/php-fpm_exporter#322.
+- `log` in `phpfpm` defaults to a discarding logger and `SetLogger` ignores nil, because it is a package
+  global that a library caller need never set.
+- **Known follow-up: `cmd/get.go` still holds logic.** `cmd` should be flag parsing and wiring, with anything
+  testable living in `internal/` (that is what `internal/server` is). `get`'s cobra `Run` closure still builds
+  the PoolManager and switches over the json/text/spew output formats, none of it reachable from a test. The
+  shape to copy is `internal/server`: a `Run(cfg, w io.Writer) error` with the output written to an injected
+  writer. Tracked in hackthebox/php-fpm_exporter#25.
+- `PoolManager.Update` returns the joined per-pool scrape errors. `Pool.error` already logs each one, so
+  callers should not log the aggregate again; `cmd/get.go` turns it into a non-zero exit code.

README.md

@@ -59,6 +59,7 @@ It uses sensible defaults which usually avoids the need to use command parameter
 
 `php-fpm_exporter` supports 2 commands, `get` and `server`.
 The `get` command allows to retrieve information from PHP-FPM without running as a server and exposing an endpoint.
+It prints whatever it managed to collect and exits non-zero if any target could not be scraped, so it can be used in scripts and health checks.
 The `server` command runs the server required for prometheus to retrieve the statistics.
 
 ### Options and defaults
@@ -82,6 +83,9 @@ The metric `active processes` is also an accumulation of multiple states (e.g. R
 Which shouldn't matter and `active processes` should still be equal or lower to `max_children`.
 
 `--phpfpm.fix-process-count` will emulate PHP-FPMs implementation including the accumulation of multiple states.
+PHP-FPM treats a child as idle only while it is accepting; every other stage (`Creating`, `Reading headers`,
+`Getting request information`, `Running`, `Finishing`, `Ending`) counts as active. `total processes` is therefore
+always the number of processes PHP-FPM reported.
 
 If you like to have a more granular reporting please use `phpfpm_process_state`.
 

cmd/get.go

@@ -16,6 +16,7 @@ package cmd
 import (
 	"encoding/json"
 	"fmt"
+	"os"
 	"time"
 
 	"github.com/davecgh/go-spew/spew"
@@ -46,9 +47,9 @@ var getCmd = &cobra.Command{
 			pm.Add(uri, "")
 		}
 
-		if err := pm.Update(); err != nil {
-			log.Fatal("Could not update pool.", err)
-		}
+		// Report the scrape result through the exit code, but print what was
+		// collected first: a partial result is still worth having.
+		scrapeErr := pm.Update()
 
 		switch output {
 		case "json":
@@ -88,6 +89,11 @@ var getCmd = &cobra.Command{
 		default:
 			log.Error("Output format not valid.")
 		}
+
+		if scrapeErr != nil {
+			log.Error("Could not update pool. ", scrapeErr)
+			os.Exit(1)
+		}
 	},
 }
 

cmd/root.go

@@ -94,8 +94,10 @@ func initLogger() {
 
 	lvl, err := logrus.ParseLevel(logLevel)
 	if err != nil {
+		// Falling back beats refusing to start: an unusable log level is no
+		// reason to take a running exporter's metrics away.
 		lvl = logrus.InfoLevel
-		log.Fatalf("Could not set log level to '%v'.", logLevel)
+		log.Errorf("Could not set log level to '%v', falling back to '%v'.", logLevel, lvl)
 	}
 
 	log.SetLevel(lvl)

phpfpm/phpfpm.go

@@ -20,6 +20,7 @@ package phpfpm
 
 import (
 	"encoding/json"
+	"errors"
 	"net/url"
 	"regexp"
 	"slices"
@@ -47,6 +48,10 @@ func resolveTimeout(d time.Duration) time.Duration {
 	return d
 }
 
+// PoolProcessRequestCreating defines a child that is being created and is not
+// yet accepting requests.
+const PoolProcessRequestCreating string = "Creating"
+
 // PoolProcessRequestIdle defines a process that is idle.
 const PoolProcessRequestIdle string = "Idle"
 
@@ -66,7 +71,19 @@ const PoolProcessRequestInfo74 string = "Getting request information"
 // PoolProcessRequestEnding defines a process that is about to end.
 const PoolProcessRequestEnding string = "Ending"
 
-var log logger
+// log defaults to discarding rather than to nil: it is a package global that a
+// library caller need never set, and the first unrecognised process state used
+// to dereference it.
+var log logger = discardLogger{}
+
+type discardLogger struct{}
+
+func (discardLogger) Info(...any)           {}
+func (discardLogger) Infof(string, ...any)  {}
+func (discardLogger) Debug(...any)          {}
+func (discardLogger) Debugf(string, ...any) {}
+func (discardLogger) Error(...any)          {}
+func (discardLogger) Errorf(string, ...any) {}
 
 type logger interface {
 	Info(ar ...any)
@@ -151,20 +168,21 @@ func (pm *PoolManager) Update() (err error) {
 	timeout := pm.ScrapeTimeout
 	started := time.Now()
 
+	failures := make([]error, len(pm.Pools))
+
 	for idx := range pm.Pools {
 		p := &pm.Pools[idx]
 		wg.Go(func() {
-			if err := p.Update(timeout); err != nil {
-				log.Error(err)
-			}
+			// Pool.error already logs, so only record it here.
+			failures[idx] = p.Update(timeout)
 		})
 	}
 
 	wg.Wait()
 
 	log.Debugf("Updated %v pool(s) in %v", len(pm.Pools), time.Since(started))
 
-	return nil
+	return errors.Join(failures...)
 }
 
 // Remove will remove a pool from the pool manager based on the given URI.
@@ -251,18 +269,21 @@ func JSONResponseFixer(content []byte) []byte {
 func CountProcessState(processes []PoolProcess) (active int64, idle int64, total int64) {
 	for idx := range processes {
 		switch processes[idx].State {
-		case PoolProcessRequestRunning:
-			active++
 		case PoolProcessRequestIdle:
 			idle++
-		case PoolProcessRequestEnding:
-		case PoolProcessRequestFinishing:
-		case PoolProcessRequestInfo:
-		case PoolProcessRequestInfo74:
-		case PoolProcessRequestReadingHeaders:
+		case PoolProcessRequestCreating,
+			PoolProcessRequestReadingHeaders,
+			PoolProcessRequestInfo,
+			PoolProcessRequestInfo74,
+			PoolProcessRequestRunning,
+			PoolProcessRequestEnding,
+			PoolProcessRequestFinishing:
 			active++
 		default:
+			// Count it anyway. A stage this build does not know about is still a
+			// process FPM reported, and dropping it understates the total.
 			log.Errorf("Unknown process state '%v'", processes[idx].State)
+			active++
 		}
 	}
 
@@ -273,7 +294,8 @@ func CountProcessState(processes []PoolProcess) (active int64, idle int64, total
 func parseURL(rawurl string) (scheme string, address string, path string, err error) {
 	uri, err := url.Parse(rawurl)
 	if err != nil {
-		return uri.Scheme, uri.Host, uri.Path, err
+		// url.Parse returns a nil *URL alongside its error.
+		return "", "", "", err
 	}
 
 	scheme = uri.Scheme
@@ -332,7 +354,11 @@ func (rd *requestDuration) UnmarshalJSON(b []byte) error {
 	return nil
 }
 
-// SetLogger configures the used logger
+// SetLogger configures the used logger. A nil logger is ignored, so the package
+// global stays safe to call unconditionally.
 func SetLogger(logger logger) {
+	if logger == nil {
+		return
+	}
 	log = logger
 }

phpfpm/phpfpm_test.go

@@ -95,7 +95,7 @@ func TestPoolManagerUpdateScrapesEveryPool(t *testing.T) {
 	pm.Add("tcp://127.0.0.1:1/status", "")
 	pm.Add("tcp://127.0.0.1:1/status", "")
 
-	require.NoError(t, pm.Update(), "Update reports per-pool failures on the pools, not as a return value")
+	require.Error(t, pm.Update(), "every pool failed, so Update must say so")
 
 	for i := range pm.Pools {
 		assert.Error(t, pm.Pools[i].ScrapeError, "every pool must have been visited")
@@ -224,6 +224,11 @@ func TestRequestDurationMarshalJSONEmitsTheNumber(t *testing.T) {
 	}
 }
 
+// PHP-FPM counts a child as idle only while it is accepting; every other stage
+// is active (sapi/fpm/fpm/fpm_status.c). Counting Finishing, Ending and Info as
+// neither dropped them from the total, which is what made phpfpm_total_processes
+// sag towards the active count under load.
+// https://github.com/hipages/php-fpm_exporter/issues/322
 func TestCountProcessState(t *testing.T) {
 	processes := []PoolProcess{
 		{State: PoolProcessRequestIdle},
@@ -236,9 +241,134 @@ func TestCountProcessState(t *testing.T) {
 
 	active, idle, total := CountProcessState(processes)
 
-	assert.Equal(t, int64(2), active, "active processes")
+	assert.Equal(t, int64(5), active, "every non-idle stage is active")
 	assert.Equal(t, int64(1), idle, "idle processes")
-	assert.Equal(t, int64(3), total, "total processes")
+	assert.Equal(t, int64(6), total, "no reported process may go uncounted")
+}
+
+func TestCountProcessStateCountsEveryReportedProcess(t *testing.T) {
+	// Every stage fpm_request.c can report, plus the PHP 7.4 spelling.
+	states := []string{
+		PoolProcessRequestCreating,
+		PoolProcessRequestIdle,
+		PoolProcessRequestReadingHeaders,
+		PoolProcessRequestInfo,
+		PoolProcessRequestInfo74,
+		PoolProcessRequestRunning,
+		PoolProcessRequestEnding,
+		PoolProcessRequestFinishing,
+	}
+
+	processes := make([]PoolProcess, 0, len(states))
+	for _, state := range states {
+		processes = append(processes, PoolProcess{State: state})
+	}
+
+	active, idle, total := CountProcessState(processes)
+
+	assert.Equal(t, int64(len(states)), total, "total must equal the processes FPM reported")
+	assert.Equal(t, int64(1), idle, "only Idle is idle")
+	assert.Equal(t, int64(len(states)-1), active)
+	assert.Equal(t, total, active+idle)
+}
+
+// https://github.com/hipages/php-fpm_exporter/issues/419
+func TestCountProcessStateKnowsTheCreatingStage(t *testing.T) {
+	logs := captureLogs(t)
+
+	active, idle, total := CountProcessState([]PoolProcess{{State: PoolProcessRequestCreating}})
+
+	assert.Equal(t, int64(1), active, "a child being created is not idle, so FPM counts it active")
+	assert.Zero(t, idle)
+	assert.Equal(t, int64(1), total)
+
+	close(logs)
+	for msg := range logs {
+		assert.NotContains(t, msg, "Unknown process state", "Creating is a documented FPM stage")
+	}
+}
+
+func TestCountProcessStateCountsUnknownStages(t *testing.T) {
+	logs := captureLogs(t)
+
+	active, idle, total := CountProcessState([]PoolProcess{{State: "Some Future Stage"}})
+
+	assert.Equal(t, int64(1), active, "an unrecognised stage still exists, so it must not vanish from the total")
+	assert.Zero(t, idle)
+	assert.Equal(t, int64(1), total)
+
+	close(logs)
+
+	logged := false
+	for msg := range logs {
+		if strings.Contains(msg, "Unknown process state 'Some Future Stage'") {
+			logged = true
+		}
+	}
+	assert.True(t, logged, "an unrecognised stage must still be reported")
+}
+
+// url.Parse returns a nil *URL alongside its error, so touching the result in
+// the error branch panics. It runs inside the scrape goroutine, so it took the
+// whole process down.
+func TestParseURLReturnsAnErrorRatherThanPanicking(t *testing.T) {
+	scheme, address, path, err := parseURL("tcp://127.0.0.1:90 00/status")
+
+	require.Error(t, err)
+	assert.Empty(t, scheme)
+	assert.Empty(t, address)
+	assert.Empty(t, path)
+}
+
+func TestPoolUpdateReportsAMalformedURI(t *testing.T) {
+	pool := Pool{Address: "tcp://127.0.0.1:90 00/status"}
+
+	err := pool.Update(time.Second)
+
+	require.Error(t, err)
+	assert.Equal(t, err, pool.ScrapeError)
+	assert.Equal(t, int64(1), pool.ScrapeFailures)
+}
+
+func TestPoolManagerUpdateReportsScrapeFailures(t *testing.T) {
+	pm := PoolManager{ScrapeTimeout: 50 * time.Millisecond}
+	pm.Add("tcp://127.0.0.1:1/status", "")
+
+	err := pm.Update()
+
+	require.Error(t, err, "a caller cannot otherwise tell that every target failed")
+	assert.ErrorIs(t, err, pm.Pools[0].ScrapeError)
+}
+
+func TestPoolManagerUpdateReturnsNilWhenNothingToDo(t *testing.T) {
+	pm := PoolManager{}
+
+	assert.NoError(t, pm.Update())
+}
+
+// discardLogger is what the package global starts as, so every method has to be
+// callable before a caller supplies a real logger.
+func TestDiscardLoggerAcceptsEveryLevel(t *testing.T) {
+	var l logger = discardLogger{}
+
+	assert.NotPanics(t, func() {
+		l.Info("info")
+		l.Infof("%s", "infof")
+		l.Debug("debug")
+		l.Debugf("%s", "debugf")
+		l.Error("error")
+		l.Errorf("%s", "errorf")
+	})
+}
+
+// The package logger is a global that library callers may never set. It used to
+// start out nil, so the first unrecognised process state panicked.
+func TestCountProcessStateWithoutALoggerSet(t *testing.T) {
+	SetLogger(nil)
+
+	assert.NotPanics(t, func() {
+		CountProcessState([]PoolProcess{{State: "Some Future Stage"}})
+	}, "a nil logger must be ignored rather than installed")
 }
 
 func TestResolveTimeout(t *testing.T) {

phpfpm/pod_discovery.go

@@ -76,7 +76,7 @@ func listPods(ctx context.Context, clientset *kubernetes.Clientset, namespace st
 // initializePodEnlisting retrieves all pods matching the specified criteria and appends their URIs to the PoolManager's PodPhases.
 // This function is invoked prior to starting the NewRetryWatcher to capture the initial state of existing pods
 // and to obtain the ResourceVersion required for initializing the NewRetryWatcher.
-func (pm *PoolManager) initialPodEnlisting(exporter *Exporter, podList *v1.PodList, port string) (string, error) {
+func (pm *PoolManager) initialPodEnlisting(exporter *Exporter, podList *v1.PodList, port string) string {
 
 	log.Infof("Found %d pod(s) during initial list", len(podList.Items))
 	for _, pod := range podList.Items {
@@ -87,7 +87,7 @@ func (pm *PoolManager) initialPodEnlisting(exporter *Exporter, podList *v1.PodLi
 		uri := fmt.Sprintf(uriTemplate, pod.Status.PodIP, port)
 		pm.processPodAdded(exporter, &pod, uri)
 	}
-	return podList.ResourceVersion, nil
+	return podList.ResourceVersion
 }
 
 // handlePodRunning is used when a pod is in the Running phase and needs to be appended into the pool manager's PodPhases.
@@ -161,10 +161,7 @@ func (pm *PoolManager) discoverPods(ctx context.Context, exporter *Exporter, cli
 		return err
 	}
 
-	initialResourceVersion, err := pm.initialPodEnlisting(exporter, podList, port)
-	if err != nil {
-		return err
-	}
+	initialResourceVersion := pm.initialPodEnlisting(exporter, podList, port)
 
 	go pm.watchPodEvents(ctx, exporter, watcher, initialResourceVersion, port)
 	return nil