Tracing code to get a look under the hood
The only way we will know that our application is working is by opening two or more browsers and using our UI to send messages. In other words, we are manually testing our code. This is fine for experimental projects such as our chat application or small projects that aren't expected to grow, but if our code is to have a longer life or be worked on by more than one person, manual testing of this kind becomes a liability. We are not going to tackle Test-driven Development (TDD) for our chat program, but we should explore another useful debugging technique called tracing.
Tracing is a practice by which we log or print key steps in the flow of a program to make what is going on under the covers visible. In the previous section, we added a log.Println
call to output the address that the chat program was binding to. In this section, we are going to formalize this and write our own complete tracing package.
We are going to explore TDD practices when writing our tracing code because TDD is a perfect example of a package that we are likely to reuse, add to, share, and hopefully, even open source.
Writing a package using TDD
Packages in Go are organized into folders, with one package per folder. It is a build error to have differing package declarations within the same folder because all sibling files are expected to contribute to a single package. Go has no concept of subpackages, which means nested packages (in nested folders) exist only for aesthetic or informational reasons but do not inherit any functionality or visibility from super packages. In our chat application, all of our files contributed to the main
package because we wanted to build an executable tool. Our tracing package will never be run directly, so it can and should use a different package name. We will also need to think about the Application Programming Interface (API) of our package, considering how to model a package so that it remains as extensible and flexible as possible for users. This includes the fields, functions, methods, and types that should be exported (visible to the user) and remain hidden for simplicity's sake.
Note
Go uses capitalization of names to denote which items are exported such that names that begin with a capital letter (for example, Tracer
) are visible to users of a package, and names that begin with a lowercase letter (for example, templateHandler
) are hidden or private.
Create a new folder called trace
, which will be the name of our tracing package, alongside the chat
folder so that the folder structure now looks like this:
/chat client.go main.go room.go /trace
Before we jump into code, let's agree on some design goals for our package by which we can measure success:
The package should be easy to use
Unit tests should cover the functionality
Users should have the flexibility to replace the tracer with their own implementation
Interfaces
Interfaces in Go are an extremely powerful language feature that allows us to define an API without being strict or specific on the implementation details. Wherever possible, describing the basic building blocks of your packages using interfaces usually ends up paying dividends down the road, and this is where we will start for our tracing package.
Create a new file called tracer.go
inside the trace
folder and write the following code:
package trace // Tracer is the interface that describes an object capable of // tracing events throughout code. type Tracer interface { Trace(...interface{}) }
The first thing to notice is that we have defined our package as trace
.
Note
While it is a good practice to have the folder name match the package name, Go tools do not enforce it, which means you are free to name them differently if it makes sense. Remember, when people import your package, they will type the name of the folder, and if suddenly a package with a different name is imported, it could get confusing.
Our Tracer
type (the capital T
means we intend this to be a publicly visible type) is an interface that describes a single method called Trace
. The ...interface{}
argument type states that our Trace
method will accept zero or more arguments of any type. You might think that this is a redundant provision as the method should just take a single string (we want to just trace out some string of characters, don't we?). However, consider functions such as fmt.Sprint
and log.Fatal
, both of which follow a pattern littered throughout Go's standard library that provides a helpful shortcut when trying to communicate multiple things in one go. Wherever possible, we should follow such patterns and practices because we want our own APIs to be familiar and clear to the Go community.
Unit tests
We promised ourselves that we would follow test-driven practices, but interfaces are simply definitions that do not provide any implementation and so cannot be directly tested. But we are about to write a real implementation of a Tracer
method, and we will indeed write the tests first.
Create a new file called tracer_test.go
in the trace
folder and insert the following scaffold code:
package trace import ( "testing" ) func TestNew(t *testing.T) { t.Error("We haven't written our test yet") }
Testing was built into the Go tool chain from the very beginning, making writing automatable tests a first-class citizen. The test code lives alongside the production code in files suffixed with _test.go
. The Go tools will treat any function that starts with Test
(taking a single *testing.T
argument) as a unit test, and it will be executed when we run our tests. To run them for this package, navigate to the trace
folder in a terminal and do the following:
go test
You will see that our tests fail because of our call to t.Error
in the body of our TestNew
function:
--- FAIL: TestNew (0.00 seconds) tracer_test.go:8: We haven't written our test yet FAIL exit status 1 FAIL trace 0.011s
Tip
Clearing the terminal before each test run is a great way to make sure you aren't confusing previous runs with the most recent one. On Windows, you can use the cls
command; on Unix machines, the clear
command does the same thing.
Obviously, we haven't properly written our test and we don't expect it to pass yet, so let's update the TestNew
function:
func TestNew(t *testing.T) { var buf bytes.Buffer tracer := New(&buf) if tracer == nil { t.Error("Return from New should not be nil") } else { tracer.Trace("Hello trace package.") if buf.String() != "Hello trace package.\n" { t.Errorf("Trace should not write '%s'.", buf.String()) } } }
Most packages throughout the book are available from the Go standard library, so you can add an import
statement for the appropriate package in order to access the package. Others are external, and that's when you need to use go get
to download them before they can be imported. For this case, you'll need to add import "bytes"
to the top of the file.
We have started designing our API by becoming the first user of it. We want to be able to capture the output of our tracer in a bytes.Buffer
variable so that we can then ensure that the string in the buffer matches the expected value. If it does not, a call to t.Errorf
will fail the test. Before that, we check to make sure the return from a made-up New
function is not nil
; again, if it is, the test will fail because of the call to t.Error
.
Red-green testing
Running go test
now actually produces an error; it complains that there is no New
function. We haven't made a mistake here; we are following a practice known as red-green testing. Red-green testing proposes that we first write a unit test, see it fail (or produce an error), write the minimum amount of code possible to make that test pass, and rinse and repeat it again. The key point here being that we want to make sure the code we add is actually doing something as well as ensuring that the test code we write is testing something meaningful.
Consider a meaningless test for a minute:
if true == true { t.Error("True should be true") }
It is logically impossible for true
to not be true (if true
ever equals false
, it's time to get a new computer), and so our test is pointless. If a test or claim cannot fail, there is no value whatsoever to be found in it.
Replacing true
with a variable that you expect to be set to true
under certain conditions would mean that such a test can indeed fail (like when the code being tested is misbehaving) at this point, you have a meaningful test that is worth contributing to the code base.
You can treat the output of go test
like a to-do list, solving only one problem at a time. Right now, the complaint about the missing New
function is all we will address. In the trace.go
file, let's add the minimum amount of code possible to progress with things; add the following snippet underneath the interface type definition:
func New() {}
Running go test
now shows us that things have indeed progressed, albeit not very far. We now have two errors:
./tracer_test.go:11: too many arguments in call to New ./tracer_test.go:11: New(&buf) used as value
The first error tells us that we are passing arguments to our New
function, but the New
function doesn't accept any. The second error says that we are using the return of the New
function as a value, but that the New
function doesn't return anything. You might have seen this coming, and indeed as you gain more experience writing test-driven code, you will most likely jump over such trivial details. However, to properly illustrate the method, we are going to be pedantic for a while. Let's address the first error by updating our New
function to take in the expected argument:
func New(w io.Writer) {}
We are taking an argument that satisfies the io.Writer
interface, which means that the specified object must have a suitable Write
method.
Note
Using existing interfaces, especially ones found in the Go standard library, is an extremely powerful and often necessary way to ensure that your code is as flexible and elegant as possible.
Accepting io.Writer
means that the user can decide where the tracing output will be written. This output could be the standard output, a file, network socket, bytes.Buffer
as in our test case, or even some custom-made object, provided it can act like an io.Writer
interface.
Running go test
again shows us that we have resolved the first error and we only need add a return type in order to progress past our second error:
func New(w io.Writer) Tracer {}
We are stating that our New
function will return a Tracer
, but we do not return anything, which go test
happily complains about:
./tracer.go:13: missing return at end of function
Fixing this is easy; we can just return nil
from the New
function:
func New(w io.Writer) Tracer { return nil }
Of course, our test code has asserted that the return should not be nil
, so go test
now gives us a failure message:
tracer_test.go:14: Return from New should not be nil
You can see how this hyper-strict adherence to the red-green principle can get a little tedious, but it is vital that we do not jump too far ahead. If we were to write a lot of implementation code in one go, we will very likely have code that is not covered by a unit test.
The ever-thoughtful core team has even solved this problem for us by providing code coverage statistics. The following command provides code statistics:
go test -cover
Provided that all tests pass, adding the -cover
flag will tell us how much of our code was touched during the execution of the tests. Obviously, the closer we get to 100 percent the better.
Implementing the interface
To satisfy this test, we need something that we can properly return from the New
method because Tracer
is only an interface and we have to return something real. Let's add an implementation of a tracer to our tracer.go
file:
type tracer struct { out io.Writer } func (t *tracer) Trace(a ...interface{}) {}
Our implementation is extremely simple: the tracer
type has an io.Writer
field called out
which is where we will write the trace output to. And the Trace
method exactly matches the method required by the Tracer
interface, although it doesn't do anything yet.
Now we can finally fix the New
method:
func New(w io.Writer) Tracer { return &tracer{out: w} }
Running go test
again shows us that our expectation was not met because nothing was written during our call to Trace
:
tracer_test.go:18: Trace should not write ''.
Let's update our Trace
method to write the blended arguments to the specified io.Writer
field:
func (t *tracer) Trace(a ...interface{}) { fmt.Fprint(t.out, a...) fmt.Fprintln(t.out) }
When the Trace
method is called, we use fmt.Fprint
(and fmt.Fprintln
) to format and write the trace details to the out
writer.
Have we finally satisfied our test?
go test -cover PASS coverage: 100.0% of statements ok trace 0.011s
Congratulations! We have successfully passed our test and have 100 percent test coverage. Once we have finished our glass of champagne, we can take a minute to consider something very interesting about our implementation.
Unexported types being returned to users
The tracer
struct type we wrote is unexported because it begins with a lowercase t
, so how is it that we are able to return it from the exported New
function? After all, doesn't the user receive the returned object? This is perfectly acceptable and valid Go code; the user will only ever see an object that satisfies the Tracer
interface and will never even know about our private tracer
type. Since they only interact with the interface anyway, it wouldn't matter if our tracer
implementation exposed other methods or fields; they would never be seen. This allows us to keep the public API of our package clean and simple.
This hidden implementation technique is used throughout the Go standard library; for example, the ioutil.NopCloser
method is a function that turns a normal io.Reader
interface into io.ReadCloser
where the Close
method does nothing (used for when io.Reader
objects that don't need to be closed are passed into functions that require io.ReadCloser
types). The method returns io.ReadCloser
as far as the user is concerned, but under the hood, there is a secret nopCloser
type hiding the implementation details.
Note
To see this for yourself, browse the Go standard library source code at
http://golang.org/src/pkg/io/ioutil/ioutil.go and search for the nopCloser
struct.
Using our new trace package
Now that we have completed the first version of our trace
package, we can use it in our chat application in order to better understand what is going on when users send messages through the user interface.
In room.go
, let's import our new package and make some calls to the Trace
method. The path to the trace
package we just wrote will depend on your GOPATH
environment variable because the import path is relative to the $GOPATH/src
folder. So if you create your trace
package in $GOPATH/src/mycode/trace
, then you would need to import mycode/trace
.
Update the room
type and the run()
method like this:
type room struct { // forward is a channel that holds incoming messages // that should be forwarded to the other clients. forward chan []byte // join is a channel for clients wishing to join the room. join chan *client // leave is a channel for clients wishing to leave the room. leave chan *client // clients holds all current clients in this room. clients map[*client]bool // tracer will receive trace information of activity // in the room. tracer trace.Tracer } func (r *room) run() { for { select { case client := <-r.join: // joining r.clients[client] = true r.tracer.Trace("New client joined") case client := <-r.leave: // leaving delete(r.clients, client) close(client.send) r.tracer.Trace("Client left") case msg := <-r.forward: r.tracer.Trace("Message received: ", string(msg)) // forward message to all clients for client := range r.clients { client.send <- msg r.tracer.Trace(" -- sent to client") } } } }
We added a trace.Tracer
field to our room
type and then made periodic calls to the Trace
method peppered throughout the code. If we run our program and try to send messages, you'll notice that the application panics because the tracer
field is nil
. We can remedy this for now by making sure we create and assign an appropriate object when we create our room
type. Update the main.go
file to do this:
r := newRoom() r.tracer = trace.New(os.Stdout)
We are using our New
method to create an object that will send the output to the os.Stdout
standard output pipe (this is a technical way of saying we want it to print the output to our terminal).
Rebuild and run the program and use two browsers to play with the application, and notice that the terminal now has some interesting trace information for us:
Now we are able to use the debug information to get an insight into what the application is doing, which will assist us when developing and supporting our project.
Making tracing optional
Once the application is released, the sort of tracing information we are generating will be pretty useless if it's just printed out to some terminal somewhere, or even worse, if it creates a lot of noise for our system administrators. Also, remember that when we don't set a tracer for our room
type, our code panics, which isn't a very user-friendly situation. To resolve these two issues, we are going to enhance our trace
package with a trace.Off()
method that will return an object that satisfies the Tracer
interface but will not do anything when the Trace
method is called.
Let's add a test that calls the Off
function to get a silent tracer before making a call to Trace
to ensure the code doesn't panic. Since the tracing won't happen, that's all we can do in our test code. Add the following test function to the tracer_test.go
file:
func TestOff(t *testing.T) { var silentTracer Tracer = Off() silentTracer.Trace("something") }
To make it pass, add the following code to the tracer.go
file:
type nilTracer struct{} func (t *nilTracer) Trace(a ...interface{}) {} // Off creates a Tracer that will ignore calls to Trace. func Off() Tracer { return &nilTracer{} }
Our nilTracer
struct has defined a Trace
method that does nothing, and a call to the Off()
method will create a new nilTracer
struct and return it. Notice that our nilTracer
struct differs from our tracer
struct in that it doesn't take an io.Writer
interface; it doesn't need one because it isn't going to write anything.
Now let's solve our second problem by updating our newRoom
method in the room.go
file:
func newRoom() *room { return &room{ forward: make(chan []byte), join: make(chan *client), leave: make(chan *client), clients: make(map[*client]bool), tracer: trace.Off(), } }
By default, our room
type will be created with a nilTracer
struct and any calls to Trace
will just be ignored. You can try this out by removing the r.tracer = trace.New(os.Stdout)
line from the main.go
file: notice that nothing gets written to the terminal when you use the application and there is no panic.
Clean package APIs
A quick glance at the API (in this context, the exposed variables, methods, and types) for our trace
package highlights that a simple and obvious design has emerged:
The
New()
- method-creates a new instance of a TracerThe
Off()
- method-gets a Tracer that does nothingThe
Tracer
interface - describes the methods Tracer objects will implement
I would be very confident to give this package to a Go programmer without any documentation or guidelines, and I'm pretty sure they would know what do to with it.
Note
In Go, adding documentation is as simple as adding comments to the line before each item. The blog post on the subject is a worthwhile read (http://blog.golang.org/godoc-documenting-go-code), where you can see a copy of the hosted source code for tracer.go
that is an example of how you might annotate the trace
package. For more information, refer to https://github.com/matryer/goblueprints/blob/master/chapter1/trace/tracer.go.