From ca83a233929eb4f88beb2ff3e0e001946b3e329d Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 3 Dec 2025 22:36:17 +0000 Subject: [PATCH 1/8] feat: forward t.Logf() output to testing.T on property test failures Property tests now capture logs from t.Logf() and include them in the error output when a test fails. This gives users debugging capability while avoiding log spam from successful iterations. Changes: - Add testingT field and logs slice to specta.T struct - Modify T.Logf() to capture messages instead of being a no-op - Pass outer testing.T when creating T instances in Property() - Forward captured logs in reportFailure() for shrunk counterexample - Add t.Helper() to Draw() function for better stack traces - Add comprehensive tests for log forwarding behavior Logs are only shown for the final shrunk failing iteration, which provides useful debugging context without cluttering test output. --- generator.go | 2 + property.go | 28 +++++++++--- property_logf_test.go | 102 ++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 126 insertions(+), 6 deletions(-) create mode 100644 property_logf_test.go diff --git a/generator.go b/generator.go index 8441501..da283d3 100644 --- a/generator.go +++ b/generator.go @@ -26,6 +26,8 @@ type Gen[T any] = conjecture.Gen[T] // - Programming errors (invalid constraints, frozen data) panic with clear messages // - Filtering errors (overrun during replay, assumption failures) trigger skipTest to skip the iteration func Draw[V any](t *T, gen Gen[V], label string) V { + t.Helper() // Mark as test helper for better error reporting + // Create a span for labeled draws var spanID int if label != "" { diff --git a/property.go b/property.go index e34da05..5d2e423 100644 --- a/property.go +++ b/property.go @@ -14,10 +14,12 @@ import ( // Unlike testing.T, calling Fatalf does not immediately terminate the test process, // but instead panics with a sentinel value to stop the current property iteration. type T struct { - failed bool - errors []string - Data *conjecture.ConjectureData // ConjectureData for drawing values - Source Source // Deprecated: kept for backward compatibility, will panic if used + testingT TestingT // Reference to outer testing.T for forwarding logs on failure + failed bool + errors []string + logs []string // Captured log messages from this iteration + Data *conjecture.ConjectureData // ConjectureData for drawing values + Source Source // Deprecated: kept for backward compatibility, will panic if used // Track generated values for error reporting generatedValues map[string]string // label -> formatted value @@ -50,8 +52,11 @@ func (t *T) Fatalf(format string, args ...any) { func (t *T) Helper() {} // Logf logs a message. -// This is a no-op for property testing but satisfies the TestingT interface. -func (t *T) Logf(format string, args ...any) {} +// Messages are captured and forwarded to the underlying testing.T only when the property test fails. +// This avoids log spam from successful iterations while preserving debugging output for failures. +func (t *T) Logf(format string, args ...any) { + t.logs = append(t.logs, fmt.Sprintf(format, args...)) +} // Assume skips the current property test iteration if the condition is false. // This is useful for filtering generated values that don't meet preconditions. @@ -139,6 +144,7 @@ func Property(t TestingT, check func(*T), opts ...PropertyOption) { data := conjecture.NewConjectureData(conjecture.WithSeed(uint64(cfg.seed + int64(i)))) pt := &T{ + testingT: t, Data: data, Source: nil, // Don't set Source - it's deprecated generatedValues: make(map[string]string), @@ -167,6 +173,7 @@ func Property(t TestingT, check func(*T), opts ...PropertyOption) { // Shrink the failing example shrinkTest := func(d *conjecture.ConjectureData) bool { testT := &T{ + testingT: t, Data: d, Source: nil, generatedValues: make(map[string]string), @@ -243,6 +250,7 @@ func reportFailure(t TestingT, shrunkSeq *conjecture.ChoiceSequence, check func( // Replay the shrunk sequence to get the actual failure and capture generated values data := conjecture.ForReplay(shrunkSeq) finalT := &T{ + testingT: t, Data: data, Source: nil, generatedValues: make(map[string]string), @@ -268,6 +276,14 @@ func reportFailure(t TestingT, shrunkSeq *conjecture.ChoiceSequence, check func( } } + // Forward captured logs from the failing iteration to the outer testing.T + if len(finalT.logs) > 0 { + msg.WriteString("\nLogs:\n") + for _, log := range finalT.logs { + msg.WriteString(fmt.Sprintf(" %s\n", log)) + } + } + // Show failure messages if len(finalT.errors) > 0 { msg.WriteString("\nFailure:\n") diff --git a/property_logf_test.go b/property_logf_test.go new file mode 100644 index 0000000..41427f8 --- /dev/null +++ b/property_logf_test.go @@ -0,0 +1,102 @@ +package specta_test + +import ( + "strings" + "testing" + + "github.com/james-w/specta" + "github.com/james-w/specta/testlib" +) + +// TestPropertyLogForwarding verifies that t.Logf() output from property tests +// is captured and included in the error output when a test fails. +func TestPropertyLogForwarding(t *testing.T) { + t.Run("logs are forwarded on failure", func(t *testing.T) { + spy := testlib.NewSpy() + + specta.Property(spy, func(pt *specta.T) { + x := specta.Draw(pt, specta.Int().Range(0, 10), "x") + + // Log some debug info + pt.Logf("Testing with x = %d", x) + pt.Logf("This is a debug message") + + // Fail the test + if x >= 5 { + pt.Fatalf("x is too large: %d", x) + } + }, specta.Seed(42)) + + // Verify that the test failed + specta.AssertThat(t, len(spy.Errors), specta.GreaterThan(0)) + + // Check that logs were forwarded in the error message + errorMsg := spy.Errors[0] + specta.AssertThat(t, errorMsg, specta.Contains("Logs:")) + specta.AssertThat(t, errorMsg, specta.Contains("Testing with x")) + specta.AssertThat(t, errorMsg, specta.Contains("This is a debug message")) + }) + + t.Run("logs are not shown on success", func(t *testing.T) { + spy := testlib.NewSpy() + + specta.Property(spy, func(pt *specta.T) { + x := specta.Draw(pt, specta.Int().Range(0, 10), "x") + + // Log something but don't fail + pt.Logf("This log should not appear because test passes") + + // Always pass + specta.AssertThat(pt, x, specta.GreaterThanOrEqual(int64(0))) + }, specta.Seed(99), specta.MaxTests(10)) + + // Verify no errors + specta.AssertThat(t, len(spy.Errors), specta.Equal(0)) + }) + + t.Run("logs are from shrunk iteration", func(t *testing.T) { + spy := testlib.NewSpy() + + specta.Property(spy, func(pt *specta.T) { + x := specta.Draw(pt, specta.Int(), "x") + + // Log the value being tested + pt.Logf("Current x value: %d", x) + + // Fail on negative values + if x < 0 { + pt.Fatalf("negative value: %d", x) + } + }, specta.Seed(12345), specta.MaxTests(100)) + + // Verify that the test failed + specta.AssertThat(t, len(spy.Errors), specta.GreaterThan(0)) + + // The error should contain logs from the shrunk (minimal) failing case + errorMsg := spy.Errors[0] + specta.AssertThat(t, errorMsg, specta.Contains("Logs:")) + specta.AssertThat(t, errorMsg, specta.Contains("Current x value:")) + + // The shrunk value should be -1 or close to 0 (shrinking minimizes negative values) + // We just verify that logs are present + }) + + t.Run("multiple log calls are all captured", func(t *testing.T) { + spy := testlib.NewSpy() + + specta.Property(spy, func(pt *specta.T) { + pt.Logf("Log 1") + pt.Logf("Log 2") + pt.Logf("Log 3") + + // Always fail immediately + pt.Fatalf("forced failure") + }, specta.MaxTests(1)) + + // Verify all three logs appear + errorMsg := spy.Errors[0] + specta.AssertThat(t, strings.Count(errorMsg, "Log 1"), specta.Equal(1)) + specta.AssertThat(t, strings.Count(errorMsg, "Log 2"), specta.Equal(1)) + specta.AssertThat(t, strings.Count(errorMsg, "Log 3"), specta.Equal(1)) + }) +} From 2f72e41fef74d51cb05731ae460f6d95b2d0f02a Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 5 Dec 2025 22:16:11 +0000 Subject: [PATCH 2/8] feat: forward logs via t.Logf() with correct line attribution Changed log forwarding to call t.Logf() directly during the final replay instead of capturing logs and printing them in the error message. This provides better integration with Go's testing infrastructure and correct file:line attribution using the Helper() mechanism. Changes: - Add logPassthrough flag to T struct - Update T.Logf() to forward directly to testingT.Logf() when enabled - Call testingT.Helper() before forwarding to get correct line attribution - Enable logPassthrough during final replay in reportFailure() - Add sanity check for replay failures (non-deterministic tests) - Update tests to check spy.Logs instead of error message contents Benefits: - Logs appear as regular log lines with correct file:line (user code, not property.go) - More idiomatic Go test output - Better IDE and test runner integration - No misleading line numbers --- property.go | 47 +++++++++++++++++++++++++++---------------- property_logf_test.go | 38 ++++++++++++++++++---------------- 2 files changed, 51 insertions(+), 34 deletions(-) diff --git a/property.go b/property.go index 5d2e423..49e191c 100644 --- a/property.go +++ b/property.go @@ -14,12 +14,13 @@ import ( // Unlike testing.T, calling Fatalf does not immediately terminate the test process, // but instead panics with a sentinel value to stop the current property iteration. type T struct { - testingT TestingT // Reference to outer testing.T for forwarding logs on failure - failed bool - errors []string - logs []string // Captured log messages from this iteration - Data *conjecture.ConjectureData // ConjectureData for drawing values - Source Source // Deprecated: kept for backward compatibility, will panic if used + testingT TestingT // Reference to outer testing.T for forwarding logs on failure + failed bool + errors []string + logs []string // Captured log messages (unused when logPassthrough is true) + logPassthrough bool // If true, forward Logf calls directly to testingT + Data *conjecture.ConjectureData // ConjectureData for drawing values + Source Source // Deprecated: kept for backward compatibility, will panic if used // Track generated values for error reporting generatedValues map[string]string // label -> formatted value @@ -52,10 +53,20 @@ func (t *T) Fatalf(format string, args ...any) { func (t *T) Helper() {} // Logf logs a message. -// Messages are captured and forwarded to the underlying testing.T only when the property test fails. -// This avoids log spam from successful iterations while preserving debugging output for failures. +// During normal test execution, logs are discarded to avoid spam from multiple iterations. +// During the final replay of a failing test, logs are forwarded directly to testing.T.Logf +// with correct line attribution using the Helper() mechanism. func (t *T) Logf(format string, args ...any) { - t.logs = append(t.logs, fmt.Sprintf(format, args...)) + if t.logPassthrough && t.testingT != nil { + // Forward directly to underlying testing.T for the final failing iteration + // Call Helper() to mark our function as a helper, so stack traces skip us + // and attribute the log to the user's code + if helper, ok := t.testingT.(interface{ Helper() }); ok { + helper.Helper() + } + t.testingT.Logf(format, args...) + } + // Otherwise, discard logs (don't capture them - we don't need them anymore) } // Assume skips the current property test iteration if the condition is false. @@ -248,14 +259,21 @@ func reportFailure(t TestingT, shrunkSeq *conjecture.ChoiceSequence, check func( } // Replay the shrunk sequence to get the actual failure and capture generated values + // Enable log passthrough so pt.Logf() calls forward directly to t.Logf() with correct line attribution data := conjecture.ForReplay(shrunkSeq) finalT := &T{ testingT: t, + logPassthrough: true, // Forward logs directly during final replay Data: data, Source: nil, generatedValues: make(map[string]string), } - runCheck(check, finalT) + failed, _ := runCheck(check, finalT) + + // Sanity check: the replay should have failed + if !failed { + t.Logf("Warning: Property test failed during initial run but passed during replay. This may indicate non-deterministic behavior.") + } // Build error message var msg strings.Builder @@ -276,13 +294,8 @@ func reportFailure(t TestingT, shrunkSeq *conjecture.ChoiceSequence, check func( } } - // Forward captured logs from the failing iteration to the outer testing.T - if len(finalT.logs) > 0 { - msg.WriteString("\nLogs:\n") - for _, log := range finalT.logs { - msg.WriteString(fmt.Sprintf(" %s\n", log)) - } - } + // Note: Logs from pt.Logf() are forwarded directly to t.Logf() during the final replay + // via the logPassthrough mechanism, so they appear as regular log lines with correct attribution // Show failure messages if len(finalT.errors) > 0 { diff --git a/property_logf_test.go b/property_logf_test.go index 41427f8..b015386 100644 --- a/property_logf_test.go +++ b/property_logf_test.go @@ -30,11 +30,13 @@ func TestPropertyLogForwarding(t *testing.T) { // Verify that the test failed specta.AssertThat(t, len(spy.Errors), specta.GreaterThan(0)) - // Check that logs were forwarded in the error message - errorMsg := spy.Errors[0] - specta.AssertThat(t, errorMsg, specta.Contains("Logs:")) - specta.AssertThat(t, errorMsg, specta.Contains("Testing with x")) - specta.AssertThat(t, errorMsg, specta.Contains("This is a debug message")) + // Check that logs were forwarded via t.Logf() (appear in spy.Logs) + specta.AssertThat(t, len(spy.Logs), specta.GreaterThan(0)) + + // Logs should contain our debug messages + allLogs := strings.Join(spy.Logs, "\n") + specta.AssertThat(t, allLogs, specta.Contains("Testing with x")) + specta.AssertThat(t, allLogs, specta.Contains("This is a debug message")) }) t.Run("logs are not shown on success", func(t *testing.T) { @@ -50,8 +52,9 @@ func TestPropertyLogForwarding(t *testing.T) { specta.AssertThat(pt, x, specta.GreaterThanOrEqual(int64(0))) }, specta.Seed(99), specta.MaxTests(10)) - // Verify no errors + // Verify no errors and no logs (logs only forwarded on failure) specta.AssertThat(t, len(spy.Errors), specta.Equal(0)) + specta.AssertThat(t, len(spy.Logs), specta.Equal(0)) }) t.Run("logs are from shrunk iteration", func(t *testing.T) { @@ -72,13 +75,12 @@ func TestPropertyLogForwarding(t *testing.T) { // Verify that the test failed specta.AssertThat(t, len(spy.Errors), specta.GreaterThan(0)) - // The error should contain logs from the shrunk (minimal) failing case - errorMsg := spy.Errors[0] - specta.AssertThat(t, errorMsg, specta.Contains("Logs:")) - specta.AssertThat(t, errorMsg, specta.Contains("Current x value:")) + // Logs should have been forwarded via t.Logf() + specta.AssertThat(t, len(spy.Logs), specta.GreaterThan(0)) - // The shrunk value should be -1 or close to 0 (shrinking minimizes negative values) - // We just verify that logs are present + // The logs should be from the shrunk (minimal) failing case + allLogs := strings.Join(spy.Logs, "\n") + specta.AssertThat(t, allLogs, specta.Contains("Current x value:")) }) t.Run("multiple log calls are all captured", func(t *testing.T) { @@ -93,10 +95,12 @@ func TestPropertyLogForwarding(t *testing.T) { pt.Fatalf("forced failure") }, specta.MaxTests(1)) - // Verify all three logs appear - errorMsg := spy.Errors[0] - specta.AssertThat(t, strings.Count(errorMsg, "Log 1"), specta.Equal(1)) - specta.AssertThat(t, strings.Count(errorMsg, "Log 2"), specta.Equal(1)) - specta.AssertThat(t, strings.Count(errorMsg, "Log 3"), specta.Equal(1)) + // Verify all three logs appear in spy.Logs + specta.AssertThat(t, len(spy.Logs), specta.Equal(3)) + + allLogs := strings.Join(spy.Logs, "\n") + specta.AssertThat(t, allLogs, specta.Contains("Log 1")) + specta.AssertThat(t, allLogs, specta.Contains("Log 2")) + specta.AssertThat(t, allLogs, specta.Contains("Log 3")) }) } From 07e73d3c3574c15468c8cb36d615e060c568c184 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 6 Dec 2025 09:23:52 +0000 Subject: [PATCH 3/8] test: improve multiple log test to verify order with DeepEqual Simplified the test to use a single DeepEqual assertion that checks both the exact logs and their order, rather than multiple individual assertions. --- property_logf_test.go | 11 +++-------- 1 file changed, 3 insertions(+), 8 deletions(-) diff --git a/property_logf_test.go b/property_logf_test.go index b015386..0794683 100644 --- a/property_logf_test.go +++ b/property_logf_test.go @@ -83,7 +83,7 @@ func TestPropertyLogForwarding(t *testing.T) { specta.AssertThat(t, allLogs, specta.Contains("Current x value:")) }) - t.Run("multiple log calls are all captured", func(t *testing.T) { + t.Run("multiple log calls are all captured in order", func(t *testing.T) { spy := testlib.NewSpy() specta.Property(spy, func(pt *specta.T) { @@ -95,12 +95,7 @@ func TestPropertyLogForwarding(t *testing.T) { pt.Fatalf("forced failure") }, specta.MaxTests(1)) - // Verify all three logs appear in spy.Logs - specta.AssertThat(t, len(spy.Logs), specta.Equal(3)) - - allLogs := strings.Join(spy.Logs, "\n") - specta.AssertThat(t, allLogs, specta.Contains("Log 1")) - specta.AssertThat(t, allLogs, specta.Contains("Log 2")) - specta.AssertThat(t, allLogs, specta.Contains("Log 3")) + // Verify all three logs appear in correct order + specta.AssertThat(t, spy.Logs, specta.DeepEqual([]string{"Log 1", "Log 2", "Log 3"})) }) } From e9b45a1c757a541433b164600e43903b6b12371f Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 6 Dec 2025 09:26:12 +0000 Subject: [PATCH 4/8] test: verify logs show shrunk values not original failures Updated tests to explicitly check that logged values are from the shrunk iteration, not the original failure: - First test checks x = 5 (minimal failing value for x >= 5) - Shrinking test checks x = -1 (minimal negative value in range) - Renamed tests to clarify they verify shrinking behavior - Added Range(-1000, 1000) to ensure predictable shrinking to -1 --- property_logf_test.go | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/property_logf_test.go b/property_logf_test.go index 0794683..ebe3c9e 100644 --- a/property_logf_test.go +++ b/property_logf_test.go @@ -11,17 +11,17 @@ import ( // TestPropertyLogForwarding verifies that t.Logf() output from property tests // is captured and included in the error output when a test fails. func TestPropertyLogForwarding(t *testing.T) { - t.Run("logs are forwarded on failure", func(t *testing.T) { + t.Run("logs are forwarded from shrunk iteration", func(t *testing.T) { spy := testlib.NewSpy() specta.Property(spy, func(pt *specta.T) { x := specta.Draw(pt, specta.Int().Range(0, 10), "x") - // Log some debug info + // Log the value being tested pt.Logf("Testing with x = %d", x) pt.Logf("This is a debug message") - // Fail the test + // Fail the test for x >= 5 if x >= 5 { pt.Fatalf("x is too large: %d", x) } @@ -30,12 +30,13 @@ func TestPropertyLogForwarding(t *testing.T) { // Verify that the test failed specta.AssertThat(t, len(spy.Errors), specta.GreaterThan(0)) - // Check that logs were forwarded via t.Logf() (appear in spy.Logs) + // Verify logs were forwarded specta.AssertThat(t, len(spy.Logs), specta.GreaterThan(0)) - // Logs should contain our debug messages + // Logs should show x = 5, the minimal failing value after shrinking + // (not a larger value that might have been the original failure) allLogs := strings.Join(spy.Logs, "\n") - specta.AssertThat(t, allLogs, specta.Contains("Testing with x")) + specta.AssertThat(t, allLogs, specta.Contains("Testing with x = 5")) specta.AssertThat(t, allLogs, specta.Contains("This is a debug message")) }) @@ -57,11 +58,11 @@ func TestPropertyLogForwarding(t *testing.T) { specta.AssertThat(t, len(spy.Logs), specta.Equal(0)) }) - t.Run("logs are from shrunk iteration", func(t *testing.T) { + t.Run("logs show shrunk values not original failures", func(t *testing.T) { spy := testlib.NewSpy() specta.Property(spy, func(pt *specta.T) { - x := specta.Draw(pt, specta.Int(), "x") + x := specta.Draw(pt, specta.Int().Range(-1000, 1000), "x") // Log the value being tested pt.Logf("Current x value: %d", x) @@ -75,12 +76,11 @@ func TestPropertyLogForwarding(t *testing.T) { // Verify that the test failed specta.AssertThat(t, len(spy.Errors), specta.GreaterThan(0)) - // Logs should have been forwarded via t.Logf() + // Logs should show x = -1, the minimal negative value after shrinking + // (not a larger negative number like -500 that might have been the original failure) specta.AssertThat(t, len(spy.Logs), specta.GreaterThan(0)) - - // The logs should be from the shrunk (minimal) failing case allLogs := strings.Join(spy.Logs, "\n") - specta.AssertThat(t, allLogs, specta.Contains("Current x value:")) + specta.AssertThat(t, allLogs, specta.Contains("Current x value: -1")) }) t.Run("multiple log calls are all captured in order", func(t *testing.T) { From 4086eb9556d051002242c14a52a6099e9c58bb63 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 6 Dec 2025 09:27:55 +0000 Subject: [PATCH 5/8] test: remove redundant log forwarding test Removed the first test which was redundant with the shrinking test. Now we have three focused tests: - logs not shown on success - logs show shrunk values (verifies shrinking behavior) - multiple logs captured in order --- property_logf_test.go | 31 +------------------------------ 1 file changed, 1 insertion(+), 30 deletions(-) diff --git a/property_logf_test.go b/property_logf_test.go index ebe3c9e..a0c8a1f 100644 --- a/property_logf_test.go +++ b/property_logf_test.go @@ -9,37 +9,8 @@ import ( ) // TestPropertyLogForwarding verifies that t.Logf() output from property tests -// is captured and included in the error output when a test fails. +// is forwarded to the underlying testing.T when a test fails. func TestPropertyLogForwarding(t *testing.T) { - t.Run("logs are forwarded from shrunk iteration", func(t *testing.T) { - spy := testlib.NewSpy() - - specta.Property(spy, func(pt *specta.T) { - x := specta.Draw(pt, specta.Int().Range(0, 10), "x") - - // Log the value being tested - pt.Logf("Testing with x = %d", x) - pt.Logf("This is a debug message") - - // Fail the test for x >= 5 - if x >= 5 { - pt.Fatalf("x is too large: %d", x) - } - }, specta.Seed(42)) - - // Verify that the test failed - specta.AssertThat(t, len(spy.Errors), specta.GreaterThan(0)) - - // Verify logs were forwarded - specta.AssertThat(t, len(spy.Logs), specta.GreaterThan(0)) - - // Logs should show x = 5, the minimal failing value after shrinking - // (not a larger value that might have been the original failure) - allLogs := strings.Join(spy.Logs, "\n") - specta.AssertThat(t, allLogs, specta.Contains("Testing with x = 5")) - specta.AssertThat(t, allLogs, specta.Contains("This is a debug message")) - }) - t.Run("logs are not shown on success", func(t *testing.T) { spy := testlib.NewSpy() From 9e098a94362b830f3711aee949723b5af9e9e0df Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 6 Dec 2025 09:30:48 +0000 Subject: [PATCH 6/8] refactor: remove unnecessary Helper() interface checks Since TestingT interface already requires Helper(), the type assertion checks are redundant. Simplified to direct calls: - T.Logf(): t.testingT.Helper() - Property(): t.Helper() - reportFailure(): t.Helper() All tests pass with the simplified code. --- property.go | 14 +++----------- 1 file changed, 3 insertions(+), 11 deletions(-) diff --git a/property.go b/property.go index 49e191c..adaffa4 100644 --- a/property.go +++ b/property.go @@ -61,9 +61,7 @@ func (t *T) Logf(format string, args ...any) { // Forward directly to underlying testing.T for the final failing iteration // Call Helper() to mark our function as a helper, so stack traces skip us // and attribute the log to the user's code - if helper, ok := t.testingT.(interface{ Helper() }); ok { - helper.Helper() - } + t.testingT.Helper() t.testingT.Logf(format, args...) } // Otherwise, discard logs (don't capture them - we don't need them anymore) @@ -132,10 +130,7 @@ func MaxShrinks(n int) PropertyOption { // AssertThat(t, x+y, Equal(y+x)) // }) func Property(t TestingT, check func(*T), opts ...PropertyOption) { - // Only call Helper() if t is a real *testing.T - if helper, ok := t.(interface{ Helper() }); ok { - helper.Helper() - } + t.Helper() // Apply configuration cfg := propertyConfig{ @@ -253,10 +248,7 @@ func runCheck(check func(*T), pt *T) (failed bool, skipped bool) { // reportFailure creates a detailed error message and fails the test. func reportFailure(t TestingT, shrunkSeq *conjecture.ChoiceSequence, check func(*T), attempts, maxTests int, seed int64, tested, skipped int, shrinkCalls int) { - // Only call Helper() if t is a real *testing.T - if helper, ok := t.(interface{ Helper() }); ok { - helper.Helper() - } + t.Helper() // Replay the shrunk sequence to get the actual failure and capture generated values // Enable log passthrough so pt.Logf() calls forward directly to t.Logf() with correct line attribution From db63285f7b78691b6dd496cd77e5c28cb0c0502d Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 6 Dec 2025 09:56:58 +0000 Subject: [PATCH 7/8] refactor: remove unused logs field and update API docs - Remove logs []string field from T struct (no longer captured, only forwarded) - Regenerate API documentation to reflect Logf() behavior change --- docs/content/docs/api-reference/_index.md | 2 +- property.go | 1 - 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/docs/content/docs/api-reference/_index.md b/docs/content/docs/api-reference/_index.md index 7b3f7b7..12dd788 100644 --- a/docs/content/docs/api-reference/_index.md +++ b/docs/content/docs/api-reference/_index.md @@ -2150,7 +2150,7 @@ Helper marks the calling function as a test helper. This is a no\-op for propert func (t *T) Logf(format string, args ...any) ``` -Logf logs a message. This is a no\-op for property testing but satisfies the TestingT interface. +Logf logs a message. During normal test execution, logs are discarded to avoid spam from multiple iterations. During the final replay of a failing test, logs are forwarded directly to testing.T.Logf with correct line attribution using the Helper\(\) mechanism. ## type TestingT diff --git a/property.go b/property.go index adaffa4..bb6bc6b 100644 --- a/property.go +++ b/property.go @@ -17,7 +17,6 @@ type T struct { testingT TestingT // Reference to outer testing.T for forwarding logs on failure failed bool errors []string - logs []string // Captured log messages (unused when logPassthrough is true) logPassthrough bool // If true, forward Logf calls directly to testingT Data *conjecture.ConjectureData // ConjectureData for drawing values Source Source // Deprecated: kept for backward compatibility, will panic if used From b8d4046eccf6ca10ac0a07ce3459e8a07137e5f3 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 6 Dec 2025 15:07:44 +0000 Subject: [PATCH 8/8] docs: add examples demonstrating pt.Logf() usage Added two Example functions showing how pt.Logf() works in property tests: - Example_propertyLogging: shows logs appearing for shrunk failures - Example_propertyLoggingMultipleValues: shows execution trace with multiple logs The examples demonstrate: - Logs only appear for failing tests (no spam) - Logs show values from the shrunk counterexample - Multiple log calls appear in order --- example/property_logging_test.go | 113 +++++++++++++++++++++++++++++++ 1 file changed, 113 insertions(+) create mode 100644 example/property_logging_test.go diff --git a/example/property_logging_test.go b/example/property_logging_test.go new file mode 100644 index 0000000..4fac00f --- /dev/null +++ b/example/property_logging_test.go @@ -0,0 +1,113 @@ +// This file demonstrates using pt.Logf() in property tests for debugging. +// Logs are forwarded to testing.T.Logf() during the final replay of a failing test, +// with correct line attribution to user code (not framework code). +// +// Key behaviors: +// 1. Logs only appear for failing tests (no spam from successful tests) +// 2. Logs show values from the shrunk counterexample (minimal failing case) +// 3. File:line attribution points to user code where pt.Logf() was called + +package example_test + +import ( + "fmt" + + "github.com/james-w/specta" + "github.com/james-w/specta/testlib" +) + +// buggySqrt incorrectly handles negative inputs +func buggySqrt(x int64) int64 { + if x < 0 { + return x // BUG: should return error or abs, but returns negative + } + // Simplified: just return the input (not real sqrt, but demonstrates the point) + return x +} + +// Example_propertyLogging demonstrates using pt.Logf() for debugging property tests. +// The logs help understand what values caused the failure, especially when shrinking +// produces minimal counterexamples. +func Example_propertyLogging() { + spy := testlib.NewSpy() + + specta.Property(spy, func(pt *specta.T) { + x := specta.Draw(pt, specta.Int().Range(-100, -1), "x") + + // Log the value being tested - this will appear in error output + pt.Logf("Testing sqrt(%d)", x) + + // Property: sqrt result should always be non-negative + result := buggySqrt(x) + + pt.Logf("Got result: %d", result) + + specta.AssertThat(pt, result, specta.GreaterThanOrEqual(int64(0))) + }, specta.Seed(42), specta.MaxTests(100)) + + // Print the logs that were forwarded from the shrunk failure + if len(spy.Logs) > 0 { + fmt.Println("Logs from failing test:") + for _, log := range spy.Logs { + fmt.Printf(" %s\n", log) + } + fmt.Println() + } + + // Print the error + if len(spy.Errors) > 0 { + fmt.Println("Error:") + fmt.Println(spy.Errors[0]) + } + + // Output: + // Logs from failing test: + // Testing sqrt(-1) + // Got result: -1 + // + // Error: + // === Property Test Failed === + // Seed: 42 + // Attempts: 1/100 + // + // Generated values: + // x = -1 + // + // Failure: + // result: expected value >= 0 but got -1 + // + // Reproduce: Property(t, check, Seed(42)) +} + +// Example_propertyLoggingMultipleValues demonstrates using pt.Logf() with multiple +// log statements to trace execution flow during property test failures. +func Example_propertyLoggingMultipleValues() { + spy := testlib.NewSpy() + + specta.Property(spy, func(pt *specta.T) { + x := specta.Draw(pt, specta.Int().Range(-10, 10), "x") + + pt.Logf("Starting test with x = %d", x) + + // Fail on negative values + if x < 0 { + pt.Logf("Found negative value, failing test") + pt.Fatalf("x should be non-negative, got: %d", x) + } + + pt.Logf("Test passed for x = %d", x) + }, specta.Seed(999), specta.MaxTests(100)) + + // Print all logs from the shrunk failing case + if len(spy.Logs) > 0 { + fmt.Println("Execution trace from shrunk failure:") + for _, log := range spy.Logs { + fmt.Printf(" %s\n", log) + } + } + + // Output: + // Execution trace from shrunk failure: + // Starting test with x = -1 + // Found negative value, failing test +}