diff --git a/CHANGELOG.org b/CHANGELOG.org index a74eca9..efed684 100644 --- a/CHANGELOG.org +++ b/CHANGELOG.org @@ -1,3 +1,113 @@ +* 2026-06-25 + +Release =v4.0.7= has been tagged. + +Added support for emitting debug log events from the =recorder= and =cassette= +packages, which makes it easier to diagnose request matching failures and +understand what the recorder is doing during a test run. See [[https://github.com/dnaeon/go-vcr/issues/108][#108]] and [[https://github.com/dnaeon/go-vcr/pull/148][#148]] for +more details. + +The new =recorder.WithDebugWriter= option configures an =io.Writer= that +receives a structured trace of recorder lifecycle events, per-request dispatch, +match attempts (including a wire-format dump of the incoming request and each +recorded interaction it was compared against), hook invocations, recorded +interactions, context cancellations, and cassette save outcomes. + +The trace is emitted via =log/slog= with a text handler at =slog.LevelDebug=. + +The debug writer may also be enabled via the =VCR_DEBUG= environment +variable. When =VCR_DEBUG= is set to =true=, and =recorder.WithDebugWriter= has +not been used in a test, them the debug trace is written to =os.Stderr=. + +An explicit =recorder.WithDebugWriter= always takes precedence over the +environment variable. + +Other changes in this release: + +- =fmt.Stringer= is now implemented for =recorder.Mode= and =recorder.HookKind=, + which produces human-readable names (e.g. =RecordOnce=, =BeforeSave=) instead + of integer values in debug output and error messages. +- =fmt.Stringer= is now implemented for =cassette.Request= and + =cassette.Response=, which renders a compact, single-line summary of the + recorded request/response that is suitable for use as a value in a debug log + attribute. +- The =sync.Mutex= previously embedded in =cassette.Cassette= is now an + unexported field. This removes the previously-exposed =Lock= and =Unlock= + methods, which were never intended to be part of the public API. +- Bumped the YAML dependency to =go.yaml.in/yaml/v4= (=v4.0.0-rc.6=). + +* 2025-11-25 + +Release =v4.0.6= has been tagged. + +Added the =recorder.WithMarshalFunc= option, which configures a custom YAML +marshalling function for the cassette. This allows customisation of the YAML +encoding process such as setting string literal style and the like. See [[https://github.com/dnaeon/go-vcr/pull/129][#129]] and +[[https://github.com/dnaeon/go-vcr/pull/132][#132]] for more details. + +Migrated back to =go.yaml.in/yaml/v4= + +* 2025-08-17 + +Release =v4.0.5= has been tagged. + +Added support for storing cassettes in any data source by introducing the +=cassette.FS= interface and the =recorder.WithFS= option. The default +implementation reads and writes cassettes from the local filesystem; alternative +implementations can target in-memory stores, mocks, or any other backend. See +[[https://github.com/dnaeon/go-vcr/pull/125][#125]] for more details. + +Replaced =gopkg.in/yaml.v3= with =github.com/goccy/go-yaml= as the YAML +implementation backing the cassette serialiser. See [[https://github.com/dnaeon/go-vcr/pull/126][#126]] for more details. + +Various test-related improvements with no functional change. See [[https://github.com/dnaeon/go-vcr/pull/120][#120]] for more +details. + +* 2025-06-27 + +Release =v4.0.4= has been tagged. + +The recorder now always calls =http.Request.ParseForm= before recording an +interaction. This makes the recorded =Form= field consistent across requests +regardless of how the caller constructed them. See [[https://github.com/dnaeon/go-vcr/pull/122][#122]] for more details. + +*NOTE*: Cassettes may need to be re-created as a result of this change. + +* 2025-06-10 + +Release =v4.0.3= has been tagged. + +The cassette YAML serialization now uses =omitempty= for fields whose zero-value +carries no useful information. See [[https://github.com/dnaeon/go-vcr/pull/110][#110]] for more details. + +The =cassette.ErrCassetteNotFound= sentinel is now wrapped with the number of +recorded interactions when returned. See [[https://github.com/dnaeon/go-vcr/pull/117][#117]] for more details. + +Fixed an issue where the recorded =Form= field captured only =PostForm= values, +missing those derived from the query string. The recorder now captures the full +form. See [[https://github.com/dnaeon/go-vcr/pull/118][#118]] for more details. + +Various test-related improvements with no functional change. See [[https://github.com/dnaeon/go-vcr/pull/111][#111]] for more +details. + +Documentation updates: see [[https://github.com/dnaeon/go-vcr/pull/115][#115]]. + +* 2024-11-27 + +Release =v4.0.2= has been tagged. + +Added two new =cassette.DefaultMatcherOption= helpers for ignoring HTTP +headers during matching: + +- =cassette.WithIgnoreAuthorization= - ignores the =Authorization= header. +- =cassette.WithIgnoreHeaders= - ignores the headers supplied to it. + +See [[https://github.com/dnaeon/go-vcr/pull/103][#103]] and [[https://github.com/dnaeon/go-vcr/pull/104][#104]] for more details. + +Fixed a panic when matching requests with a =nil= body. The recorder now sets +=http.NoBody= in this case so the matcher can proceed safely. See [[https://github.com/dnaeon/go-vcr/pull/105][#105]] for more +details. + * 2024-08-19 Release =v4.0.0= has been tagged. diff --git a/README.md b/README.md index cde2220..4200162 100644 --- a/README.md +++ b/README.md @@ -79,26 +79,57 @@ additional examples. ## Custom YAML Marshaling Function If you need control how YAML is encoded, set `WithMarshalFunc` with a custom -func. This default to `yaml.Marshal`. +func. This defaults to `yaml.Marshal`. ```go -marshalFunc := func(in any) (out []byte, err error) { - var buff bytes.Buffer - enc := yaml.NewEncoder(&buff) +package marshalfunc_test - // Example of custom options from - // https://pkg.go.dev/go.yaml.in/yaml/v4 - enc.CompactSeqIndent() - enc.SetIndent(4) +import ( + "bytes" + "path/filepath" + "strings" + "testing" + + "go.yaml.in/yaml/v4" + "gopkg.in/dnaeon/go-vcr.v4/pkg/recorder" +) + +func TestCustomMarshalFunc(t *testing.T) { + marshalFunc := func(in any) ([]byte, error) { + var buf bytes.Buffer + enc := yaml.NewEncoder(&buf) + + // Example of custom options from + // https://pkg.go.dev/go.yaml.in/yaml/v4 + enc.CompactSeqIndent() + enc.SetIndent(4) + + if err := enc.Encode(in); err != nil { + return nil, err + } + return buf.Bytes(), nil + } - if err := enc.Encode(in); err != nil { - return nil, err + r, err := recorder.New( + filepath.Join("testdata", strings.ReplaceAll(t.Name(), "/", "_")), + recorder.WithMarshalFunc(marshalFunc), + ) + if err != nil { + t.Fatal(err) } - return buff.Bytes(), nil -} + t.Cleanup(func() { + if err := r.Stop(); err != nil { + t.Error(err) + } + }) -rec, err := recorder.New("cassette_name", recorder.WithMarshalFunc(marshalFunc)) -// ... + client := r.GetDefaultClient() + resp, err := client.Get("https://go.dev/VERSION?m=text") + if err != nil { + t.Fatal(err) + } + resp.Body.Close() +} ``` ## Custom Request Matching @@ -110,41 +141,56 @@ function. For example, the following matcher will match on method, URL and body: ``` go +package matcher_test + +import ( + "bytes" + "io" + "net/http" + "path/filepath" + "strings" + "testing" + + "gopkg.in/dnaeon/go-vcr.v4/pkg/cassette" + "gopkg.in/dnaeon/go-vcr.v4/pkg/recorder" +) func customMatcher(r *http.Request, i cassette.Request) bool { if r.Body == nil || r.Body == http.NoBody { return cassette.DefaultMatcher(r, i) } - var reqBody []byte - var err error - reqBody, err = io.ReadAll(r.Body) + reqBody, err := io.ReadAll(r.Body) if err != nil { - log.Fatal("failed to read request body") + return false } r.Body.Close() - r.Body = ioutil.NopCloser(bytes.NewBuffer(reqBody)) + r.Body = io.NopCloser(bytes.NewBuffer(reqBody)) return r.Method == i.Method && r.URL.String() == i.URL && string(reqBody) == i.Body } -... - -// Recorder options -opts := []recorder.Option{ - recorder.WithMatcher(customMatcher), -} +func TestCustomMatcher(t *testing.T) { + r, err := recorder.New( + filepath.Join("testdata", strings.ReplaceAll(t.Name(), "/", "_")), + recorder.WithMatcher(customMatcher), + ) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + if err := r.Stop(); err != nil { + t.Error(err) + } + }) -rec, err := recorder.New("testdata/matchers", opts...) -if err != nil { - log.Fatal(err) + client := r.GetDefaultClient() + resp, err := client.Get("https://go.dev/VERSION?m=text") + if err != nil { + t.Fatal(err) + } + resp.Body.Close() } -defer rec.Stop() // Make sure recorder is stopped once done with it - -client := rec.GetDefaultClient() -resp, err := client.Get("https://www.google.com/") - -... ``` ## Hooks @@ -173,25 +219,45 @@ Here is an example that removes the `Authorization` header from all requests right after capturing a new interaction. ``` go -// A hook which removes Authorization headers from all requests -hook := func(i *cassette.Interaction) error { - delete(i.Request.Headers, "Authorization") - return nil -} +package hooks_test -// Recorder options -opts := []recorder.Option{ - recorder.WithHook(hook, recorder.AfterCaptureHook), - recorder.WithMatcher(cassette.NewDefaultMatcher(cassette.WithIgnoreAuthorization())), -} +import ( + "path/filepath" + "strings" + "testing" -r, err := recorder.New("testdata/filters", opts...) -if err != nil { - log.Fatal(err) -} -defer r.Stop() // Make sure recorder is stopped once done with it + "gopkg.in/dnaeon/go-vcr.v4/pkg/cassette" + "gopkg.in/dnaeon/go-vcr.v4/pkg/recorder" +) -... +func TestAfterCaptureHook(t *testing.T) { + // A hook which removes Authorization headers from all requests + hook := func(i *cassette.Interaction) error { + delete(i.Request.Headers, "Authorization") + return nil + } + + r, err := recorder.New( + filepath.Join("testdata", strings.ReplaceAll(t.Name(), "/", "_")), + recorder.WithHook(hook, recorder.AfterCaptureHook), + recorder.WithMatcher(cassette.NewDefaultMatcher(cassette.WithIgnoreAuthorization())), + ) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + if err := r.Stop(); err != nil { + t.Error(err) + } + }) + + client := r.GetDefaultClient() + resp, err := client.Get("https://go.dev/VERSION?m=text") + if err != nil { + t.Fatal(err) + } + resp.Body.Close() +} ``` Hooks added using `recorder.AfterCaptureHook` are applied right after an @@ -209,28 +275,47 @@ they are saved on disk. For that purpose you should be using a `BeforeSaveHook`, e.g. ``` go -// Your test code will continue to see the real access token and -// it is redacted before the recorded interactions are saved on disk -hook := func(i *cassette.Interaction) error { - if strings.Contains(i.Request.URL, "/oauth/token") { - i.Response.Body = `{"access_token": "[REDACTED]"}` - } +package hooks_test - return nil -} +import ( + "path/filepath" + "strings" + "testing" -// Recorder options -opts := []recorder.Option{ - recorder.WithHook(hook, recorder.BeforeSaveHook), -} + "gopkg.in/dnaeon/go-vcr.v4/pkg/cassette" + "gopkg.in/dnaeon/go-vcr.v4/pkg/recorder" +) -r, err := recorder.New("testdata/filters", opts...) -if err != nil { - log.Fatal(err) -} -defer r.Stop() // Make sure recorder is stopped once done with it +func TestBeforeSaveHook(t *testing.T) { + // Your test code will continue to see the real access token and + // it is redacted before the recorded interactions are saved on disk + hook := func(i *cassette.Interaction) error { + if strings.Contains(i.Request.URL, "/oauth/token") { + i.Response.Body = `{"access_token": "[REDACTED]"}` + } + return nil + } + + r, err := recorder.New( + filepath.Join("testdata", strings.ReplaceAll(t.Name(), "/", "_")), + recorder.WithHook(hook, recorder.BeforeSaveHook), + ) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + if err := r.Stop(); err != nil { + t.Error(err) + } + }) -... + client := r.GetDefaultClient() + resp, err := client.Get("https://go.dev/VERSION?m=text") + if err != nil { + t.Fatal(err) + } + resp.Body.Close() +} ``` ## Passing Through Requests @@ -245,22 +330,96 @@ recorder. Here's an example to pass through requests to a specific endpoint: ``` go -passthrough := func(req *http.Request) bool { - return req.URL.Path == "/login" -} +package passthrough_test + +import ( + "net/http" + "path/filepath" + "strings" + "testing" -// Recorder options -opts := []recorder.Option{ - recorder.WithPassthrough(passthrough), + "gopkg.in/dnaeon/go-vcr.v4/pkg/recorder" +) + +func TestPassthrough(t *testing.T) { + passthrough := func(req *http.Request) bool { + return req.URL.Path == "/login" + } + + r, err := recorder.New( + filepath.Join("testdata", strings.ReplaceAll(t.Name(), "/", "_")), + recorder.WithPassthrough(passthrough), + ) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + if err := r.Stop(); err != nil { + t.Error(err) + } + }) + + client := r.GetDefaultClient() + resp, err := client.Get("https://go.dev/VERSION?m=text") + if err != nil { + t.Fatal(err) + } + resp.Body.Close() } +``` + +## Debug Tracing + +When a test fails because the recorder did not match the request you expected, +it is often useful to see exactly what the recorder is doing. + +The `recorder.WithDebugWriter` option allows API clients to configure an +`io.Writer` that is used to write debug events via an internal `slog.Logger` +instance. + +``` go +package debug_test + +import ( + "os" + "path/filepath" + "strings" + "testing" -r, err := recorder.New("testdata/filters", opts...) -if err != nil { - log.Fatal(err) + "gopkg.in/dnaeon/go-vcr.v4/pkg/recorder" +) + +func TestDebugTrace(t *testing.T) { + r, err := recorder.New( + filepath.Join("testdata", strings.ReplaceAll(t.Name(), "/", "_")), + recorder.WithDebugWriter(os.Stderr), + ) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + if err := r.Stop(); err != nil { + t.Error(err) + } + }) + + client := r.GetDefaultClient() + resp, err := client.Get("https://go.dev/VERSION?m=text") + if err != nil { + t.Fatal(err) + } + resp.Body.Close() } -defer r.Stop() // Make sure recorder is stopped once done with it +``` + +The debug writer may also be enabled without changing the code by setting the +`VCR_DEBUG` environment variable to `true`. + +An explicit `recorder.WithDebugWriter` option always takes precedence over the +environment variable. -... +``` sh +VCR_DEBUG=true go test ./... ``` ## Server Side diff --git a/examples/debug_test.go b/examples/debug_test.go new file mode 100644 index 0000000..92f8fbe --- /dev/null +++ b/examples/debug_test.go @@ -0,0 +1,85 @@ +// Copyright (c) 2015-2026 Marin Atanasov Nikolov +// All rights reserved. +// +// Redistribution and use in source and binary forms, with or without +// modification, are permitted provided that the following conditions +// are met: +// 1. Redistributions of source code must retain the above copyright +// notice, this list of conditions and the following disclaimer +// in this position and unchanged. +// 2. Redistributions in binary form must reproduce the above copyright +// notice, this list of conditions and the following disclaimer in the +// documentation and/or other materials provided with the distribution. +// +// THIS SOFTWARE IS PROVIDED BY THE AUTHOR(S) ``AS IS'' AND ANY EXPRESS OR +// IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES +// OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED. +// IN NO EVENT SHALL THE AUTHOR(S) BE LIABLE FOR ANY DIRECT, INDIRECT, +// INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT +// NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, +// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY +// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT +// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF +// THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + +package vcr_test + +import ( + "bytes" + "strings" + "testing" + + "gopkg.in/dnaeon/go-vcr.v4/pkg/recorder" +) + +// TestDebugTrace demonstrates how to enable the recorder's debug trace using +// the WithDebugWriter option. The trace is a structured log of recorder +// lifecycle events. +// +// In a real test you would typically pass os.Stderr to WithDebugWriter, or set +// the VCR_DEBUG environment variable to a value parseable as true by +// strconv.ParseBool to enable the same trace on os.Stderr without changing the +// code: +// +// VCR_DEBUG=true go test ./... +// +// Here we capture the trace into a bytes.Buffer so the example is deterministic +// and can assert that the expected event names appear in the output. +func TestDebugTrace(t *testing.T) { + var traceBuf bytes.Buffer + + r, err := recorder.New( + "testdata/debug-trace", + recorder.WithDebugWriter(&traceBuf), + ) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + // Make sure recorder is stopped once done with it. + if err := r.Stop(); err != nil { + t.Error(err) + } + }) + + client := r.GetDefaultClient() + url := "https://go.dev/VERSION?m=text" + resp, err := client.Get(url) + if err != nil { + t.Fatalf("Failed to get url %s: %s", url, err) + } + resp.Body.Close() + + // The captured trace should include the recorder's lifecycle events and + // the per-request breadcrumbs for the request we just made. Each event + // is one line in the trace and carries structured key=value attributes. + trace := traceBuf.String() + for _, want := range []string{ + "recorder initialized", + "request received", + } { + if !strings.Contains(trace, want) { + t.Errorf("debug trace missing %q\n--- trace ---\n%s", want, trace) + } + } +} diff --git a/examples/testdata/debug-trace.yaml b/examples/testdata/debug-trace.yaml new file mode 100644 index 0000000..eb85578 --- /dev/null +++ b/examples/testdata/debug-trace.yaml @@ -0,0 +1,42 @@ +--- +version: 2 +interactions: + - id: 0 + request: + proto: HTTP/1.1 + proto_major: 1 + proto_minor: 1 + content_length: 0 + host: go.dev + form: + m: + - text + url: https://go.dev/VERSION?m=text + method: GET + response: + proto: HTTP/2.0 + proto_major: 2 + proto_minor: 0 + content_length: -1 + uncompressed: true + body: | + go1.26.4 + time 2026-05-29T15:26:39Z + headers: + Content-Security-Policy: + - 'connect-src ''self'' www.google-analytics.com stats.g.doubleclick.net ; default-src ''self'' ; font-src ''self'' fonts.googleapis.com fonts.gstatic.com data: ; frame-ancestors ''self'' ; frame-src ''self'' www.google.com feedback.googleusercontent.com www.googletagmanager.com scone-pa.clients6.google.com www.youtube.com player.vimeo.com ; img-src ''self'' www.google.com www.google-analytics.com ssl.gstatic.com www.gstatic.com gstatic.com data: * ; object-src ''none'' ; script-src ''self'' ''sha256-n6OdwTrm52KqKm6aHYgD0TFUdMgww4a0GQlIAVrMzck='' ''sha256-4ryYrf7Y5daLOBv0CpYtyBIcJPZkRD2eBPdfqsN3r1M='' ''sha256-sVKX08+SqOmnWhiySYk3xC7RDUgKyAkmbXV2GWts4fo='' www.google.com apis.google.com www.gstatic.com gstatic.com support.google.com www.googletagmanager.com www.google-analytics.com ssl.google-analytics.com tagmanager.google.com ; style-src ''self'' ''unsafe-inline'' fonts.googleapis.com feedback.googleusercontent.com www.gstatic.com gstatic.com tagmanager.google.com ;' + Content-Type: + - text/plain; charset=utf-8 + Date: + - Tue, 23 Jun 2026 09:36:51 GMT + Server: + - Google Frontend + Strict-Transport-Security: + - max-age=31536000; includeSubDomains; preload + Vary: + - Accept-Encoding + X-Cloud-Trace-Context: + - 44a73a361c6507cd0d431a97de11642b + status: 200 OK + code: 200 + duration: 454.994084ms diff --git a/pkg/cassette/cassette.go b/pkg/cassette/cassette.go index 6800c52..335871d 100644 --- a/pkg/cassette/cassette.go +++ b/pkg/cassette/cassette.go @@ -29,16 +29,123 @@ import ( "errors" "fmt" "io" + "log/slog" "net/http" + "net/http/httputil" "net/url" "reflect" "strings" "sync" "time" + "unicode" + "unicode/utf8" "go.yaml.in/yaml/v4" ) +// debugBodyLimit is the maximum number of body bytes rendered in a debug dump. +// Anything larger is truncated with a "(truncated, N bytes total)" suffix. +const debugBodyLimit = 16 * 1024 + +// debugSummaryBodyLimit is the maximum number of body bytes rendered in a +// compact one-line request/response summary. Keeps the per-attempt match log +// readable when there are many interactions to compare against. +const debugSummaryBodyLimit = 80 + +// summarizeBody returns a single-line, bounded rendering of the given body for +// inclusion in a compact request/response summary. Newlines are collapsed and +// the result is truncated to debugSummaryBodyLimit bytes. +func summarizeBody(b string) string { + if b == "" { + return "" + } + s := strings.ReplaceAll(b, "\n", `\n`) + s = strings.ReplaceAll(s, "\r", `\r`) + if len(s) > debugSummaryBodyLimit { + s = s[:debugSummaryBodyLimit] + "..." + } + + return s +} + +// formatBody returns a human-readable rendering of the given body bytes for +// inclusion in a debug dump. Binary content is replaced with a "" placeholder so that the trace stays readable in a text-based slog +// handler. +func formatBody(b []byte) string { + if len(b) == 0 { + return "" + } + if !isPrintable(b) { + return fmt.Sprintf("", len(b)) + } + if len(b) > debugBodyLimit { + return fmt.Sprintf("%s\n(truncated, %d bytes total)", b[:debugBodyLimit], len(b)) + } + + return string(b) +} + +// isPrintable reports whether b is safe to render as text in a debug trace: +// it must be valid UTF-8 and contain no control characters other than the +// whitespace runes commonly found in HTTP payloads (tab, LF, CR). +func isPrintable(b []byte) bool { + if !utf8.Valid(b) { + return false + } + for _, r := range string(b) { + switch r { + case '\t', '\n', '\r': + continue + } + if !unicode.IsPrint(r) { + return false + } + } + + return true +} + +// dumpHTTPRequest renders an [*http.Request] in wire format for inclusion in a +// debug trace. The request body is consumed and replaced with a fresh reader +// so subsequent code (the matcher, the round-tripper) can still read it. +func dumpHTTPRequest(r *http.Request) string { + if r.Body == nil || r.Body == http.NoBody { + dump, err := httputil.DumpRequest(r, false) + if err != nil { + return fmt.Sprintf("", err) + } + + return string(dump) + } + body, err := io.ReadAll(r.Body) + if err != nil { + return fmt.Sprintf("", err) + } + r.Body = io.NopCloser(bytes.NewReader(body)) + dump, err := httputil.DumpRequest(r, false) + if err != nil { + return fmt.Sprintf("", err) + } + + return fmt.Sprintf("%s\n%s", dump, formatBody(body)) +} + +// dumpCassetteRequest renders a recorded [Request] in a wire-format-like form +// for visual diffing against an [*http.Request] dumped via [dumpHTTPRequest]. +func dumpCassetteRequest(req Request) string { + var b strings.Builder + fmt.Fprintf(&b, "%s %s %s\n", req.Method, req.URL, req.Proto) + fmt.Fprintf(&b, "Host: %s\n", req.Host) + if err := req.Headers.Write(&b); err != nil { + fmt.Fprintf(&b, "
\n", err) + } + b.WriteString("\n") + b.WriteString(formatBody([]byte(req.Body))) + + return b.String() +} + const ( // CassetteFormatVersion is the supported cassette version. CassetteFormatVersion = 2 @@ -85,6 +192,14 @@ type Request struct { Method string `yaml:"method"` } +// String implements [fmt.Stringer]. It renders the recorded request as a +// compact, single-line summary suitable for inclusion in a debug log +// attribute. The body is bounded and stripped of newlines so it fits cleanly +// in a key=value line. +func (r Request) String() string { + return fmt.Sprintf("%s %s body=%q", r.Method, r.URL, summarizeBody(r.Body)) +} + // Response represents a server response as recorded in the cassette file. type Response struct { Proto string `yaml:"proto"` @@ -111,6 +226,13 @@ type Response struct { Duration time.Duration `yaml:"duration"` } +// String implements [fmt.Stringer]. It renders the recorded response as a +// compact, single-line summary suitable for inclusion in a debug log +// attribute. +func (r Response) String() string { + return fmt.Sprintf("%d body=%q", r.Code, summarizeBody(r.Body)) +} + // Interaction type contains a pair of request/response for a single HTTP // interaction between a client and a server. type Interaction struct { @@ -279,7 +401,7 @@ func (m *defaultMatcher) bodyMatches(r *http.Request, i Request) bool { return false } - r.Body = io.NopCloser(bytes.NewBuffer(buffer.Bytes())) + r.Body = io.NopCloser(bytes.NewReader(buffer.Bytes())) if buffer.String() != i.Body { return false } @@ -372,7 +494,7 @@ var DefaultMatcher = NewDefaultMatcher() // Cassette represents a cassette containing recorded interactions. type Cassette struct { - sync.Mutex `yaml:"-"` + mu sync.Mutex `yaml:"-"` // Name of the cassette Name string `yaml:"-"` @@ -402,6 +524,10 @@ type Cassette struct { // MarshalFunc is a custom marshal func. MarshalFunc MarshalFunc `yaml:"-"` + + // DebugLogger is an [slog.Logger] which is used to emit debug events. + // To enable debugging, see [recorder.WithDebugWriter] option. + DebugLogger *slog.Logger `yaml:"-"` } // New creates a new empty cassette @@ -415,6 +541,7 @@ func New(name string) *Cassette { ReplayableInteractions: false, IsNew: true, nextInteractionId: 0, + DebugLogger: slog.New(slog.DiscardHandler), } return c @@ -448,11 +575,16 @@ func LoadWithFS(name string, fs FS) (*Cassette, error) { // AddInteraction appends a new interaction to the cassette func (c *Cassette) AddInteraction(i *Interaction) { - c.Lock() - defer c.Unlock() + c.mu.Lock() + defer c.mu.Unlock() i.ID = c.nextInteractionId c.nextInteractionId += 1 c.Interactions = append(c.Interactions, i) + c.debug("interaction added", + "id", i.ID, + "request", i.Request, + "response", i.Response, + ) } // GetInteraction retrieves a recorded request/response interaction @@ -460,26 +592,57 @@ func (c *Cassette) GetInteraction(r *http.Request) (*Interaction, error) { return c.getInteraction(r) } +// debug emits a debug event +func (c *Cassette) debug(msg string, args ...any) { + c.DebugLogger.Debug(msg, args...) +} + // getInteraction searches for the interaction corresponding to the given HTTP // request, by using the configured [MatcherFunc]. func (c *Cassette) getInteraction(r *http.Request) (*Interaction, error) { - c.Lock() - defer c.Unlock() + c.mu.Lock() + defer c.mu.Unlock() if r.Body == nil { // causes an error in the matcher when we try to do r.ParseForm if r.Body is nil // r.ParseForm returns missing form body error r.Body = http.NoBody } + c.debug("matching request", + "method", r.Method, + "url", r.URL, + "host", r.Host, + "dump", dumpHTTPRequest(r), + ) replayed := 0 for _, i := range c.Interactions { if i.replayed { replayed++ } - if (c.ReplayableInteractions || !i.replayed) && c.Matcher(r, i.Request) { + eligible := c.ReplayableInteractions || !i.replayed + matched := eligible && c.Matcher(r, i.Request) + attrs := []any{ + "id", i.ID, + "already_replayed", i.replayed, + "eligible", eligible, + "matched", matched, + "request", i.Request, + } + if !matched && eligible { + attrs = append(attrs, "dump", dumpCassetteRequest(i.Request)) + } + c.debug("match attempt", attrs...) + if matched { i.replayed = true + c.debug("match found", + "id", i.ID, + "request", i.Request, + ) + return i, nil } } + c.debug("no match", "already_replayed_count", replayed) + return nil, ErrInteractionNotFound } @@ -490,8 +653,9 @@ func (c *Cassette) Save() error { // SaveWithFS writes the cassette data on abstract filesystem for future re-use func (c *Cassette) SaveWithFS(fs FS) error { - c.Lock() - defer c.Unlock() + c.mu.Lock() + defer c.mu.Unlock() + c.debug("saving cassette", "interaction_count", len(c.Interactions)) // Filter out interactions which should be discarded. While discarding // interactions we should also fix the interaction IDs, so that we don't @@ -499,7 +663,9 @@ func (c *Cassette) SaveWithFS(fs FS) error { nextId := 0 interactions := make([]*Interaction, 0) for _, i := range c.Interactions { - if !i.DiscardOnSave { + if i.DiscardOnSave { + c.debug("discarding interaction", "id", i.ID) + } else { i.ID = nextId interactions = append(interactions, i) nextId += 1 @@ -515,5 +681,11 @@ func (c *Cassette) SaveWithFS(fs FS) error { // Honor the YAML structure specification // http://www.yaml.org/spec/1.2/spec.html#id2760395 - return fs.WriteFile(c.File, append([]byte("---\n"), data...)) + payload := append([]byte("---\n"), data...) + if err := fs.WriteFile(c.File, payload); err != nil { + return err + } + c.debug("cassette saved", "bytes_written", len(payload), "interactions_saved", len(c.Interactions)) + + return nil } diff --git a/pkg/cassette/cassette_test.go b/pkg/cassette/cassette_test.go index cefbe6c..17e1e13 100644 --- a/pkg/cassette/cassette_test.go +++ b/pkg/cassette/cassette_test.go @@ -29,6 +29,7 @@ import ( "io" "net/http" "net/url" + "slices" "strings" "testing" ) @@ -293,3 +294,203 @@ func TestMatcher(t *testing.T) { }) }) } + +func TestIsPrintable(t *testing.T) { + t.Run("empty", func(t *testing.T) { + if !isPrintable(nil) { + t.Fatalf("nil should be printable") + } + if !isPrintable([]byte{}) { + t.Fatalf("empty slice should be printable") + } + }) + + t.Run("plain ASCII", func(t *testing.T) { + if !isPrintable([]byte("hello world")) { + t.Fatalf("plain ASCII should be printable") + } + }) + + t.Run("HTTP whitespace runes are allowed", func(t *testing.T) { + if !isPrintable([]byte("a\tb\nc\rd")) { + t.Fatalf("tab, LF and CR should be allowed") + } + }) + + t.Run("NUL is not printable", func(t *testing.T) { + if isPrintable([]byte{'a', 0x00, 'b'}) { + t.Fatalf("NUL byte should not be printable") + } + }) + + t.Run("other control chars are not printable", func(t *testing.T) { + if isPrintable([]byte{'a', 0x01, 'b'}) { + t.Fatalf("0x01 should not be printable") + } + if isPrintable([]byte{'a', 0x1F, 'b'}) { + t.Fatalf("0x1F should not be printable") + } + }) + + t.Run("invalid UTF-8 is not printable", func(t *testing.T) { + if isPrintable([]byte{0xFF, 0xFE, 0xFD}) { + t.Fatalf("invalid UTF-8 should not be printable") + } + }) + + t.Run("valid multi-byte UTF-8 is printable", func(t *testing.T) { + if !isPrintable([]byte("héllo wörld")) { + t.Fatalf("valid multi-byte UTF-8 should be printable") + } + }) +} + +func TestFormatBody(t *testing.T) { + t.Run("empty body renders as empty string", func(t *testing.T) { + if got := formatBody(nil); got != "" { + t.Fatalf("got %q, want empty string", got) + } + if got := formatBody([]byte{}); got != "" { + t.Fatalf("got %q, want empty string", got) + } + }) + + t.Run("plain text is rendered verbatim", func(t *testing.T) { + in := []byte("hello world") + if got := formatBody(in); got != "hello world" { + t.Fatalf("got %q, want %q", got, "hello world") + } + }) + + t.Run("binary body renders as placeholder", func(t *testing.T) { + in := []byte{0x00, 0x01, 0x02, 0x03} + want := fmt.Sprintf("", len(in)) + if got := formatBody(in); got != want { + t.Fatalf("got %q, want %q", got, want) + } + }) + + t.Run("body larger than debugBodyLimit is truncated", func(t *testing.T) { + in := slices.Repeat([]byte{'a'}, debugBodyLimit+128) + got := formatBody(in) + if !strings.HasPrefix(got, strings.Repeat("a", debugBodyLimit)) { + t.Fatalf("truncated body does not start with the first debugBodyLimit bytes") + } + wantSuffix := fmt.Sprintf("(truncated, %d bytes total)", len(in)) + if !strings.HasSuffix(got, wantSuffix) { + t.Fatalf("got %q, want suffix %q", got, wantSuffix) + } + }) +} + +func TestSummarizeBody(t *testing.T) { + t.Run("empty body", func(t *testing.T) { + if got := summarizeBody(""); got != "" { + t.Fatalf("got %q, want empty string", got) + } + }) + + t.Run("plain body is returned unchanged", func(t *testing.T) { + if got := summarizeBody("hello"); got != "hello" { + t.Fatalf("got %q, want %q", got, "hello") + } + }) + + t.Run("newlines are escaped", func(t *testing.T) { + got := summarizeBody("foo\nbar\rbaz") + want := `foo\nbar\rbaz` + if got != want { + t.Fatalf("got %q, want %q", got, want) + } + }) + + t.Run("oversized body is truncated", func(t *testing.T) { + in := strings.Repeat("a", debugSummaryBodyLimit+10) + got := summarizeBody(in) + want := strings.Repeat("a", debugSummaryBodyLimit) + "..." + if got != want { + t.Fatalf("got %q, want %q", got, want) + } + }) +} + +func TestSummarizeCassetteRequest(t *testing.T) { + req := Request{ + Method: "GET", + URL: "https://example.com/foo", + Body: "", + } + want := `GET https://example.com/foo body=""` + if got := req.String(); got != want { + t.Fatalf("got %q, want %q", got, want) + } +} + +func TestSummarizeCassetteResponse(t *testing.T) { + resp := Response{ + Code: 200, + Body: "ok", + } + want := `200 body="ok"` + if got := resp.String(); got != want { + t.Fatalf("got %q, want %q", got, want) + } +} + +func TestDumpHTTPRequestRestoresBody(t *testing.T) { + t.Run("nil body", func(t *testing.T) { + r, err := http.NewRequest(http.MethodGet, "http://example.com/", nil) + if err != nil { + t.Fatal(err) + } + got := dumpHTTPRequest(r) + if !strings.Contains(got, "GET / HTTP/1.1") { + t.Fatalf("dump missing request line: %q", got) + } + }) + + t.Run("body is restored and dump contains it", func(t *testing.T) { + body := "hello world" + r, err := http.NewRequest(http.MethodPost, "http://example.com/", strings.NewReader(body)) + if err != nil { + t.Fatal(err) + } + got := dumpHTTPRequest(r) + if !strings.Contains(got, body) { + t.Fatalf("dump %q does not contain body %q", got, body) + } + // The body must still be readable by subsequent code (the matcher, + // the round-tripper, etc.). + read, err := io.ReadAll(r.Body) + if err != nil { + t.Fatalf("body unreadable after dump: %v", err) + } + if string(read) != body { + t.Fatalf("got body %q after dump, want %q", string(read), body) + } + }) +} + +func TestDumpCassetteRequest(t *testing.T) { + req := Request{ + Method: "POST", + URL: "https://example.com/v1", + Proto: "HTTP/1.1", + Host: "example.com", + Headers: http.Header{"Content-Type": {"application/json"}}, + Body: `{"x":1}`, + } + got := dumpCassetteRequest(req) + if !strings.Contains(got, "POST https://example.com/v1 HTTP/1.1") { + t.Fatalf("dump missing request line: %q", got) + } + if !strings.Contains(got, "Host: example.com") { + t.Fatalf("dump missing Host header: %q", got) + } + if !strings.Contains(got, "Content-Type: application/json") { + t.Fatalf("dump missing Content-Type header: %q", got) + } + if !strings.Contains(got, `{"x":1}`) { + t.Fatalf("dump missing body: %q", got) + } +} diff --git a/pkg/recorder/middleware.go b/pkg/recorder/middleware.go index f5ed5c3..5c0adcb 100644 --- a/pkg/recorder/middleware.go +++ b/pkg/recorder/middleware.go @@ -10,6 +10,10 @@ import ( // HTTPMiddleware intercepts and records all incoming requests and the server's response func (rec *Recorder) HTTPMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + rec.debug("server request received", + "method", r.Method, + "url", r.URL, + ) ww := newPassthrough(w) // Tee the body so it can be read by the next handler and by the recorder diff --git a/pkg/recorder/recorder.go b/pkg/recorder/recorder.go index b5e1131..167f4d5 100644 --- a/pkg/recorder/recorder.go +++ b/pkg/recorder/recorder.go @@ -31,8 +31,12 @@ import ( "errors" "fmt" "io" + "log/slog" "net/http" "net/http/httputil" + "os" + "slices" + "strconv" "time" "go.yaml.in/yaml/v4" @@ -85,6 +89,24 @@ const ( ModePassthrough ) +// String implements the [fmt.Stringer] interface for [Mode]. +func (m Mode) String() string { + switch m { + case ModeRecordOnly: + return "RecordOnly" + case ModeReplayOnly: + return "ReplayOnly" + case ModeReplayWithNewEpisodes: + return "ReplayWithNewEpisodes" + case ModeRecordOnce: + return "RecordOnce" + case ModePassthrough: + return "Passthrough" + default: + return fmt.Sprintf("Mode(%d)", m) + } +} + // ErrInvalidMode is returned when attempting to start the recorder with invalid // mode var ErrInvalidMode = errors.New("invalid recorder mode") @@ -120,6 +142,22 @@ const ( OnRecorderStopHook ) +// String implements the [fmt.Stringer] interface for [HookKind]. +func (hk HookKind) String() string { + switch hk { + case AfterCaptureHook: + return "AfterCapture" + case BeforeSaveHook: + return "BeforeSave" + case BeforeResponseReplayHook: + return "BeforeResponseReplay" + case OnRecorderStopHook: + return "OnRecorderStop" + default: + return fmt.Sprintf("HookKind(%d)", hk) + } +} + // Hook represents a function hook of a given kind. Depending on the hook kind, // the function will be invoked in different stages of the playback. type Hook struct { @@ -152,16 +190,24 @@ var ErrUnsafeRequestMethod = errors.New("request uses an unsafe method") type blockUnsafeMethodsRoundTripper struct { RoundTripper http.RoundTripper + debugLogger *slog.Logger +} + +// safeMethods enumerates the HTTP methods that are considered safe per +// RFC 9110, section 9.2.1. +var safeMethods = []string{ + http.MethodGet, + http.MethodHead, + http.MethodOptions, + http.MethodTrace, } func (r *blockUnsafeMethodsRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) { - safeMethods := map[string]bool{ - http.MethodGet: true, - http.MethodHead: true, - http.MethodOptions: true, - http.MethodTrace: true, - } - if _, ok := safeMethods[req.Method]; !ok { + if !slices.Contains(safeMethods, req.Method) { + r.debugLogger.Debug("unsafe method blocked", + "method", req.Method, + "url", req.URL.String(), + ) return nil, ErrUnsafeRequestMethod } return r.RoundTripper.RoundTrip(req) @@ -211,7 +257,14 @@ type Recorder struct { // fs specifies custom filesystem ([cassette.FS]) implementation. fs cassette.FS + // marshalFunc is the [cassette.MarshalFunc] which is called for + // encoding the cassette. marshalFunc cassette.MarshalFunc + + // debugWriter and debugLogger are used for emitting debug events by the + // recorder. + debugWriter io.Writer + debugLogger *slog.Logger } // Option is a function which configures the [Recorder]. @@ -305,9 +358,10 @@ func WithReplayableInteractions(val bool) Option { return opt } -// WithFS is an [Option], which configures the [Recorder] to use -// custom filesystem ([cassette.FS]) implementation. This allows the [Recorder] to use any -// FS-compatible backend (e.g., local disk, in-memory, or mock) for reading and writing files. +// WithFS is an [Option], which configures the [Recorder] to use custom +// filesystem ([cassette.FS]) implementation. This allows the [Recorder] to use +// any FS-compatible backend (e.g., local disk, in-memory, or mock) for reading +// and writing files. func WithFS(fs cassette.FS) Option { opt := func(r *Recorder) { r.fs = fs @@ -316,15 +370,25 @@ func WithFS(fs cassette.FS) Option { return opt } -// WithMarshalFunc is an [Option], which configures the [Recorder] to use -// custom YAML marshal func. This allows customization of the YAML encoding -// process, such as setting string literal style, etc. +// WithMarshalFunc is an [Option], which configures the [Recorder] to use custom +// YAML marshal func. This allows customization of the YAML encoding process, +// such as setting string literal style, etc. func WithMarshalFunc(marshalFunc cassette.MarshalFunc) Option { return func(r *Recorder) { r.marshalFunc = marshalFunc } } +// WithDebugWriter is an [Option], which configures the [Recorder] to use the +// given [io.Writer] for recording debug events. +func WithDebugWriter(w io.Writer) Option { + opt := func(r *Recorder) { + r.debugWriter = w + } + + return opt +} + // New creates a new [Recorder] and configures it using the provided options. func New(cassetteName string, opts ...Option) (*Recorder, error) { r := &Recorder{ @@ -339,6 +403,7 @@ func New(cassetteName string, opts ...Option) (*Recorder, error) { replayableInteractions: false, fs: cassette.NewDiskFS(), marshalFunc: yaml.Marshal, + debugWriter: io.Discard, } for _, opt := range opts { @@ -350,62 +415,108 @@ func New(cassetteName string, opts ...Option) (*Recorder, error) { if err != nil { return nil, err } + r.cassette = c r.cassette.Matcher = r.matcher r.cassette.ReplayableInteractions = r.replayableInteractions r.cassette.MarshalFunc = r.marshalFunc + // Configure debug logger to [os.Stderr] if `VCR_DEBUG' env var is set, + // and the current debug writer is [io.Discard]. That way tests which + // configure their own debug writers will not be affected, but tests + // that don't explicitly set it will get one for free. + ok, _ := strconv.ParseBool(os.Getenv("VCR_DEBUG")) + if ok && r.debugWriter == io.Discard { + r.debugWriter = os.Stderr + } + + logHandler := slog.NewTextHandler(r.debugWriter, &slog.HandlerOptions{Level: slog.LevelDebug}) + r.debugLogger = slog.New(logHandler).With( + "component", "recorder", + "mode", r.mode.String(), + ) + r.cassette.DebugLogger = slog.New(logHandler).With( + "component", "cassette", + "file", r.cassette.File, + ) + + if !r.cassette.IsNew { + r.cassette.DebugLogger.Debug("cassette loaded", + "version", r.cassette.Version, + "interaction_count", len(r.cassette.Interactions), + ) + } + + r.debug("recorder initialized", + "cassette_name", r.cassette.Name, + "cassette_file", r.cassette.File, + "is_new_cassette", r.cassette.IsNew, + "interaction_count", len(r.cassette.Interactions), + "replayable_interactions", r.replayableInteractions, + "block_unsafe_methods", r.blockUnsafeMethods, + "skip_request_latency", r.skipRequestLatency, + "passthroughs", len(r.passthroughs), + "hooks", len(r.hooks), + ) + return r, nil } +// debug emits a debug event +func (r *Recorder) debug(msg string, args ...any) { + r.debugLogger.Debug(msg, args...) +} + // getCassette creates a new [*cassette.Cassette], or loads an already existing // one depending on the mode of the recorder. -func (rec *Recorder) getCassette() (*cassette.Cassette, error) { - if rec.cassetteName == "" { +func (r *Recorder) getCassette() (*cassette.Cassette, error) { + if r.cassetteName == "" { return nil, ErrNoCassetteName } // Create or the cassette depending on the mode we are operating in. - cassetteFile := cassette.New(rec.cassetteName).File - cassetteExists := rec.fs.IsFileExists(cassetteFile) + cassetteFile := cassette.New(r.cassetteName).File + cassetteExists := r.fs.IsFileExists(cassetteFile) switch { - case rec.mode == ModeRecordOnly: - return cassette.New(rec.cassetteName), nil - case rec.mode == ModeReplayOnly && !cassetteExists: + case r.mode == ModeRecordOnly: + return cassette.New(r.cassetteName), nil + case r.mode == ModeReplayOnly && !cassetteExists: return nil, fmt.Errorf("%w: %s", cassette.ErrCassetteNotFound, cassetteFile) - case rec.mode == ModeReplayOnly && cassetteExists: - return cassette.LoadWithFS(rec.cassetteName, rec.fs) - case rec.mode == ModeReplayWithNewEpisodes && !cassetteExists: - return cassette.New(rec.cassetteName), nil - case rec.mode == ModeReplayWithNewEpisodes && cassetteExists: - return cassette.LoadWithFS(rec.cassetteName, rec.fs) - case rec.mode == ModeRecordOnce && !cassetteExists: - return cassette.New(rec.cassetteName), nil - case rec.mode == ModeRecordOnce && cassetteExists: - return cassette.LoadWithFS(rec.cassetteName, rec.fs) - case rec.mode == ModePassthrough: - return cassette.New(rec.cassetteName), nil + case r.mode == ModeReplayOnly && cassetteExists: + return cassette.LoadWithFS(r.cassetteName, r.fs) + case r.mode == ModeReplayWithNewEpisodes && !cassetteExists: + return cassette.New(r.cassetteName), nil + case r.mode == ModeReplayWithNewEpisodes && cassetteExists: + return cassette.LoadWithFS(r.cassetteName, r.fs) + case r.mode == ModeRecordOnce && !cassetteExists: + return cassette.New(r.cassetteName), nil + case r.mode == ModeRecordOnce && cassetteExists: + return cassette.LoadWithFS(r.cassetteName, r.fs) + case r.mode == ModePassthrough: + return cassette.New(r.cassetteName), nil default: return nil, ErrInvalidMode } } // getRoundTripper returns the [http.RoundTripper] used by the recorder. -func (rec *Recorder) getRoundTripper() http.RoundTripper { - if rec.blockUnsafeMethods { +func (r *Recorder) getRoundTripper() http.RoundTripper { + if r.blockUnsafeMethods { return &blockUnsafeMethodsRoundTripper{ - RoundTripper: rec.realTransport, + RoundTripper: r.realTransport, + debugLogger: r.debugLogger, } } - return rec.realTransport + return r.realTransport } // requestHandler proxies requests to their original destination // If serverResponse is provided, this is used for the recording instead of using RoundTrip func (rec *Recorder) requestHandler(r *http.Request, serverResponse *http.Response) (*cassette.Interaction, error) { if err := r.Context().Err(); err != nil { + rec.debug("request cancelled before handling", "error", err) return nil, err } @@ -419,6 +530,7 @@ func (rec *Recorder) requestHandler(r *http.Request, serverResponse *http.Respon return interaction, nil } else if errors.Is(err, cassette.ErrInteractionNotFound) { // Interaction not found, we have a new episode + rec.debug("no match, will record new episode") break } else { // Any other error is an error @@ -426,6 +538,7 @@ func (rec *Recorder) requestHandler(r *http.Request, serverResponse *http.Respon } case rec.mode == ModeRecordOnce && !rec.cassette.IsNew: // We've got an existing cassette, return what we've got + rec.debug("replaying from existing cassette") return rec.cassette.GetInteraction(r) case rec.mode == ModePassthrough: // Passthrough requests always hit the original endpoint @@ -434,12 +547,14 @@ func (rec *Recorder) requestHandler(r *http.Request, serverResponse *http.Respon // When running with replayable interactions look for existing // interaction first, so we avoid hitting multiple times the // same endpoint. + rec.debug("checking cassette before recording (replayable interactions enabled)") interaction, err := rec.cassette.GetInteraction(r) if err == nil { // Interaction found, return it return interaction, nil } else if errors.Is(err, cassette.ErrInteractionNotFound) { // Interaction not found, we have to record it + rec.debug("no match, will record") break } else { // Any other error is an error @@ -483,13 +598,30 @@ func (rec *Recorder) requestHandler(r *http.Request, serverResponse *http.Respon var start time.Time start = time.Now() resp := serverResponse - if resp == nil { + switch resp { + case nil: + rec.debug("forwarding to real transport", + "method", r.Method, + "url", r.URL.String(), + ) resp, err = rec.getRoundTripper().RoundTrip(r) if err != nil { + rec.debug("real transport error", "error", err) return nil, err } + default: + rec.debug("got handler response", + "method", r.Method, + "url", r.URL.String(), + "status", resp.StatusCode, + ) } requestDuration := time.Since(start) + rec.debug("response received", + "status", resp.StatusCode, + "duration_ms", requestDuration.Milliseconds(), + "content_length", resp.ContentLength, + ) defer resp.Body.Close() respBody, err := io.ReadAll(resp.Body) @@ -545,26 +677,31 @@ func (rec *Recorder) requestHandler(r *http.Request, serverResponse *http.Respon // Stop is used to stop the recorder and save any recorded // interactions if running in one of the recording modes. When // running in ModePassthrough no cassette will be saved on disk. -func (rec *Recorder) Stop() error { - cassetteFile := rec.cassette.File - cassetteExists := rec.fs.IsFileExists(cassetteFile) +func (r *Recorder) Stop() error { + r.debug("stopping recorder") + cassetteFile := r.cassette.File + cassetteExists := r.fs.IsFileExists(cassetteFile) // Nothing to do for ModeReplayOnly and ModePassthrough here switch { - case rec.mode == ModeRecordOnly || rec.mode == ModeReplayWithNewEpisodes: - if err := rec.persistCassette(); err != nil { + case r.mode == ModeRecordOnly || r.mode == ModeReplayWithNewEpisodes: + r.debug("persisting cassette", "reason", "recording mode") + if err := r.persistCassette(); err != nil { return err } - case rec.mode == ModeRecordOnce && !cassetteExists: - if err := rec.persistCassette(); err != nil { + case r.mode == ModeRecordOnce && !cassetteExists: + r.debug("persisting cassette", "reason", "record_once with new cassette") + if err := r.persistCassette(); err != nil { return err } + default: + r.debug("skipping persist", "reason", "replay or existing cassette") } // Apply on-recorder-stop hooks - for _, interaction := range rec.cassette.Interactions { - if err := rec.applyHooks(interaction, OnRecorderStopHook); err != nil { + for _, interaction := range r.cassette.Interactions { + if err := r.applyHooks(interaction, OnRecorderStopHook); err != nil { return err } } @@ -573,25 +710,28 @@ func (rec *Recorder) Stop() error { } // persisteCassette persists the cassette on disk for future re-use -func (rec *Recorder) persistCassette() error { +func (r *Recorder) persistCassette() error { // Apply any before-save hooks - for _, interaction := range rec.cassette.Interactions { - if err := rec.applyHooks(interaction, BeforeSaveHook); err != nil { + for _, interaction := range r.cassette.Interactions { + if err := r.applyHooks(interaction, BeforeSaveHook); err != nil { return err } } - return rec.cassette.SaveWithFS(rec.fs) + return r.cassette.SaveWithFS(r.fs) } // applyHooks applies the registered hooks of the given kind with the // specified interaction -func (rec *Recorder) applyHooks(i *cassette.Interaction, kind HookKind) error { - for _, hook := range rec.hooks { - if hook.Kind == kind { - if err := hook.Handler(i); err != nil { - return err - } +func (r *Recorder) applyHooks(i *cassette.Interaction, kind HookKind) error { + for _, hook := range r.hooks { + if hook.Kind != kind { + continue + } + r.debug("applying hook", "kind", kind, "id", i.ID) + if err := hook.Handler(i); err != nil { + r.debug("hook returned error", "kind", kind, "id", i.ID, "error", err) + return err } } @@ -599,57 +739,74 @@ func (rec *Recorder) applyHooks(i *cassette.Interaction, kind HookKind) error { } // RoundTrip implements the [http.RoundTripper] interface -func (rec *Recorder) RoundTrip(req *http.Request) (*http.Response, error) { - return rec.executeAndRecord(req, nil) +func (r *Recorder) RoundTrip(req *http.Request) (*http.Response, error) { + r.debug("request received", + "method", req.Method, + "url", req.URL.String(), + "host", req.Host, + ) + + return r.executeAndRecord(req, nil) } // executeAndRecord is used internally by the HTTPMiddleware to allow recording a response on the server side -func (rec *Recorder) executeAndRecord(req *http.Request, serverResponse *http.Response) (*http.Response, error) { +func (r *Recorder) executeAndRecord(req *http.Request, serverResponse *http.Response) (*http.Response, error) { // Passthrough mode, use real transport - if rec.mode == ModePassthrough { - return rec.getRoundTripper().RoundTrip(req) + if r.mode == ModePassthrough { + r.debug("passthrough mode, bypassing cassette") + return r.getRoundTripper().RoundTrip(req) } // Apply passthrough handler functions - for _, passthroughFunc := range rec.passthroughs { + for i, passthroughFunc := range r.passthroughs { if passthroughFunc(req) { - return rec.getRoundTripper().RoundTrip(req) + r.debug("passthrough func matched", "index", i) + return r.getRoundTripper().RoundTrip(req) } } - interaction, err := rec.requestHandler(req, serverResponse) + interaction, err := r.requestHandler(req, serverResponse) if err != nil { return nil, err } // Apply before-response-replay hooks - if err := rec.applyHooks(interaction, BeforeResponseReplayHook); err != nil { + if err := r.applyHooks(interaction, BeforeResponseReplayHook); err != nil { return nil, err } select { case <-req.Context().Done(): - return nil, req.Context().Err() + err := req.Context().Err() + r.debug("request cancelled during replay", "error", err) + return nil, err default: // Apply the duration defined in the interaction - if !rec.skipRequestLatency { + if !r.skipRequestLatency { + r.debug("simulating latency", "duration_ms", interaction.Response.Duration.Milliseconds()) <-time.After(interaction.Response.Duration) } + r.debug("replaying response", + "id", interaction.ID, + "status", interaction.Response.Code, + "response", interaction.Response, + ) + return interaction.GetHTTPResponse() } } // Mode returns recorder state -func (rec *Recorder) Mode() Mode { - return rec.mode +func (r *Recorder) Mode() Mode { + return r.mode } // GetDefaultClient returns an HTTP client with a pre-configured // transport -func (rec *Recorder) GetDefaultClient() *http.Client { +func (r *Recorder) GetDefaultClient() *http.Client { client := &http.Client{ - Transport: rec, + Transport: r, } return client @@ -658,8 +815,8 @@ func (rec *Recorder) GetDefaultClient() *http.Client { // IsNewCassette returns true, if the recorder was started with a // new/empty cassette. Returns false, if it was started using an // existing cassette, which was loaded. -func (rec *Recorder) IsNewCassette() bool { - return rec.cassette.IsNew +func (r *Recorder) IsNewCassette() bool { + return r.cassette.IsNew } // IsRecording returns true, if the recorder is recording @@ -672,13 +829,13 @@ func (rec *Recorder) IsNewCassette() bool { // present in the cassette, but will also record new ones, if they are // not part of the cassette already. In these cases the recorder is // considered to be recording for these modes. -func (rec *Recorder) IsRecording() bool { +func (r *Recorder) IsRecording() bool { switch { - case rec.mode == ModeRecordOnly || rec.mode == ModeReplayWithNewEpisodes: + case r.mode == ModeRecordOnly || r.mode == ModeReplayWithNewEpisodes: return true - case rec.mode == ModeReplayOnly || rec.mode == ModePassthrough: + case r.mode == ModeReplayOnly || r.mode == ModePassthrough: return false - case rec.mode == ModeRecordOnce && rec.IsNewCassette(): + case r.mode == ModeRecordOnce && r.IsNewCassette(): return true default: return false diff --git a/pkg/recorder/recorder_test.go b/pkg/recorder/recorder_test.go index f1e077b..dffff55 100644 --- a/pkg/recorder/recorder_test.go +++ b/pkg/recorder/recorder_test.go @@ -53,7 +53,7 @@ type testCase struct { } func (tc testCase) run(ctx context.Context, client *http.Client, serverUrl string) error { - url := fmt.Sprintf("%s%s", serverUrl, tc.path) + url := serverUrl + tc.path req, err := http.NewRequest(tc.method, url, strings.NewReader(tc.body)) if err != nil { return err @@ -1358,3 +1358,164 @@ func TestRecordAndPlaybackWithQueryParams(t *testing.T) { } }() } + +func TestDebugWriterCapturesEvents(t *testing.T) { + t.Parallel() + + server := newEchoHttpServer() + defer server.Close() + + cassPath := t.TempDir() + var buf bytes.Buffer + + rec, err := recorder.New(cassPath, recorder.WithDebugWriter(&buf)) + if err != nil { + t.Fatal(err) + } + + // Drive a request through so the per-request and match events fire. + client := rec.GetDefaultClient() + req, err := http.NewRequest(http.MethodGet, server.URL+"/api/v1/foo", nil) + if err != nil { + t.Fatal(err) + } + resp, err := client.Do(req) + if err != nil { + t.Fatal(err) + } + resp.Body.Close() + + if err := rec.Stop(); err != nil { + t.Fatal(err) + } + + out := buf.String() + for _, want := range []string{ + "recorder initialized", + "request received", + "forwarding to real transport", + "interaction added", + } { + if !strings.Contains(out, want) { + t.Fatalf("debug output missing %q\n--- output ---\n%s", want, out) + } + } +} + +func TestDebugWriterDefaultIsDiscard(t *testing.T) { + // Cannot t.Parallel() because we set VCR_DEBUG via t.Setenv. + + // Make sure VCR_DEBUG does not leak in from the surrounding environment. + t.Setenv("VCR_DEBUG", "") + + server := newEchoHttpServer() + defer server.Close() + + cassPath := t.TempDir() + + rec, err := recorder.New(cassPath) + if err != nil { + t.Fatal(err) + } + + client := rec.GetDefaultClient() + req, err := http.NewRequest(http.MethodGet, server.URL+"/api/v1/foo", nil) + if err != nil { + t.Fatal(err) + } + resp, err := client.Do(req) + if err != nil { + t.Fatal(err) + } + resp.Body.Close() + + if err := rec.Stop(); err != nil { + t.Fatal(err) + } + // Nothing observable to assert here other than the recorder didn't + // crash with the default io.Discard writer. The absence of stderr + // output is the contract; we cannot directly capture os.Stderr from + // here without process-wide redirection. +} + +func TestVCRDebugEnvEnablesStderr(t *testing.T) { + // Cannot t.Parallel() because t.Setenv and os.Stderr redirection are + // process-wide. + t.Setenv("VCR_DEBUG", "true") + + // Redirect os.Stderr so we can observe the trace. + origStderr := os.Stderr + r, w, err := os.Pipe() + if err != nil { + t.Fatal(err) + } + os.Stderr = w + defer func() { os.Stderr = origStderr }() + + server := newEchoHttpServer() + defer server.Close() + + rec, err := recorder.New(t.TempDir()) + if err != nil { + t.Fatal(err) + } + + client := rec.GetDefaultClient() + req, err := http.NewRequest(http.MethodGet, server.URL+"/api/v1/foo", nil) + if err != nil { + t.Fatal(err) + } + resp, err := client.Do(req) + if err != nil { + t.Fatal(err) + } + resp.Body.Close() + if err := rec.Stop(); err != nil { + t.Fatal(err) + } + + // Close the writer so the reader sees EOF. + w.Close() + out, err := io.ReadAll(r) + if err != nil { + t.Fatal(err) + } + + if !strings.Contains(string(out), "recorder initialized") { + t.Fatalf("expected VCR_DEBUG=true to enable stderr debug trace, got:\n%s", string(out)) + } +} + +func TestVCRDebugEnvOverriddenByWithDebugWriter(t *testing.T) { + // Cannot t.Parallel() because we set VCR_DEBUG via t.Setenv. + t.Setenv("VCR_DEBUG", "true") + + var buf bytes.Buffer + server := newEchoHttpServer() + defer server.Close() + + rec, err := recorder.New(t.TempDir(), recorder.WithDebugWriter(&buf)) + if err != nil { + t.Fatal(err) + } + + client := rec.GetDefaultClient() + req, err := http.NewRequest(http.MethodGet, server.URL+"/api/v1/foo", nil) + if err != nil { + t.Fatal(err) + } + resp, err := client.Do(req) + if err != nil { + t.Fatal(err) + } + resp.Body.Close() + if err := rec.Stop(); err != nil { + t.Fatal(err) + } + + // The explicit WithDebugWriter must win over VCR_DEBUG, so the trace + // is in the buffer. + if !strings.Contains(buf.String(), "recorder initialized") { + t.Fatalf("WithDebugWriter should have received the trace, got buf:\n%s", buf.String()) + } +}