1// Copyright 2016 The Go Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style
3// license that can be found in the LICENSE file.
4
5package testing
6
7import (
8	"bytes"
9	"fmt"
10	"reflect"
11	"regexp"
12	"runtime"
13	"strings"
14	"sync"
15	"sync/atomic"
16	"time"
17)
18
19func init() {
20	// Make benchmark tests run 10x faster.
21	benchTime.d = 100 * time.Millisecond
22}
23
24func TestTestContext(t *T) {
25	const (
26		add1 = 0
27		done = 1
28	)
29	// After each of the calls are applied to the context, the
30	type call struct {
31		typ int // run or done
32		// result from applying the call
33		running int
34		waiting int
35		started bool
36	}
37	testCases := []struct {
38		max int
39		run []call
40	}{{
41		max: 1,
42		run: []call{
43			{typ: add1, running: 1, waiting: 0, started: true},
44			{typ: done, running: 0, waiting: 0, started: false},
45		},
46	}, {
47		max: 1,
48		run: []call{
49			{typ: add1, running: 1, waiting: 0, started: true},
50			{typ: add1, running: 1, waiting: 1, started: false},
51			{typ: done, running: 1, waiting: 0, started: true},
52			{typ: done, running: 0, waiting: 0, started: false},
53			{typ: add1, running: 1, waiting: 0, started: true},
54		},
55	}, {
56		max: 3,
57		run: []call{
58			{typ: add1, running: 1, waiting: 0, started: true},
59			{typ: add1, running: 2, waiting: 0, started: true},
60			{typ: add1, running: 3, waiting: 0, started: true},
61			{typ: add1, running: 3, waiting: 1, started: false},
62			{typ: add1, running: 3, waiting: 2, started: false},
63			{typ: add1, running: 3, waiting: 3, started: false},
64			{typ: done, running: 3, waiting: 2, started: true},
65			{typ: add1, running: 3, waiting: 3, started: false},
66			{typ: done, running: 3, waiting: 2, started: true},
67			{typ: done, running: 3, waiting: 1, started: true},
68			{typ: done, running: 3, waiting: 0, started: true},
69			{typ: done, running: 2, waiting: 0, started: false},
70			{typ: done, running: 1, waiting: 0, started: false},
71			{typ: done, running: 0, waiting: 0, started: false},
72		},
73	}}
74	for i, tc := range testCases {
75		ctx := &testContext{
76			startParallel: make(chan bool),
77			maxParallel:   tc.max,
78		}
79		for j, call := range tc.run {
80			doCall := func(f func()) chan bool {
81				done := make(chan bool)
82				go func() {
83					f()
84					done <- true
85				}()
86				return done
87			}
88			started := false
89			switch call.typ {
90			case add1:
91				signal := doCall(ctx.waitParallel)
92				select {
93				case <-signal:
94					started = true
95				case ctx.startParallel <- true:
96					<-signal
97				}
98			case done:
99				signal := doCall(ctx.release)
100				select {
101				case <-signal:
102				case <-ctx.startParallel:
103					started = true
104					<-signal
105				}
106			}
107			if started != call.started {
108				t.Errorf("%d:%d:started: got %v; want %v", i, j, started, call.started)
109			}
110			if ctx.running != call.running {
111				t.Errorf("%d:%d:running: got %v; want %v", i, j, ctx.running, call.running)
112			}
113			if ctx.numWaiting != call.waiting {
114				t.Errorf("%d:%d:waiting: got %v; want %v", i, j, ctx.numWaiting, call.waiting)
115			}
116		}
117	}
118}
119
120func TestTRun(t *T) {
121	realTest := t
122	testCases := []struct {
123		desc   string
124		ok     bool
125		maxPar int
126		chatty bool
127		output string
128		f      func(*T)
129	}{{
130		desc:   "failnow skips future sequential and parallel tests at same level",
131		ok:     false,
132		maxPar: 1,
133		output: `
134--- FAIL: failnow skips future sequential and parallel tests at same level (N.NNs)
135    --- FAIL: failnow skips future sequential and parallel tests at same level/#00 (N.NNs)
136    `,
137		f: func(t *T) {
138			ranSeq := false
139			ranPar := false
140			t.Run("", func(t *T) {
141				t.Run("par", func(t *T) {
142					t.Parallel()
143					ranPar = true
144				})
145				t.Run("seq", func(t *T) {
146					ranSeq = true
147				})
148				t.FailNow()
149				t.Run("seq", func(t *T) {
150					realTest.Error("test must be skipped")
151				})
152				t.Run("par", func(t *T) {
153					t.Parallel()
154					realTest.Error("test must be skipped.")
155				})
156			})
157			if !ranPar {
158				realTest.Error("parallel test was not run")
159			}
160			if !ranSeq {
161				realTest.Error("sequential test was not run")
162			}
163		},
164	}, {
165		desc:   "failure in parallel test propagates upwards",
166		ok:     false,
167		maxPar: 1,
168		output: `
169--- FAIL: failure in parallel test propagates upwards (N.NNs)
170    --- FAIL: failure in parallel test propagates upwards/#00 (N.NNs)
171        --- FAIL: failure in parallel test propagates upwards/#00/par (N.NNs)
172        `,
173		f: func(t *T) {
174			t.Run("", func(t *T) {
175				t.Parallel()
176				t.Run("par", func(t *T) {
177					t.Parallel()
178					t.Fail()
179				})
180			})
181		},
182	}, {
183		desc:   "skipping without message, chatty",
184		ok:     true,
185		chatty: true,
186		output: `
187=== RUN   skipping without message, chatty
188--- SKIP: skipping without message, chatty (N.NNs)`,
189		f: func(t *T) { t.SkipNow() },
190	}, {
191		desc:   "chatty with recursion",
192		ok:     true,
193		chatty: true,
194		output: `
195=== RUN   chatty with recursion
196=== RUN   chatty with recursion/#00
197=== RUN   chatty with recursion/#00/#00
198--- PASS: chatty with recursion (N.NNs)
199    --- PASS: chatty with recursion/#00 (N.NNs)
200        --- PASS: chatty with recursion/#00/#00 (N.NNs)`,
201		f: func(t *T) {
202			t.Run("", func(t *T) {
203				t.Run("", func(t *T) {})
204			})
205		},
206	}, {
207		desc: "skipping without message, not chatty",
208		ok:   true,
209		f:    func(t *T) { t.SkipNow() },
210	}, {
211		desc: "skipping after error",
212		output: `
213--- FAIL: skipping after error (N.NNs)
214    sub_test.go:NNN: an error
215    sub_test.go:NNN: skipped`,
216		f: func(t *T) {
217			t.Error("an error")
218			t.Skip("skipped")
219		},
220	}, {
221		desc:   "use Run to locally synchronize parallelism",
222		ok:     true,
223		maxPar: 1,
224		f: func(t *T) {
225			var count uint32
226			t.Run("waitGroup", func(t *T) {
227				for i := 0; i < 4; i++ {
228					t.Run("par", func(t *T) {
229						t.Parallel()
230						atomic.AddUint32(&count, 1)
231					})
232				}
233			})
234			if count != 4 {
235				t.Errorf("count was %d; want 4", count)
236			}
237		},
238	}, {
239		desc: "alternate sequential and parallel",
240		// Sequential tests should partake in the counting of running threads.
241		// Otherwise, if one runs parallel subtests in sequential tests that are
242		// itself subtests of parallel tests, the counts can get askew.
243		ok:     true,
244		maxPar: 1,
245		f: func(t *T) {
246			t.Run("a", func(t *T) {
247				t.Parallel()
248				t.Run("b", func(t *T) {
249					// Sequential: ensure running count is decremented.
250					t.Run("c", func(t *T) {
251						t.Parallel()
252					})
253
254				})
255			})
256		},
257	}, {
258		desc: "alternate sequential and parallel 2",
259		// Sequential tests should partake in the counting of running threads.
260		// Otherwise, if one runs parallel subtests in sequential tests that are
261		// itself subtests of parallel tests, the counts can get askew.
262		ok:     true,
263		maxPar: 2,
264		f: func(t *T) {
265			for i := 0; i < 2; i++ {
266				t.Run("a", func(t *T) {
267					t.Parallel()
268					time.Sleep(time.Nanosecond)
269					for i := 0; i < 2; i++ {
270						t.Run("b", func(t *T) {
271							time.Sleep(time.Nanosecond)
272							for i := 0; i < 2; i++ {
273								t.Run("c", func(t *T) {
274									t.Parallel()
275									time.Sleep(time.Nanosecond)
276								})
277							}
278
279						})
280					}
281				})
282			}
283		},
284	}, {
285		desc:   "stress test",
286		ok:     true,
287		maxPar: 4,
288		f: func(t *T) {
289			t.Parallel()
290			for i := 0; i < 12; i++ {
291				t.Run("a", func(t *T) {
292					t.Parallel()
293					time.Sleep(time.Nanosecond)
294					for i := 0; i < 12; i++ {
295						t.Run("b", func(t *T) {
296							time.Sleep(time.Nanosecond)
297							for i := 0; i < 12; i++ {
298								t.Run("c", func(t *T) {
299									t.Parallel()
300									time.Sleep(time.Nanosecond)
301									t.Run("d1", func(t *T) {})
302									t.Run("d2", func(t *T) {})
303									t.Run("d3", func(t *T) {})
304									t.Run("d4", func(t *T) {})
305								})
306							}
307						})
308					}
309				})
310			}
311		},
312	}, {
313		desc:   "skip output",
314		ok:     true,
315		maxPar: 4,
316		f: func(t *T) {
317			t.Skip()
318		},
319	}, {
320		desc: "subtest calls error on parent",
321		ok:   false,
322		output: `
323--- FAIL: subtest calls error on parent (N.NNs)
324    sub_test.go:NNN: first this
325    sub_test.go:NNN: and now this!
326    sub_test.go:NNN: oh, and this too`,
327		maxPar: 1,
328		f: func(t *T) {
329			t.Errorf("first this")
330			outer := t
331			t.Run("", func(t *T) {
332				outer.Errorf("and now this!")
333			})
334			t.Errorf("oh, and this too")
335		},
336	}, {
337		desc: "subtest calls fatal on parent",
338		ok:   false,
339		output: `
340--- FAIL: subtest calls fatal on parent (N.NNs)
341    sub_test.go:NNN: first this
342    sub_test.go:NNN: and now this!
343    --- FAIL: subtest calls fatal on parent/#00 (N.NNs)
344        testing.go:NNN: test executed panic(nil) or runtime.Goexit: subtest may have called FailNow on a parent test`,
345		maxPar: 1,
346		f: func(t *T) {
347			outer := t
348			t.Errorf("first this")
349			t.Run("", func(t *T) {
350				outer.Fatalf("and now this!")
351			})
352			t.Errorf("Should not reach here.")
353		},
354	}, {
355		desc: "subtest calls error on ancestor",
356		ok:   false,
357		output: `
358--- FAIL: subtest calls error on ancestor (N.NNs)
359    sub_test.go:NNN: Report to ancestor
360    --- FAIL: subtest calls error on ancestor/#00 (N.NNs)
361        sub_test.go:NNN: Still do this
362    sub_test.go:NNN: Also do this`,
363		maxPar: 1,
364		f: func(t *T) {
365			outer := t
366			t.Run("", func(t *T) {
367				t.Run("", func(t *T) {
368					outer.Errorf("Report to ancestor")
369				})
370				t.Errorf("Still do this")
371			})
372			t.Errorf("Also do this")
373		},
374	}, {
375		desc: "subtest calls fatal on ancestor",
376		ok:   false,
377		output: `
378--- FAIL: subtest calls fatal on ancestor (N.NNs)
379    sub_test.go:NNN: Nope`,
380		maxPar: 1,
381		f: func(t *T) {
382			outer := t
383			t.Run("", func(t *T) {
384				for i := 0; i < 4; i++ {
385					t.Run("", func(t *T) {
386						outer.Fatalf("Nope")
387					})
388					t.Errorf("Don't do this")
389				}
390				t.Errorf("And neither do this")
391			})
392			t.Errorf("Nor this")
393		},
394	}, {
395		desc:   "panic on goroutine fail after test exit",
396		ok:     false,
397		maxPar: 4,
398		f: func(t *T) {
399			ch := make(chan bool)
400			t.Run("", func(t *T) {
401				go func() {
402					<-ch
403					defer func() {
404						if r := recover(); r == nil {
405							realTest.Errorf("expected panic")
406						}
407						ch <- true
408					}()
409					t.Errorf("failed after success")
410				}()
411			})
412			ch <- true
413			<-ch
414		},
415	}, {
416		desc: "log in finished sub test logs to parent",
417		ok:   false,
418		output: `
419		--- FAIL: log in finished sub test logs to parent (N.NNs)
420    sub_test.go:NNN: message2
421    sub_test.go:NNN: message1
422    sub_test.go:NNN: error`,
423		maxPar: 1,
424		f: func(t *T) {
425			ch := make(chan bool)
426			t.Run("sub", func(t2 *T) {
427				go func() {
428					<-ch
429					t2.Log("message1")
430					ch <- true
431				}()
432			})
433			t.Log("message2")
434			ch <- true
435			<-ch
436			t.Errorf("error")
437		},
438	}, {
439		// A chatty test should always log with fmt.Print, even if the
440		// parent test has completed.
441		desc:   "log in finished sub test with chatty",
442		ok:     false,
443		chatty: true,
444		output: `
445		--- FAIL: log in finished sub test with chatty (N.NNs)`,
446		maxPar: 1,
447		f: func(t *T) {
448			ch := make(chan bool)
449			t.Run("sub", func(t2 *T) {
450				go func() {
451					<-ch
452					t2.Log("message1")
453					ch <- true
454				}()
455			})
456			t.Log("message2")
457			ch <- true
458			<-ch
459			t.Errorf("error")
460		},
461	}, {
462		// If a subtest panics we should run cleanups.
463		desc:   "cleanup when subtest panics",
464		ok:     false,
465		chatty: false,
466		output: `
467--- FAIL: cleanup when subtest panics (N.NNs)
468    --- FAIL: cleanup when subtest panics/sub (N.NNs)
469    sub_test.go:NNN: running cleanup`,
470		f: func(t *T) {
471			t.Cleanup(func() { t.Log("running cleanup") })
472			t.Run("sub", func(t2 *T) {
473				t2.FailNow()
474			})
475		},
476	}}
477	for _, tc := range testCases {
478		t.Run(tc.desc, func(t *T) {
479			ctx := newTestContext(tc.maxPar, newMatcher(regexp.MatchString, "", ""))
480			buf := &bytes.Buffer{}
481			root := &T{
482				common: common{
483					signal:  make(chan bool),
484					barrier: make(chan bool),
485					name:    "Test",
486					w:       buf,
487				},
488				context: ctx,
489			}
490			if tc.chatty {
491				root.chatty = newChattyPrinter(root.w)
492			}
493			ok := root.Run(tc.desc, tc.f)
494			ctx.release()
495
496			if ok != tc.ok {
497				t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, tc.ok)
498			}
499			if ok != !root.Failed() {
500				t.Errorf("%s:root failed: got %v; want %v", tc.desc, !ok, root.Failed())
501			}
502			if ctx.running != 0 || ctx.numWaiting != 0 {
503				t.Errorf("%s:running and waiting non-zero: got %d and %d", tc.desc, ctx.running, ctx.numWaiting)
504			}
505			got := strings.TrimSpace(buf.String())
506			want := strings.TrimSpace(tc.output)
507			re := makeRegexp(want)
508			if ok, err := regexp.MatchString(re, got); !ok || err != nil {
509				t.Errorf("%s:output:\ngot:\n%s\nwant:\n%s", tc.desc, got, want)
510			}
511		})
512	}
513}
514
515func TestBRun(t *T) {
516	work := func(b *B) {
517		for i := 0; i < b.N; i++ {
518			time.Sleep(time.Nanosecond)
519		}
520	}
521	testCases := []struct {
522		desc   string
523		failed bool
524		chatty bool
525		output string
526		f      func(*B)
527	}{{
528		desc: "simulate sequential run of subbenchmarks.",
529		f: func(b *B) {
530			b.Run("", func(b *B) { work(b) })
531			time1 := b.result.NsPerOp()
532			b.Run("", func(b *B) { work(b) })
533			time2 := b.result.NsPerOp()
534			if time1 >= time2 {
535				t.Errorf("no time spent in benchmark t1 >= t2 (%d >= %d)", time1, time2)
536			}
537		},
538	}, {
539		desc: "bytes set by all benchmarks",
540		f: func(b *B) {
541			b.Run("", func(b *B) { b.SetBytes(10); work(b) })
542			b.Run("", func(b *B) { b.SetBytes(10); work(b) })
543			if b.result.Bytes != 20 {
544				t.Errorf("bytes: got: %d; want 20", b.result.Bytes)
545			}
546		},
547	}, {
548		desc: "bytes set by some benchmarks",
549		// In this case the bytes result is meaningless, so it must be 0.
550		f: func(b *B) {
551			b.Run("", func(b *B) { b.SetBytes(10); work(b) })
552			b.Run("", func(b *B) { work(b) })
553			b.Run("", func(b *B) { b.SetBytes(10); work(b) })
554			if b.result.Bytes != 0 {
555				t.Errorf("bytes: got: %d; want 0", b.result.Bytes)
556			}
557		},
558	}, {
559		desc:   "failure carried over to root",
560		failed: true,
561		output: "--- FAIL: root",
562		f:      func(b *B) { b.Fail() },
563	}, {
564		desc:   "skipping without message, chatty",
565		chatty: true,
566		output: "--- SKIP: root",
567		f:      func(b *B) { b.SkipNow() },
568	}, {
569		desc:   "chatty with recursion",
570		chatty: true,
571		f: func(b *B) {
572			b.Run("", func(b *B) {
573				b.Run("", func(b *B) {})
574			})
575		},
576	}, {
577		desc: "skipping without message, not chatty",
578		f:    func(b *B) { b.SkipNow() },
579	}, {
580		desc:   "skipping after error",
581		failed: true,
582		output: `
583--- FAIL: root
584    sub_test.go:NNN: an error
585    sub_test.go:NNN: skipped`,
586		f: func(b *B) {
587			b.Error("an error")
588			b.Skip("skipped")
589		},
590	}, {
591		desc: "memory allocation",
592		f: func(b *B) {
593			const bufSize = 256
594			alloc := func(b *B) {
595				var buf [bufSize]byte
596				for i := 0; i < b.N; i++ {
597					_ = append([]byte(nil), buf[:]...)
598				}
599			}
600			b.Run("", func(b *B) {
601				alloc(b)
602				b.ReportAllocs()
603			})
604			b.Run("", func(b *B) {
605				alloc(b)
606				b.ReportAllocs()
607			})
608			// runtime.MemStats sometimes reports more allocations than the
609			// benchmark is responsible for. Luckily the point of this test is
610			// to ensure that the results are not underreported, so we can
611			// simply verify the lower bound.
612			if got := b.result.MemAllocs; got < 2 {
613				t.Errorf("MemAllocs was %v; want 2", got)
614			}
615			if got := b.result.MemBytes; got < 2*bufSize {
616				t.Errorf("MemBytes was %v; want %v", got, 2*bufSize)
617			}
618		},
619	}, {
620		desc: "cleanup is called",
621		f: func(b *B) {
622			var calls, cleanups, innerCalls, innerCleanups int
623			b.Run("", func(b *B) {
624				calls++
625				b.Cleanup(func() {
626					cleanups++
627				})
628				b.Run("", func(b *B) {
629					b.Cleanup(func() {
630						innerCleanups++
631					})
632					innerCalls++
633				})
634				work(b)
635			})
636			if calls == 0 || calls != cleanups {
637				t.Errorf("mismatched cleanups; got %d want %d", cleanups, calls)
638			}
639			if innerCalls == 0 || innerCalls != innerCleanups {
640				t.Errorf("mismatched cleanups; got %d want %d", cleanups, calls)
641			}
642		},
643	}, {
644		desc:   "cleanup is called on failure",
645		failed: true,
646		f: func(b *B) {
647			var calls, cleanups int
648			b.Run("", func(b *B) {
649				calls++
650				b.Cleanup(func() {
651					cleanups++
652				})
653				b.Fatalf("failure")
654			})
655			if calls == 0 || calls != cleanups {
656				t.Errorf("mismatched cleanups; got %d want %d", cleanups, calls)
657			}
658		},
659	}}
660	for _, tc := range testCases {
661		t.Run(tc.desc, func(t *T) {
662			var ok bool
663			buf := &bytes.Buffer{}
664			// This is almost like the Benchmark function, except that we override
665			// the benchtime and catch the failure result of the subbenchmark.
666			root := &B{
667				common: common{
668					signal: make(chan bool),
669					name:   "root",
670					w:      buf,
671				},
672				benchFunc: func(b *B) { ok = b.Run("test", tc.f) }, // Use Run to catch failure.
673				benchTime: durationOrCountFlag{d: 1 * time.Microsecond},
674			}
675			if tc.chatty {
676				root.chatty = newChattyPrinter(root.w)
677			}
678			root.runN(1)
679			if ok != !tc.failed {
680				t.Errorf("%s:ok: got %v; want %v", tc.desc, ok, !tc.failed)
681			}
682			if !ok != root.Failed() {
683				t.Errorf("%s:root failed: got %v; want %v", tc.desc, !ok, root.Failed())
684			}
685			// All tests are run as subtests
686			if root.result.N != 1 {
687				t.Errorf("%s: N for parent benchmark was %d; want 1", tc.desc, root.result.N)
688			}
689			got := strings.TrimSpace(buf.String())
690			want := strings.TrimSpace(tc.output)
691			re := makeRegexp(want)
692			if ok, err := regexp.MatchString(re, got); !ok || err != nil {
693				t.Errorf("%s:output:\ngot:\n%s\nwant:\n%s", tc.desc, got, want)
694			}
695		})
696	}
697}
698
699func makeRegexp(s string) string {
700	s = regexp.QuoteMeta(s)
701	s = strings.ReplaceAll(s, ":NNN:", `:\d\d\d\d?:`)
702	s = strings.ReplaceAll(s, "N\\.NNs", `\d*\.\d*s`)
703	return s
704}
705
706func TestBenchmarkOutput(t *T) {
707	// Ensure Benchmark initialized common.w by invoking it with an error and
708	// normal case.
709	Benchmark(func(b *B) { b.Error("do not print this output") })
710	Benchmark(func(b *B) {})
711}
712
713func TestBenchmarkStartsFrom1(t *T) {
714	var first = true
715	Benchmark(func(b *B) {
716		if first && b.N != 1 {
717			panic(fmt.Sprintf("Benchmark() first N=%v; want 1", b.N))
718		}
719		first = false
720	})
721}
722
723func TestBenchmarkReadMemStatsBeforeFirstRun(t *T) {
724	var first = true
725	Benchmark(func(b *B) {
726		if first && (b.startAllocs == 0 || b.startBytes == 0) {
727			panic(fmt.Sprintf("ReadMemStats not called before first run"))
728		}
729		first = false
730	})
731}
732
733func TestParallelSub(t *T) {
734	c := make(chan int)
735	block := make(chan int)
736	for i := 0; i < 10; i++ {
737		go func(i int) {
738			<-block
739			t.Run(fmt.Sprint(i), func(t *T) {})
740			c <- 1
741		}(i)
742	}
743	close(block)
744	for i := 0; i < 10; i++ {
745		<-c
746	}
747}
748
749type funcWriter struct {
750	write func([]byte) (int, error)
751}
752
753func (fw *funcWriter) Write(b []byte) (int, error) {
754	return fw.write(b)
755}
756
757func TestRacyOutput(t *T) {
758	var runs int32  // The number of running Writes
759	var races int32 // Incremented for each race detected
760	raceDetector := func(b []byte) (int, error) {
761		// Check if some other goroutine is concurrently calling Write.
762		if atomic.LoadInt32(&runs) > 0 {
763			atomic.AddInt32(&races, 1) // Race detected!
764		}
765		atomic.AddInt32(&runs, 1)
766		defer atomic.AddInt32(&runs, -1)
767		runtime.Gosched() // Increase probability of a race
768		return len(b), nil
769	}
770
771	var wg sync.WaitGroup
772	root := &T{
773		common:  common{w: &funcWriter{raceDetector}},
774		context: newTestContext(1, newMatcher(regexp.MatchString, "", "")),
775	}
776	root.chatty = newChattyPrinter(root.w)
777	root.Run("", func(t *T) {
778		for i := 0; i < 100; i++ {
779			wg.Add(1)
780			go func(i int) {
781				defer wg.Done()
782				t.Run(fmt.Sprint(i), func(t *T) {
783					t.Logf("testing run %d", i)
784				})
785			}(i)
786		}
787	})
788	wg.Wait()
789
790	if races > 0 {
791		t.Errorf("detected %d racy Writes", races)
792	}
793}
794
795// The late log message did not include the test name.  Issue 29388.
796func TestLogAfterComplete(t *T) {
797	ctx := newTestContext(1, newMatcher(regexp.MatchString, "", ""))
798	var buf bytes.Buffer
799	t1 := &T{
800		common: common{
801			// Use a buffered channel so that tRunner can write
802			// to it although nothing is reading from it.
803			signal: make(chan bool, 1),
804			w:      &buf,
805		},
806		context: ctx,
807	}
808
809	c1 := make(chan bool)
810	c2 := make(chan string)
811	tRunner(t1, func(t *T) {
812		t.Run("TestLateLog", func(t *T) {
813			go func() {
814				defer close(c2)
815				defer func() {
816					p := recover()
817					if p == nil {
818						c2 <- "subtest did not panic"
819						return
820					}
821					s, ok := p.(string)
822					if !ok {
823						c2 <- fmt.Sprintf("subtest panic with unexpected value %v", p)
824						return
825					}
826					const want = "Log in goroutine after TestLateLog has completed: log after test"
827					if !strings.Contains(s, want) {
828						c2 <- fmt.Sprintf("subtest panic %q does not contain %q", s, want)
829					}
830				}()
831
832				<-c1
833				t.Log("log after test")
834			}()
835		})
836	})
837	close(c1)
838
839	if s := <-c2; s != "" {
840		t.Error(s)
841	}
842}
843
844func TestBenchmark(t *T) {
845	if Short() {
846		t.Skip("skipping in short mode")
847	}
848	res := Benchmark(func(b *B) {
849		for i := 0; i < 5; i++ {
850			b.Run("", func(b *B) {
851				for i := 0; i < b.N; i++ {
852					time.Sleep(time.Millisecond)
853				}
854			})
855		}
856	})
857	if res.NsPerOp() < 4000000 {
858		t.Errorf("want >5ms; got %v", time.Duration(res.NsPerOp()))
859	}
860}
861
862func TestCleanup(t *T) {
863	var cleanups []int
864	t.Run("test", func(t *T) {
865		t.Cleanup(func() { cleanups = append(cleanups, 1) })
866		t.Cleanup(func() { cleanups = append(cleanups, 2) })
867	})
868	if got, want := cleanups, []int{2, 1}; !reflect.DeepEqual(got, want) {
869		t.Errorf("unexpected cleanup record; got %v want %v", got, want)
870	}
871}
872
873func TestConcurrentCleanup(t *T) {
874	cleanups := 0
875	t.Run("test", func(t *T) {
876		done := make(chan struct{})
877		for i := 0; i < 2; i++ {
878			i := i
879			go func() {
880				t.Cleanup(func() {
881					cleanups |= 1 << i
882				})
883				done <- struct{}{}
884			}()
885		}
886		<-done
887		<-done
888	})
889	if cleanups != 1|2 {
890		t.Errorf("unexpected cleanup; got %d want 3", cleanups)
891	}
892}
893
894func TestCleanupCalledEvenAfterGoexit(t *T) {
895	cleanups := 0
896	t.Run("test", func(t *T) {
897		t.Cleanup(func() {
898			cleanups++
899		})
900		t.Cleanup(func() {
901			runtime.Goexit()
902		})
903	})
904	if cleanups != 1 {
905		t.Errorf("unexpected cleanup count; got %d want 1", cleanups)
906	}
907}
908
909func TestRunCleanup(t *T) {
910	outerCleanup := 0
911	innerCleanup := 0
912	t.Run("test", func(t *T) {
913		t.Cleanup(func() { outerCleanup++ })
914		t.Run("x", func(t *T) {
915			t.Cleanup(func() { innerCleanup++ })
916		})
917	})
918	if innerCleanup != 1 {
919		t.Errorf("unexpected inner cleanup count; got %d want 1", innerCleanup)
920	}
921	if outerCleanup != 1 {
922		t.Errorf("unexpected outer cleanup count; got %d want 0", outerCleanup)
923	}
924}
925
926func TestCleanupParallelSubtests(t *T) {
927	ranCleanup := 0
928	t.Run("test", func(t *T) {
929		t.Cleanup(func() { ranCleanup++ })
930		t.Run("x", func(t *T) {
931			t.Parallel()
932			if ranCleanup > 0 {
933				t.Error("outer cleanup ran before parallel subtest")
934			}
935		})
936	})
937	if ranCleanup != 1 {
938		t.Errorf("unexpected cleanup count; got %d want 1", ranCleanup)
939	}
940}
941
942func TestNestedCleanup(t *T) {
943	ranCleanup := 0
944	t.Run("test", func(t *T) {
945		t.Cleanup(func() {
946			if ranCleanup != 2 {
947				t.Errorf("unexpected cleanup count in first cleanup: got %d want 2", ranCleanup)
948			}
949			ranCleanup++
950		})
951		t.Cleanup(func() {
952			if ranCleanup != 0 {
953				t.Errorf("unexpected cleanup count in second cleanup: got %d want 0", ranCleanup)
954			}
955			ranCleanup++
956			t.Cleanup(func() {
957				if ranCleanup != 1 {
958					t.Errorf("unexpected cleanup count in nested cleanup: got %d want 1", ranCleanup)
959				}
960				ranCleanup++
961			})
962		})
963	})
964	if ranCleanup != 3 {
965		t.Errorf("unexpected cleanup count: got %d want 3", ranCleanup)
966	}
967}
968