diff --git a/AGENTS.md b/AGENTS.md index 9036f904..0fa74a52 100644 --- a/AGENTS.md +++ b/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. 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)