Groking our trace log file

In order to get a deeper understanding of why our attempts failed, we can look in our trace file.

Groking is an old Scots term meaning to look at somebody while they're eating in the hope that they'll give you some of their food. In our case, we'll be looking intently at a trace log file in hope of getting some morsel of understanding:

INFO  : 13:46:19 Metrics server listening on 127.0.0.1:3000
INFO  : 13:46:20 Proxy listening on 127.0.0.1:8080
DEBUG : 2017/05/17 13:46:30 requester.go:114: makeRequest:
client: 13:46:30 GET http://127.0.0.1:3000
DEBUG : 2017/05/17 13:46:30 metrics.go:66: - randInt: 3081
DEBUG : 2017/05/17 13:46:31 decorator.go:107: backing off...
client: 13:46:31 GET http://web02:3000
DEBUG : 2017/05/17 13:46:31 metrics.go:66: - randInt: 2887
DEBUG : 2017/05/17 13:46:32 decorator.go:107: backing off...
client: 13:46:33 GET http://web03:3000
DEBUG : 2017/05/17 13:46:33 metrics.go:66: - randInt: 1847
DEBUG : 2017/05/17 13:46:34 decorator.go:107: backing off...
INFO  : 13:46:36 FAILURE! 

Here's the call to our call to the FaultTolerance function:

FaultTolerance(2, time.Second),

The key lines from our FaultTolerance decorator are as follows:

func FaultTolerance(attempts int, backoff time.Duration) Decorator
   . . .
       for i := 0; i <= attempts; i++ {
              if res, err = c.Do(r); err == nil {
                     Info.Println("SUCCESS!")
                     break
              }
              Debug.Println("backing off...")
              time.Sleep(backoff * time.Duration(i))
       }

       if err != nil { Info.Println("FAILURE!") }
       return res, err
   . . .

This indicates that if we don't succeed at first, we'll try again twice and wait for a second between each attempt.

The work is performed in the metrics.go file. Note that work can take anywhere from 0 to 5,000 milliseconds:

func work() {
       randInt := rand.Intn(5000)
       decorator.Debug.Printf("- randInt: %v", randInt)
       workTime := time.Duration(randInt) * time.Millisecond
       time.Sleep(workTime)
}

Lastly, recall that we set our per request timeout to 1 second when we defined proxyTimeoutClient:

proxyTimeoutClient := &http.Client{Transport: tr, Timeout: 1 * time.Second}

We tried thrice and none of our attempts took less than a second, so our first set of requests resulted in a failure.