From 0702427146da435c5aa572a2f6580cc5d78c3ec7 Mon Sep 17 00:00:00 2001 From: Dimosthenis Schizas Date: Sun, 13 Sep 2026 23:04:59 +0300 Subject: [PATCH 1/3] fix: count every PHP-FPM stage, stop panicking on a bad URI, report scrape failures Six defects found in one sweep, five of them inherited from upstream and untouched since the fork. Process accounting (hipages/php-fpm_exporter#322, #419). CountProcessState put Finishing, Ending and Getting request information in empty switch cases, so they counted as neither active nor idle and disappeared from the total: six processes in, total=3 out. PHP-FPM itself treats a child as idle only while it is accepting and everything else as active, which is also what README.md already claimed this flag did. The Creating stage was missing entirely, which is the 'Unknown process state' log spam in #419; it is a documented stage in php-src sapi/fpm/fpm/fpm_request.c. An unrecognised stage is still logged but now counts as active, so a future PHP release cannot silently shrink the total. parseURL dereferenced the nil *url.URL that url.Parse returns alongside its error. A malformed --phpfpm.scrape-uri therefore panicked, and since it runs in the scrape goroutine it took the process with it. Present since 2018. PoolManager.Update always returned nil, so get's 'Could not update pool' branch was unreachable and the command exited 0 even when every target failed. It now returns the joined per-pool errors, and get prints what it collected before exiting non-zero. Pool.error already logs each failure, so the redundant second log in the update goroutine is gone. An invalid --log.level called Fatalf and killed the process, with a dead fallback assignment directly above it showing the intent. It now warns and falls back to info rather than taking a running exporter's metrics away. The package logger was nil until SetLogger ran, so the first unrecognised process state panicked for library callers. It defaults to discarding and SetLogger ignores nil. initialPodEnlisting returned an error that was always nil. --- AGENTS.md | 9 +++ README.md | 4 ++ cmd/get.go | 12 +++- cmd/root.go | 4 +- phpfpm/phpfpm.go | 54 ++++++++++---- phpfpm/phpfpm_test.go | 136 ++++++++++++++++++++++++++++++++++- phpfpm/pod_discovery.go | 9 +-- phpfpm/pod_discovery_test.go | 3 +- 8 files changed, 202 insertions(+), 29 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 9036f904..0c5d48d8 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -126,3 +126,12 @@ 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. +- `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. diff --git a/README.md b/README.md index 8f95e81e..9b07e29b 100644 --- a/README.md +++ b/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`. diff --git a/cmd/get.go b/cmd/get.go index 8a801364..925b4b47 100644 --- a/cmd/get.go +++ b/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) + } }, } diff --git a/cmd/root.go b/cmd/root.go index bd903448..43e9798e 100644 --- a/cmd/root.go +++ b/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) diff --git a/phpfpm/phpfpm.go b/phpfpm/phpfpm.go index 6e38153e..5b61950d 100644 --- a/phpfpm/phpfpm.go +++ b/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,12 +168,13 @@ 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) }) } @@ -164,7 +182,7 @@ func (pm *PoolManager) Update() (err error) { 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 } diff --git a/phpfpm/phpfpm_test.go b/phpfpm/phpfpm_test.go index 9084fd72..28129d74 100644 --- a/phpfpm/phpfpm_test.go +++ b/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) { diff --git a/phpfpm/pod_discovery.go b/phpfpm/pod_discovery.go index f01e3579..1797add4 100644 --- a/phpfpm/pod_discovery.go +++ b/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 diff --git a/phpfpm/pod_discovery_test.go b/phpfpm/pod_discovery_test.go index e5e461ff..f364ef41 100644 --- a/phpfpm/pod_discovery_test.go +++ b/phpfpm/pod_discovery_test.go @@ -226,7 +226,7 @@ func TestInitialPodEnlistingAddsOnlyRunningPodsWithAnIP(t *testing.T) { pm := newPoolManager() exporter := NewExporter(pm) - resourceVersion, err := pm.initialPodEnlisting(exporter, &v1.PodList{ + resourceVersion := pm.initialPodEnlisting(exporter, &v1.PodList{ ListMeta: metav1.ListMeta{ResourceVersion: "42"}, Items: []v1.Pod{ *pod("running-with-ip", "10.0.0.1", v1.PodRunning), @@ -235,7 +235,6 @@ func TestInitialPodEnlistingAddsOnlyRunningPodsWithAnIP(t *testing.T) { }, }, "9000") - require.NoError(t, err) assert.Equal(t, "42", resourceVersion, "the list's ResourceVersion seeds the retry watcher") require.Len(t, pm.Pools, 1) From 02281e71446c5cc3cdaa060ee7e99f13e89c75f7 Mon Sep 17 00:00:00 2001 From: Dimosthenis Schizas Date: Sun, 13 Sep 2026 23:16:29 +0300 Subject: [PATCH 2/3] docs: record the cmd/get restructure as a follow-up GitHub issues are disabled on this repo, so AGENTS.md is where a known follow-up has to live. cmd/get.go still holds the output formatting logic that internal/ should own, which is why its mutation survivors had to be accepted rather than covered. --- AGENTS.md | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/AGENTS.md b/AGENTS.md index 0c5d48d8..8f78f70d 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -133,5 +133,10 @@ and cannot resolve a tag built from an `ARG`, so an indirected pin is one it wil 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. GitHub issues are disabled on this repo, so this note is the tracking record. - `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. From b9673e487d76de0f0820b55e380a6224bf34e575 Mon Sep 17 00:00:00 2001 From: Dimosthenis Schizas Date: Sun, 13 Sep 2026 23:24:45 +0300 Subject: [PATCH 3/3] docs: point the cmd/get follow-up at its issue Issues are enabled on the repo now, so the note can reference #25 rather than standing in for a tracker. --- AGENTS.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/AGENTS.md b/AGENTS.md index 8f78f70d..0fa74a52 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -137,6 +137,6 @@ and cannot resolve a tag built from an `ARG`, so an indirected pin is one it wil 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. GitHub issues are disabled on this repo, so this note is the tracking record. + 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.