From 5196dec2e45460bf4885ad6a90d12210a182207f Mon Sep 17 00:00:00 2001 From: Onsi Fakhouri Date: Sun, 6 May 2018 14:14:00 -0600 Subject: [PATCH] add -debug flag to emit node output to files --- .gitignore | 3 +- config/config.go | 7 +++ ginkgo/testrunner/test_runner.go | 3 +- ginkgo_dsl.go | 9 ++- .../debug_parallel_fixture_suite_test.go | 13 ++++ .../debug_parallel_fixture_test.go | 18 ++++++ integration/integration_suite_test.go | 2 +- integration/run_test.go | 42 +++++++++++++ .../remote/fake_output_interceptor_test.go | 5 ++ internal/remote/forwarding_reporter.go | 61 ++++++++++++++++++- internal/remote/forwarding_reporter_test.go | 2 +- internal/remote/output_interceptor.go | 3 + internal/remote/output_interceptor_unix.go | 28 +++++++++ internal/remote/output_interceptor_win.go | 3 + internal/remote/server_test.go | 2 +- internal/writer/writer.go | 16 +++-- reporters/stenographer/stenographer.go | 5 +- 17 files changed, 206 insertions(+), 16 deletions(-) create mode 100644 integration/_fixtures/debug_parallel_fixture/debug_parallel_fixture_suite_test.go create mode 100644 integration/_fixtures/debug_parallel_fixture/debug_parallel_fixture_test.go diff --git a/.gitignore b/.gitignore index f69b042c3..18793c248 100644 --- a/.gitignore +++ b/.gitignore @@ -3,4 +3,5 @@ TODO tmp/**/* *.coverprofile .vscode -.idea/ \ No newline at end of file +.idea/ +*.log \ No newline at end of file diff --git a/config/config.go b/config/config.go index 9e54fa33f..1284391f3 100644 --- a/config/config.go +++ b/config/config.go @@ -34,6 +34,7 @@ type GinkgoConfigType struct { FlakeAttempts int EmitSpecProgress bool DryRun bool + DebugParallel bool ParallelNode int ParallelTotal int @@ -81,6 +82,8 @@ func Flags(flagSet *flag.FlagSet, prefix string, includeParallelFlags bool) { flagSet.BoolVar(&(GinkgoConfig.EmitSpecProgress), prefix+"progress", false, "If set, ginkgo will emit progress information as each spec runs to the GinkgoWriter.") + flagSet.BoolVar(&(GinkgoConfig.DebugParallel), prefix+"debug", false, "If set, ginkgo will emit node output to files when running in parallel.") + if includeParallelFlags { flagSet.IntVar(&(GinkgoConfig.ParallelNode), prefix+"parallel.node", 1, "This worker node's (one-indexed) node number. For running specs in parallel.") flagSet.IntVar(&(GinkgoConfig.ParallelTotal), prefix+"parallel.total", 1, "The total number of worker nodes. For running specs in parallel.") @@ -141,6 +144,10 @@ func BuildFlagArgs(prefix string, ginkgo GinkgoConfigType, reporter DefaultRepor result = append(result, fmt.Sprintf("--%sprogress", prefix)) } + if ginkgo.DebugParallel { + result = append(result, fmt.Sprintf("--%sdebug", prefix)) + } + if ginkgo.ParallelNode != 0 { result = append(result, fmt.Sprintf("--%sparallel.node=%d", prefix, ginkgo.ParallelNode)) } diff --git a/ginkgo/testrunner/test_runner.go b/ginkgo/testrunner/test_runner.go index e12913668..5df41be4c 100644 --- a/ginkgo/testrunner/test_runner.go +++ b/ginkgo/testrunner/test_runner.go @@ -17,6 +17,7 @@ import ( "github.com/onsi/ginkgo/ginkgo/testsuite" "github.com/onsi/ginkgo/internal/remote" "github.com/onsi/ginkgo/reporters/stenographer" + colorable "github.com/onsi/ginkgo/reporters/stenographer/support/go-colorable" "github.com/onsi/ginkgo/types" ) @@ -313,7 +314,7 @@ func (t *TestRunner) runParallelGinkgoSuite() RunResult { writers := make([]*logWriter, t.numCPU) reports := make([]*bytes.Buffer, t.numCPU) - stenographer := stenographer.New(!config.DefaultReporterConfig.NoColor, config.GinkgoConfig.FlakeAttempts > 1) + stenographer := stenographer.New(!config.DefaultReporterConfig.NoColor, config.GinkgoConfig.FlakeAttempts > 1, colorable.NewColorableStdout()) aggregator := remote.NewAggregator(t.numCPU, result, config.DefaultReporterConfig, stenographer) server, err := remote.NewServer(t.numCPU) diff --git a/ginkgo_dsl.go b/ginkgo_dsl.go index ea5b7ccde..158acdd5e 100644 --- a/ginkgo_dsl.go +++ b/ginkgo_dsl.go @@ -29,6 +29,7 @@ import ( "github.com/onsi/ginkgo/internal/writer" "github.com/onsi/ginkgo/reporters" "github.com/onsi/ginkgo/reporters/stenographer" + colorable "github.com/onsi/ginkgo/reporters/stenographer/support/go-colorable" "github.com/onsi/ginkgo/types" ) @@ -228,10 +229,14 @@ func RunSpecsWithCustomReporters(t GinkgoTestingT, description string, specRepor func buildDefaultReporter() Reporter { remoteReportingServer := config.GinkgoConfig.StreamHost if remoteReportingServer == "" { - stenographer := stenographer.New(!config.DefaultReporterConfig.NoColor, config.GinkgoConfig.FlakeAttempts > 1) + stenographer := stenographer.New(!config.DefaultReporterConfig.NoColor, config.GinkgoConfig.FlakeAttempts > 1, colorable.NewColorableStdout()) return reporters.NewDefaultReporter(config.DefaultReporterConfig, stenographer) } else { - return remote.NewForwardingReporter(remoteReportingServer, &http.Client{}, remote.NewOutputInterceptor()) + debugFile := "" + if config.GinkgoConfig.DebugParallel { + debugFile = fmt.Sprintf("ginkgo-node-%d.log", config.GinkgoConfig.ParallelNode) + } + return remote.NewForwardingReporter(config.DefaultReporterConfig, remoteReportingServer, &http.Client{}, remote.NewOutputInterceptor(), GinkgoWriter.(*writer.Writer), debugFile) } } diff --git a/integration/_fixtures/debug_parallel_fixture/debug_parallel_fixture_suite_test.go b/integration/_fixtures/debug_parallel_fixture/debug_parallel_fixture_suite_test.go new file mode 100644 index 000000000..429aebc5f --- /dev/null +++ b/integration/_fixtures/debug_parallel_fixture/debug_parallel_fixture_suite_test.go @@ -0,0 +1,13 @@ +package debug_parallel_fixture_test + +import ( + "testing" + + . "github.com/onsi/ginkgo" + . "github.com/onsi/gomega" +) + +func TestDebugParallelFixture(t *testing.T) { + RegisterFailHandler(Fail) + RunSpecs(t, "DebugParallelFixture Suite") +} diff --git a/integration/_fixtures/debug_parallel_fixture/debug_parallel_fixture_test.go b/integration/_fixtures/debug_parallel_fixture/debug_parallel_fixture_test.go new file mode 100644 index 000000000..b609a8bca --- /dev/null +++ b/integration/_fixtures/debug_parallel_fixture/debug_parallel_fixture_test.go @@ -0,0 +1,18 @@ +package debug_parallel_fixture_test + +import ( + "fmt" + "time" + + . "github.com/onsi/ginkgo" +) + +var _ = Describe("DebugParallelFixture", func() { + It("emits output to a file", func() { + for i := 0; i < 10; i += 1 { + fmt.Printf("StdOut %d\n", i) + GinkgoWriter.Write([]byte(fmt.Sprintf("GinkgoWriter %d\n", i))) + } + time.Sleep(time.Second) + }) +}) diff --git a/integration/integration_suite_test.go b/integration/integration_suite_test.go index 9c814f80b..0325f2ca4 100644 --- a/integration/integration_suite_test.go +++ b/integration/integration_suite_test.go @@ -93,4 +93,4 @@ func startGinkgo(dir string, args ...string) *gexec.Session { func removeSuccessfully(path string) { err := os.RemoveAll(path) Expect(err).NotTo(HaveOccurred()) -} \ No newline at end of file +} diff --git a/integration/run_test.go b/integration/run_test.go index 871ba7ecb..81db623c0 100644 --- a/integration/run_test.go +++ b/integration/run_test.go @@ -2,6 +2,7 @@ package integration_test import ( "fmt" + "io/ioutil" "os" "regexp" "runtime" @@ -292,6 +293,47 @@ var _ = Describe("Running Specs", func() { }) }) + Context("when running in parallel with -debug", func() { + BeforeEach(func() { + pathToTest = tmpPath("ginkgo") + copyIn("debug_parallel_fixture", pathToTest) + }) + + Context("without -v", func() { + It("should emit node output to files on disk", func() { + session := startGinkgo(pathToTest, "--nodes=2", "--debug") + Eventually(session).Should(gexec.Exit(0)) + + f0, err := ioutil.ReadFile(pathToTest + "/ginkgo-node-1.log") + Ω(err).ShouldNot(HaveOccurred()) + f1, err := ioutil.ReadFile(pathToTest + "/ginkgo-node-2.log") + Ω(err).ShouldNot(HaveOccurred()) + content := string(append(f0, f1...)) + + for i := 0; i < 10; i += 1 { + Ω(content).Should(ContainSubstring("StdOut %d\n", i)) + Ω(content).Should(ContainSubstring("GinkgoWriter %d\n", i)) + } + }) + }) + + Context("without -v", func() { + It("should emit node output to files on disk, without duplicating the GinkgoWriter output", func() { + session := startGinkgo(pathToTest, "--nodes=2", "--debug", "-v") + Eventually(session).Should(gexec.Exit(0)) + + f0, err := ioutil.ReadFile(pathToTest + "/ginkgo-node-1.log") + Ω(err).ShouldNot(HaveOccurred()) + f1, err := ioutil.ReadFile(pathToTest + "/ginkgo-node-2.log") + Ω(err).ShouldNot(HaveOccurred()) + content := string(append(f0, f1...)) + + out := strings.Split(content, "GinkgoWriter 2") + Ω(out).Should(HaveLen(2)) + }) + }) + }) + Context("when streaming in parallel", func() { BeforeEach(func() { pathToTest = tmpPath("ginkgo") diff --git a/internal/remote/fake_output_interceptor_test.go b/internal/remote/fake_output_interceptor_test.go index a928f93d3..ef54862ea 100644 --- a/internal/remote/fake_output_interceptor_test.go +++ b/internal/remote/fake_output_interceptor_test.go @@ -1,5 +1,7 @@ package remote_test +import "os" + type fakeOutputInterceptor struct { DidStartInterceptingOutput bool DidStopInterceptingOutput bool @@ -15,3 +17,6 @@ func (interceptor *fakeOutputInterceptor) StopInterceptingAndReturnOutput() (str interceptor.DidStopInterceptingOutput = true return interceptor.InterceptedOutput, nil } + +func (interceptor *fakeOutputInterceptor) StreamTo(*os.File) { +} diff --git a/internal/remote/forwarding_reporter.go b/internal/remote/forwarding_reporter.go index 025eb5064..284bc62e5 100644 --- a/internal/remote/forwarding_reporter.go +++ b/internal/remote/forwarding_reporter.go @@ -3,8 +3,14 @@ package remote import ( "bytes" "encoding/json" + "fmt" "io" "net/http" + "os" + + "github.com/onsi/ginkgo/internal/writer" + "github.com/onsi/ginkgo/reporters" + "github.com/onsi/ginkgo/reporters/stenographer" "github.com/onsi/ginkgo/config" "github.com/onsi/ginkgo/types" @@ -30,14 +36,41 @@ type ForwardingReporter struct { serverHost string poster Poster outputInterceptor OutputInterceptor + debugMode bool + debugFile *os.File + nestedReporter *reporters.DefaultReporter } -func NewForwardingReporter(serverHost string, poster Poster, outputInterceptor OutputInterceptor) *ForwardingReporter { - return &ForwardingReporter{ +func NewForwardingReporter(config config.DefaultReporterConfigType, serverHost string, poster Poster, outputInterceptor OutputInterceptor, ginkgoWriter *writer.Writer, debugFile string) *ForwardingReporter { + reporter := &ForwardingReporter{ serverHost: serverHost, poster: poster, outputInterceptor: outputInterceptor, } + + if debugFile != "" { + var err error + reporter.debugMode = true + reporter.debugFile, err = os.Create(debugFile) + if err != nil { + fmt.Println(err.Error()) + os.Exit(1) + } + + if !config.Verbose { + //if verbose is true then the GinkgoWriter emits to stdout. Don't _also_ redirect GinkgoWriter output as that will result in duplication. + ginkgoWriter.AndRedirectTo(reporter.debugFile) + } + outputInterceptor.StreamTo(reporter.debugFile) //This is not working + + stenographer := stenographer.New(false, true, reporter.debugFile) + config.Succinct = false + config.Verbose = true + config.FullTrace = true + reporter.nestedReporter = reporters.NewDefaultReporter(config, stenographer) + } + + return reporter } func (reporter *ForwardingReporter) post(path string, data interface{}) { @@ -56,6 +89,10 @@ func (reporter *ForwardingReporter) SpecSuiteWillBegin(conf config.GinkgoConfigT } reporter.outputInterceptor.StartInterceptingOutput() + if reporter.debugMode { + reporter.nestedReporter.SpecSuiteWillBegin(conf, summary) + reporter.debugFile.Sync() + } reporter.post("/SpecSuiteWillBegin", data) } @@ -63,10 +100,18 @@ func (reporter *ForwardingReporter) BeforeSuiteDidRun(setupSummary *types.SetupS output, _ := reporter.outputInterceptor.StopInterceptingAndReturnOutput() reporter.outputInterceptor.StartInterceptingOutput() setupSummary.CapturedOutput = output + if reporter.debugMode { + reporter.nestedReporter.BeforeSuiteDidRun(setupSummary) + reporter.debugFile.Sync() + } reporter.post("/BeforeSuiteDidRun", setupSummary) } func (reporter *ForwardingReporter) SpecWillRun(specSummary *types.SpecSummary) { + if reporter.debugMode { + reporter.nestedReporter.SpecWillRun(specSummary) + reporter.debugFile.Sync() + } reporter.post("/SpecWillRun", specSummary) } @@ -74,6 +119,10 @@ func (reporter *ForwardingReporter) SpecDidComplete(specSummary *types.SpecSumma output, _ := reporter.outputInterceptor.StopInterceptingAndReturnOutput() reporter.outputInterceptor.StartInterceptingOutput() specSummary.CapturedOutput = output + if reporter.debugMode { + reporter.nestedReporter.SpecDidComplete(specSummary) + reporter.debugFile.Sync() + } reporter.post("/SpecDidComplete", specSummary) } @@ -81,10 +130,18 @@ func (reporter *ForwardingReporter) AfterSuiteDidRun(setupSummary *types.SetupSu output, _ := reporter.outputInterceptor.StopInterceptingAndReturnOutput() reporter.outputInterceptor.StartInterceptingOutput() setupSummary.CapturedOutput = output + if reporter.debugMode { + reporter.nestedReporter.AfterSuiteDidRun(setupSummary) + reporter.debugFile.Sync() + } reporter.post("/AfterSuiteDidRun", setupSummary) } func (reporter *ForwardingReporter) SpecSuiteDidEnd(summary *types.SuiteSummary) { reporter.outputInterceptor.StopInterceptingAndReturnOutput() + if reporter.debugMode { + reporter.nestedReporter.SpecSuiteDidEnd(summary) + reporter.debugFile.Sync() + } reporter.post("/SpecSuiteDidEnd", summary) } diff --git a/internal/remote/forwarding_reporter_test.go b/internal/remote/forwarding_reporter_test.go index be7768e70..0d7e4769c 100644 --- a/internal/remote/forwarding_reporter_test.go +++ b/internal/remote/forwarding_reporter_test.go @@ -30,7 +30,7 @@ var _ = Describe("ForwardingReporter", func() { InterceptedOutput: "The intercepted output!", } - reporter = NewForwardingReporter(serverHost, poster, interceptor) + reporter = NewForwardingReporter(config.DefaultReporterConfigType{}, serverHost, poster, interceptor, nil, "") suiteSummary = &types.SuiteSummary{ SuiteDescription: "My Test Suite", diff --git a/internal/remote/output_interceptor.go b/internal/remote/output_interceptor.go index 093f4513c..5154abe87 100644 --- a/internal/remote/output_interceptor.go +++ b/internal/remote/output_interceptor.go @@ -1,5 +1,7 @@ package remote +import "os" + /* The OutputInterceptor is used by the ForwardingReporter to intercept and capture all stdin and stderr output during a test run. @@ -7,4 +9,5 @@ intercept and capture all stdin and stderr output during a test run. type OutputInterceptor interface { StartInterceptingOutput() error StopInterceptingAndReturnOutput() (string, error) + StreamTo(*os.File) } diff --git a/internal/remote/output_interceptor_unix.go b/internal/remote/output_interceptor_unix.go index 980065da5..ab6622a29 100644 --- a/internal/remote/output_interceptor_unix.go +++ b/internal/remote/output_interceptor_unix.go @@ -6,6 +6,8 @@ import ( "errors" "io/ioutil" "os" + + "github.com/hpcloud/tail" ) func NewOutputInterceptor() OutputInterceptor { @@ -14,7 +16,10 @@ func NewOutputInterceptor() OutputInterceptor { type outputInterceptor struct { redirectFile *os.File + streamTarget *os.File intercepting bool + tailer *tail.Tail + doneTailing chan bool } func (interceptor *outputInterceptor) StartInterceptingOutput() error { @@ -37,6 +42,18 @@ func (interceptor *outputInterceptor) StartInterceptingOutput() error { syscallDup(int(interceptor.redirectFile.Fd()), 1) syscallDup(int(interceptor.redirectFile.Fd()), 2) + if interceptor.streamTarget != nil { + interceptor.tailer, _ = tail.TailFile(interceptor.redirectFile.Name(), tail.Config{Follow: true}) + interceptor.doneTailing = make(chan bool) + + go func() { + for line := range interceptor.tailer.Lines { + interceptor.streamTarget.Write([]byte(line.Text + "\n")) + } + close(interceptor.doneTailing) + }() + } + return nil } @@ -51,5 +68,16 @@ func (interceptor *outputInterceptor) StopInterceptingAndReturnOutput() (string, interceptor.intercepting = false + if interceptor.streamTarget != nil { + interceptor.tailer.Stop() + interceptor.tailer.Cleanup() + <-interceptor.doneTailing + interceptor.streamTarget.Sync() + } + return string(output), err } + +func (interceptor *outputInterceptor) StreamTo(out *os.File) { + interceptor.streamTarget = out +} diff --git a/internal/remote/output_interceptor_win.go b/internal/remote/output_interceptor_win.go index c8f97d97f..40c790336 100644 --- a/internal/remote/output_interceptor_win.go +++ b/internal/remote/output_interceptor_win.go @@ -4,6 +4,7 @@ package remote import ( "errors" + "os" ) func NewOutputInterceptor() OutputInterceptor { @@ -31,3 +32,5 @@ func (interceptor *outputInterceptor) StopInterceptingAndReturnOutput() (string, return "", nil } + +func (interceptor *outputInterceptor) StreamTo(*os.File) {} diff --git a/internal/remote/server_test.go b/internal/remote/server_test.go index 569fafae0..36bd00355 100644 --- a/internal/remote/server_test.go +++ b/internal/remote/server_test.go @@ -47,7 +47,7 @@ var _ = Describe("Server", func() { server.RegisterReporters(reporterA, reporterB) - forwardingReporter = NewForwardingReporter(server.Address(), &http.Client{}, &fakeOutputInterceptor{}) + forwardingReporter = NewForwardingReporter(config.DefaultReporterConfigType{}, server.Address(), &http.Client{}, &fakeOutputInterceptor{}, nil, "") suiteSummary = &types.SuiteSummary{ SuiteDescription: "My Test Suite", diff --git a/internal/writer/writer.go b/internal/writer/writer.go index 6b23b1a64..98eca3bdd 100644 --- a/internal/writer/writer.go +++ b/internal/writer/writer.go @@ -16,10 +16,11 @@ type WriterInterface interface { } type Writer struct { - buffer *bytes.Buffer - outWriter io.Writer - lock *sync.Mutex - stream bool + buffer *bytes.Buffer + outWriter io.Writer + lock *sync.Mutex + stream bool + redirector io.Writer } func New(outWriter io.Writer) *Writer { @@ -31,6 +32,10 @@ func New(outWriter io.Writer) *Writer { } } +func (w *Writer) AndRedirectTo(writer io.Writer) { + w.redirector = writer +} + func (w *Writer) SetStream(stream bool) { w.lock.Lock() defer w.lock.Unlock() @@ -42,6 +47,9 @@ func (w *Writer) Write(b []byte) (n int, err error) { defer w.lock.Unlock() n, err = w.buffer.Write(b) + if w.redirector != nil { + w.redirector.Write(b) + } if w.stream { return w.outWriter.Write(b) } diff --git a/reporters/stenographer/stenographer.go b/reporters/stenographer/stenographer.go index 600192a0a..601c74d66 100644 --- a/reporters/stenographer/stenographer.go +++ b/reporters/stenographer/stenographer.go @@ -12,7 +12,6 @@ import ( "runtime" "strings" - "github.com/onsi/ginkgo/reporters/stenographer/support/go-colorable" "github.com/onsi/ginkgo/types" ) @@ -62,7 +61,7 @@ type Stenographer interface { SummarizeFailures(summaries []*types.SpecSummary) } -func New(color bool, enableFlakes bool) Stenographer { +func New(color bool, enableFlakes bool, writer io.Writer) Stenographer { denoter := "•" if runtime.GOOS == "windows" { denoter = "+" @@ -72,7 +71,7 @@ func New(color bool, enableFlakes bool) Stenographer { denoter: denoter, cursorState: cursorStateTop, enableFlakes: enableFlakes, - w: colorable.NewColorableStdout(), + w: writer, } }