From 7bfe73e2ea0758ef262f91fc0815bdb06c44d80a Mon Sep 17 00:00:00 2001 From: "Matthew H. Irby" Date: Mon, 26 Oct 2026 16:12:38 -0400 Subject: [PATCH 1/2] chore(logs): add HTTP trace logs Signed-off-by: Matthew H. Irby --- e2e/.gitignore | 2 +- internal/command/command.go | 10 +- internal/command/httptrace.go | 293 +++++++++++++++++++++++++++++ internal/command/httptrace_test.go | 168 +++++++++++++++++ 4 files changed, 471 insertions(+), 2 deletions(-) create mode 100644 internal/command/httptrace.go create mode 100644 internal/command/httptrace_test.go diff --git a/e2e/.gitignore b/e2e/.gitignore index 85a5cd1..0b60cfb 100644 --- a/e2e/.gitignore +++ b/e2e/.gitignore @@ -1,3 +1,3 @@ -.env +*.env certs/* !**/.gitkeep \ No newline at end of file diff --git a/internal/command/command.go b/internal/command/command.go index 8cf1b5f..b207910 100644 --- a/internal/command/command.go +++ b/internal/command/command.go @@ -1,5 +1,5 @@ /* -Copyright © 2025 Keyfactor +Copyright © 2026 Keyfactor Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -32,6 +32,7 @@ import ( v1 "github.com/Keyfactor/keyfactor-go-client-sdk/v25/api/keyfactor/v1" cmpki "github.com/cert-manager/cert-manager/pkg/util/pki" "github.com/go-logr/logr" + ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/log" ) @@ -280,6 +281,13 @@ func newInternalSigner(ctx context.Context, config *Config, newClientFunc newCom return nil, fmt.Errorf("failed to create new Command API client: %w", err) } + if httpTraceEnabled() && client != nil && client.V1 != nil { + // Use the global logger: the client is cached for the process lifetime, so a + // logger derived from this reconcile's ctx would carry a stale reconcileID. + log.Info("HTTP tracing enabled; each request to Command will emit an 'http trace' log line", "env", EnvHTTPTrace) + client.V1.AuthClient = enableHTTPTrace(client.V1.AuthClient, serverConfig, ctrl.Log) + } + adapter := &clientAdapter{ enrollCSR: client.V1.EnrollmentApi.CreateEnrollmentCSRExecute, getAllMetadataFields: client.V1.MetadataFieldApi.GetMetadataFieldsExecute, diff --git a/internal/command/httptrace.go b/internal/command/httptrace.go new file mode 100644 index 0000000..d942aec --- /dev/null +++ b/internal/command/httptrace.go @@ -0,0 +1,293 @@ +/* +Copyright © 2026 Keyfactor + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package command + +import ( + "crypto/tls" + "errors" + "fmt" + "io" + "net/http" + "net/http/httptrace" + "os" + "strings" + "sync" + "time" + + "github.com/Keyfactor/keyfactor-auth-client-go/auth_providers" + v1 "github.com/Keyfactor/keyfactor-go-client-sdk/v25/api/keyfactor/v1" + "github.com/go-logr/logr" +) + +/* +This utility provides diagnostic-only network tracing, enabled by the environment variable +"COMMAND_ISSUER_HTTP_TRACE=true" or "COMMAND_ISSUER_HTTP_TRACE=1" on the controller. When enabled, +every outbound Command HTTP request emits one structured "http trace" log line +describing how the connection was obtained and where the time went. + +Request behavior is unaffected. +*/ + +const EnvHTTPTrace = "COMMAND_ISSUER_HTTP_TRACE" + +func httpTraceEnabled() bool { + v := strings.ToLower(strings.TrimSpace(os.Getenv(EnvHTTPTrace))) + return v == "true" || v == "1" +} + +// Wraps the AuthClient on a freshly build SDK client so that all SDK requests and healthcheck +// are traced. +func enableHTTPTrace(client v1.AuthConfig, server *auth_providers.Server, logger logr.Logger) v1.AuthConfig { + return &tracingAuthConfig{inner: client, server: server, logger: logger.WithName("httptrace")} +} + +// Thin wrapper around the AuthConfig that attaches HTTP tracing to each request. +// It implements the v1.AuthConfig interface and delegates all calls to the inner AuthConfig, +// adding HTTP tracing to the HTTP client returned by GetHttpClient(). +type tracingAuthConfig struct { + inner v1.AuthConfig + server *auth_providers.Server + logger logr.Logger +} + +var _ v1.AuthConfig = &tracingAuthConfig{} + +func (t *tracingAuthConfig) GetServerConfig() *auth_providers.Server { + return t.inner.GetServerConfig() +} + +func (t *tracingAuthConfig) GetHttpClient() (*http.Client, error) { + hc, err := t.inner.GetHttpClient() + if err != nil { + return nil, err + } + hc.Transport = &traceTransport{base: hc.Transport, logger: t.logger} + return hc, nil +} + +// Mirrors the auth_provider.CommandAuthConfig.Authenticate method by performing +// the same HTTP GET request to the Status/Endpoints endpoint. The upstream implementation +// builds its own client internally, which leaves no hook for tracing. +// TODO: Revalidate this behavior when keyfactor-auth-client-go is bumped. +func (t *tracingAuthConfig) Authenticate() error { + hc, err := t.GetHttpClient() + if err != nil { + return err + } + if t.server.ClientTimeout > 0 { + hc.Timeout = time.Duration(t.server.ClientTimeout) * time.Second + } + + endpoint := fmt.Sprintf("%s://%s/%s/Status/Endpoints", auth_providers.DefaultHttpProtocol, t.server.Host, t.server.APIPath) + req, err := http.NewRequest(http.MethodGet, endpoint, nil) + if err != nil { + return err + } + req.Header.Set("Content-Type", "application/json") + req.Header.Set("Accept", "application/json") + req.Header.Set("x-keyfactor-api-version", auth_providers.DefaultAPIVersion) + req.Header.Set("x-keyfactor-requested-with", auth_providers.DefaultAPIClientName) + + resp, err := hc.Do(req) + if err != nil { + return err + } + defer resp.Body.Close() + + body, err := io.ReadAll(resp.Body) + if err != nil { + return err + } + if resp.StatusCode != http.StatusOK { + return fmt.Errorf("failed to authenticate, received status code %d from Keyfactor Command: %s", resp.StatusCode, string(body)) + } + return nil +} + +// traceTransport attaches an httptrace.ClientTrace to each request and logs a +// single summary line when the round trip finishes. +type traceTransport struct { + base http.RoundTripper + logger logr.Logger +} + +func (t *traceTransport) RoundTrip(req *http.Request) (*http.Response, error) { + rec := &traceRecord{start: time.Now()} + trace := rec.clientTrace() + req = req.WithContext(httptrace.WithClientTrace(req.Context(), trace)) + + proxy := "none" + if u, err := http.ProxyFromEnvironment(req); err == nil && u != nil { + proxy = u.Host // host only; never log userinfo + } + + resp, err := t.base.RoundTrip(req) + t.logger.Info("http trace", rec.fields(req, proxy, resp, err)...) + return resp, err +} + +type connInfo struct { + reused, wasIdle bool + idleTime time.Duration + local, remote string + at time.Duration +} + +// traceRecord collects events for one RoundTrip. httptrace callbacks can fire +// from goroutines other than the caller's (dial), hence the mutex. +type traceRecord struct { + mu sync.Mutex + start time.Time + + conns []connInfo + dnsStart, dnsDone time.Time + connectStart, connectDone time.Time + connectAddr string + connectErr error + tlsStart, tlsDone time.Time + tlsErr error + wroteHeaders, wroteRequest, firstByte time.Time + wroteErr error +} + +func (r *traceRecord) clientTrace() *httptrace.ClientTrace { + now := time.Now + return &httptrace.ClientTrace{ + GotConn: func(i httptrace.GotConnInfo) { + r.mu.Lock() + defer r.mu.Unlock() + c := connInfo{reused: i.Reused, wasIdle: i.WasIdle, idleTime: i.IdleTime, at: time.Since(r.start)} + if i.Conn != nil { + c.local = i.Conn.LocalAddr().String() + c.remote = i.Conn.RemoteAddr().String() + } + r.conns = append(r.conns, c) + }, + DNSStart: func(httptrace.DNSStartInfo) { r.mu.Lock(); r.dnsStart = now(); r.mu.Unlock() }, + DNSDone: func(httptrace.DNSDoneInfo) { r.mu.Lock(); r.dnsDone = now(); r.mu.Unlock() }, + ConnectStart: func(_, addr string) { + r.mu.Lock() + r.connectStart, r.connectAddr = now(), addr + r.mu.Unlock() + }, + ConnectDone: func(_, _ string, err error) { + r.mu.Lock() + r.connectDone, r.connectErr = now(), err + r.mu.Unlock() + }, + TLSHandshakeStart: func() { r.mu.Lock(); r.tlsStart = now(); r.mu.Unlock() }, + TLSHandshakeDone: func(_ tls.ConnectionState, err error) { + r.mu.Lock() + r.tlsDone, r.tlsErr = now(), err + r.mu.Unlock() + }, + WroteHeaders: func() { r.mu.Lock(); r.wroteHeaders = now(); r.mu.Unlock() }, + WroteRequest: func(i httptrace.WroteRequestInfo) { + r.mu.Lock() + r.wroteRequest, r.wroteErr = now(), i.Err + r.mu.Unlock() + }, + GotFirstResponseByte: func() { r.mu.Lock(); r.firstByte = now(); r.mu.Unlock() }, + } +} + +func (r *traceRecord) span(from, to time.Time) string { + if from.IsZero() || to.IsZero() { + return "n/a" + } + return to.Sub(from).Round(time.Millisecond).String() +} + +// stage reports the last stage the request reached, which for a failed +// request identifies the phase in which the peer (or a middlebox) dropped it. +func (r *traceRecord) stage() string { + switch { + case r.connectErr != nil: + return "tcp-connect-failed" + case r.tlsErr != nil: + return "tls-handshake-failed" + case !r.firstByte.IsZero(): + return "response-received" + case !r.wroteRequest.IsZero(): + return "request-written-awaiting-response" + case len(r.conns) > 0: + return "got-conn-writing-request" + case !r.tlsStart.IsZero() && r.tlsDone.IsZero(): + return "tls-handshake" + case !r.tlsDone.IsZero(): + return "tls-done-before-got-conn" + case !r.connectStart.IsZero() && r.connectDone.IsZero(): + return "tcp-connect" + case !r.dnsStart.IsZero() && r.dnsDone.IsZero(): + return "dns" + default: + return "before-dial" + } +} + +func (r *traceRecord) fields(req *http.Request, proxy string, resp *http.Response, err error) []any { + r.mu.Lock() + defer r.mu.Unlock() + + u := req.URL.Host + req.URL.Path // no scheme, query, or userinfo + f := []any{ + "method", req.Method, + "url", u, + "proxy", proxy, + // More than one entry means net/http transparently retried the request + // on another connection after the first failed. + "gotConnCount", len(r.conns), + "total", time.Since(r.start).Round(time.Millisecond).String(), + "dns", r.span(r.dnsStart, r.dnsDone), + "tcpConnect", r.span(r.connectStart, r.connectDone), + "connectAddr", r.connectAddr, + "tlsHandshake", r.span(r.tlsStart, r.tlsDone), + "timeToFirstByte", r.span(r.wroteRequest, r.firstByte), + "stage", r.stage(), + } + for i, c := range r.conns { + p := fmt.Sprintf("conn%d.", i+1) + f = append(f, + p+"reused", c.reused, + p+"wasIdle", c.wasIdle, + p+"idleTime", c.idleTime.Round(time.Millisecond).String(), + p+"local", c.local, + p+"remote", c.remote, + p+"atOffset", c.at.Round(time.Millisecond).String(), + ) + } + if r.connectErr != nil { + f = append(f, "connectErr", r.connectErr.Error()) + } + if r.tlsErr != nil { + f = append(f, "tlsErr", r.tlsErr.Error()) + } + if r.wroteErr != nil { + f = append(f, "wroteErr", r.wroteErr.Error()) + } + if resp != nil { + f = append(f, "status", resp.StatusCode) + } + if err != nil { + f = append(f, + "error", err.Error(), + "isEOF", errors.Is(err, io.EOF), + "isUnexpectedEOF", errors.Is(err, io.ErrUnexpectedEOF), + ) + } + return f +} diff --git a/internal/command/httptrace_test.go b/internal/command/httptrace_test.go new file mode 100644 index 0000000..a1a3eb0 --- /dev/null +++ b/internal/command/httptrace_test.go @@ -0,0 +1,168 @@ +/* +Copyright © 2026 Keyfactor + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package command + +import ( + "net" + "net/http" + "net/http/httptest" + "os" + "strings" + "sync" + "testing" + + "github.com/Keyfactor/keyfactor-auth-client-go/auth_providers" + commandsdk "github.com/Keyfactor/keyfactor-go-client-sdk/v25/api/keyfactor/v1" + "github.com/go-logr/logr/funcr" + "github.com/stretchr/testify/require" +) + +type lineSink struct { + mu sync.Mutex + lines []string +} + +func (s *lineSink) add(prefix, args string) { + s.mu.Lock() + defer s.mu.Unlock() + s.lines = append(s.lines, prefix+" "+args) +} + +func newTraceServer(t *testing.T, newConns *int) *httptest.Server { + var mu sync.Mutex + srv := httptest.NewUnstartedServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + _, _ = w.Write([]byte(`[]`)) + })) + srv.Config.ConnState = func(_ net.Conn, s http.ConnState) { + if s == http.StateNew { + mu.Lock() + *newConns++ + mu.Unlock() + } + } + srv.StartTLS() + t.Cleanup(srv.Close) + return srv +} + +func TestHTTPTrace_LogsHealthCheckAndSDKRequests(t *testing.T) { + servers := map[string]func(host string) *auth_providers.Server{ + "basic": func(host string) *auth_providers.Server { + return &auth_providers.Server{Host: host, APIPath: "KeyfactorAPI", AuthType: "basic", Username: "u", Password: "p", SkipTLSVerify: true} + }, + "oauth-access-token": func(host string) *auth_providers.Server { + return &auth_providers.Server{Host: host, APIPath: "KeyfactorAPI", AuthType: "oauth", AccessToken: "tok", SkipTLSVerify: true} + }, + } + for name, mk := range servers { + t.Run(name, func(t *testing.T) { + var newConns int + srv := newTraceServer(t, &newConns) + cfg := mk(strings.TrimPrefix(srv.URL, "https://")) + + client, err := commandsdk.NewAPIClient(cfg) + require.NoError(t, err) + + sink := &lineSink{} + logger := funcr.New(sink.add, funcr.Options{}) + client.AuthClient = enableHTTPTrace(client.AuthClient, cfg, logger) + + require.NoError(t, client.AuthClient.Authenticate()) + _, resp, err := client.MetadataFieldApi.GetMetadataFieldsExecute(commandsdk.ApiGetMetadataFieldsRequest{}) + require.NoError(t, err) + _ = resp.Body.Close() + + require.Len(t, sink.lines, 2) + require.Contains(t, sink.lines[0], `"url"="`+cfg.Host+`/KeyfactorAPI/Status/Endpoints"`) + require.Contains(t, sink.lines[1], "MetadataFields") + for _, l := range sink.lines { + require.Contains(t, l, `"conn1.reused"=false`) + require.Contains(t, l, `"conn1.local"="127.0.0.1:`) + require.Contains(t, l, `"conn1.remote"="127.0.0.1:`) + require.Contains(t, l, `"status"=200`) + require.Contains(t, l, `"stage"="response-received"`) + require.NotContains(t, l, "tok") + } + // Documents the dependency behavior this diagnostic is investigating: the + // auth client builds a new transport per call, so no connection is reused. + require.Equal(t, 3, newConns, "1 at construction + 1 per traced request") + }) + } +} + +func TestHTTPTrace_RecordsEOF(t *testing.T) { + // A server that accepts TCP and closes immediately simulates a middlebox dropping a new tunnel. + ln, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + t.Cleanup(func() { _ = ln.Close() }) + go func() { + for { + c, err := ln.Accept() + if err != nil { + return + } + _ = c.Close() + } + }() + + sink := &lineSink{} + cfg := &auth_providers.Server{Host: ln.Addr().String(), APIPath: "KeyfactorAPI", AuthType: "basic", Username: "u", Password: "p", SkipTLSVerify: true} + ta := &tracingAuthConfig{inner: &fakeAuth{cfg: cfg}, server: cfg, logger: funcr.New(sink.add, funcr.Options{})} + + require.Error(t, ta.Authenticate()) + require.Len(t, sink.lines, 1) + require.Contains(t, sink.lines[0], `"stage"="tls-handshake-failed"`) + require.Contains(t, sink.lines[0], `"isEOF"=true`) +} + +func TestHTTPTrace_httpTraceEnabled(t *testing.T) { + t.Run("enabled with true", func(t *testing.T) { + os.Setenv(EnvHTTPTrace, "true") + defer os.Unsetenv(EnvHTTPTrace) + require.True(t, httpTraceEnabled()) + }) + t.Run("enabled with 1", func(t *testing.T) { + os.Setenv(EnvHTTPTrace, "1") + defer os.Unsetenv(EnvHTTPTrace) + require.True(t, httpTraceEnabled()) + }) + t.Run("disabled with false", func(t *testing.T) { + os.Setenv(EnvHTTPTrace, "false") + defer os.Unsetenv(EnvHTTPTrace) + require.False(t, httpTraceEnabled()) + }) + t.Run("disabled with 0", func(t *testing.T) { + os.Setenv(EnvHTTPTrace, "0") + defer os.Unsetenv(EnvHTTPTrace) + require.False(t, httpTraceEnabled()) + }) + t.Run("disabled with empty", func(t *testing.T) { + os.Unsetenv(EnvHTTPTrace) + require.False(t, httpTraceEnabled()) + }) +} + +type fakeAuth struct{ cfg *auth_providers.Server } + +func (f *fakeAuth) Authenticate() error { return nil } +func (f *fakeAuth) GetServerConfig() *auth_providers.Server { return f.cfg } +func (f *fakeAuth) GetHttpClient() (*http.Client, error) { + b := &auth_providers.CommandAuthConfig{SkipVerify: true} + tr, err := b.BuildTransport() + return &http.Client{Transport: tr}, err +} From 18ce4d906f16605aca5f0f58c8ad8e5b9bb702d0 Mon Sep 17 00:00:00 2001 From: "Matthew H. Irby" Date: Mon, 26 Oct 2026 16:36:41 -0400 Subject: [PATCH 2/2] chore: address copilot feedback Signed-off-by: Matthew H. Irby --- internal/command/httptrace.go | 38 ++++++++++++++++++++++++----------- 1 file changed, 26 insertions(+), 12 deletions(-) diff --git a/internal/command/httptrace.go b/internal/command/httptrace.go index d942aec..2cea756 100644 --- a/internal/command/httptrace.go +++ b/internal/command/httptrace.go @@ -1,5 +1,5 @@ /* -Copyright © 2026 Keyfactor +Copyright © 2025 Keyfactor Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. @@ -18,6 +18,7 @@ package command import ( "crypto/tls" + "encoding/json" "errors" "fmt" "io" @@ -88,9 +89,11 @@ func (t *tracingAuthConfig) Authenticate() error { if err != nil { return err } - if t.server.ClientTimeout > 0 { - hc.Timeout = time.Duration(t.server.ClientTimeout) * time.Second + timeout := t.inner.GetServerConfig().ClientTimeout + if timeout <= 0 { + timeout = auth_providers.DefaultClientTimeout } + hc.Timeout = time.Duration(timeout) * time.Second endpoint := fmt.Sprintf("%s://%s/%s/Status/Endpoints", auth_providers.DefaultHttpProtocol, t.server.Host, t.server.APIPath) req, err := http.NewRequest(http.MethodGet, endpoint, nil) @@ -115,7 +118,10 @@ func (t *tracingAuthConfig) Authenticate() error { if resp.StatusCode != http.StatusOK { return fmt.Errorf("failed to authenticate, received status code %d from Keyfactor Command: %s", resp.StatusCode, string(body)) } - return nil + // Upstream also requires the body to be a JSON string array; keep that so an + // HTML login/error page served with 200 still fails the check. + var endpoints []string + return json.Unmarshal(body, &endpoints) } // traceTransport attaches an httptrace.ClientTrace to each request and logs a @@ -157,7 +163,7 @@ type traceRecord struct { dnsStart, dnsDone time.Time connectStart, connectDone time.Time connectAddr string - connectErr error + connectErrs []string // one per failed dial attempt (dials can race) tlsStart, tlsDone time.Time tlsErr error wroteHeaders, wroteRequest, firstByte time.Time @@ -186,7 +192,13 @@ func (r *traceRecord) clientTrace() *httptrace.ClientTrace { }, ConnectDone: func(_, _ string, err error) { r.mu.Lock() - r.connectDone, r.connectErr = now(), err + // Dial attempts can run in parallel (Happy Eyeballs); a losing attempt may + // fail after another succeeded, so only a success marks the connect done. + if err != nil { + r.connectErrs = append(r.connectErrs, err.Error()) + } else { + r.connectDone = now() + } r.mu.Unlock() }, TLSHandshakeStart: func() { r.mu.Lock(); r.tlsStart = now(); r.mu.Unlock() }, @@ -215,17 +227,19 @@ func (r *traceRecord) span(from, to time.Time) string { // stage reports the last stage the request reached, which for a failed // request identifies the phase in which the peer (or a middlebox) dropped it. func (r *traceRecord) stage() string { + // Later successful stages take precedence over errors from other attempts + // (a losing dial, or a first connection that net/http retried past). switch { - case r.connectErr != nil: - return "tcp-connect-failed" - case r.tlsErr != nil: - return "tls-handshake-failed" case !r.firstByte.IsZero(): return "response-received" case !r.wroteRequest.IsZero(): return "request-written-awaiting-response" case len(r.conns) > 0: return "got-conn-writing-request" + case len(r.connectErrs) > 0 && r.connectDone.IsZero(): + return "tcp-connect-failed" + case r.tlsErr != nil: + return "tls-handshake-failed" case !r.tlsStart.IsZero() && r.tlsDone.IsZero(): return "tls-handshake" case !r.tlsDone.IsZero(): @@ -270,8 +284,8 @@ func (r *traceRecord) fields(req *http.Request, proxy string, resp *http.Respons p+"atOffset", c.at.Round(time.Millisecond).String(), ) } - if r.connectErr != nil { - f = append(f, "connectErr", r.connectErr.Error()) + if len(r.connectErrs) > 0 { + f = append(f, "connectErrs", strings.Join(r.connectErrs, "; ")) } if r.tlsErr != nil { f = append(f, "tlsErr", r.tlsErr.Error())