feat: forward t.Logf() output to testing.T on property test failures

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.
 
 <a name="TestingT"></a>
 ## type TestingT

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

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 != "" {

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

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