A Story of Capturing go test Log Output and Integrating with Test Management Tools

This is a translated version of the original article. [https://tech.groove-x.com/entry/go-test-capture]

Development

This article is part of the GROOVE X Advent Calendar 2024 and marks Day 19.

Hello, I'm Junya, currently working on QA automation after moving to the QA team.

Recently, I've been experimenting with a test management tool called Qase. While trying to associate the results of go test executions with specific test cases in Qase and upload them, I encountered several challenges. Today, I'll share my experience.

For those curious about Qase, refer to their official documentation for more details.

Goals

  • Capture logs during test execution
  • Associate t.Run results with test case steps and save them (planned for another time)
  • Link results of Parameterized tests with parameters in Qase (planned for another time)

Two Approaches to Qase Integration

There are two primary approaches to linking go test results with Qase:

  1. Run go test or gotestsum and then use the CLI to upload results to Qase.
  2. Capture log output during go test execution and upload directly to Qase.

The first approach is straightforward but limited. Since go test lacks a detailed annotation mechanism, it doesn't fully utilize Qase's features, such as steps and parameters. To leverage Qase's full capabilities, I opted for the second approach.

For those interested in the first method, refer to this GitHub documentation.

Capturing Logs During Test Execution

Here's the solution I arrived at: create a custom structure to intercept the standard output into a buffer, using TestMain and the t.Cleanup method to process the logs.

type StdoutCapturer struct {
    r, w      *os.File
    stdout    *os.File
    buf       *bytes.Buffer
    lastIndex int
}

// NewStdoutCapturer creates a structure for capturing standard output
func NewStdoutCapturer() *StdoutCapturer {
    r, w, err := os.Pipe()
    if err != nil {
        log.Fatal(err)
    }
    stdout := os.Stdout
    os.Stdout = w

    var buf bytes.Buffer
    tee := io.TeeReader(r, stdout) // Write to both buf and stdout

    go func() {
        _, _ = buf.ReadFrom(tee)
    }()

    return &StdoutCapturer{r: r, w: w, stdout: stdout, buf: &buf}
}

func (c *StdoutCapturer) Close() {
    _ = c.w.Close()
    _ = c.r.Close()
    os.Stdout = c.stdout
}

// Flush returns the content written to stdout so far
func (c *StdoutCapturer) Flush() string {
    full := c.buf.String()
    content := full[c.lastIndex:]
    c.lastIndex = len(full)
    return content
}

TestMain Implementation

1
2
3
4
5
6
7
8
var capturer *testutil.StdoutCapturer

func TestMain(m *testing.M) {
    // Replace standard output with Capturer before generating `testing.T`
    capturer = testutil.NewStdoutCapturer()
    m.Run()
    capturer.Close()
}

The capturer is defined as a global variable in the package. During tests, we use t.Cleanup to retrieve the captured logs:

1
2
3
4
t.Cleanup(func() {
    captured := capturer.Flush()
    UploadResult(t, captured) // Upload the result to the test management tool
})

Challenges and Solutions

1. Hooks in Test Setup and Teardown

I initially tried to avoid using a global capturer by intercepting standard output during setup and teardown within each test:

1
2
3
4
5
6
func TestExample(t *testing.T) {
    capturer := testutil.NewStdoutCapturer()
    t.Cleanup(func() {
        captured := capturer.Flush()
    })
}

However, this didn't work. The testing package binds os.Stdout to the T object's writer before the test starts:

1
2
3
4
5
6
7
t := &T{
    common: common{
        w: os.Stdout,
        // Other fields...
    },
    // Other fields...
}

So, I had to rewrite os.Stdout in TestMain.

2. Logs Missed by t.Cleanup (Unresolved)

When running go test -v, test outputs look like this:

1
2
3
4
5
6
1 === RUN   TestExample
2     run_test.go:49: TestExample was called
3 === NAME  TestExample_Title
4     run_test.go:46: {"status":true,"result":{"case_id":1115,"hash":"xxx"}}
5 --- PASS: TestExample_Title (0.45s)
6     --- PASS: TestExample_Title/TestExample_Title (0.00s)

While lines 1–4 can be captured in t.Cleanup, lines 5–6 are logged after the test finishes, so they're missed. For now, I've accepted this limitation.

3. Rewriting Flush to Exclude Extra Strings

Missed logs end up in the next test's results, so I modified Flush to remove unwanted content:

func (c *StdoutCapturer) Flush() string {
    full := c.buf.String()
    content := full[c.lastIndex:]
    c.lastIndex = len(full)

    // Ignore lines until "=== RUN"
    for {
        index := strings.Index(content, "\n")
        if index == -1 {
            break
        }
        line := content[:index]
        if strings.HasPrefix(line, "=== RUN") {
            break
        }
        content = content[index+1:]
    }
    return content
}

Wrapping t.Log

I also tried wrapping t.Log to capture logs:

package wrapper

type Wrapper struct {
    t *testing.T
}

func T(t *testing.T) *Wrapper {
    return &Wrapper{t: t}
}

func (w *Wrapper) Log(args ...interface{}) {
    w.t.Helper()
    // Save the log here
    w.t.Log(args...)
}

Usage example:

wrapper.T(t).Log("...")

However, while this works for explicit t.Log calls, it doesn't capture logs generated internally by the testing module.

Behavior in Parallel Test Execution (Unverified)

Since the solution rewrites os.Stdout and hooks each test's end to capture logs, parallel tests might result in log content getting mixed.

For now, running go test -p 1 (single-threaded) avoids this issue.

Summary

By overwriting os.Stdout, I managed to upload logs from test runs to Qase. However, some logs can't be captured, and parallel execution poses challenges. These issues will require further improvements.

Potential Enhancements:

  • Use a centralized service to monitor and parse logs during test runs.
  • Leverage tools like gotestsum and its go test -json output for easier parsing.
  • Contribute to tools like gotestsum or qasectl to enhance integration options.

I'll cover topics like Parameterized tests and step integrations with Qase in a future articles.

Edit
Pub: 06 Jan 2025 06:39 UTC
Edit: 06 Jan 2025 06:56 UTC
Views: 25