tracing/tracetest: Prevent deadlocks when there are extra events not consumed by main checker

A deadlock scenario was possible before this patch:

- main thread finished checks, wants to return, goes to deferred wg.Wait();
- that wg.Wait waits for other spawned threads to complete;
- in one of that thread there is extra event being sent to a stream;
- that send is blocked waiting for main thread to receive it, but the
  main thread is waiting in wg.Wait() and only after that it would go to
  call T.closeStreamTab() which marks all the channels as down -> deadlock.

-> Fix it by explicitly detecting deadlocks not only in Recv, but also on Send.

NOTE Contrary to Recv - which is always called from main thread - Send is
always called from non-main threads. T.unsentv and the logic prepared in
the previous patch care to handle that correctly.

tracing/tracetest/chan.go

@@ -54,25 +54,44 @@ type _chan struct {
 	name string        // name of the channel/stream
 	msgq chan *_Msg
 	down chan struct{} // becomes ready when closed
+
+	// messages that were not sent due to e.g. detected deadlock.
+	// T includes these in final printout for pending events
+	// protected by t.mu
+	unsentv []*_Msg
 }
 
 // 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{}) {
+	t := ch.t
 	if *chatty {
 		fmt.Printf("%s <- %T %v\n", ch.name, event, event)
 	}
-	ack := make(chan error)
+	ack := make(chan error, 1)
+	msg := &_Msg{event, ack}
+	unsentWhy := ""
 	select {
-	case <-ch.down:
-		ch.t.fatalfInNonMain("%s: send: channel was closed", ch.name)
-
-	case ch.msgq <- &_Msg{event, ack}:
+	case ch.msgq <- msg:
 		err := <-ack
 		if err != nil {
-			ch.t.fatalfInNonMain("%s: send: %s", ch.name, err)
+			t.fatalfInNonMain("%s: send: %s", ch.name, err)
 		}
+		return
+
+	case <-ch.down:
+		unsentWhy = "channel was closed"
+
+	case <-time.After(*deadTime):
+		unsentWhy = "deadlock"
 	}
+
+	// remember event as still "send-pending"
+	t.mu.Lock()
+	ch.unsentv = append(ch.unsentv, msg)
+	t.mu.Unlock()
+
+	t.fatalfInNonMain("%s: send: %s", ch.name, unsentWhy)
 }
 
 // Close closes the sending side of the channel.

tracing/tracetest/example_test.go

@@ -188,6 +188,24 @@ func TestRace(t *testing.T) {
 
 // other tests (mainly to verify tracetest itself)
 
+// TestDeadlockExtra demonstrates deadlock detection when there is extra event
+// not consumed by main checker.
+func TestDeadlockExtra(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")
+			hi("T1·Extra")
+		}()
+
+		t.Expect("t1", eventHi("T1·A"))
+	}, "-tracetest.deadtime=0.5s")
+}
+
 // TestExpectType demonstrates Expect asserting with "unexpected event type".
 func TestExpectType(t *testing.T) {
 	verify(t, func(t *tracetest.T) {
@@ -302,7 +320,7 @@ var testExpectMap = map[string]testExpect{
         t1	<- tracetest_test.eventHi T1·A
         # t2
 
-    tracetest.go:<LINE>: chan.go:<LINE>: t1: send: canceled (test failed)
+    tracetest.go:<LINE>: chan.go:<LINE>: t1: send: deadlock
 `},
 
 	"TestRace":       {1,
@@ -315,10 +333,19 @@ var testExpectMap = map[string]testExpect{
             +"x·B"
 `},
 
+	"TestDeadlockExtra": {1,
+`Hi, T1·A
+--- FAIL: TestDeadlockExtra (<TIME>)
+    tracetest.go:<LINE>: test shutdown: #streams: 1,  #(pending events): 1
+        t1	<- tracetest_test.eventHi T1·Extra
+
+    tracetest.go:<LINE>: chan.go:<LINE>: t1: send: deadlock
+`},
+
 	"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
+    example_test.go:221: t1: expect: tracetest_test.eventHello:  got tracetest_test.eventHi T1·A
+    example_test.go:221: test shutdown: #streams: 1,  #(pending events): 0
         # t1
 
     tracetest.go:<LINE>: chan.go:<LINE>: t1: send: unexpected event type
@@ -326,14 +353,14 @@ var testExpectMap = map[string]testExpect{
 
 	"TestExpectValue": {1,
 `--- FAIL: TestExpectValue (<TIME>)
-    example_test.go:219: t1: expect: tracetest_test.eventHi:
+    example_test.go:237: 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
+    example_test.go:237: test shutdown: #streams: 1,  #(pending events): 0
         # t1
 
     tracetest.go:<LINE>: chan.go:<LINE>: t1: send: unexpected event data

tracing/tracetest/tracetest.go

@@ -336,6 +336,12 @@ func (t *T) closeStreamTab() (nnak int) {
 				break loop
 			}
 		}
+		// include ch.unsentv into pending as well (we want to show
+		// such events as pending even if corresponding send deadlocked).
+		for _, msg := range ch.unsentv {
+			sendv = append(sendv, sendInfo{ch, msg})
+			quiet = false
+		}
 
 		if quiet {
 			quietv = append(quietv, ch)