xgo trace: a powerful visualization tool in go

April 21, 2024

Overview

Xgo has a set of tools to help go developers write unit test faster and easier.

These tools include:

Trace
Mock
Trap

This blog introduces the Trace tool.

In case you don’t know, the xgo project is at https://github.com/xhd2015/xgo.

About the trace

The trace in xgo can be used to visualize execution of a go program.

In some cases, this can replace the debugger, reducing the effort to find a bug.

The problem

When starting with a new strange project, we cannot quickly get a picture of what the whole program do under the hood.

It’s hard to break down the details by just running some tests and observing the results.

Fortunately, this will never be the case in xgo, which brings a trace utility to address this issue.

To demonstrate how trace helps us understand code quickly, I’ll start with a random project asked by a reddit user the other day, which can be found at https://www.reddit.com/r/golang/s/RpEtEApIUj.

Clone the repo and run some tests

The project chosen is pocketbase.

To get started, let’s follow these steps:

Clone it

git clone https://github.com/pocketbase/pocketbase.git
cd pocketbase

Run a top level test of apis/backup_test.go

go test -v -run TestBackupsList ./apis

Output:

=== RUN   TestBackupsList
=== PAUSE TestBackupsList
=== CONT  TestBackupsList
=== RUN   TestBackupsList/unauthorized
=== RUN   TestBackupsList/authorized_as_auth_record
=== RUN   TestBackupsList/authorized_as_admin_(empty_list)
=== RUN   TestBackupsList/authorized_as_admin
--- PASS: TestBackupsList (0.83s)
    --- PASS: TestBackupsList/unauthorized (0.23s)
    --- PASS: TestBackupsList/authorized_as_auth_record (0.29s)
    --- PASS: TestBackupsList/authorized_as_admin_(empty_list) (0.08s)
    --- PASS: TestBackupsList/authorized_as_admin (0.23s)
PASS
ok      github.com/pocketbase/pocketbase/apis   2.483s

Fine, all goes well, let’s visualize the stack trace of the above tests.

First attempt to use trace

Xgo trace comes with zero dependency, this is dedicated as you do not have to modify anything in your project.

However a minimal installation of xgo is required:

go install github.com/xhd2015/xgo/cmd/xgo@latest

Then, just replace go test with xgo test, and add a --strace flag(abbrev. for stack trace):

xgo test -v -run TestBackupsList --strace ./apis

Output:

xgo is taking a while to setup, please wait...
=== RUN   TestBackupsList
=== PAUSE TestBackupsList
=== CONT  TestBackupsList
=== RUN   TestBackupsList/unauthorized
=== RUN   TestBackupsList/authorized_as_auth_record
=== RUN   TestBackupsList/authorized_as_admin_(empty_list)
=== RUN   TestBackupsList/authorized_as_admin
--- PASS: TestBackupsList (1.17s)
--- PASS: TestBackupsList/unauthorized (0.35s)
--- PASS: TestBackupsList/authorized_as_auth_record (0.35s)
--- PASS: TestBackupsList/authorized_as_admin_(empty_list) (0.13s)
--- PASS: TestBackupsList/authorized_as_admin (0.33s)
PASS
ok      github.com/pocketbase/pocketbase/apis   3.196s

The generated stack trace is one json file per test:

$ ls ./apis/TestBackupsList
authorized_as_admin.json
authorized_as_auth_record.json
authorized_as_admin_(empty_list).json
unauthorized.json

Visualize the test named TestBackupsList/unauthorized:

$ xgo tool trace apis/TestBackupsList/unauthorized.json
Server listen at http://localhost:7070

And the browser automatically opens up, showing:

Bingo! We get the stack trace… visualized!

Try to understand the code with the stack trace

As shown above in the stack trace screenshot:

in the left side is the call tree, each item represents a function entry, including:
- a colored rectangle before each item
  - navy indicates the function returned normally
  - red indicates the function returned an error
- a greyed time to indicate the duration of this call
in the right side is the selected function’s package path, request and response
- a VSCode icon next to function name
- when clicked, will open vscode and locate to the position where the function is defined

And for this specific case, we can see there is a tree of red rectangles, meaning something is wrong there.

Since function usually bubbles error bottom up, we can directly locate the root cause of this error:

This function literally says:

error:The request requires valid admin authorization token to be set.

OK, so let’s click the VSCode icon to find out why. Here is the code apis/middlewares.go#L116:

// RequireAdminAuth middleware requires a request to have
// a valid admin Authorization header.
func RequireAdminAuth() echo.MiddlewareFunc {
	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {      <--- located to this line
			admin, _ := c.Get(ContextAdminKey).(*models.Admin)
			if admin == nil {
				return NewUnauthorizedError("The request requires valid admin authorization token to be set.", nil)
			}

			return next(c)
		}
	}
}

That is so obvious, the line admin, _ := c.Get(ContextAdminKey).(*models.Admin) just returned nil, so the error pops up.

So there must be somewhere a *models.Admin is injected to the context, and by looking at the stack trace, we find this func:

Let’s look into its code by clicking the VSCode icon, which leads us to apis/middlewares.go#L219:

func LoadAuthContext(app core.App) echo.MiddlewareFunc {
	return func(next echo.HandlerFunc) echo.HandlerFunc {
		return func(c echo.Context) error {        <--- located to this line
			token := c.Request().Header.Get("Authorization")
			if token == "" {
				return next(c)
			}

			// the schema is not required and it is only for
			// compatibility with the defaults of some HTTP clients
			token = strings.TrimPrefix(token, "Bearer ")
    ...
    switch tokenType {
			case tokens.TypeAdmin:
            ...
				if err == nil && admin != nil {
					c.Set(ContextAdminKey, admin)
				}
                ...
        }
    }
}

Obviously, it is this func’s responsibility to parse authorization header and inject a *models.Admin into the context.

So now we know this basically tests the scenario where the incoming user is not an appropriate admin but requires doing admin-only operation. Thus it should fail.

Compared with traditional stack trace

The usual stack trace generated by the runtime is a snapshot of the program when trace is generated, thus it’s missing full footprints of the program.

Besides, the stack trace generated by by runtime does not resolve values deeply. Only hex encoded values are shown.

While xgo generate nearly full lifetime of a function execution trace, and each step contains a detailed request and response record. That makes them much different.

Summary

So through this simple example we have examined how the xgo stack trace can help when we are facing new project, the above example stack trace can be found at https://blog.xhd2015.xyz/trace-pocketbase.html.

But the benefit is not only understanding new things quickly. It could also eliminate the need to use a debugger like delve.

Using devle to debug the program is sometimes tedious if the code contains many level of indirections. But xgo reveals all compile-time indirections to their implementations, which means you can get a real footprint of your program, and possibly finding the bottleneck of your program by looking at the cost of each step.

That’s all, thanks for reading! You can leave a comment at https://github.com/xhd2015/xgo if you’d like to discuss. And if you find this project useful, please leave a star so more people can see it!