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/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 +} 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..bb6bc6b 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 + 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 @@ -50,8 +52,19 @@ 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) {} +// 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) { + 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 + t.testingT.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. // This is useful for filtering generated values that don't meet preconditions. @@ -116,10 +129,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{ @@ -139,6 +149,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 +178,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), @@ -235,19 +247,24 @@ 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 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 @@ -268,6 +285,9 @@ func reportFailure(t TestingT, shrunkSeq *conjecture.ChoiceSequence, check func( } } + // 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 { msg.WriteString("\nFailure:\n") diff --git a/property_logf_test.go b/property_logf_test.go new file mode 100644 index 0000000..a0c8a1f --- /dev/null +++ b/property_logf_test.go @@ -0,0 +1,72 @@ +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 forwarded to the underlying testing.T when a test fails. +func TestPropertyLogForwarding(t *testing.T) { + 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 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 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().Range(-1000, 1000), "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)) + + // 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)) + allLogs := strings.Join(spy.Logs, "\n") + specta.AssertThat(t, allLogs, specta.Contains("Current x value: -1")) + }) + + t.Run("multiple log calls are all captured in order", 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 in correct order + specta.AssertThat(t, spy.Logs, specta.DeepEqual([]string{"Log 1", "Log 2", "Log 3"})) + }) +}