fix(agent-proxy): stop logging client cancellations as proxy errors

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 {

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)
+	}
+}

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)
 	}