tracing/tracetest: First draft

Tracetest is a package to verify concurrent systems based on synchronous
tracing. It is used in NEO/go tests and originates from what was
initially explained in https://navytux.spb.ru/~kirr/neo.html in

    """On top of that package tracetest provides infrastructure for
    testing concurrent systems..."""

See top-level package overview + example_test.go for details.

tracing/tracetest/chan.go

+// Copyright (C) 2017-2021  Nexedi SA and Contributors.
+//                          Kirill Smelkov <kirr@nexedi.com>
+//
+// This program is free software: you can Use, Study, Modify and Redistribute
+// it under the terms of the GNU General Public License version 3, or (at your
+// option) any later version, as published by the Free Software Foundation.
+//
+// You can also Link and Combine this program with other software covered by
+// the terms of any of the Free Software licenses or any of the Open Source
+// Initiative approved licenses and Convey the resulting work. Corresponding
+// source of such a combination shall include the source code for all other
+// software used.
+//
+// This program is distributed WITHOUT ANY WARRANTY; without even the implied
+// warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
+//
+// See COPYING file for full licensing terms.
+// See https://www.nexedi.com/licensing for rationale and options.
+
+package tracetest
+// synchronous channels.
+
+import (
+	"errors"
+	"flag"
+	"fmt"
+	"reflect"
+	"time"
+)
+
+var (
+	chatty   = flag.Bool("tracetest.v", false, "verbose: print events as they are sent on trace channels")
+	deadTime = flag.Duration("tracetest.deadtime", 3*time.Second, "time after which no events activity is considered to be a deadlock")
+)
+
+// _Msg represents message with 1 event sent over _chan.
+//
+// The goroutine which sent the message will wait for Ack before continue.
+type _Msg struct {
+	Event interface {}
+	ack   chan<- error // nil on Ack; !nil on nak
+}
+
+// _chan provides synchronous channel associated with a stream.
+//
+// It comes with additional property that send blocks until receiving side
+// explicitly acknowledges message was received and processed.
+//
+// New channels must be created via T.newChan.
+//
+// It is safe to use _chan from multiple goroutines simultaneously.
+type _chan struct {
+	t    *T            // created for stream <.name> under <.t>
+	name string        // name of the channel/stream
+	msgq chan *_Msg
+	down chan struct{} // becomes ready when closed
+}
+
+// Send sends event to a consumer and waits for ack.
+// if main testing goroutine detects any problem Send panics.
+func (ch *_chan) Send(event interface{}) {
+	if *chatty {
+		fmt.Printf("%s <- %T %v\n", ch.name, event, event)
+	}
+	ack := make(chan error)
+	select {
+	case <-ch.down:
+		ch.t.fatalfInNonMain("%s: send: channel was closed", ch.name)
+
+	case ch.msgq <- &_Msg{event, ack}:
+		err := <-ack
+		if err != nil {
+			ch.t.fatalfInNonMain("%s: send: %s", ch.name, err)
+		}
+	}
+}
+
+// Close closes the sending side of the channel.
+func (ch *_chan) Close() {
+	close(ch.down) // note - not .msgq
+}
+
+// Recv receives message from a producer.
+//
+// The consumer, after dealing with the message, must send back an ack.
+// Must be called from main testing thread.
+func (ch *_chan) Recv() *_Msg {
+	t := ch.t; t.Helper()
+	msg := ch.recv()
+	if msg == nil {
+		t.Fatalf("%s: recv: deadlock\n", ch.name)
+	}
+	return msg
+}
+
+// RecvInto receives message from a producer, verifies that event type is the
+// same as type of *event, and saves received event there.
+//
+// Must be called from main testing thread.
+func (ch *_chan) RecvInto(eventp interface{}) *_Msg {
+	t := ch.t; t.Helper()
+	msg := ch.recv()
+	if msg == nil {
+		t.Fatalf("%s: recv: deadlock waiting for %T\n", ch.name, eventp)
+	}
+
+	reventp := reflect.ValueOf(eventp)
+	if reventp.Type().Elem() != reflect.TypeOf(msg.Event) {
+		t.queuenak(msg, "unexpected event type")
+		t.Fatalf("%s: expect: %s:  got %T %v", ch.name, reventp.Elem().Type(), msg.Event, msg.Event)
+	}
+
+	// *eventp = msg.Event
+	reventp.Elem().Set(reflect.ValueOf(msg.Event))
+
+	return msg
+}
+
+func (ch *_chan) recv() *_Msg {
+	select {
+	case msg := <-ch.msgq:
+		return msg // ok
+
+	case <-time.After(*deadTime):
+		return nil // deadlock
+	}
+}
+
+
+// Ack acknowledges the event was processed and unblocks producer goroutine.
+func (m *_Msg) Ack() {
+	m.ack <- nil
+}
+
+// nak tells sender that event verification failed and why.
+// it is called only by tracetest internals.
+func (m *_Msg) nak(why string) {
+	m.ack <- errors.New(why)
+}
+
+// nak represents scheduled call to `msg.nak(why)`.
+type nak struct {
+	msg *_Msg
+	why string
+}
+
+// queuenak schedules call to `msg.nak(why)`.
+func (t *T) queuenak(msg *_Msg, why string) {
+	t.nakq = append(t.nakq, nak{msg, why})
+}
+
+// newChan creates new _chan channel.
+func (t *T) newChan(name string) *_chan {
+	// NOTE T ensures not to create channels with duplicate names.
+	return &_chan{t: t, name: name, msgq: make(chan *_Msg), down: make(chan struct{})}
+}

tracing/tracetest/example_test.go

+// Copyright (C) 2018-2021  Nexedi SA and Contributors.
+//                          Kirill Smelkov <kirr@nexedi.com>
+//
+// This program is free software: you can Use, Study, Modify and Redistribute
+// it under the terms of the GNU General Public License version 3, or (at your
+// option) any later version, as published by the Free Software Foundation.
+//
+// You can also Link and Combine this program with other software covered by
+// the terms of any of the Free Software licenses or any of the Open Source
+// Initiative approved licenses and Convey the resulting work. Corresponding
+// source of such a combination shall include the source code for all other
+// software used.
+//
+// This program is distributed WITHOUT ANY WARRANTY; without even the implied
+// warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
+//
+// See COPYING file for full licensing terms.
+// See https://www.nexedi.com/licensing for rationale and options.
+
+// Package tracetest_test demonstrates how to use package tracetest.
+//
+// It also serves as set of testcases for tracetest itself.
+package tracetest_test
+
+//go:generate gotrace gen .
+
+import (
+	"fmt"
+	"os"
+	"os/exec"
+	"regexp"
+	"strings"
+	"sync"
+	"testing"
+	"time"
+
+	"lab.nexedi.com/kirr/go123/tracing"
+	"lab.nexedi.com/kirr/go123/tracing/tracetest"
+)
+
+// hi and hello are functions that emit "(Hi|Hello), <who>" and can be traced.
+
+//trace:event traceHi(who string)
+//trace:event traceHello(who string)
+func hi(who string) {
+	traceHi(who)
+	fmt.Println("Hi,", who)
+}
+func hello(who string) {
+	traceHello(who)
+	fmt.Println("Hello,", who)
+}
+
+// we use tracing to attach probes to hi and hello, and emit corresponding
+// eventHi and eventHello to tracetest.T from there.
+type eventHi string
+type eventHello string
+func setupTracing(t *tracetest.T) *tracing.ProbeGroup {
+	pg := &tracing.ProbeGroup{}
+	tracing.Lock()
+	traceHi_Attach(pg, func(who string) {
+		t.RxEvent(eventHi(who))
+	})
+	traceHello_Attach(pg, func(who string) {
+		t.RxEvent(eventHello(who))
+	})
+	tracing.Unlock()
+	// NOTE pg.Done must be invoked by caller when setup tracing is no longer needed.
+	return pg
+}
+
+// routeEvent tells to which stream an event should go.
+// Here, in example, we use the convention that who comes as "<threadID>·..."
+// and we route the event to stream that corresponds to threadID.
+func routeEvent(event interface{}) (stream string) {
+	who := ""
+	switch ev := event.(type) {
+	default:
+		panic(fmt.Sprintf("unexpected event type %T", event))
+	case eventHi:
+		who = string(ev)
+	case eventHello:
+		who = string(ev)
+	}
+
+	i := strings.Index(who, "·")
+	if i == -1 {
+		panic(fmt.Sprintf("who does not have threadID: %q", who))
+	}
+
+	return strings.ToLower(who[:i])
+}
+
+// verify calls tracetest.Verify on f with first preparing tracing setup and events delivery.
+// It also verifies that tracetest detects errors as expected.
+func verify(t *testing.T, f func(t *tracetest.T), targvExtra ...string) {
+	t.Helper()
+	verifyInSubprocess(t, func (t *testing.T) {
+		tracetest.Verify(t, func(t *tracetest.T) {
+			// setup tracing to deliver trace events to t.
+			pg := setupTracing(t)
+			defer pg.Done()
+			// tell t to which stream an event should go.
+			t.SetEventRouter(routeEvent)
+
+			// run test code
+			f(t)
+		})
+	}, targvExtra...)
+}
+
+
+// Test2ThreadsOK demonstrates verifying 2 threads that execute independently.
+// There is no concurrency problem here.
+func Test2ThreadsOK(t *testing.T) {
+	verify(t, func(t *tracetest.T) {
+		var wg sync.WaitGroup
+		defer wg.Wait()
+		wg.Add(2)
+
+		go func() { // thread1
+			defer wg.Done()
+			hi("T1·A")
+			hello("T1·B")
+		}()
+
+		go func() { // thread2
+			defer wg.Done()
+			hello("T2·C")
+			hi("T2·D")
+		}()
+
+		// assert that events come as expected
+		// NOTE in checks t2 vs t1 order does not matter
+		t.Expect("t2", eventHello("T2·C"))
+		t.Expect("t2", eventHi("T2·D"))
+		t.Expect("t1", eventHi("T1·A"))
+		t.Expect("t1", eventHello("T1·B"))
+	})
+}
+
+// TestDeadlock demonstrates deadlock detection.
+// XXX also test for wrong decomposition   XXX or is it also covered by this test as well?
+func TestDeadlock(t *testing.T) {
+	verify(t, func(t *tracetest.T) {
+		var wg sync.WaitGroup
+		defer wg.Wait()
+		wg.Add(1)
+
+		go func() { // thread1
+			defer wg.Done()
+			hi("T1·A")
+		}()
+
+		// the checker expects something on stream "t2", but there is
+		// no event sent there -> deadlock.
+		t.Expect("t2", eventHi("zzz"))
+	}, "-tracetest.deadtime=0.5s")
+}
+
+// TestRace demonstrates detection of logical race.
+func TestRace(t *testing.T) {
+	verify(t, func(t *tracetest.T) {
+		var wg sync.WaitGroup
+		defer wg.Wait()
+		wg.Add(2)
+
+		// 2 threads should synchronize with each other and do step A before B.
+		// They do not properly synchronize though, and just happen to
+		// usually emit events in expected order due to sleep in T2.
+		// Tracetest detects that.
+		go func() { // thread1
+			defer wg.Done()
+			hi("x·A")
+		}()
+
+		go func() { // thread2
+			defer wg.Done()
+			time.Sleep(100*time.Millisecond)
+			hi("x·B")
+		}()
+
+		t.Expect("x", eventHi("x·A"))
+		t.Expect("x", eventHi("x·B"))
+	})
+}
+
+
+// other tests (mainly to verify tracetest itself)
+
+// TestExpectType demonstrates Expect asserting with "unexpected event type".
+func TestExpectType(t *testing.T) {
+	verify(t, func(t *tracetest.T) {
+		var wg sync.WaitGroup
+		defer wg.Wait()
+		wg.Add(1)
+
+		go func() { // thread 1
+			defer wg.Done()
+			hi("T1·A")
+		}()
+
+		t.Expect("t1", eventHello("T1·A"))
+	})
+}
+
+// TestExpectValue demonstrates Expect asserting with "unexpected event value".
+func TestExpectValue(t *testing.T) {
+	verify(t, func(t *tracetest.T) {
+		var wg sync.WaitGroup
+		defer wg.Wait()
+		wg.Add(1)
+
+		go func() { // thread 1
+			defer wg.Done()
+			hi("T1·A")
+		}()
+
+		t.Expect("t1", eventHi("T1·B"))
+	})
+}
+
+
+
+// ----------------------------------------
+
+// verifyInSubprocess runs f in subprocess and verifies that its output matches testExpectMap[t.Name].
+func verifyInSubprocess(t *testing.T, f func(t *testing.T), targvExtra ...string) {
+	t.Helper()
+	if os.Getenv("TRACETEST_EX_VERIFY_IN_SUBPROCESS") == "1" {
+		f(t)
+		return
+	}
+
+	// spawn the test in subprocess and verify its output
+	expectOK, ok := testExpectMap[t.Name()]
+	if !ok {
+		panic(fmt.Sprintf("testExpectMap[%q] not defined", t.Name()))
+	}
+	outputOK := regexp.QuoteMeta(expectOK.output)
+	// empty line -> kind of "<BLANKLINE>"
+	for {
+		__ := strings.ReplaceAll(outputOK, "\n\n", "\n\\s*\n")
+		if __ == outputOK {
+			break
+		}
+		outputOK = __
+	}
+	outputOK = strings.ReplaceAll(outputOK, "<TIME>", ".+s")
+	outputOK = strings.ReplaceAll(outputOK, "<LINE>", "[0-9]+")
+	outputRe := regexp.MustCompile(outputOK)
+	argv := []string{"-test.run="+t.Name()}
+	argv = append(argv, targvExtra...)
+	cmd := exec.Command(os.Args[0], argv...)
+	cmd.Env = append(os.Environ(), "TRACETEST_EX_VERIFY_IN_SUBPROCESS=1")
+	bout, err := cmd.CombinedOutput() // NOTE `go test` itself combines everything to stdout only
+	out := string(bout)
+	ecode := 0
+	if testing.Verbose() {
+		t.Logf("stdout:\n%s\n", out)
+	}
+	if err != nil {
+		e, ok := err.(*exec.ExitError)
+		if !ok {
+			// e.g. could not respawn at all
+			t.Fatal(err)
+		}
+		ecode = e.ExitCode()
+	}
+
+	bad := ""
+	badf := func(format string, argv ...interface{}) {
+		bad += fmt.Sprintf(format+"\n", argv...)
+	}
+
+	if ecode != expectOK.exitCode {
+		badf("exit code: %d  ; expected: %d", ecode, expectOK.exitCode)
+	}
+
+	if !outputRe.MatchString(out) {
+		badf("unexpected output:\n%s\nwant: ~\n%s\n", out, expectOK.output)
+	}
+
+	if bad != "" {
+		t.Fatal(bad)
+	}
+}
+
+// testExpect describes what result to expect from a test.
+type testExpect struct {
+	exitCode int
+	output   string
+}
+// testExpectMap maps <test name> -> testExpect.
+var testExpectMap = map[string]testExpect{
+	"Test2ThreadsOK": {0, ""},
+
+	"TestDeadlock":   {1,
+`--- FAIL: TestDeadlock (<TIME>)
+    example_test.go:157: t2: recv: deadlock waiting for *tracetest_test.eventHi
+    example_test.go:157: test shutdown: #streams: 2,  #(pending events): 1
+        t1	<- tracetest_test.eventHi T1·A
+        # t2
+
+    chan.go:<LINE>: t1: send: canceled (test failed)
+`},
+
+	"TestRace":       {1,
+`    --- FAIL: TestRace/delay@0(=x:0) (<TIME>)
+        example_test.go:183: x: expect: tracetest_test.eventHi:
+            want: x·A
+            have: x·B
+            diff:
+            -"x·A"
+            +"x·B"
+`},
+
+	"TestExpectType": {1,
+`--- FAIL: TestExpectType (<TIME>)
+    example_test.go:203: t1: expect: tracetest_test.eventHello:  got tracetest_test.eventHi T1·A
+    example_test.go:203: test shutdown: #streams: 1,  #(pending events): 0
+        # t1
+
+    chan.go:<LINE>: t1: send: unexpected event type
+`},
+
+	"TestExpectValue": {1,
+`--- FAIL: TestExpectValue (<TIME>)
+    example_test.go:219: t1: expect: tracetest_test.eventHi:
+        want: T1·B
+        have: T1·A
+        diff:
+        -"T1·B"
+        +"T1·A"
+
+    example_test.go:219: test shutdown: #streams: 1,  #(pending events): 0
+        # t1
+
+    chan.go:<LINE>: t1: send: unexpected event data
+`},
+}

tracing/tracetest/ztrace_x_test.go

+// Code generated by lab.nexedi.com/kirr/go123/tracing/cmd/gotrace; DO NOT EDIT.
+
+package tracetest_test
+// code generated for tracepoints
+
+import (
+	"lab.nexedi.com/kirr/go123/tracing"
+	"unsafe"
+)
+
+// traceevent: traceHello(who string)
+
+type _t_traceHello struct {
+	tracing.Probe
+	probefunc     func(who string)
+}
+
+var _traceHello *_t_traceHello
+
+func traceHello(who string) {
+	if _traceHello != nil {
+		_traceHello_run(who)
+	}
+}
+
+func _traceHello_run(who string) {
+	for p := _traceHello; p != nil; p = (*_t_traceHello)(unsafe.Pointer(p.Next())) {
+		p.probefunc(who)
+	}
+}
+
+func traceHello_Attach(pg *tracing.ProbeGroup, probe func(who string)) *tracing.Probe {
+	p := _t_traceHello{probefunc: probe}
+	tracing.AttachProbe(pg, (**tracing.Probe)(unsafe.Pointer(&_traceHello)), &p.Probe)
+	return &p.Probe
+}
+
+// traceevent: traceHi(who string)
+
+type _t_traceHi struct {
+	tracing.Probe
+	probefunc     func(who string)
+}
+
+var _traceHi *_t_traceHi
+
+func traceHi(who string) {
+	if _traceHi != nil {
+		_traceHi_run(who)
+	}
+}
+
+func _traceHi_run(who string) {
+	for p := _traceHi; p != nil; p = (*_t_traceHi)(unsafe.Pointer(p.Next())) {
+		p.probefunc(who)
+	}
+}
+
+func traceHi_Attach(pg *tracing.ProbeGroup, probe func(who string)) *tracing.Probe {
+	p := _t_traceHi{probefunc: probe}
+	tracing.AttachProbe(pg, (**tracing.Probe)(unsafe.Pointer(&_traceHi)), &p.Probe)
+	return &p.Probe
+}
+
+// trace export signature
+func _trace_exporthash_2cac17aa362e1c23f638766808e976bffdb10ba8() {}

tracing/tracing.go

-// Copyright (C) 2017-2020  Nexedi SA and Contributors.
+// Copyright (C) 2017-2021  Nexedi SA and Contributors.
 //                          Kirill Smelkov <kirr@nexedi.com>
 //
 // This program is free software: you can Use, Study, Modify and Redistribute
@@ -146,7 +146,7 @@ a set of goroutines in tested code in question
 	- produce events in correct order, and
 	- at every event associated internal state is correct.
 
-TODO example.
+Please see package lab.nexedi.com/kirr/go123/tracing/tracetest for details.
 
 
 Cross package tracing