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 Tracer
• The Off() - method-gets a Tracer that does nothing
• The 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.