diff --git a/packages/agentproxy/activitylog_test.go b/packages/agentproxy/activitylog_test.go index b250dae0..33138ed4 100644 --- a/packages/agentproxy/activitylog_test.go +++ b/packages/agentproxy/activitylog_test.go @@ -43,6 +43,7 @@ func TestLevelFor(t *testing.T) { decisionPassthrough: zerolog.DebugLevel, decisionBlocked: zerolog.WarnLevel, decisionError: zerolog.ErrorLevel, + decisionCanceled: zerolog.DebugLevel, } for decision, want := range cases { if got := levelFor(decision); got != want { diff --git a/packages/agentproxy/forward_test.go b/packages/agentproxy/forward_test.go index 47ae78ba..a687fa13 100644 --- a/packages/agentproxy/forward_test.go +++ b/packages/agentproxy/forward_test.go @@ -2,6 +2,7 @@ package agentproxy import ( "bufio" + "bytes" "encoding/base64" "fmt" "io" @@ -12,6 +13,9 @@ import ( "strings" "testing" "time" + + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" ) func proxyAuthHeader(projectID, environment, secretPath, jwt string) string { @@ -186,3 +190,109 @@ func TestPlainForwardBlocksUnmatchedHost(t *testing.T) { t.Fatalf("expected 403 in block mode for an unmatched host, got %d", resp.StatusCode) } } + +func TestClientAbortIsNotLoggedAsError(t *testing.T) { + var buf bytes.Buffer + previous := log.Logger + log.Logger = zerolog.New(&buf) + t.Cleanup(func() { log.Logger = previous }) + + release := make(chan struct{}) + upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + <-release + })) + t.Cleanup(func() { close(release); upstream.Close() }) + + u, err := url.Parse(upstream.URL) + if err != nil { + t.Fatal(err) + } + + jwt := "test.jwt.token" + scope := agentScope{projectID: "proj", environment: "dev", secretPath: "/"} + client := newTestProxy(t, UnmatchedAllow, jwt, scope, nil) + + if _, err := fmt.Fprintf(client, "POST http://%s/v1/messages HTTP/1.1\r\nHost: %s\r\nProxy-Authorization: %s\r\nContent-Length: 0\r\n\r\n", + u.Host, u.Host, proxyAuthHeader("proj", "dev", "/", jwt)); err != nil { + t.Fatal(err) + } + time.Sleep(200 * time.Millisecond) + _ = client.Close() + + var line string + for deadline := time.Now().Add(3 * time.Second); time.Now().Before(deadline); { + if line = buf.String(); strings.Contains(line, activityEventName) { + break + } + time.Sleep(20 * time.Millisecond) + } + if !strings.Contains(line, activityEventName) { + t.Fatalf("expected an activity record for the aborted request, got %q", line) + } + if !strings.Contains(line, `"decision":"`+decisionCanceled+`"`) { + t.Errorf("expected decision %q, got %q", decisionCanceled, line) + } + if strings.Contains(line, `"level":"error"`) { + t.Errorf("client abort logged at error level: %q", line) + } + if strings.Contains(line, `"status":`) { + t.Errorf("a canceled request has no response status to report: %q", line) + } +} + +func TestClientAbortStillRecordsBrokeredCredential(t *testing.T) { + var buf bytes.Buffer + previous := log.Logger + log.Logger = zerolog.New(&buf) + t.Cleanup(func() { log.Logger = previous }) + + release := make(chan struct{}) + upstream := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + <-release + })) + t.Cleanup(func() { close(release); upstream.Close() }) + + u, err := url.Parse(upstream.URL) + if err != nil { + t.Fatal(err) + } + + jwt := "test.jwt.token" + scope := agentScope{projectID: "proj", environment: "dev", secretPath: "/"} + services := []*resolvedService{{ + name: "internal", + hostPatterns: parseHostPatterns(u.Hostname()), + isEnabled: true, + credentials: []resolvedCredential{ + {secretKey: "GITHUB_PAT", role: roleHeaderRewrite, headerName: "Authorization", headerPrefix: "Bearer", value: "real_secret"}, + }, + }} + client := newTestProxy(t, UnmatchedAllow, jwt, scope, services) + + if _, err := fmt.Fprintf(client, "POST http://%s/issues HTTP/1.1\r\nHost: %s\r\nProxy-Authorization: %s\r\nContent-Length: 0\r\n\r\n", + u.Host, u.Host, proxyAuthHeader("proj", "dev", "/", jwt)); err != nil { + t.Fatal(err) + } + time.Sleep(200 * time.Millisecond) + _ = client.Close() + + var line string + for deadline := time.Now().Add(3 * time.Second); time.Now().Before(deadline); { + if line = buf.String(); strings.Contains(line, activityEventName) { + break + } + time.Sleep(20 * time.Millisecond) + } + if !strings.Contains(line, `"decision":"`+decisionBrokered+`"`) { + t.Errorf("a credential was applied, so the record must stay %q: %q", decisionBrokered, line) + } + if !strings.Contains(line, `"level":"info"`) { + t.Errorf("brokered records must stay at info so they survive the default filter: %q", line) + } + if !strings.Contains(line, "GITHUB_PAT") { + t.Errorf("the applied credential must still be named on the record: %q", line) + } + if strings.Contains(line, "real_secret") { + t.Errorf("the record must never contain the secret value: %q", line) + } +} diff --git a/packages/agentproxy/proxy.go b/packages/agentproxy/proxy.go index 1b6016ce..aa7df7c9 100644 --- a/packages/agentproxy/proxy.go +++ b/packages/agentproxy/proxy.go @@ -71,6 +71,7 @@ const ( decisionPassthrough = "passthrough" decisionBlocked = "blocked" decisionError = "error" + decisionCanceled = "canceled" activityEventName = "agent-proxy.request" @@ -286,7 +287,7 @@ func Start(opts Options) error { return fmt.Errorf("failed to listen on port %d: %w", opts.Port, err) } log.Info().Msgf("Infisical agent proxy listening on :%d", opts.Port) - log.Info().Msg("per-request activity logging on: brokered=info, blocked=warn, error=error, passthrough=debug (use --log-level to filter)") + log.Info().Msg("per-request activity logging on: brokered=info, blocked=warn, error=error, passthrough=debug, canceled=debug (use --log-level to filter)") sigCh := make(chan os.Signal, 1) signal.Notify(sigCh, os.Interrupt, syscall.SIGTERM) @@ -480,11 +481,19 @@ func (ps *proxyServer) forwardHTTP(w http.ResponseWriter, r *http.Request, schem resp, outcome, err := ps.forward(r, scheme, hostname, port, jwt, scope) + canceled := err != nil && r.Context().Err() != nil + status := http.StatusOK decision := decisionPassthrough + // Blocked and brokered are checked before canceled, so hanging up cannot drop them from the log. switch { case errors.Is(err, errHostBlocked): decision, status = decisionBlocked, http.StatusForbidden + case canceled && outcome.service != nil: + decision, status = decisionBrokered, 0 + ps.recordUsage(outcome.service.id) + case canceled: + decision, status = decisionCanceled, 0 case err != nil: decision, status = decisionError, http.StatusBadGateway case outcome.service != nil: @@ -496,7 +505,9 @@ func (ps *proxyServer) forwardHTTP(w http.ResponseWriter, r *http.Request, schem ps.emitActivity(method, reqPath, hostname, port, decision, status, scope, outcome, err) if err != nil { - http.Error(w, err.Error(), status) + if !canceled { + http.Error(w, err.Error(), status) + } return } defer resp.Body.Close() @@ -524,7 +535,7 @@ func levelFor(decision string) zerolog.Level { return zerolog.WarnLevel case decisionError: return zerolog.ErrorLevel - case decisionPassthrough: + case decisionPassthrough, decisionCanceled: return zerolog.DebugLevel default: return zerolog.InfoLevel @@ -544,8 +555,10 @@ func (ps *proxyServer) emitActivity(method, reqPath, hostname, port, decision st Str("method", method). Str("host", hostname). Int("port", portNum). - Str("path", reqPath). - Int("status", status) + Str("path", reqPath) + if status != 0 { + ev = ev.Int("status", status) + } if outcome.agentName != "" { ev = ev.Str("agentName", outcome.agentName) }