This post talks about the internals of the testing package.

I am releasing a series of articles to dive deep into the internals of a few packages.

If you are interested, I’ll post their release on Twitter and LinkedIn .

Internal of the testing Log API

Every time in a test we use the Log API from the T type, part of the testing package, what happens behind the scene is more complex than you may think.

package testlog

func TestLog(t *testing.T) {
    t.Log("Deep dive!")
}

Depth

Each test log has a specific depth.

The depth concept is introduced because logs are written as nested information.

OT: I wrote a go package long time ago to reproduce similar behaviours

As an example, this test:

package testlog

func TestNestedLog(t *testing.T) {
    t.Run("test one", func(t *testing.T) {
        t.Log("One")
        t.Run("test nested one", func(t *testing.T) {
            t.Log("Nested One")
        })
    })

    t.Run("test two", func(t *testing.T) {
        t.Log("Two")
    })

    t.Run("test three", func(t *testing.T) {
        t.Log("Three")
    })
}

Will output this log:

=== RUN   TestNestedLog
=== RUN   TestNestedLog/test_one
    test_test.go:17: One
=== RUN   TestNestedLog/test_one/test_nested_one
    test_test.go:19: Nested One
=== RUN   TestNestedLog/test_two
    test_test.go:24: Two
=== RUN   TestNestedLog/test_three
    test_test.go:28: Three
--- PASS: TestNestedLog (0.00s)
    --- PASS: TestNestedLog/test_one (0.00s)
        --- PASS: TestNestedLog/test_one/test_nested_one (0.00s)
    --- PASS: TestNestedLog/test_two (0.00s)
    --- PASS: TestNestedLog/test_three (0.00s)
PASS

To achieve this behavior, the Log API calls the logDepth unexported method, which implements most of the logging behaviors.

package testing

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L915
func (c *common) Log(args ...any) {
    // ...
    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L917
    c.log(fmt.Sprintln(args...))
}

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L875
func (c *common) log(s string) {
    c.logDepth(s, 3)
}

Verbose is chatty!

When using the Log API, we know that the testing binary will print the log message only when at least one of the following criteria is met:

The flag test.v is set as true
A test fails

ThelogDepth method implements the logic itself.

package testing

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L880
func (c *common) logDepth(s string, depth int) {
    // ...
    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L896
    if c.chatty != nil {
        // ...
        // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L902
        c.chatty.Printf(c.name, "%s", c.decorate(s, depth+1))
        return
    }
    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L907
    c.output = append(c.output, c.decorate(s, depth+1)...)
    // ...
}

The chatty field represents a printer, nil by default, but when passing the flag test.v as true, it is initiated with newChattyPrinter(t.w) to print the content of the log also on test success.

The chattyPrinter has a simple implementation logic, since it prints the log appending some extra information, such as the test name or === CONT if the previously written log came from another test case.

package testing

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L476
func (p *chattyPrinter) Printf(testName, format string, args ...any) {
    p.lastNameMu.Lock()
    defer p.lastNameMu.Unlock()
    
    if p.lastName == "" {
        p.lastName = testName
    } else if p.lastName != testName {
        fmt.Fprintf(p.w, "=== CONT  %s\n", testName)
        p.lastName = testName
    }
    
    fmt.Fprintf(p.w, format, args...)
}

Non-verbose prints only on failure

In the other scenario, if the flag test.v is not set as true, the log is appended to the test output, as shown

package testing

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L880
func (c *common) logDepth(s string, depth int) {
    // ...
    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L907
    c.output = append(c.output, c.decorate(s, depth+1)...)
}

The test output is printed from the t.report function only if the test is marked as failed.

package testing

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L1758
func (t *T) report() {
    // ...
    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L1762
    dstr := fmtDuration(t.duration)
    format := "--- %s: %s (%s)\n"
    if t.Failed() {
        t.flushToParent(t.name, format, "FAIL", t.name, dstr)
    } 
   // ...
}

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L689
func (c *common) flushToParent(testName, format string, args ...any) {
    p := c.parent
    p.mu.Lock()
    defer p.mu.Unlock()
    
    c.mu.Lock()
    defer c.mu.Unlock(

    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L717
    fmt.Fprintf(p.w, format, args...)
    // ...
}

Logging when testing.T is done

There are, of course, edge cases that the testing package needs to handle, letting the software engineers know that something is not going down as planned.

In fact, it may happen that your tests are finished, but a non-terminated goroutine spawned in the tests tries to call the Log API.

An example:

package testlog

func TestMain(m *testing.M) {
   code := m.Run()
   time.Sleep(time.Second)
   os.Exit(code)
}

func TestPanicAfterCompletion(t *testing.T) {
   t.Parallel()

   t.Run("sub", func(t *testing.T) {
      go func() {
         time.Sleep(100 * time.Millisecond)
         t.Log("No, Surprise!")
      }()
      t.Log("I think you are, yeah!")
   })

   t.Log("Am I really done?")
}

Running this test makes the testing binary produce a panic:

panic: Log in goroutine after TestPanicAfterCompletion/inner has completed: No, Surprise!

goroutine 6 [running]:
testing.(*common).logDepth(0x14000003a00, {0x14000020200, 0xe}, 0x3)
   /opt/homebrew/Cellar/go/1.19.4/libexec/src/testing/testing.go:894 +0x3c0
testing.(*common).log(...)
   /opt/homebrew/Cellar/go/1.19.4/libexec/src/testing/testing.go:876
testing.(*common).Log(0x14000003a00, {0x140000487b8?, 0x0?, 0x0?})
   /opt/homebrew/Cellar/go/1.19.4/libexec/src/testing/testing.go:917 +0x4c
github.com/damianopetrungaro/testlog.TestPanicAfterCompletion.func1.1()
   /Users/damianopetrungaro/go/src/github.com/damianopetrungaro/testlog/test_test.go:21 +0x60
created by github.com/damianopetrungaro/testlog.TestPanicAfterCompletion.func1
   /Users/damianopetrungaro/go/src/github.com/damianopetrungaro/testlog/test_test.go:19 +0x60

To handle this edge case, the standard library tries to append the content of the log to the first non-done parent of the given *T caller.

If all the parents are done, a panic is called.

This is the implementation:

package testing

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L880
func (c *common) logDepth(s string, depth int) {
    c.mu.Lock()
    defer c.mu.Unlock()
    if c.done {
        for parent := c.parent; parent != nil; parent = parent.parent {
            parent.mu.Lock()
            defer parent.mu.Unlock()
            if !parent.done {
                parent.output = append(parent.output, parent.decorate(s, depth+1)...)
                return
            }
        }
        panic("Log in goroutine after " + c.name + " has completed: " + s)
    }
    // ...
}

On the other hand when a parent test is available and non-done as shown in this snippet:

package testlog

func TestMain(m *testing.M) {
   code := m.Run()
   time.Sleep(time.Second)
   os.Exit(code)
}

func TestPanicAfterCompletion(t *testing.T) {
   t.Parallel()

   t.Run("sub", func(t *testing.T) {
      go func() {
         time.Sleep(100 * time.Millisecond)
         t.Log("No, Surprise!")
      }()
      t.Log("I think you are, yeah!")
   })

    time.Sleep(200 * time.Millisecond)
    t.Log("Am I really done?")
}

The late log t.Log("No, Surprise!") is printed as part of the parent TestPanicAfterCompletion test and not as the TestPanicAfterCompletion/sub one.

=== RUN   TestPanicAfterCompletion
=== PAUSE TestPanicAfterCompletion
=== CONT  TestPanicAfterCompletion
=== CONT  TestPanicAfterCompletion
    test_test.go:27: Am I really done?
--- PASS: TestPanicAfterCompletion (0.20s)
    test_test.go:21: No, Surprise!
=== RUN   TestPanicAfterCompletion/sub
    test_test.go:23: I think you are, yeah!
    --- PASS: TestPanicAfterCompletion/sub (0.00s)
PASS

Do you need “help”?

The last piece of information I feel worth sharing is what happen when calling a t.Log() from a function marked as helper viat.Helper().

For example let’s take this simple test:

package testlog

import (
    "testing"
)

func TestHelper(t *testing.T) {
    helper(t)
    nonHelper(t)
}

func nonHelper(t *testing.T) {
    t.Log("I come from nonHelper!")
}

func helper(t *testing.T) {
    t.Helper()
    t.Log("I come from helper!")
}

When running, it prints:

=== RUN   TestHelper
    test_test.go:8: I come from helper!
    test_test.go:13: I come from nonHelper!
--- PASS: TestHelper (0.00s)
PASS

If you notice, the first log message comes from the “wrong line”.

This occurs thanks to the Helper API, which records the caller’s stack frame.

package testing

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L999
func (c *common) Helper() {
    c.mu.Lock()
    defer c.mu.Unlock()
    if c.helperPCs == nil {
        c.helperPCs = make(map[uintptr]struct{})
    }
    //...
    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L1011
    if _, found := c.helperPCs[pc[0]]; !found {
        c.helperPCs[pc[0]] = struct{}{}
        c.helperNames = nil // map will be recreated next time it is needed
    }
}

When printing logs (always passing by logDepth) the decorate method will call frameSkip that searches for the previously recorded frames and skips them:

package testing

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L880
func (c *common) logDepth(s string, depth int) {
    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L902
    c.chatty.Printf(c.name, "%s", c.decorate(s, depth+1))
    return
    // ...
}

// ...

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L651
func (c *common) decorate(s string, skip int) string {
    frame := c.frameSkip(skip)
    file := frame.File
    line := frame.Line
   // ...
}

// https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L577
func (c *common) frameSkip(skip int) runtime.Frame {
    // https://github.com/golang/go/blob/go1.19.5/src/testing/testing.go#L640
    if _, ok := c.helperNames[frame.Function]; !ok {
        // Found a frame that wasn't inside a helper function.
        return frame
    }
    // ...
}

Conclusion

I hope the implementation details are now clear to you, and expect more content about internals related to the testing package in the following weeks.

Feel free to send me a DM on Twitter, LinkedIn or add a comment in the section below!

Internal of the testing Log API#

Depth#

Verbose is chatty!#

Non-verbose prints only on failure#

Logging when testing.T is done#

Do you need “help”?#

Conclusion#